Oracle mechanics

31.03.2013

asynch descriptor resize, Oracle 11.2.0.3 Linux x86_64

Запрос с непредсказуемыми изменениями времени выполнения:

11.2.0.3.@ SQL> select sql_exec_id,
  2         sql_plan_hash_value,
  3         max(sample_time) - min(sample_time) as QUERY_DURATION,
  4         round(sum(tm_delta_db_time) / 1000000) as db_time_sec,
  5         round(sum(tm_delta_cpu_time) / 1000000) as cpu_time_sec,
  6         sum(delta_read_io_requests + delta_write_io_requests) IO_REQUESTS,
  7         round(sum(delta_read_io_bytes + delta_write_io_bytes) / 1024 / 1024) as IO_MB
  8    from v$active_session_history
  9   where sql_id = 'fspy8r76zbmvq'
 10     and sql_exec_id between 17017534 and 17017547
 11   group by sql_exec_id, sql_plan_hash_value
 12   order by sql_exec_id
 13  /

SQL_EXEC_ID PLAN_HASH_V QUERY_DURATION DB_TIME_SEC CPU_TIME_SEC IO_REQUESTS      IO_MB
----------- ----------- -------------- ----------- ------------ ----------- ----------
   17017534  1249237767  00:04:44.432          284           23         342        333
   17017537  1249237767  00:00:02.000            2            1         356        334
   17017539  1249237767  00:00:02.000            1            0         339        327
   17017540  1249237767  00:00:01.000            3            1         395        385
   17017541  1249237767  00:00:02.000            3            2         341        320
   17017542  1249237767  00:00:03.000            2            0         343        334
   17017543  1249237767  00:00:01.000            6            5         323        288
   17017544  1249237767  00:00:01.000            2            1         307        298
   17017545  1249237767  00:00:02.000            3            1         346        334
   17017546  1249237767  00:00:02.000            2            1         258        247
   17017547  1249237767  00:45:49.989         2753           59         346        334

- разброс времени выполнения от 1 сек до 45 минут (что представляет некоторое неудобство для пользователей), при этом план, статистика, значения св.переменных в запросе и общая загрузка сервера не менялись. Различным значениям DB_TIME, зафиксированным в V$ACTIVE_SESSION_HISTORY, соответствует приблизительно одинаковый ввод-вывод и незначительно различающиеся CPU_TIME, например, в последнем выполнении из 2753 сек DB_TIME только 59 секунд занимает CPU_TIME согласно ASH, в отличие от V$SESS_TIME_MODEL, где увеличение длительности таких запросов полностью отражается в увеличении CPU_TIME

Кроме этого, статистика последнего медленного выполнения запроса показывает:

SQL> @ash_sqlmon fspy8r76zbmvq 17017547

ID PLAN_OPERATION                                        COST CARDINALITY      BYTES SESSION_STATE    WAIT_COUNT
-- -------------------------------------------------- ------- ----------- ---------- ---------------- ----------------
 0   SELECT STATEMENT                                  212904
 1     TEMP TABLE TRANSFORMATION
 2       LOAD AS SELECT
 3         SORT AGGREGATE                                               1          8
 4           INDEX FULL SCAN (MIN/MAX)                      3           1          8
 5       HASH GROUP BY                                 212901        4572      86868
 6         VIEW                                        212898       64250    1220750
 7           UNION-ALL
 8             CONCATENATION
 9               FILTER
