ReSQL.ru
     
powered by simpleCommunicator - 2.0.61     © 2026 Programmizd 02
Мобильная версия    Контакт    Правила    FAQ    Помощь
Целевая тема:
Создать новую тему:
Автор:
Закрыть
Цитировать
Доб. в избранное | Игнор. тему | Прикреп. тему | Пометить прочит. / непрочит. | Фильтр
Форумы / Oracle [игнор отключен] [закрыт для гостей] / Ожидание SQL net message from client перед Fetch
17 сообщений из 17, страница 1 из 1
Ожидание SQL net message from client перед Fetch
    #39360987
nata44845
Скрыть профиль Поместить в игнор-лист Сообщения автора в теме
nata44845
Участник
Рассматриваю торможение программы.
Сделала трассировку в процессе прохода по циклу (программа выбрала X ID с внешними ключами, по ним подтягивает данные и заполняет табличку).

Код: sql
1.
2.
3.
4.
5.
6.
7.
8.
9.
10.
11.
12.
13.
14.
15.
16.
17.
18.
19.
20.
OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse     2153      0.03       0.13          0          0          0           0
Execute   3602      1.21       2.11         28        103       1356          63
Fetch     3538      0.18       0.53          4     131636          0        3299
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total     9293      1.43       2.78         32     131739       1356        3362

Misses in library cache during parse: 21
Misses in library cache during execute: 21

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                    4420        0.00          0.00
  SQL*Net message from client                  4420        0.39         58.44
  log file sync                                  63        0.07          0.30
  db file sequential read                        32        0.26          1.08



Заинтересовал особенно один запрос, из 60 секунд ожидания 22 секунды относятся к нему.

Код: sql
1.
2.
3.
4.
5.
6.
7.
8.
9.
10.
11.
12.
13.
14.
15.
16.
17.
18.
19.
20.
21.
SQL ID: 3u2v7p5ta8rz1 Plan Hash: 1136062454

select X from Y where (ID=:P1) and (F_ID=:P2) order by Z

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        0      0.00       0.00          0          0          0           0
Execute    756      0.20       0.11          0          0          0           0
Fetch      755      0.00       0.02          0       2327          0          62
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total     1511      0.20       0.14          0       2327          0          62

Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 84  

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                    1511        0.00          0.00
  SQL*Net message from client                  1511        0.22         21.69



в трассировке вот такое постоянно в конце данного запроса

Код: sql
1.
2.
3.
4.
5.
6.
7.
EXEC #702016640:c=0,e=220,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=1136062454,tim=1055877131656
XCTEND rlbk=0, rd_only=1, tim=1055877131715
WAIT #702016640: nam='SQL*Net message to client' ela= 2 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=1055877131940
WAIT #702016640: nam='SQL*Net message from client' ela= 30433 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=1055877162409
FETCH #702016640:c=0,e=51,p=0,cr=3,cu=0,mis=0,r=0,dep=0,og=1,plh=1136062454,tim=1055877162620
WAIT #702016640: nam='SQL*Net message to client' ela= 2 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=1055877162692
WAIT #702016640: nam='SQL*Net message from client' ela= 499 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=1055877163227



То есть SQL*Net message from client идет 2 раза, один раз перед FETCH.

Для сравнения нормальный запрос:

Код: sql
1.
2.
3.
4.
5.
6.
EXEC #755903600:c=0,e=116,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2655081132,tim=532353304089
WAIT #755903600: nam='SQL*Net message to client' ela= 3 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=532353304164
FETCH #755903600:c=0,e=65,p=0,cr=5,cu=0,mis=0,r=1,dep=0,og=1,plh=2655081132,tim=532353304317
STAT...
XCTEND rlbk=0, rd_only=1, tim=532353304437
WAIT #755903600: nam='SQL*Net message from client' ela= 2632 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=532353307160



В журнале tkprof к данному запросу план не показывает.
Хотя через explain plan получила, план как план по индексу.
Меня больше интересует, чего это такое интересное делается в программе, что такие ожидания.
...
Рейтинг: 0 / 0
06.12.2016, 08:58
| Ответить | Цитировать | Написать  
Ожидание SQL net message from client перед Fetch
    #39360997
Фотография env
Скрыть профиль Поместить в игнор-лист Сообщения автора в теме
env
Участник
nata44845,

На клиенте fetch size никто не трогал?
...
Рейтинг: 0 / 0
06.12.2016, 09:30
| Ответить | Цитировать | Написать  
Ожидание SQL net message from client перед Fetch
    #39361003
nata44845
Скрыть профиль Поместить в игнор-лист Сообщения автора в теме
nata44845
Участник
env,

Приложение не мое, что там внутри не знаю.

