Добро пожаловать в форум, Guest  >>   Войти | Регистрация | Поиск | Правила | В избранное | Подписаться
Все форумы / Oracle Новый топик    Ответить
 PARSE маленького блока длился > 35 минут  [new]
expimp
Member

Откуда:
Сообщений: 573
От разработчиков пошли жалобы на зависание.
Да, действительно, прогнал на выполнение один из блоков, включив 10046.
Все висело на парсе.
В файле трассировке вижу


=====================
PARSING IN CURSOR #6 len=1003 dep=0 uid=116 oct=47 lid=116 tim=1426065627995724 hv=3165883101 ad='10871d758' sqlid='6zzxz0fyb72qx'
DECLARE
type v_Return_cur is REF CURSOR;
v_Return v_Return_cur;
RULE_NODE_ID NUMBER;
PARENT_RULE_NODE_ID NUMBER;
BPR_CONTROL_UNIT_ID NUMBER;
RULE_NODE_TY NUMBER;
RULE_OPERATOR_CV NUMBER;
BPR_ID NUMBER;
ORDER_COL NUMBER;
MATCH VARCHAR2(255);
i PLS_INTEGER:=0;
BEGIN
v_Return := KSA$VR_J2EE_INTERFACE_DS.GET_BPRRULENODE();
LOOP
i:=i+1;
FETCH v_Return
into RULE_NODE_ID, PARENT_RULE_NODE_ID, BPR_CONTROL_UNIT_ID, RULE_NODE_TY, RULE_OPERATOR_CV, BPR_ID, ORDER_COL, MATCH;
exit when v_Return%notfound;
dbms_output.put_line(RULE_NODE_ID || ', ' || PARENT_RULE_NODE_ID || ', ' || BPR_CONTROL_UNIT_ID || ', ' || RULE_NODE_TY || ', ' || RULE_NODE_TY || ', ' || RULE_OPERATOR_CV || ', ' || BPR_ID || ', ' || ORDER_COL || ', ' || MATCH);
end loop;
IF v_Return%isOPEN THEN
close v_Return;
END IF;
END;
END OF STMT
PARSE #6:c=1060555771,e=2154882166,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=0,tim=1426065627995722

Если облагородить через tkprof


call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 1060.55 2154.88 0 0 0 0
Execute 1 13.07 32.95 0 0 1 1
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2 1073.63 2187.83 0 0 1 1

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 116

Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
single-task message 1 0.31 0.31
SQL*Net message from dblink 8 0.21 0.70
SQL*Net message to dblink 7 0.00 0.00
SQL*Net more data from dblink 31 0.07 0.33
SQL*Net message to client 1 0.00 0.00
SQL*Net message from client 1 0.00 0.00
********************************************************************************

У разработчиков пять почти одинаковых схем. На двух из них отрабатывало нормально.
И, после перезапуска проблема ушла.
Я совсем не рад, что проблема закончилась. Потому что, вопрос остался - что было. Что могло быть?!
11 мар 15, 14:37    [17370234]     Ответить | Цитировать Сообщить модератору
 Re: PARSE маленького блока длился > 35 минут  [new]
xtender
Member

Откуда: Мск
Сообщений: 5704
expimp
KSA$VR_J2EE_INTERFACE_DS.GET_BPRRULENODE()
эту штуку разбирать надо скорее всего
11 мар 15, 15:31    [17370687]     Ответить | Цитировать Сообщить модератору
 Re: PARSE маленького блока длился > 35 минут  [new]
DВА
Member

Откуда:
Сообщений: 5439
xtender
expimp
KSA$VR_J2EE_INTERFACE_DS.GET_BPRRULENODE()
эту штуку разбирать надо скорее всего

да еще на удаленном сервере ))
11 мар 15, 15:36    [17370718]     Ответить | Цитировать Сообщить модератору
 Re: PARSE маленького блока длился > 35 минут  [new]
expimp
Member

Откуда:
Сообщений: 573
Читал, читал и, кажется, вычитал, что это проблема
"Oracle bug 5184776 can affect 11g databases that deploy the mutex latching, causing excessive ‘cursor pin s wait on x’ wait events".
Жаль, Металинка нет.