10                 NESTED LOOPS                           105       64247    2055904
11                   NESTED LOOPS                         100       64248    1670448
12                     HASH JOIN                           96       64249    1284980 ON CPU           1
13                       TABLE ACCESS FULL                 47       64249     642490
14                       TABLE ACCESS FULL                 47       64250     642500
15                     INDEX UNIQUE SCAN                    0           1          6
16                   INDEX UNIQUE SCAN                      0           1          6
17               FILTER
18                 NESTED LOOPS                             3           1         32
19                   NESTED LOOPS                           2           1         22
20                     NESTED LOOPS                         2           1         16
21                       TABLE ACCESS BY INDEX ROWID        2           1         10
22                         INDEX UNIQUE SCAN                1           1
23                       INDEX UNIQUE SCAN                  0       64249     385494
24                     INDEX UNIQUE SCAN                    0       64249     385494
25                   TABLE ACCESS BY INDEX ROWID            1       64249     642490
26                     INDEX UNIQUE SCAN                    0           1
27             HASH GROUP BY                           212435           1         44 ON CPU           1
28               NESTED LOOPS OUTER                    212434         244      10736
29                 NESTED LOOPS                        212429         244       6832
30                   VIEW                                   2           1          6
31                     TABLE ACCESS FULL                    2           1          8
32                   PARTITION RANGE ITERATOR          212427         244       5368
33                     TABLE ACCESS FULL               212427         244       5368 ON CPU / WAITING 1 / 1 -- filter(("C"."CAMPAIGN_ID"=NVL(:B1,"C"."CAMPAIGN_ID")))
34                 VIEW PUSHED PREDICATE                    1           1         16
35                   HASH JOIN                              9           1         24 ON CPU           2739  -- основное время выполнения
36                     NESTED LOOPS                         5           1         14
37                       TABLE ACCESS BY INDEX ROWID        2           1         10
38                         INDEX UNIQUE SCAN                1           1            ON CPU           1
39                       TABLE ACCESS FULL                  3           1          4 ON CPU           3
40                     TABLE ACCESS FULL                    3           7         70
41             HASH GROUP BY                                            1         28
42               CONCATENATION
43                 FILTER
44                   NESTED LOOPS                         342           2         56
45                     VIEW                                 2           1          6
46                       TABLE ACCESS FULL                  2           1          8
47                     TABLE ACCESS FULL                  340           2         44
48                 FILTER
49                   NESTED LOOPS                          12           1         28
50                     TABLE ACCESS BY INDEX ROWID         10           1         22
51                       INDEX RANGE SCAN                   1           9
52                     VIEW                                 2           1          6
53                       TABLE ACCESS FULL                  2           1          8

, что выполнение запроса в ASH чаще всего фиксировалось при выполнении HASH JOIN, что необычно для непараллельно выполняющегося запроса в системе, не испытывающей проблем с ресурсом ЦПУ

Установка на уровне системы события sql_trace для запроса:

SQL> alter system set events 'sql_trace [sql:fspy8r76zbmvq] level 28';

System altered.

- позволила получить трейсы длинных выполнений, которые после обработки tkprof показали, что основное время, согласно трейсу, относится к фазе FETCH, что не совсем понятно для запроса с финальным GROUP BY и учитывая, что тут приведены данные из трейса прерванного по ^C запроса, не успевшего вернуть ни одной строки:

$ less inst1_ora_10021_WWW.fchela

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.01       0.02          0          3          7           0
Fetch        1     33.59    1521.16      21558     823385          4           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        3     33.61    1521.19      21558     823388         11           0

В трейсе отсутствуют длительные ожидания, кроме короткого, но многочисленного asynch descriptor resize:

  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  asynch descriptor resize                   103422        0.00          0.12
  direct path write temp                          1        0.00          0.00
  SQL*Net message to client                       1        0.00          0.00
  db file sequential read                         1        0.01          0.01
  reliable message                                1        0.00          0.00
  enq: KO - fast object checkpoint                1        0.02          0.02
  direct path read                              192        0.00          0.36    -- используется serial direct path read
********************************************************************************

«Сырой» трейс подтверждает, что основным (в смысле самым частым) при выполнении было ожидание asynch descriptor resize:

$ grep 'WAIT #47813501883248' inst1_ora_10021_WWW.trc | wc -l
103619
$ grep 'asynch descriptor resize' inst1_ora_10021_WWW.trc | wc -l
103423

, которое, в основном, фиксировалось после выполнения всех типичных для запроса ожиданий / действий:

WAIT #47813501883248: nam='direct path read' ela= 45 file number=56 first dba=63424 block cnt=64 obj#=169408 tim=1364549892266732
WAIT #47813501883248: nam='direct path read' ela= 2061 file number=56 first dba=63488 block cnt=64 obj#=169408 tim=1364549892270926
WAIT #47813501883248: nam='direct path read' ela= 72 file number=56 first dba=63552 block cnt=64 obj#=169408 tim=1364549892273096
WAIT #47813501883248: nam='direct path read' ela= 2112 file number=56 first dba=63616 block cnt=64 obj#=169408 tim=1364549892277287
WAIT #47813501883248: nam='asynch descriptor resize' ela= 1 outstanding #aio=1 current aio limit=128 new aio limit=3116 obj#=169408 tim=1364549892279480
WAIT #47813501883248: nam='asynch descriptor resize' ela= 2 outstanding #aio=1 current aio limit=128 new aio limit=3180 obj#=169408 tim=1364549892297549
WAIT #47813501883248: nam='asynch descriptor resize' ela= 2 outstanding #aio=1 current aio limit=128 new aio limit=3245 obj#=169408 tim=1364549892307522
WAIT #47813501883248: nam='asynch descriptor resize' ela= 1 outstanding #aio=1 current aio limit=128 new aio limit=3245 obj#=169408 tim=1364549892317537
...
WAIT #47813501883248: nam='asynch descriptor resize' ela= 2 outstanding #aio=1 current aio limit=0 new aio limit=3245 obj#=169408 tim=1364551412052902
FETCH #47813501883248:c=33599893,e=1521165602,p=21558,cr=823385,cu=4,mis=0,r=0,dep=0,og=1,plh=1249237767,tim=1364551412089543
WAIT #47813501883248: nam='direct path read' ela= 21 file number=56 first dba=64320 block cnt=64 obj#=169408 tim=1364551412094857
STAT #47813501883248 id=1 cnt=0 pid=0 pos=1 obj=0 op='TEMP TABLE TRANSFORMATION  (cr=3 pr=0 pw=1 time=13722 us)'