Разработчику предложила пересмотреть вывод данных, может где что лишнее.
Есть подозрение, что дело в XCTEND.
...
Рейтинг: 0 / 0
06.12.2016, 09:43
| Ответить | Цитировать | Написать  
Ожидание SQL net message from client перед Fetch
    #39361434
Nobody1111
Скрыть профиль Поместить в игнор-лист Сообщения автора в теме
Nobody1111
Гость
фетчей 755, а записей получено 62. Большинство выполнений интересующего селекта возвращает 0 записей (возможно, клиент ). fetch size ни при чем.

в отличие от "нормального" селекта, в данном случае возвращается 0 записей. Поэтому RO-транзакция завершается сразу, по трейсу до формального фетча.

может, клиент или сетка тормозит?
...
Рейтинг: 0 / 0
06.12.2016, 17:55
| Ответить | Цитировать | Написать  
Ожидание SQL net message from client перед Fetch
    #39361565
nata44845
Скрыть профиль Поместить в игнор-лист Сообщения автора в теме
nata44845
Участник
Nobody1111,

Заметила, если учесть, что трассировку прервала в середине вывода строки, то там 63 строки и 756 фетчей, то есть по 12 на строку, попробую копать в направлении уменьшения количества вызовов.

Вот другой вариант работы того же запроса, когда открывают уже готовый документ, тут то с выбором все нормально, в каждой строке, а XCTEND там же...

Код: sql
1.
2.
3.
4.
5.
6.
7.
EXEC #755872928:c=0,e=221,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=1136062454,tim=532353389197
XCTEND rlbk=0, rd_only=1, tim=532353389267
WAIT #755872928: nam='SQL*Net message to client' ela= 2 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=532353389362
WAIT #755872928: nam='SQL*Net message from client' ela= 19555 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=532353408952
WAIT #755872928: nam='SQL*Net message to client' ela= 3 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=532353409181
FETCH #755872928:c=0,e=103,p=0,cr=4,cu=0,mis=0,r=1,dep=0,og=1,plh=1136062454,tim=532353409234
WAIT #755872928: nam='SQL*Net message from client' ela= 513 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=532353409826



Код: sql
1.
2.
3.
4.
5.
6.
7.
8.
9.
10.
11.
12.
13.
14.
15.
16.
17.
call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        0      0.00       0.00          0          0          0           0
Execute     93      0.01       0.01          0          0          0           0
Fetch       93      0.04       0.00          0        372          0          93
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total      186      0.06       0.02          0        372          0          93

Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 84  

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                     186        0.00          0.00
  SQL*Net message from client                   186        0.02          1.81
...
Рейтинг: 0 / 0
07.12.2016, 05:59
| Ответить | Цитировать | Написать  
Ожидание SQL net message from client перед Fetch
    #39361566
nata44845
Скрыть профиль Поместить в игнор-лист Сообщения автора в теме
nata44845
Участник
r
Количество строк, возвращаемых вызовом.

(Миллсап)
...
Рейтинг: 0 / 0
07.12.2016, 06:09
| Ответить | Цитировать | Написать  
Ожидание SQL net message from client перед Fetch
    #39361582
Фотография SeaGate
Скрыть профиль Поместить в игнор-лист Сообщения автора в теме
SeaGate
Участник
nata44845,

Я бы выдвинул 3 гипотезы:
1. клиент бомбит базу отдельными запросами exec/fetch. Для проверки соберите трассу с событиями 10046 level 8, 10051 level 1.
2. внутри select есть commit
3. autocommit

Откуда взялся XCTEND после EXEC на SELECT в RO-транзакции, не ясно.
Ничего там нет у вас дополнительно, а ля функций с pragma autonomous_transaction+commit в этом select, аудит, FGA, RLS ?
Проверьте того же клиента на других таблицах. Например, вот так выглядит SQL*Plus на 12й версии, где в функции делается commit:
 