И нашел еще, на форуме обсуждалось подобное
https://www.sql.ru/forum/744646/cursor-pin-s-wait-on-x
11 мар 15, 15:43    [17370769]     Ответить | Цитировать Сообщить модератору
 Re: PARSE маленького блока длился > 35 минут  [new]
Melkomyagkii_newbi
Member

Откуда: из прошлого
Сообщений: 1861
У нас встречались ‘cursor pin s wait on x’ при AMM, одновременно с ORA-04031(какой-то подбуфер shared poolа протекал и раздувался) - отказались от AMM.
11 мар 15, 16:10    [17370962]     Ответить | Цитировать Сообщить модератору
 Re: PARSE маленького блока длился > 35 минут  [new]
usolcew
Member

Откуда: Россия
Сообщений: 121
expimp,

>> вопрос остался - что было

в сыром трейсе не смотрели на что потрачены неотражённые в Elapsed times include waiting on following events 2000 секунд?
+ в dba_hist_active_session_history
11 мар 15, 18:34    [17371986]     Ответить | Цитировать Сообщить модератору
 Re: PARSE маленького блока длился > 35 минут  [new]
expimp
Member

Откуда:
Сообщений: 573
usolcew
expimp,

>> вопрос остался - что было

в сыром трейсе не смотрели на что потрачены неотражённые в Elapsed times include waiting on following events 2000 секунд?
+ в dba_hist_active_session_history


вот, я в глубоких размышлениях. На этот курсор #6 (именно этот, до смены хозяина этого тега) имею записи через grep