- при этом на первый же за время запроса FETCH Oracle относит практически всё время выполнения запроса FETCH #47813501883248:c=33599893,e=1521165602 — более 1,500 секунд!

И та же картина отражается в трейса каждого длинного запроса — не только прерванного, как предыдущий, но и успешно выполнившегося за 2,497 сек:

WAIT #47481803450624: nam='asynch descriptor resize' ela= 1 outstanding #aio=0 current aio limit=128 new aio limit=4096 obj#=-40005906 tim=1364476992416587
WAIT #47481803450624: nam='asynch descriptor resize' ela= 1 outstanding #aio=0 current aio limit=128 new aio limit=4096 obj#=-40005906 tim=1364476992433641
WAIT #47481803450624: nam='asynch descriptor resize' ela= 2 outstanding #aio=0 current aio limit=128 new aio limit=4096 obj#=-40005906 tim=1364476992463003
FETCH #47481803450624:c=65626024,e=2497346735,p=1,cr=1285057,cu=5,mis=0,r=100,dep=1,og=1,plh=1249237767,tim=1364476992481794 -- 2,497 сек первый FETCH
FETCH #47481803450624:c=0,e=57,p=0,cr=0,cu=0,mis=0,r=100,dep=1,og=1,plh=1249237767,tim=1364476992494701                      -- следующие FETCH имеют адекватные длительности

- при разнице времён последнего synch descriptor resize и первого FETCH — tim=1364476992463003 и tim=1364476992481794 — не более 20 мс

AWR при этом считает, что (почти) все ожидания asynch descriptor resize заканчивались таймаутом:

Foreground Wait Events         DB/Inst: DB1/inst1  Snaps: 3695-3697

                                                             Avg
                                        %Time Total Wait    wait    Waits   % DB
Event                             Waits -outs   Time (s)    (ms)     /txn   time
-------------------------- ------------ ----- ---------- ------- -------- ------
...
asynch descriptor resize        354,762   100          1       0      0.0     .0

Т.о. формально Oracle предоставляет достаточно противоречивую информацию о причинах неожиданно медленного выполнения запроса, за исключением относительно многочисленного, но формально короткого ожидания asynch descriptor resize при использовании direct path read (в данном случае — serial)

Есть несколько багов с похожей симптоматикой:

1) Bug 9829397 Excessive CPU and many «asynch descriptor resize» waits for SQL using Async IO — очень похож, но исправлен в 11.2.0.3 и не должен быть актуален, однако рекомендуемое в качестве решения отключение direct path read работает, попутно увеличивая среднее время выполнения с 3 до 53 секунд (и как бы ещё раз доказывая эффективность метода «прямого чтения»):

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.00       0.00          0          3          7           0
Fetch     4355     53.00      53.12          1    2662299          5       65297 --  все 53 секунды формально FETCH / CPU
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total     4357     53.00      53.12          1    2662302         12       65297
...
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  direct path write temp                          1        0.00          0.00
  SQL*Net message to client                    4355        0.00          0.00
  db file sequential read                         1        0.01          0.01
  asynch descriptor resize                        1        0.00          0.00
  latch: row cache objects                        2        0.00          0.00
  SQL*Net message from client                  4355        0.30          9.39
********************************************************************************

2) Bug 13080541 : WITH QUERY CONTAINS FUNCTION AND WHERE CLAUSE IS VERY SLOW — интересный случай, ожидание asynch descriptor resize / замедление запроса связано с использованием WITH и наличием условия. В моём запросе эквивалентное удаление условия WHERE CAMPAIGN_ID = NVL(:B1, CAMPAIGN_ID) при :B1 = NULL (необходимое условие длинного выполнения) также решает проблему:

WITH DC AS
...
-- WHERE CAMPAIGN_ID = NVL(:B1, CAMPAIGN_ID)
 GROUP BY CAMPAIGN_ID

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.00       0.01          0          3          7           0
Fetch     4355      0.98       2.68      22388     104962          6       65303
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total     4357      0.99       2.70      22388     104965         13       65303
...
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  asynch descriptor resize                       54        0.00          0.00   -- значительное уменьшение количества
  direct path write temp                          1        0.00          0.00
  SQL*Net message to client                    4355        0.00          0.00
  db file sequential read                         1        0.00          0.00
  direct path read                              242        0.02          1.01   -- продолжает использоваться
  SQL*Net message from client                  4355        0.07         10.09