Код: plsql
1.
2.
3.
4.
5.
6.
7.
8.
9.
10.
11.
12.
13.
14.
15.
16.
17.
18.
19.
20.
21.
22.
23.
24.
25.
26.
WAIT #18446744071511082656: nam='SQL*Net message from client' ela= 2251171 driver id=1952673792 #bytes=1 p3=0 obj#=-1 tim=8476639270095
OPI CALL: type=105 argc= 2 cursor=  0 name=Cursor close all
CLOSE #18446744071521633080:c=18,e=17,dep=0,type=1,tim=8476639270579
CLOSE #18446744071511082656:c=83,e=82,dep=0,type=3,tim=8476639270754
OPI CALL: type=94 argc=31 cursor=  0 name=V8 Bundled Exec
=====================
PARSING IN CURSOR #18446744071521611952 len=36 dep=0 uid=122 oct=3 lid=122 tim=8476639278766 hv=3239018269 ad='4807c0440' sqlid='7bkn5670hyzsx'
select commit_inside_me x2 from dual
END OF STMT
PARSE #18446744071521611952:c=7709,e=7709,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=1546270724,tim=8476639278764
EXEC #18446744071521611952:c=116,e=117,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=1546270724,tim=8476639279427
WAIT #18446744071521611952: nam='SQL*Net message to client' ela= 12 driver id=1952673792 #bytes=1 p3=0 obj#=-1 tim=8476639279600
=====================
PARSING IN CURSOR #18446744071517498128 len=6 dep=1 uid=122 oct=44 lid=122 tim=8476639280011 hv=255718823 ad='0' sqlid='8ggw94h7mvxd7'
COMMIT
END OF STMT
PARSE #18446744071517498128:c=22,e=22,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=0,plh=0,tim=8476639280010
XCTEND rlbk=0, rd_only=1, tim=8476639280482
EXEC #18446744071517498128:c=207,e=208,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=0,plh=0,tim=8476639280648
CLOSE #18446744071517498128:c=5,e=5,dep=1,type=3,tim=8476639280830
FETCH #18446744071521611952:c=1257,e=1257,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,plh=1546270724,tim=8476639281005
STAT #18446744071521611952 id=1 cnt=1 pid=0 pos=1 obj=0 op='FAST DUAL  (cr=0 pr=0 pw=0 time=10 us cost=2 size=0 card=1)'
WAIT #18446744071521611952: nam='SQL*Net message from client' ela= 740 driver id=1952673792 #bytes=1 p3=0 obj#=-1 tim=8476639282143
OPI CALL: type= 5 argc= 2 cursor= 14 name=FETCH
FETCH #18446744071521611952:c=5,e=5,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=1546270724,tim=8476639282426
WAIT #18446744071521611952: nam='SQL*Net message to client' ela= 10 driver id=1952673792 #bytes=1 p3=0 obj#=-1 tim=8476639282548


Это, в целом похоже, на то, что у Вас, но только тут SQL*Net message from client после первого fetch. Судя по номерам курсоров в трассе, предположу, что это до 11 версии. Возможно, старые версии так и писали в таких случаях (commit in select-list, например), но надо проверять, клиентский код смотреть.

На доступных 12х версиях я не вижу, как сходу это воспроизвести, а клиенты у меня только JDBC с UCP или SQL*Plus, sqlcl.
Я бы списал XCTEND на AutoCommit, но тестовый Java класс (JDBC/UCP 12.1) с кое-какими доп патчами UCP на 12й версии так не делают, а других клиентов нет под рукой.
 
Трассировка (10046+10051) августовского UCP на SELECT запросах с включенным AutoCommit
Код: plsql
1.
2.
3.
4.
5.
6.
7.
8.
9.
10.
11.
12.
13.
14.
15.
16.
17.
18.
19.
20.
21.
22.
23.
24.
25.
26.
27.
28.
29.
30.
31.
32.
33.
34.
35.
36.
37.
38.
39.
40.
41.
42.
43.
44.
45.
46.
47.
48.
49.
50.
51.
XCTEND rlbk=0, rd_only=1, tim=6556917783711
WAIT #18446744071512212592: nam='SQL*Net message to client' ela= 153 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=6556917785359
WAIT #18446744071512212592: nam='SQL*Net message from client' ela= 12169 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=6556917797625
*** CLIENT ID:(I'm a client) 2016-08-18 12:25:12.032
*** MODULE NAME:(my_module) 2016-08-18 12:25:12.032
*** ACTION NAME:(my_action) 2016-08-18 12:25:12.032
  
OPI CALL: type=94 argc=31 cursor=  0 name=V8 Bundled Exec
=====================
PARSING IN CURSOR #18446744071512206216 len=94 dep=0 uid=223 oct=3 lid=223 tim=6556917798255 hv=4007800643 ad='41c26ec40' sqlid='8k277uzrf4bu3'
select sys_context('userenv', 'instance'), to_char(sysdate, 'yyyy-mm-dd hh24:mi:ss') from dual
END OF STMT
PARSE #18446744071512206216:c=111,e=112,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=1546270724,tim=6556917798254
EXEC #18446744071512206216:c=67,e=67,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=1546270724,tim=6556917798597
WAIT #18446744071512206216: nam='SQL*Net message to client' ela= 149 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=6556917798841
FETCH #18446744071512206216:c=71,e=72,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,plh=1546270724,tim=6556917799023
STAT #18446744071512206216 id=1 cnt=1 pid=0 pos=1 obj=0 op='FAST DUAL  (cr=0 pr=0 pw=0 time=6 us cost=2 size=0 card=1)'
 
*** 2016-08-18 12:25:13.069
WAIT #18446744071512206216: nam='SQL*Net message from client' ela= 1036951 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=6556918836274
OPI CALL: type=94 argc=31 cursor=  3 name=V8 Bundled Exec
EXEC #18446744071512206216:c=107,e=107,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=1546270724,tim=6556918836623
WAIT #18446744071512206216: nam='SQL*Net message to client' ela= 144 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=6556918836919
FETCH #18446744071512206216:c=289,e=290,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,plh=1546270724,tim=6556918837001
 
*** 2016-08-18 12:25:14.076
WAIT #18446744071512206216: nam='SQL*Net message from client' ela= 1005787 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=6556919842935
OPI CALL: type=94 argc=31 cursor=  3 name=V8 Bundled Exec
EXEC #18446744071512206216:c=88,e=88,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=1546270724,tim=6556919843246
WAIT #18446744071512206216: nam='SQL*Net message to client' ela= 123 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=6556919843499
FETCH #18446744071512206216:c=245,e=245,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,plh=1546270724,tim=6556919843562
 
*** 2016-08-18 12:25:15.082
WAIT #18446744071512206216: nam='SQL*Net message from client' ela= 1005352 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=6556920849039
OPI CALL: type=94 argc=31 cursor=  3 name=V8 Bundled Exec
EXEC #18446744071512206216:c=94,e=95,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=1546270724,tim=6556920849331
WAIT #18446744071512206216: nam='SQL*Net message to client' ela= 123 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=6556920849591
FETCH #18446744071512206216:c=271,e=271,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,plh=1546270724,tim=6556920849679
 
*** 2016-08-18 12:25:16.087
WAIT #18446744071512206216: nam='SQL*Net message from client' ela= 1004660 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=6556921854471
OPI CALL: type=94 argc=31 cursor=  3 name=V8 Bundled Exec
EXEC #18446744071512206216:c=89,e=89,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=1546270724,tim=6556921854761
WAIT #18446744071512206216: nam='SQL*Net message to client' ela= 123 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=6556921855016
FETCH #18446744071512206216:c=247,e=247,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,plh=1546270724,tim=6556921855080
 
*** 2016-08-18 12:25:17.104
WAIT #18446744071512206216: nam='SQL*Net message from client' ela= 1015444 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=6556922870650
CLOSE #18446744071512206216:c=19,e=19,dep=0,type=0,tim=6556922876357
CLOSE #18446744071512212592:c=2,e=2,dep=0,type=0,tim=6556922876445
CLOSE #18446744071512217664:c=7,e=7,dep=0,type=0,tim=6556922876503



Из чего видно, что посылается V8 Bundled Exec, флаг AutoCommit идет в рамках того же SQL*Net пакета (что также по дампам SQL*Net можно отследить), XCTEND нет - "лишних" commit RO-транзакций не наблюдается в отличии от AutoCommit с Read-Write активностью:
 
Код: plsql
1.
2.
3.
4.
5.
6.
7.
8.
9.
10.
11.
12.
13.
14.
15.
16.
17.
18.
19.
20.
21.
22.
23.
24.
25.
26.
27.
28.
29.
30.
31.
32.
33.
34.
35.
36.
37.
38.
39.
40.
41.
42.
43.
44.
45.
46.
47.
48.
49.
50.
51.
XCTEND rlbk=0, rd_only=1, tim=6556911657342
WAIT #18446744071512212592: nam='SQL*Net message to client' ela= 197 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=6556911659431
WAIT #18446744071512212592: nam='SQL*Net message from client' ela= 11091 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=6556911670643
*** CLIENT ID:(I'm a client) 2016-08-18 12:25:05.906
*** MODULE NAME:(my_module) 2016-08-18 12:25:05.906
*** ACTION NAME:(my_action) 2016-08-18 12:25:05.906
  
OPI CALL: type=94 argc=31 cursor=  0 name=V8 Bundled Exec
=====================
PARSING IN CURSOR #18446744071512206216 len=41 dep=0 uid=223 oct=2 lid=223 tim=6556911671278 hv=3235864348 ad='458ced380' sqlid='1vbk4s70dyrsw'
insert into jdbc_test(d) values (sysdate)
END OF STMT
PARSE #18446744071512206216:c=114,e=115,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=0,tim=6556911671277
EXEC #18446744071512206216:c=354,e=354,p=0,cr=1,cu=5,mis=0,r=1,dep=0,og=1,plh=0,tim=6556911671919
STAT #18446744071512206216 id=1 cnt=0 pid=0 pos=1 obj=0 op='LOAD TABLE CONVENTIONAL  JDBC_TEST (cr=1 pr=0 pw=0 time=244 us)'
XCTEND rlbk=0, rd_only=0, tim=6556911672161
WAIT #18446744071512206216: nam='log file sync' ela= 3113 buffer#=286 sync scn=17224311 p3=0 obj#=-1 tim=6556911675565
WAIT #18446744071512206216: nam='SQL*Net message to client' ela= 180 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=6556911676028
*** 2016-08-18 12:25:06.915
WAIT #18446744071512206216: nam='SQL*Net message from client' ela= 1005383 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=6556912681517
OPI CALL: type=94 argc=31 cursor=  3 name=V8 Bundled Exec
EXEC #18446744071512206216:c=265,e=265,p=0,cr=0,cu=3,mis=0,r=1,dep=0,og=1,plh=0,tim=6556912681989
XCTEND rlbk=0, rd_only=0, tim=6556912682113
WAIT #18446744071512206216: nam='log file sync' ela= 5268 buffer#=288 sync scn=17224314 p3=0 obj#=-1 tim=6556912687617
WAIT #18446744071512206216: nam='SQL*Net message to client' ela= 135 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=6556912687961
*** 2016-08-18 12:25:07.927
WAIT #18446744071512206216: nam='SQL*Net message from client' ela= 1005453 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=6556913693495
OPI CALL: type=94 argc=31 cursor=  3 name=V8 Bundled Exec
EXEC #18446744071512206216:c=279,e=278,p=0,cr=0,cu=3,mis=0,r=1,dep=0,og=1,plh=0,tim=6556913693974
XCTEND rlbk=0, rd_only=0, tim=6556913694088
WAIT #18446744071512206216: nam='log file sync' ela= 1515 buffer#=290 sync scn=17224316 p3=0 obj#=-1 tim=6556913695835
WAIT #18446744071512206216: nam='SQL*Net message to client' ela= 112 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=6556913696082
*** 2016-08-18 12:25:08.934
WAIT #18446744071512206216: nam='SQL*Net message from client' ela= 1004563 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=6556914700734
OPI CALL: type=94 argc=31 cursor=  3 name=V8 Bundled Exec
EXEC #18446744071512206216:c=272,e=272,p=0,cr=0,cu=3,mis=0,r=1,dep=0,og=1,plh=0,tim=6556914701197
XCTEND rlbk=0, rd_only=0, tim=6556914701320
WAIT #18446744071512206216: nam='log file sync' ela= 1574 buffer#=292 sync scn=17224318 p3=0 obj#=-1 tim=6556914703142
WAIT #18446744071512206216: nam='SQL*Net message to client' ela= 135 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=6556914703426
*** 2016-08-18 12:25:09.942
WAIT #18446744071512206216: nam='SQL*Net message from client' ela= 1004733 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=6556915708233
OPI CALL: type=94 argc=31 cursor=  3 name=V8 Bundled Exec
EXEC #18446744071512206216:c=292,e=292,p=0,cr=0,cu=3,mis=0,r=1,dep=0,og=1,plh=0,tim=6556915708733
XCTEND rlbk=0, rd_only=0, tim=6556915708851
WAIT #18446744071512206216: nam='log file sync' ela= 5390 buffer#=294 sync scn=17224320 p3=0 obj#=-1 tim=6556915714479
WAIT #18446744071512206216: nam='SQL*Net message to client' ela= 148 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=6556915714894
*** 2016-08-18 12:25:10.963
WAIT #18446744071512206216: nam='SQL*Net message from client' ela= 1014892 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=6556916729898
CLOSE #18446744071512206216:c=13,e=13,dep=0,type=0,tim=6556916735636
CLOSE #18446744071512212592:c=3,e=2,dep=0,type=0,tim=6556916735725
CLOSE #18446744071512217664:c=7,e=8,dep=0,type=0,tim=6556916735784



Что это за клиент и какая версия Oracle Server с точностью до патчсета? Приведите клиентский псевдо-код.
...
Рейтинг: 0 / 0
07.12.2016, 08:05
| Ответить | Цитировать | Написать  
Ожидание SQL net message from client перед Fetch
    #39361617
Nobody1111
Скрыть профиль Поместить в игнор-лист Сообщения автора в теме
Nobody1111
Гость
SeaGate,

SeaGateОткуда взялся XCTEND после EXEC на SELECT в RO-транзакции, не ясно.

XCTEND здесь - просто завершение RO-транзакции.

XCTEND rlbk=0, rd_only=1 ................

Так же как и у вас: наверняка ни в функции, вызываемой из селекта, ни до селекта в транзакции модификации данных не было.
...
Рейтинг: 0 / 0
07.12.2016, 10:19
| Ответить | Цитировать | Написать  
Ожидание SQL net message from client перед Fetch
    #39361634
nata44845
Скрыть профиль Поместить в игнор-лист Сообщения автора в теме
nata44845
Участник
SeaGate,

1) даже отрицать не буду, так оно и есть, бомбит в цикле минизапросами.
2) Внутри точно нету, триггеров на таблицу тоже нету.