PARSING IN CURSOR #66 len=1003 dep=0 uid=116 oct=47 lid=116 tim=1426065627995724 hv=3165883101 ad='10871d758' sqlid='6zzxz0fyb72qx'
PARSE #6:c=1060555771,e=2154882166,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=0,tim=1426065627995722
WAIT #6: nam='single-task message' ela= 317489 p1=0 p2=0 p3=0 obj#=-1 tim=1426065628314865
WAIT #6: nam='SQL*Net message from dblink' ela= 67365 driver id=675562835 #bytes=1 p3=0 obj#=-1 tim=1426065628382525
WAIT #6: nam='SQL*Net message to dblink' ela= 2 driver id=675562835 #bytes=1 p3=0 obj#=-1 tim=1426065628382595
WAIT #6: nam='SQL*Net message from dblink' ela= 68560 driver id=675562835 #bytes=1 p3=0 obj#=-1 tim=1426065628451574
WAIT #6: nam='SQL*Net message to dblink' ela= 3 driver id=675562835 #bytes=1 p3=0 obj#=-1 tim=1426065628451977
WAIT #6: nam='SQL*Net message from dblink' ela= 68221 driver id=675562835 #bytes=1 p3=0 obj#=-1 tim=1426065628520232
WAIT #6: nam='SQL*Net message to dblink' ela= 3 driver id=675562835 #bytes=1 p3=0 obj#=-1 tim=1426065628520680
WAIT #6: nam='SQL*Net message from dblink' ela= 84836 driver id=675562835 #bytes=1 p3=0 obj#=-1 tim=1426065628605561
WAIT #6: nam='SQL*Net message to dblink' ela= 4 driver id=675562835 #bytes=1 p3=0 obj#=-1 tim=1426065628605877
WAIT #6: nam='SQL*Net message from dblink' ela= 67909 driver id=675562835 #bytes=1 p3=0 obj#=-1 tim=1426065628673839
WAIT #6: nam='SQL*Net message to dblink' ela= 4 driver id=675562835 #bytes=1 p3=0 obj#=-1 tim=1426065628674033
WAIT #6: nam='SQL*Net message from dblink' ela= 69084 driver id=675562835 #bytes=1 p3=0 obj#=-1 tim=1426065628743151
WAIT #6: nam='SQL*Net message to dblink' ela= 4 driver id=675562835 #bytes=1 p3=0 obj#=-1 tim=1426065628743463
WAIT #6: nam='SQL*Net message from dblink' ela= 67021 driver id=675562835 #bytes=1 p3=0 obj#=-1 tim=1426065628810516
WAIT #6: nam='SQL*Net message to dblink' ela= 3 driver id=675562835 #bytes=1 p3=0 obj#=-1 tim=1426065628810612
WAIT #6: nam='SQL*Net message from dblink' ela= 213983 driver id=675562835 #bytes=100 p3=0 obj#=-1 tim=1426065629024652
WAIT #6: nam='SQL*Net more data from dblink' ela= 30 driver id=675562835 #bytes=197 p3=0 obj#=-1 tim=1426065629027184
WAIT #6: nam='SQL*Net more data from dblink' ela= 63997 driver id=675562835 #bytes=44 p3=0 obj#=-1 tim=1426065629091714
WAIT #6: nam='SQL*Net more data from dblink' ela= 1249 driver id=675562835 #bytes=147 p3=0 obj#=-1 tim=1426065629093639
WAIT #6: nam='SQL*Net more data from dblink' ela= 93 driver id=675562835 #bytes=250 p3=0 obj#=-1 tim=1426065629094375
WAIT #6: nam='SQL*Net more data from dblink' ela= 66079 driver id=675562835 #bytes=97 p3=0 obj#=-1 tim=1426065629161178
WAIT #6: nam='SQL*Net more data from dblink' ela= 13 driver id=675562835 #bytes=200 p3=0 obj#=-1 tim=1426065629161767
WAIT #6: nam='SQL*Net more data from dblink' ela= 20 driver id=675562835 #bytes=47 p3=0 obj#=-1 tim=1426065629162485
WAIT #6: nam='SQL*Net more data from dblink' ela= 20 driver id=675562835 #bytes=150 p3=0 obj#=-1 tim=1426065629163321
WAIT #6: nam='SQL*Net more data from dblink' ela= 20 driver id=675562835 #bytes=253 p3=0 obj#=-1 tim=1426065629164075
WAIT #6: nam='SQL*Net more data from dblink' ela= 12 driver id=675562835 #bytes=93 p3=0 obj#=-1 tim=1426065629164595
WAIT #6: nam='SQL*Net more data from dblink' ela= 63781 driver id=675562835 #bytes=196 p3=0 obj#=-1 tim=1426065629228921
WAIT #6: nam='SQL*Net more data from dblink' ela= 22 driver id=675562835 #bytes=43 p3=0 obj#=-1 tim=1426065629229875
WAIT #6: nam='SQL*Net more data from dblink' ela= 46 driver id=675562835 #bytes=146 p3=0 obj#=-1 tim=1426065629230683
WAIT #6: nam='SQL*Net more data from dblink' ela= 19 driver id=675562835 #bytes=249 p3=0 obj#=-1 tim=1426065629231423
WAIT #6: nam='SQL*Net more data from dblink' ela= 20 driver id=675562835 #bytes=96 p3=0 obj#=-1 tim=1426065629232176
WAIT #6: nam='SQL*Net more data from dblink' ela= 19 driver id=675562835 #bytes=199 p3=0 obj#=-1 tim=1426065629232932
WAIT #6: nam='SQL*Net more data from dblink' ela= 19 driver id=675562835 #bytes=46 p3=0 obj#=-1 tim=1426065629233667
WAIT #6: nam='SQL*Net more data from dblink' ela= 79491 driver id=675562835 #bytes=149 p3=0 obj#=-1 tim=1426065629313716
WAIT #6: nam='SQL*Net more data from dblink' ela= 15 driver id=675562835 #bytes=252 p3=0 obj#=-1 tim=1426065629315697
WAIT #6: nam='SQL*Net more data from dblink' ela= 12 driver id=675562835 #bytes=92 p3=0 obj#=-1 tim=1426065629316159
WAIT #6: nam='SQL*Net more data from dblink' ela= 11 driver id=675562835 #bytes=195 p3=0 obj#=-1 tim=1426065629316640
WAIT #6: nam='SQL*Net more data from dblink' ela= 12 driver id=675562835 #bytes=42 p3=0 obj#=-1 tim=1426065629317136
WAIT #6: nam='SQL*Net more data from dblink' ela= 22 driver id=675562835 #bytes=145 p3=0 obj#=-1 tim=1426065629317631
WAIT #6: nam='SQL*Net more data from dblink' ela= 12 driver id=675562835 #bytes=248 p3=0 obj#=-1 tim=1426065629318145
WAIT #6: nam='SQL*Net more data from dblink' ela= 11 driver id=675562835 #bytes=95 p3=0 obj#=-1 tim=1426065629318626
WAIT #6: nam='SQL*Net more data from dblink' ela= 14 driver id=675562835 #bytes=198 p3=0 obj#=-1 tim=1426065629319833
WAIT #6: nam='SQL*Net more data from dblink' ela= 12 driver id=675562835 #bytes=45 p3=0 obj#=-1 tim=1426065629320311
WAIT #6: nam='SQL*Net more data from dblink' ela= 11 driver id=675562835 #bytes=148 p3=0 obj#=-1 tim=1426065629320795
WAIT #6: nam='SQL*Net more data from dblink' ela= 59983 driver id=675562835 #bytes=251 p3=0 obj#=-1 tim=1426065629381222
WAIT #6: nam='SQL*Net more data from dblink' ela= 86 driver id=675562835 #bytes=91 p3=0 obj#=-1 tim=1426065629381982
WAIT #6: nam='SQL*Net more data from dblink' ela= 19 driver id=675562835 #bytes=194 p3=0 obj#=-1 tim=1426065629382634
EXEC #6:c=23429437,e=72904576,p=51,cr=72446,cu=384238,mis=0,r=1,dep=0,og=1,plh=0,tim=1426065700900502
WAIT #6: nam='SQL*Net message to client' ela= 3 driver id=1952673792 #bytes=1 p3=0 obj#=-1 tim=1426065700901283
WAIT #6: nam='SQL*Net message from client' ela= 1190 driver id=1952673792 #bytes=1 p3=0 obj#=-1 tim=1426065700902505
CLOSE #6:c=0,e=29,dep=0,type=0,tim=1426065701310261

т.е. какая-то возня с dblink происходит, но ela очень не значительна. И ведь сразу же написано, что висит на PARSING
11 мар 15, 19:13    [17372124]     Ответить | Цитировать Сообщить модератору
 Re: PARSE маленького блока длился > 35 минут  [new]
usolcew
Member

Откуда: Россия
Сообщений: 121
expimp,

а покажите строку, предшествующую:

PARSING IN CURSOR #6 len=1003 dep=0 uid=116 oct=47 lid=116 tim=1426065627995724 hv=3165883101 ad='10871d758' sqlid='6zzxz0fyb72qx'

в кот. есть tim=
, ну и dba_hist_active_session_history смотрите по сессии/sql_id
12 мар 15, 10:21    [17373673]     Ответить | Цитировать Сообщить модератору
 Re: PARSE маленького блока длился > 35 минут  [new]
expimp
Member

Откуда:
Сообщений: 573
usolcew
expimp,

а покажите строку, предшествующую:

PARSING IN CURSOR #6 len=1003 dep=0 uid=116 oct=47 lid=116 tim=1426065627995724 hv=3165883101 ad='10871d758' sqlid='6zzxz0fyb72qx'

в кот. есть tim=
, ну и dba_hist_active_session_history смотрите по сессии/sql_id


вот такая ботва


=====================
PARSING IN CURSOR #5 len=76 dep=0 uid=116 oct=3 lid=116 tim=1426063467937606 hv=1778212192 ad='108e0f610' sqlid='gypnfv5nzurb0'
select child_number from v$sql
where sql_id = :1
order by child_number
END OF STMT
PARSE #5:c=0,e=32,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=4252345203,tim=1426063467937604
EXEC #5:c=0,e=39,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=4252345203,tim=1426063467937745
WAIT #5: nam='SQL*Net message to client' ela= 2 driver id=1952673792 #bytes=1 p3=0 obj#=-1 tim=1426063467937807
FETCH #5:c=0,e=24,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=4252345203,tim=1426063467937860

*** 2015-03-11 11:44:29.436
WAIT #5: nam='SQL*Net message from client' ela= 1498764 driver id=1952673792 #bytes=1 p3=0 obj#=-1 tim=1426063469436674
CLOSE #5:c=0,e=10,dep=0,type=3,tim=1426063469436776
=====================
PARSING IN CURSOR #4 len=76 dep=0 uid=116 oct=3 lid=116 tim=1426063469436855 hv=1778212192 ad='108e0f610' sqlid='gypnfv5nzurb0'
select child_number from v$sql
where sql_id = :1
order by child_number
END OF STMT
PARSE #4:c=0,e=31,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=4252345203,tim=1426063469436853
EXEC #4:c=0,e=36,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=4252345203,tim=1426063469436959
WAIT #4: nam='SQL*Net message to client' ela= 2 driver id=1952673792 #bytes=1 p3=0 obj#=-1 tim=1426063469437016
FETCH #4:c=1000,e=83,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,plh=4252345203,tim=1426063469437127

*** 2015-03-11 11:44:33.113
WAIT #4: nam='SQL*Net message from client' ela= 3676221 driver id=1952673792 #bytes=1 p3=0 obj#=-1 tim=1426063473113401
CLOSE #4:c=0,e=10,dep=0,type=3,tim=1426063473113505
WAIT #6: nam='cursor: pin S' ela= 2154878518 idn=3165883101 value=16578573762560 where=21474836480 obj#=-1 tim=1426065627992127

*** 2015-03-11 12:20:27.995
=====================
PARSING IN CURSOR #6 len=1003 dep=0 uid=116 oct=47 lid=116 tim=1426065627995724 hv=3165883101 ad='10871d758' sqlid='6zzxz0fyb72qx'
DECLARE
type v_Return_cur is REF CURSOR;
v_Return v_Return_cur;
RULE_NODE_ID NUMBER;
PARENT_RULE_NODE_ID NUMBER;
BPR_CONTROL_UNIT_ID NUMBER;
RULE_NODE_TY NUMBER;
RULE_OPERATOR_CV NUMBER;
BPR_ID NUMBER;
ORDER_COL NUMBER;
MATCH VARCHAR2(255);
i PLS_INTEGER:=0;
BEGIN
v_Return := KSA$VR_J2EE_INTERFACE_DS.GET_BPRRULENODE();
LOOP
i:=i+1;
FETCH v_Return
into RULE_NODE_ID, PARENT_RULE_NODE_ID, BPR_CONTROL_UNIT_ID, RULE_NODE_TY, RULE_OPERATOR_CV, BPR_ID, ORDER_COL, MATCH;
exit when v_Return%notfound;
dbms_output.put_line(RULE_NODE_ID || ', ' || PARENT_RULE_NODE_ID || ', ' || BPR_CONTROL_UNIT_ID || ', ' || RULE_NODE_TY || ', ' || RULE_NODE_TY || ', ' || RULE_OPERATOR_CV || ', ' || BPR_ID || ', ' || ORDER_COL || ', ' || MATCH);
end loop;
IF v_Return%isOPEN THEN
close v_Return;
END IF;
END;
END OF STMT
PARSE #6:c=1060555771,e=2154882166,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=0,tim=1426065627995722
=====================
PARSING IN CURSOR #3 len=55 dep=1 uid=116 oct=3 lid=116 tim=1426065627996803 hv=1484832305 ad='1083d71a0' sqlid='cqq69xjc81gjj'
SELECT KSA$SE_TMP_SERVICE_INFO_01.NEXTVAL FROM SYS.DUAL
END OF STMT
PARSE #3:c=1000,e=727,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=1,plh=319471665,tim=1426065627996802
12 мар 15, 17:05    [17376792]     Ответить | Цитировать Сообщить модератору
 Re: PARSE маленького блока длился > 35 минут  [new]
usolcew
Member

Откуда: Россия
Сообщений: 121
expimp,

теперь видно на что ушло время, кот. tkprof отнёс на parsing:

WAIT #6: nam='cursor: pin S' ela= 2154878518 idn=3165883101 value=16578573762560 where=21474836480 obj#=-1 tim=1426065627992127


из AWR/ASH несложно найти блокера
12 мар 15, 21:50    [17378016]     Ответить | Цитировать Сообщить модератору
 Re: PARSE маленького блока длился > 35 минут  [new]
expimp
Member

Откуда:
Сообщений: 573
usolcew
expimp,

теперь видно на что ушло время, кот. tkprof отнёс на parsing:

WAIT #6: nam='cursor: pin S' ela= 2154878518 idn=3165883101 value=16578573762560 where=21474836480 obj#=-1 tim=1426065627992127


из AWR/ASH несложно найти блокера


Спасибо! Но это событие ожидания я видел и в v$session. И прочитал разные посты и блоги про это ожидание.
И что это скорее всего баг "Oracle bug 5184776". Но думал, вдруг в сырой трассировке еще что-нибудь увижу.

Повторю, все равно, спасибо!
13 мар 15, 18:03    [17382388]     Ответить | Цитировать Сообщить модератору
Все форумы / Oracle Ответить