Этот баннер — требование Роскомнадзора для исполнения 152 ФЗ.
«На сайте осуществляется обработка файлов cookie, необходимых для работы сайта, а также для анализа использования сайта и улучшения предоставляемых сервисов с использованием метрической программы Яндекс.Метрика. Продолжая использовать сайт, вы даёте согласие с использованием данных технологий».
Политика конфиденциальности
|
|
|
Задержки в выполнении запроса
|
|||
|---|---|---|---|
|
#18+
Делаю Код: plsql 1. Oracle 10gr2. Примерно каждый 10ый раз запрос выполняется с задержкой. Выполняется примерно пару секунд. Снимаю трассировку ораклом, по трассировке всё норм. PARSING IN CURSOR #2 len=19 dep=0 uid=74 oct=3 lid=74 tim=1298242663574167 hv=792291897 ad='44ba3e88' select 1 from dual END OF STMT PARSE #2:c=0,e=21,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1298242663574165 BINDS #2: EXEC #2:c=0,e=34,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1298242663574248 WAIT #2: nam='SQL*Net message to client' ela= 3 driver id=1297371904 #bytes=1 p3=0 obj#=-1 tim=1298242663574272 FETCH #2:c=0,e=9,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,tim=1298242663574304 WAIT #0: nam='SQL*Net message from client' ela= 2 driver id=1297371904 #bytes=1 p3=0 obj#=-1 tim=1298242663574722 FETCH #2:c=0,e=1,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,tim=1298242663574752 WAIT #2: nam='SQL*Net message to client' ela= 2 driver id=1297371904 #bytes=1 p3=0 obj#=-1 tim=1298242663574778 WAIT #0: nam='SQL*Net message from client' ela= 3 driver id=1297371904 #bytes=1 p3=0 obj#=-1 tim=1298242666584950 STAT #2 id=1 cnt=1 pid=0 pos=1 obj=0 op='FAST DUAL (cr=0 pr=0 pw=0 time=1 us)' ===================== PARSING IN CURSOR #1 len=19 dep=0 uid=74 oct=3 lid=74 tim=1298242666585126 hv=792291897 ad='44ba3e88' select 1 from dual END OF STMT PARSE #1:c=0,e=24,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1298242666585124 BINDS #1: EXEC #1:c=0,e=38,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1298242666585210 WAIT #1: nam='SQL*Net message to client' ela= 4 driver id=1297371904 #bytes=1 p3=0 obj#=-1 tim=1298242666585236 FETCH #1:c=0,e=9,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,tim=1298242666585269 WAIT #0: nam='SQL*Net message from client' ela= 1 driver id=1297371904 #bytes=1 p3=0 obj#=-1 tim=1298242666585762 FETCH #1:c=0,e=1,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,tim=1298242666585793 WAIT #1: nam='SQL*Net message to client' ela= 2 driver id=1297371904 #bytes=1 p3=0 obj#=-1 tim=1298242666585815 WAIT #0: nam='SQL*Net message from client' ela= 3 driver id=1297371904 #bytes=1 p3=0 obj#=-1 tim=1298242678303715 STAT #1 id=1 cnt=1 pid=0 pos=1 obj=0 op='FAST DUAL (cr=0 pr=0 pw=0 time=1 us)' Снимаю трассу снифером, вижу что ответ приходит почти через 2 секунды. 8 1.792068 AAA.BBB.4.95 AAA.BBB.23.204 TNS 207 Request, Data (6), Data 9 1.832550 AAA.BBB.23.204 AAA.BBB.4.95 TCP 60 ncube-lm > 55652 [ACK] Seq=559 Ack=655 Win=501 Len=0 10 3.502099 AAA.BBB.23.204 AAA.BBB.4.95 TNS 300 Response, Data (6), Data В чём может быть дело? Почему в трассе оракла не вижу ожиданий оракла? Проверял с разных машин, т.е. влияние клиента исключено. На сетевой карте сервера нагрузка далека от пиковой. netstat -i Kernel Interface table Iface MTU Met RX-OK RX-ERR RX-DRP RX-OVR TX-OK TX-ERR TX-DRP TX-OVR Flg eth0 1500 0 1514489225 0 0 0 1824012784 0 0 0 BMRU lo 16436 0 531182957 0 0 0 531182957 0 0 0 LRU netstat -s Ip: 1822729155 total packets received 93549 with invalid addresses 0 forwarded 0 incoming packets discarded 1822634898 incoming packets delivered 1109360539 requests sent out 1047 reassemblies required 349 packets reassembled ok 349 fragments received ok 1047 fragments created Icmp: 1802238 ICMP messages received 45 input ICMP message failed. ICMP input histogram: destination unreachable: 474 timeout in transit: 29 redirects: 1 echo requests: 1801666 echo replies: 68 1802081 ICMP messages sent 0 ICMP messages failed ICMP output histogram: destination unreachable: 343 echo request: 72 echo replies: 1801666 IcmpMsg: InType0: 68 InType3: 474 InType5: 1 InType8: 1801666 InType11: 29 OutType0: 1801666 OutType3: 343 OutType8: 72 Tcp: 2314572 active connections openings 3184059 passive connection openings 1558095 failed connection attempts 2527 connection resets received 36 connections established 1318783998 segments received 606224252 segments send out 24045 segments retransmited 235 bad segments received. 1561782 resets sent Udp: 501200674 packets received 326 packets to unknown port received. 0 packet receive errors 501205111 packets sent TcpExt: 64 invalid SYN cookies received 21 resets received for embryonic SYN_RECV sockets 4256 packets pruned from receive queue because of socket buffer overrun 56 ICMP packets dropped because they were out-of-window 2587069 TCP sockets finished time wait in fast timer 269 time wait sockets recycled by time stamp 1953034 delayed acks sent 440 delayed acks further delayed because of locked socket Quick ack mode was activated 582 times 246 times the listen queue of a socket overflowed 246 SYNs to LISTEN sockets ignored 49535532 packets directly queued to recvmsg prequeue. 690689 packets directly received from backlog 4149738007 packets directly received from prequeue 491370818 packets header predicted 40751974 packets header predicted and directly queued to user 13187278 acknowledgments not containing data received 1011767672 predicted acknowledgments 5023 times recovered from packet loss due to SACK data Detected reordering 5 times using FACK Detected reordering 17 times using SACK 1 congestion windows fully recovered TCPDSACKUndo: 167 1106 congestion windows recovered after partial ack 70136 TCP data loss events TCPLostRetransmit: 5 309 timeouts after SACK recovery 2 timeouts in loss state 16163 fast retransmits 1520 forward retransmits 705 retransmits in slow start 4621 other TCP timeouts 134 sack retransmits failed 18 times receiver scheduled too late for direct processing 302710 packets collapsed in receive queue due to low socket buffer 670 DSACKs sent for old packets 17 DSACKs sent for out of order packets 1370 DSACKs received 7 DSACKs for out of order packets received 95 connections reset due to unexpected data 2357 connections reset due to early user close 47 connections aborted due to timeout IpExt: InMcastPkts: 213408 OutMcastPkts: 106646 InBcastPkts: 634224 ... |
|||
|
:
Нравится:
Не нравится:
|
|||
| 16.02.2012, 18:59 |
|
||
|
Задержки в выполнении запроса
|
|||
|---|---|---|---|
|
#18+
А загрузку процессора на сервере не смотрели в эти моменты? - это раз Но скорее всего дело не в этом, а в специфике работы TCP (Стивенса почитайте) Попробуйте вот так select "jdfjskdgjhdfhfgj -<тут с килобайт текста->djfdjfghd" from dual; Как в этом случае поведение меняется? ... |
|||
|
:
Нравится:
Не нравится:
|
|||
| 17.02.2012, 09:50 |
|
||
|
Задержки в выполнении запроса
|
|||
|---|---|---|---|
|
#18+
On 02/16/2012 07:59 PM, Амаразм wrote: > Oracle 10gr2. > Примерно каждый 10ый раз запрос выполняется с задержкой. > Выполняется примерно пару секунд. > Снимаю трассировку ораклом, по трассировке всё норм.> Работа в многозадачной среде -- случайный процесс, что же ты хочешь > select 1 from dual; Действительно, полный маразм мерить производительность такого запроса. Posted via ActualForum NNTP Server 1.5 ... |
|||
|
:
Нравится:
Не нравится:
|
|||
| 17.02.2012, 13:07 |
|
||
|
Задержки в выполнении запроса
|
|||
|---|---|---|---|
|
#18+
Пинги большими пакетами пробовали? Без потерь? etherchannel есть на хосте? Запрос с рабочей станции? checksum offload на адаптерах включен? ... |
|||
|
:
Нравится:
Не нравится:
|
|||
| 17.02.2012, 15:31 |
|
||
|
Задержки в выполнении запроса
|
|||
|---|---|---|---|
|
#18+
MasterZivДействительно, полный маразм мерить производительность такого запроса. Это не производительность, а время отклика. Для запроса к виртуальному объекту немножко долго. Нет? ... |
|||
|
:
Нравится:
Не нравится:
|
|||
| 17.02.2012, 15:33 |
|
||
|
Задержки в выполнении запроса
|
|||
|---|---|---|---|
|
#18+
ИхтиандрПинги большими пакетами пробовали? Без потерь? etherchannel есть на хосте? Запрос с рабочей станции? checksum offload на адаптерах включен? Нагрузку процессора в первую очередь проверил. К сожалению, данная проблема куда то исчезла, сейчас время выполнения в норме. Изначально проблема наблюдалась на "больших" запросах, потом уже упростилась до select from dual. Запросы на сервере отрабатывали без ошибочно. Пробовал пинги по 1к , проходили без потерь. Сервер подключен всего лишь одной сетевой картой. ethtool -k eth0 Offload parameters for eth0: Cannot get device udp large send offload settings: Operation not supported rx-checksumming: on tx-checksumming: on scatter-gather: on tcp segmentation offload: on udp fragmentation offload: off generic segmentation offload: off generic-receive-offload: on ... |
|||
|
:
Нравится:
Не нравится:
|
|||
| 20.02.2012, 12:22 |
|
||
|
Задержки в выполнении запроса
|
|||
|---|---|---|---|
|
#18+
sar статистика собирается? Посмотрите в отчеты старые - может у вас система вообще в своп уходит временами. На будущее можете vmstat 1 100 запускать и смотреть pi po de столбцы. ... |
|||
|
:
Нравится:
Не нравится:
|
|||
| 20.02.2012, 12:32 |
|
||
|
Задержки в выполнении запроса
|
|||
|---|---|---|---|
|
#18+
Ихтиандрsar статистика собирается? Посмотрите в отчеты старые - может у вас система вообще в своп уходит временами. На будущее можете vmstat 1 100 запускать и смотреть pi po de столбцы. sar собираются, всплесков нагрузки нет (ни по процессору, ни по использованию памяти). Насчёт vmstat спасибо, во время проблемы, наблюдал через top. ... |
|||
|
:
Нравится:
Не нравится:
|
|||
| 20.02.2012, 14:20 |
|
||
|
Задержки в выполнении запроса
|
|||
|---|---|---|---|
|
#18+
Ситуация повторилась vmstat procs -----------memory---------- ---swap-- -----io---- --system-- -----cpu------ r b swpd free buff cache si so bi bo in cs us sy id wa st 0 0 316400 428176 150452 28524056 0 0 0 0 1479 1546 1 0 99 0 0 0 0 316400 439716 150452 28524056 0 0 0 0 1283 1053 0 0 99 0 0 0 0 316400 439836 150452 28524056 0 0 0 48 1033 390 0 0 100 0 0 0 0 316400 439836 150452 28524056 0 0 0 0 1011 341 0 0 100 0 0 0 0 316400 439712 150464 28524048 0 0 0 32 1061 456 0 0 100 0 0 0 0 316400 439712 150464 28524048 0 0 0 48 1018 348 0 0 100 0 0 0 0 316400 439564 150464 28524056 0 0 0 0 1045 418 0 0 100 0 0 0 0 316400 436572 150464 28524056 0 0 0 0 1057 578 0 1 99 0 0 0 0 316400 437444 150464 28524056 0 0 0 48 1027 380 1 0 99 0 0 0 0 316400 437444 150464 28524056 0 0 0 0 1026 385 0 0 100 0 0 0 0 316400 437940 150480 28524048 0 0 0 224 1010 322 0 0 100 0 0 0 0 316400 437940 150480 28524048 0 0 0 48 1036 415 0 0 100 0 0 0 0 316400 438204 150480 28524056 0 0 0 0 1003 307 0 0 100 0 0 0 0 316400 438204 150480 28524056 0 0 0 0 1030 397 0 0 100 0 0 0 0 316400 438700 150480 28524056 0 0 0 48 1010 316 0 0 100 0 0 0 0 316400 438700 150480 28524056 0 0 0 0 1029 398 0 0 100 0 0 0 0 316400 438840 150496 28524048 0 0 0 24 1042 409 0 0 100 0 0 0 0 316400 438840 150496 28524048 0 0 0 48 1040 412 0 0 100 0 0 0 0 316400 436692 150496 28524056 0 0 0 0 1014 667 1 0 99 0 0 0 0 316400 436148 150496 28524056 0 0 0 4 1183 1235 2 1 97 0 0 0 0 316400 436404 150496 28524060 0 0 0 240 1055 403 0 0 100 0 0 0 0 316400 436404 150496 28524060 0 0 0 0 1042 417 0 0 100 0 0 А вот трасса. Причём видимо из за погрешностей стадия PARSING IN CURSOR имеет более позднюю отметку нежели стадия PARSE. PARSING IN CURSOR #2 len=1122 dep=0 uid=74 oct=3 lid=74 tim=1298658257219240 hv=1358752691 ad='36412328' SELECT '01234567...(1К текста)...89' from dual END OF STMT PARSE #2:c=0,e=25,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1298658257219236 EXEC #2:c=0,e=18,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1298658257219312 WAIT #2: nam='SQL*Net message to client' ela= 2 driver id=1297371904 #bytes=1 p3=0 obj#=-1 tim=1298658257219337 WAIT #0: nam='SQL*Net message from client' ela= 2 driver id=1297371904 #bytes=1 p3=0 obj#=-1 tim=1298658257220589 WAIT #2: nam='SQL*Net message to client' ela= 2 driver id=1297371904 #bytes=1 p3=0 obj#=-1 tim=1298658257220636 FETCH #2:c=0,e=32,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,tim=1298658257220657 WAIT #0: nam='SQL*Net message from client' ela= 2 driver id=1297371904 #bytes=1 p3=0 obj#=-1 tim=1298658257225940 ... |
|||
|
:
Нравится:
Не нравится:
|
|||
| 21.02.2012, 17:14 |
|
||
|
Задержки в выполнении запроса
|
|||
|---|---|---|---|
|
#18+
проблемы не в свопе и не во вводе/выводе тоже. по таймингам видно, что наибольшее время уходит как раз на коммуникации с клиентом. Точно дело не в клиенте и не в сети в целом? ... |
|||
|
:
Нравится:
Не нравится:
|
|||
| 21.02.2012, 19:23 |
|
||
|
Задержки в выполнении запроса
|
|||
|---|---|---|---|
|
#18+
Проверял запрос с другого сервера, поведение тоже самое. Смотрели сетевую статистику на сетевом оборудовании, проблем не обнаружено. Там гигабитный интерфейс и он "курит" большую часть времени. Потерь пакетов, конфликтов нет. Всё таки MasterZiv, несмотря на демагогию был прав, вероятно какие то конфликты на сервере мешают. Вот только не пойму каким образом можно раскопать проблему дальше. ethtool -S eth0 NIC statistics: rx_packets: 1681742489 tx_packets: 2104084763 rx_bytes: 950015927929 tx_bytes: 2645100776623 rx_broadcast: 4045214 tx_broadcast: 5438 rx_multicast: 118638 tx_multicast: 112468 rx_errors: 0 tx_errors: 0 tx_dropped: 0 multicast: 118638 collisions: 0 rx_length_errors: 0 rx_over_errors: 0 rx_crc_errors: 0 rx_frame_errors: 0 rx_no_buffer_count: 0 rx_missed_errors: 0 tx_aborted_errors: 0 tx_carrier_errors: 0 tx_fifo_errors: 0 tx_heartbeat_errors: 0 tx_window_errors: 0 tx_abort_late_coll: 0 tx_deferred_ok: 0 tx_single_coll_ok: 0 tx_multi_coll_ok: 0 tx_timeout_count: 0 tx_restart_queue: 0 rx_long_length_errors: 0 rx_short_length_errors: 0 rx_align_errors: 0 tx_tcp_seg_good: 161651253 tx_tcp_seg_failed: 0 rx_flow_control_xon: 0 rx_flow_control_xoff: 0 tx_flow_control_xon: 0 tx_flow_control_xoff: 0 rx_long_byte_count: 950015927929 rx_csum_offload_good: 1681737318 rx_csum_offload_errors: 238 tx_dma_out_of_sync: 0 alloc_rx_buff_failed: 0 tx_smbus: 0 rx_smbus: 3625634 dropped_smbus: 0 tx_queue_0_packets: 367057933 tx_queue_0_bytes: 240947604370 rx_queue_0_packets: 357925130 rx_queue_0_bytes: 224517776489 rx_queue_1_packets: 517526382 rx_queue_1_bytes: 173667667353 rx_queue_2_packets: 439233042 rx_queue_2_bytes: 304156456612 rx_queue_3_packets: 0 rx_queue_3_bytes: 73014444035 rx_csum_offload_errors: 238 - и не меняется. ... |
|||
|
:
Нравится:
Не нравится:
|
|||
| 22.02.2012, 11:53 |
|
||
|
Задержки в выполнении запроса
|
|||
|---|---|---|---|
|
#18+
Столбец tim= в 10046 это реальное время, я там 2 секунд не вижу. Я бы сравнил показания tcpdump на сервере и на клиенте ... |
|||
|
:
Нравится:
Не нравится:
|
|||
| 22.02.2012, 12:57 |
|
||
|
Задержки в выполнении запроса
|
|||
|---|---|---|---|
|
#18+
Новые подробности и решение проблемы. Вчера обнаружил oracle сессии, поначалу не придал им особого внимания. Суть - порядка 30 параллельных сессий одного запроса (P000...P029). Из них 6 постоянно активны. Висели вчера вечером, висели сегодня утром. Глянул SQL text, а там элементарный запрос из таблицы на 2к строк. Реально никакой активности в этих сессиях не происходило. Т.е. ни чтений, ни обработки, и в longops ничего нет, и блокировок нет. После того как прибил все эти сессии, а pmon потом почистил - запросы сразу стали летать без задержек :) Причина: SQL Navigator каким то образом подвесил сессии в БД. Всем спасибо. ... |
|||
|
:
Нравится:
Не нравится:
|
|||
| 22.02.2012, 13:01 |
|
||
|
Задержки в выполнении запроса
|
|||
|---|---|---|---|
|
#18+
Журавлев ДенисСтолбец tim= в 10046 это реальное время, я там 2 секунд не вижу. Я бы сравнил показания tcpdump на сервере и на клиенте tcpdump сравнивал - одинаковые, задержки и там и там. В первом посте я написал, что в трассировке так же не вижу проблем. ... |
|||
|
:
Нравится:
Не нравится:
|
|||
| 22.02.2012, 14:12 |
|
||
|
Задержки в выполнении запроса
|
|||
|---|---|---|---|
|
#18+
Отказались от SQL Navigator, однако сегодня история повторилась :( PARSING IN CURSOR #2 len=1122 dep=0 uid=74 oct=3 lid=74 tim=1299511563518395 hv=1358752691 ad='34bde520' SELECT '01234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789q012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789' from dual END OF STMT PARSE #2:c=0,e=18,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1299511563518391 EXEC #2:c=0,e=13,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1299511563518463 WAIT #2: nam='SQL*Net message to client' ela= 2 driver id=1297371904 #bytes=1 p3=0 obj#=-1 tim=1299511563518486 *** 2012-03-02 18:50:44.094 *** SESSION ID:(167.44429) 2012-03-02 18:50:44.094 WAIT #0: nam='SQL*Net message from client' ela= 2 driver id=1297371904 #bytes=1 p3=0 obj#=-1 tim=1299511566498719 Видно, что запрос быстро отработал на сервере, а дальше очень долго (почти 3сек) шёл до клиента. ... |
|||
|
:
Нравится:
Не нравится:
|
|||
| 02.03.2012, 19:01 |
|
||
|
|
start [/forum/topic.php?fid=25&msg=37674391&tid=1483705]: |
0ms |
get settings: |
11ms |
get forum list: |
12ms |
check forum access: |
4ms |
check topic access: |
4ms |
track hit: |
76ms |
get topic data: |
11ms |
get forum data: |
2ms |
get page messages: |
51ms |
get tp. blocked users: |
2ms |
| others: | 292ms |
| total: | 465ms |
| 0 / 0 |