На других таблицах по разному, некоторые таблицы все стандартно

Код: sql
1.
2.
3.
4.
5.
6.
7.
8.
PARSING IN CURSOR #552774560 len=327 dep=0 uid=84 oct=3 lid=84 tim=1151464955265 hv=1353079493 ad='37c2091b8' sqlid='2pmj6tj8acqq5'
****
END OF STMT
EXEC #552774560:c=0,e=25,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2644142349,tim=1151464955264
WAIT #552774560: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=1151464955386
FETCH #552774560:c=0,e=64,p=0,cr=5,cu=0,mis=0,r=1,dep=0,og=1,plh=2644142349,tim=1151464955412
XCTEND rlbk=0, rd_only=1, tim=1151464955447
WAIT #552774560: nam='SQL*Net message from client' ela= 184 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=1151464955700



Некоторые то же самое, но таких единицы и они не в цикле, суммарное ожидание там меньше.

Кусочек 10051-1, что тут что из перечня запросов мне не понятно.

Код: sql
1.
2.
3.
4.
5.
6.
7.
8.
9.
10.
11.
12.
13.
14.
15.
16.
OPI CALL: type=105 argc= 2 cursor=  0 name=Cursor close all
OPI CALL: type=94 argc=28 cursor=  0 name=V8 Bundled Exec
OPI CALL: type=94 argc=28 cursor=  0 name=V8 Bundled Exec
OPI CALL: type=105 argc= 2 cursor=  0 name=Cursor close all
OPI CALL: type=94 argc=28 cursor= 13 name=V8 Bundled Exec
OPI CALL: type=94 argc=28 cursor= 11 name=V8 Bundled Exec
OPI CALL: type=94 argc=28 cursor=  7 name=V8 Bundled Exec
OPI CALL: type=94 argc=28 cursor=  7 name=V8 Bundled Exec
OPI CALL: type=120 argc= 2 cursor=  0 name=Cancel All
OPI CALL: type=94 argc=28 cursor=  0 name=V8 Bundled Exec
OPI CALL: type=105 argc= 2 cursor=  0 name=Cursor close all
OPI CALL: type=94 argc=28 cursor=  0 name=V8 Bundled Exec
OPI CALL: type=105 argc= 2 cursor=  0 name=Cursor close all
OPI CALL: type=94 argc=28 cursor=  0 name=V8 Bundled Exec
OPI CALL: type=105 argc= 2 cursor=  0 name=Cursor close all
...



В dbforge этот запрос прогоняла, тоже все стандартно.
...
Рейтинг: 0 / 0
07.12.2016, 10:36
| Ответить | Цитировать | Написать  
Ожидание SQL net message from client перед Fetch
    #39361635
nata44845
Скрыть профиль Поместить в игнор-лист Сообщения автора в теме
nata44845
Участник
SeaGate,

Версия 11.2.0.2
...
Рейтинг: 0 / 0
07.12.2016, 10:37
| Ответить | Цитировать | Написать  
Ожидание SQL net message from client перед Fetch
    #39361643
Nobody1111
Скрыть профиль Поместить в игнор-лист Сообщения автора в теме
Nobody1111
Гость
возможно, лишний XCTEND - от рекурсивных запросов, которые должны быть в трейсе до приведенного куска.

А тормозит клиентская программа вероятнее всего, или ОС клиента, или сеть. SQL*Net message to client отрабатывает быстро, а SQL*Net message from client - десятки мс
...
Рейтинг: 0 / 0
07.12.2016, 10:48
| Ответить | Цитировать | Написать  
Ожидание SQL net message from client перед Fetch
    #39361649
nata44845
Скрыть профиль Поместить в игнор-лист Сообщения автора в теме
nata44845
Участник
Nobody1111,

Не не не, он явно не туда воткнут.
И последний трейс я проводила целиком для всей операции, которую сама выполняла, она немного другая, но блок выбора из этой таблицы такой же.
...
Рейтинг: 0 / 0
07.12.2016, 11:05
| Ответить | Цитировать | Написать  
Ожидание SQL net message from client перед Fetch
    #39361750
Фотография SeaGate
Скрыть профиль Поместить в игнор-лист Сообщения автора в теме
SeaGate
Участник
Nobody1111,

Nobody1111Так же как и у вас: наверняка ни в функции, вызываемой из селекта, ни до селекта в транзакции модификации данных не было.

Вы можете привести кейс, воспроизводящий последовательность записей в трейс файл как у ТС?
Конкретно:
Код: plsql
1.
2.
3.
4.
5.
6.
7.
EXEC #702016640:c=0,e=220,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=1136062454,tim=1055877131656
XCTEND rlbk=0, rd_only=1, tim=1055877131715
WAIT #702016640: nam='SQL*Net message to client' ela= 2 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=1055877131940
WAIT #702016640: nam='SQL*Net message from client' ela= 30433 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=1055877162409
FETCH #702016640:c=0,e=51,p=0,cr=3,cu=0,mis=0,r=0,dep=0,og=1,plh=1136062454,tim=1055877162620
WAIT #702016640: nam='SQL*Net message to client' ela= 2 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=1055877162692
WAIT #702016640: nam='SQL*Net message from client' ela= 499 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=1055877163227


Где курсор 702016640 это SELECT.
В моем примере с commit-ом в функции нет SQL*Net message from client перед FETCH, поэтому это не полное воспроизводство того, что у ТС.
Если будет тест-кейс, можно будет сказать, что также, пока я не уверен в этом.
Nobody1111наверняка ни в функции, вызываемой из селекта, ни до селекта в транзакции модификации данных не было.
Если была функция с автономкой (это было предположение, что она есть), то до селекта могла быть модификация данных.
Я пока не вижу по предоставленным данным, что до селекта не было модификации данных. ТС приводил некий нормальный запрос (Для сравнения нормальный запрос:...) с rd_only=1 в конце, но не факт, что то же самое у проблемного запроса.

nata44845OPI CALL: type=94 argc=28 cursor= 0 name=V8 Bundled Exec
Отдельно от 10046 здесь не факт, что это трасса того же процесса, но, если так, то тут V8 Bundled Exec, т.е. первое предположение отметаем.

nata448452pmj6tj8acqq5
Покажите:
Код: plsql
1.
select * from table(dbms_xplan.display_cursor( '2pmj6tj8acqq5', null));


nata44845Версия 11.2.0.2
32 бита тогда.
Кроме номера курсора и адреса вроде ничего не писали. Для номера это великовато, 32 битный адрес в самый раз.
Вот 11.2.0.4 x64:
Код: plsql
1.
2.
3.
4.
5.
6.
7.
8.
9.
10.
PARSING IN CURSOR #18446744071521613472 len=18 dep=0 uid=175 oct=3 lid=175 tim=8522188322965 hv=942515969 ad='5e57bbe00' sqlid='a5ks9fhw2v9s1'
select * from dual
END OF STMT
PARSE #18446744071521613472:c=2637,e=2636,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=3543395131,tim=8522188322964
EXEC #18446744071521613472:c=61,e=61,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=3543395131,tim=8522188323730
FETCH #18446744071521613472:c=708,e=17724,p=2,cr=3,cu=0,mis=0,r=1,dep=0,og=1,plh=3543395131,tim=8522188341647
STAT #18446744071521613472 id=1 cnt=1 pid=0 pos=1 obj=222 op='TABLE ACCESS FULL DUAL (cr=3 pr=2 pw=0 time=17700 us cost=2 size=2 card=1)'
FETCH #18446744071521613472:c=4,e=4,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=3543395131,tim=8522188343776
PARSE #18446744071519719664:c=69,e=69,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=0,tim=8522188345456
EXEC #18446744071519719664:c=465,e=464,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,plh=0,tim=8522188346270


Здесь вижу, что sql_id есть, и адреса 64-битные.

nata44845Заинтересовал особенно один запрос, из 60 секунд ожидания 22 секунды относятся к нему.
...
Меня больше интересует, чего это такое интересное делается в программе, что такие ожидания.
Ну если 60-22=38 секунд устраивает, которые за счет разового выполнения запроса "могут" быть (если 21.69 секунды на 1500 SQL*Net message from client это сеть, а не активность клиента) достигнуты, то пусть программисты перепишут и уйдут от построчных фетчей, фетчат пачками, если допустимо для этого процесса.
Здесь я бы исследовал только SQL*Net message to/from client после EXEC, остальное пусть программисты переписывают, чтобы "было быстро". У меня на 12.1.0.2 не получается такая картина сходу.
...
Рейтинг: 0 / 0
07.12.2016, 12:57
| Ответить | Цитировать | Написать  
Ожидание SQL net message from client перед Fetch
    #39362227
nata44845
Скрыть профиль Поместить в игнор-лист Сообщения автора в теме
nata44845
Участник
SeaGate,

Поняла тебя, не знаю, зачем тебе план того левого запроса, запустила сразу оба трейса, смешанный трейс будет такой

Код: sql
1.
2.
3.
4.
5.
6.
7.
8.
9.
10.
11.
12.
13.
PARSING IN CURSOR #711263776 len=88 dep=0 uid=84 oct=3 lid=84 tim=1226462632451 hv=1923375073 ad='370371c30' sqlid='3u2v7p5ta8rz1'
select VALUE from Y where (ID=:P1) and (F_ID=:P2) order by Z
END OF STMT
EXEC #711263776:c=0,e=25,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=1136062454,tim=1226462632450
XCTEND rlbk=0, rd_only=1, tim=1226462632609
WAIT #711263776: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=1226462632677
WAIT #711263776: nam='SQL*Net message from client' ela= 19092 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=1226462651813
OPI CALL: type=94 argc=28 cursor=  7 name=V8 Bundled Exec
WAIT #711263776: nam='SQL*Net message to client' ela= 3 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=1226462652058
FETCH #711263776:c=0,e=85,p=0,cr=4,cu=0,mis=0,r=1,dep=0,og=1,plh=1136062454,tim=1226462652101
WAIT #711263776: nam='SQL*Net message from client' ela= 604 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=1226462652786
OPI CALL: type=120 argc= 2 cursor=  0 name=Cancel All
OPI CALL: type=94 argc=28 cursor=  0 name=V8 Bundled Exec




select * from table(dbms_xplan.display_cursor( '3u2v7p5ta8rz1', null));

Код: sql
1.
2.
3.
|   0 | SELECT STATEMENT            |                  |       |       |     4 (100)|          |
|   1 |  TABLE ACCESS BY INDEX ROWID| Y   |     1 |    26 |     4   (0)| 00:00:01 |
|*  2 |   INDEX RANGE SCAN          | Y_PK |     1 |       |     3   (0)| 00:00:01 |
...
Рейтинг: 0 / 0
08.12.2016, 06:55
| Ответить | Цитировать | Написать  
Ожидание SQL net message from client перед Fetch
    #39362414
Nobody1111
Скрыть профиль Поместить в игнор-лист Сообщения автора в теме
Nobody1111
Гость
SeaGateВы можете привести кейс, воспроизводящий последовательность записей в трейс файл как у ТС?Попробовал, не получилось. Правда, сильно не старался.

...вообще, конечно, 11.2.0.2 - сырая версия. Стоило бы на 11.2.0.4 переехать. Возможно, и пропадет этот артефакт.
...
Рейтинг: 0 / 0
08.12.2016, 11:51
| Ответить | Цитировать | Написать  
Ожидание SQL net message from client перед Fetch
    #39362423
Фотография env
Скрыть профиль Поместить в игнор-лист Сообщения автора в теме
env
Участник
Nobody1111 Стоило бы на 11.2.0.4 переехать. Возможно, и пропадет этот артефакт.
И появится много новых других.
...
Рейтинг: 0 / 0
08.12.2016, 11:56
| Ответить | Цитировать | Написать  
Ожидание SQL net message from client перед Fetch
    #39362580
Nobody1111
Скрыть профиль Поместить в игнор-лист Сообщения автора в теме
Nobody1111
Гость
envNobody1111 Стоило бы на 11.2.0.4 переехать. Возможно, и пропадет этот артефакт.
И появится много новых других.

Ну, на ответственных базах с кондачка такие вопросы не решаются. Тестировать, конечно, надо.
...
Рейтинг: 0 / 0
08.12.2016, 14:35
| Ответить | Цитировать | Написать  
17 сообщений из 17, страница 1 из 1
Форумы / Oracle [игнор отключен] [закрыт для гостей] / Ожидание SQL net message from client перед Fetch
Найденые пользователи ...
Разблокировать пользователей ...
Читали тему (0):
Читали форум (0):
Пользователи онлайн (0):
Польз. соглашение   Полит. конфиден.  
NoSQL.ru       Кролег: Проекты, Новости, Чат       РЕД ФОРУМ       Фотоальбом: Участники, Встречи
Закрыть
start [/forum/topic.php?fid=52&msg=39360997&tid=1886865]:
 0ms
get settings:
 9ms
get forum list:
 14ms
check forum access:
 3ms
check topic access:
 3ms
track hit:
 184ms
get topic data:
 8ms
get forum data:
 2ms
get page messages:
 80ms
get tp. blocked users:
 1ms
others: 237ms
total:  541ms
созд. / загр.: 541ms
x
x
Закрыть


Просмотр
0 / 0
Close
Debug Console [Select Text]