********************************************************************************

3) Bug 13507330 : MANY «ASYNCH DESCRIPTOR RESIZE» WAITS FOR SQL USING ASYNC IO (11.2.0.3 Linux x86_64) — имеет Status 45 — Vendor OS Problem, содержит стандартный Workaround: отключить режим «прямого чтения», однако отмечается, что проблема может быть решена увеличением на уровне ОС максимума одновременных асинхронных запросов aio-max-nr

Аналогичное решение работает и в нашем случае:

# sysctl -a | grep aio
fs.aio-nr = 1048538                                    -- в текущем проблемном состоянии кол-во текущих запросов почти равно максимуму
fs.aio-max-nr = 1048576                                -- установлено в соответствии с руководством
...
# sysctl -w fs.aio-max-nr=10000000                     -- после увеличения
fs.aio-max-nr = 10000000
...                                                    -- по прошествии незначительного времени
# cat /proc/sys/fs/aio-nr
1684663                                                -- кол-во одновременно используемых запросов заметно выросло

Посмотреть как используются / распределяются асинхронные запросы между процессами можно с использованием systemtap, например, как показано в Troubleshooting ORA-27090 async I/O errors with systemtap — важнее то, что aio-nr более не увеличивается и максимальное время выполнения запроса снизилось с 45 минут до 30 сек:

SQL> select max(sample_time) - min(sample_time) as QUERY_DURATION,
  2         round(sum(tm_delta_db_time) / 1000000) as db_time_sec,
  3         round(sum(tm_delta_cpu_time) / 1000000) as cpu_time_sec,
  4         sum(delta_read_io_requests + delta_write_io_requests) IO_REQUESTS,
  5         round(sum(delta_read_io_bytes + delta_write_io_bytes) / 1024 / 1024) as IO_MB
  6    from v$active_session_history
  7   where sql_id = 'fspy8r76zbmvq'
  8   group by sql_exec_id, sql_plan_hash_value
  9   having max(sample_time) - min(sample_time) > TO_DSINTERVAL('0 00:00:25.000')
 10   order by max(sample_time) - min(sample_time) desc
 11  /

QUERY_DURATION      DB_TIME_SEC CPU_TIME_SEC IO_REQUESTS      IO_MB
------------------- ----------- ------------ ----------- ----------
+000000000 00:00:26          20           18         392        374
+000000000 00:00:25          27           20         436        375
+000000000 00:00:25          19           16         384        374

Что, как я понимаю, не противоречит официальному описанию ожидания asynch descriptor resize:

Wait event ‘asynch descriptor resize’ is waited for when the number of asynchronous descriptors reserved inside the OS kernel is being re-adjusted.

When the number of asynchronous I/O’s submitted by a process has to be dynamically increased, the unix kernel is signalled to make the changes and the process will wait on ‘asynch descriptor resize’ . Many Unix Kernels (for example: Linux kernel) do not allow the limit to be increased when there are outstanding I/O’s; all outstanding I/O’s must be resolved before the limit is increased. This means that all sessions doing asynchronous I/O will wait at this time. The event is shown when the kernel wants to increase the limit and is waiting for all the outstanding I/O’s to be resolved so that the increase can be implemented.

- с той разницей, что в рассматриваемом случае общее кол-во одновременных aio запросов, доступных  процессам в системе, включая процессы Oracle, было ограничено сверху параметром aio-max-nr

При этом в трейсе/статистиках отрадаются короткие 1-2 мкс ожидания asynch descriptor resize с длинными паузами между ними ~ 150 мс в случае таймаута (неуспешного увеличения current aio limit=128 new aio limit=4096), в течение которых процесс продолжает использовать процессорное время, увеличивая CPU_TIME запроса

About these ads

Добавить комментарий »

Комментариев нет.

RSS-лента комментариев к этой записи. TrackBack URI

Добавить комментарий

Заполните поля или щелкните по значку, чтобы оставить свой комментарий:

Логотип WordPress.com

Для комментария используется ваша учётная запись WordPress.com. Выход / Изменить )

Фотография Twitter

Для комментария используется ваша учётная запись Twitter. Выход / Изменить )

Фотография Facebook

Для комментария используется ваша учётная запись Facebook. Выход / Изменить )

Google+ photo

Для комментария используется ваша учётная запись Google+. Выход / Изменить )

Connecting to %s

Theme: Rubric. Get a free blog at WordPress.com

Отслеживать

Get every new post delivered to your Inbox.

Join 126 other followers

%d bloggers like this: