Oracle mechanics

24.11.2012

Таймауты параллельных ожиданий, или почему по умолчанию объекты бд создаются noparallel

Filed under: Oracle,parameters,PX,statistics,wait events — Игорь Усольцев @ 00:43
Tags: , , , ,

Простой недорогой OLTP запрос в непараллельном режиме выполняется предсказуемо быстро:

11.2.0.3.@ SQL> select /*+ noparallel */ *
  2    from view_history
  3   where order_id = 4181494
  4     and start_dt >= sysdate - 20
  5     and sysdate - 20 < end_dt
  6  /

no rows selected

Elapsed: 00:00:00.12

------------------------------------------------------------------------------------------------------
| Id  | Operation                            | Name          | Rows  | Bytes | Cost (%CPU)| Time     |
------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                     |               |     2 |   244 |    16  (25)| 00:00:01 |
|   1 |  VIEW                                | VIEW_HISTORY  |     2 |   244 |    16  (25)| 00:00:01 |
|   2 |   UNION-ALL                          |               |       |       |            |       |
|   3 |    PARTITION RANGE ITERATOR          |               |     1 |    53 |    12  (34)| 00:00:01 |
|*  4 |     TABLE ACCESS BY LOCAL INDEX ROWID| T_HISTORY     |     1 |    53 |    12  (34)| 00:00:01 |
|*  5 |      INDEX SKIP SCAN                 | T_CH_PK_PRT   |     1 |       |    11  (37)| 00:00:01 |
|*  6 |    FILTER                            |               |       |       |            |       |
|   7 |     NESTED LOOPS                     |               |     1 |    71 |     4   (0)| 00:00:01 |
|*  8 |      TABLE ACCESS BY INDEX ROWID     | T_ORDER       |     1 |    29 |     3   (0)| 00:00:01 |
|*  9 |       INDEX UNIQUE SCAN              | T_ORDER_PK    |     1 |       |     2   (0)| 00:00:01 |
|* 10 |      TABLE ACCESS BY INDEX ROWID     | T_SHIPMENT    |   116K|  4788K|     1   (0)| 00:00:01 | -- 116К строк - имхо, просто ошибка отображения в плане:
|* 11 |       INDEX UNIQUE SCAN              | T_SHIPMENT_PK |     1 |       |     0   (0)| 00:00:01 | --   цифра получена из условий FILTER #6 и #10 = 5% от кол-ва строк таблицы T_SHIPMENT
------------------------------------------------------------------------------------------------------ -- , не влияет на план и выполнение

Predicate Information (identified by operation id):
---------------------------------------------------

  ...
   6 - filter(TRUNC(SYSDATE@!+1)>SYSDATE@!-20)
  ...
  10 - filter(TRUNC(INTERNAL_FUNCTION("S"."DT"))>=SYSDATE@!-20)
  11 - access("S"."SERVICE_ID"="O"."SERVICE_ID" AND "S"."SERVICE_ORDER_ID"="O"."SERVICE_ORDER_ID")

Statistics
----------------------------------------------------------
          0  recursive calls
          0  db block gets
         37  consistent gets
          0  physical reads
          0  redo size
        771  bytes sent via SQL*Net to client
        465  bytes received via SQL*Net from client
          1  SQL*Net roundtrips to/from client
          0  sorts (memory)
          0  sorts (disk)
          0  rows processed

Тот же запрос при параллельном выполнении (по умолчанию, без подсказок) часто выполняется ~ 2 сек без серьёзных оснований:

SQL> select *
  2    from view_history
  3   where order_id = 4181494
  4     and start_dt >= sysdate - 20
  5     and sysdate - 20 < end_dt
  6  /

no rows selected

Elapsed: 00:00:02.06

--------------------------------------------------------------------------------------------------------------------------------------
| Id  | Operation                               | Name          | Rows  | Bytes | Cost (%CPU)| Time     |    TQ  |IN-OUT| PQ Distrib |
--------------------------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                        |               |     2 |   244 |    16  (75)| 00:00:01 |        |      |            | -- выполняется процессом QC
|   1 |  PX COORDINATOR                         |               |       |       |            |          |        |      |            |
|   2 |   PX SEND QC (RANDOM)                   | :TQ10001      |     2 |   244 |    16  (75)| 00:00:01 |  Q1,01 | P->S | QC (RAND)  | -- выполняется параллельно процессами PX
|   3 |    BUFFER SORT                          |               |     2 |   244 |            |          |  Q1,01 | PCWP |            |
|   4 |     VIEW                                | VIEW_HISTORY  |     2 |   244 |    16  (75)| 00:00:01 |  Q1,01 | PCWP |            |
|   5 |      UNION-ALL                          |               |       |       |            |          |  Q1,01 | PCWP |            |
|   6 |       PX PARTITION RANGE ITERATOR       |               |     1 |    53 |    12  (34)| 00:00:01 |  Q1,01 | PCWC |            |
|*  7 |        TABLE ACCESS BY LOCAL INDEX ROWID| T_HISTORY     |     1 |    53 |    12  (34)| 00:00:01 |  Q1,01 | PCWP |            |
|*  8 |         INDEX SKIP SCAN                 | T_CH_PK_PRT   |     1 |       |    11  (37)| 00:00:01 |  Q1,01 | PCWP |            |
|   9 |       BUFFER SORT                       |               |       |       |            |          |  Q1,01 | PCWC |            |
|  10 |        PX RECEIVE                       |               |     1 |    71 |     4   (0)| 00:00:01 |  Q1,01 | PCWP |            |
|  11 |         PX SEND ROUND-ROBIN             | :TQ10000      |     1 |    71 |     4   (0)| 00:00:01 |        | S->P | RND-ROBIN  | -- выполняется последовательно процессом QC
|* 12 |          FILTER                         |               |       |       |            |          |        |      |            |
|  13 |           NESTED LOOPS                  |               |     1 |    71 |     4   (0)| 00:00:01 |        |      |            |
|* 14 |            TABLE ACCESS BY INDEX ROWID  | T_ORDER       |     1 |    29 |     3   (0)| 00:00:01 |        |      |            |
|* 15 |             INDEX UNIQUE SCAN           | T_ORDER_PK    |     1 |       |     2   (0)| 00:00:01 |        |      |            |
|* 16 |            TABLE ACCESS BY INDEX ROWID  | T_SHIPMENT    |   116K|  4788K|     1   (0)| 00:00:01 |        |      |            |
|* 17 |             INDEX UNIQUE SCAN           | T_SHIPMENT_PK |     1 |       |     0   (0)| 00:00:01 |        |      |            |
--------------------------------------------------------------------------------------------------------------------------------------

Statistics
----------------------------------------------------------
         15  recursive calls                              -- избыток рекурсивных запросов
          0  db block gets
         46  consistent gets
          0  physical reads
          0  redo size
        771  bytes sent via SQL*Net to client
        465  bytes received via SQL*Net from client
          1  SQL*Net roundtrips to/from client
          5  sorts (memory)                               -- много сортировок в соответствии с планом
          0  sorts (disk)
          0  rows processed

Причину параллельного выполнения запроса по умолчанию найти несложно: для ускорения постоения / перестроения локального индекса партицированной таблицы T_HISTORY была использована и забыта опция PARALLEL:

SQL> alter index T_CH_PK_PRT rebuild online parallel 15;
...
SQL> select table_name, index_name, degree from dba_indexes where index_name in ('T_CH_PK_PRT');
 
TABLE_NAME INDEX_NAME  DEGREE
---------- ----------- ------
T_HISTORY  T_CH_PK_PRT 15

и легко решается установкой DEGREE = 1 / NOPARALLEL, что является значением по умолчанию при создании индексов и таблиц в Oracle

Причины медленного параллельного выполнения можно попробовать найти в статистике выполнения запроса:

SQL> @sessof 258

Session Time Model -- только для QC процесса

STAT_NAME                                                               DELTA
---------------------------------------------------------------- ------------
DB time                                                                  2180 -- для QC процесса
sql execute elapsed time                                                 2053 -- --//--
DB CPU                                                                   1999 -- похоже на высокое потребление ЦПУ ?
parse time elapsed                                                         43

Session Statistics -- для всех процессов, участвовавших в выполнении запроса

NAME                                                                    DELTA
---------------------------------------------------------------- ------------
...
DB time                                                                   616 -- для трёх процессов: QC + 2 * PX
in call idle wait time                                                    615 -- также суммарно для 3-х: интересные idle waits ???
...
consistent gets from cache                                                 47
session logical reads                                                      47
consistent gets                                                            47
...
recursive calls                                                            15 -- больше чем при сериальном выполнении, однако не влияет на скорость
...
sorts (memory)                                                              5 -- небольшие по размеру, sorts (rows) = 2
...
opened cursors cumulative                                                   4 -- было открыто и выполнено 4 курсора: 1xQC + 2xPX + 1xQC
execute count                                                               4 -- (нерекурсивных)
parse count (total)                                                         2
...
parse time elapsed                                                          2
...
session cursor cache hits                                                   2 -- , два из которых, использованные PX Slave процессами, не потребовали разбора - взяты из кэша
...
sorts (rows)                                                                2
session cursor cache count                                                  2
...
DFO trees parallelized                                                      1 -- Data Flow Operation tree: одно переключение Serial -> Parallel
...
queries parallelized                                                        1
...
Parallel operations not downgraded                                          1 -- непонятно *

Session Wait Events -- только для QC процесса

NAME                                                                    WAITS      TIME_MS     TIMEOUTS AVG_WAIT_MS
---------------------------------------------------------------- ------------ ------------ ------------ -----------
SQL*Net message from client                                                 1         6315            0      6314,8
PX Deq Credit: send blkd                                                    1         2047            0      2047,1 -- непонятное ожидание для QC в запросе с незначительными объёмами данных **
PX Deq: Execute Reply                                                      10            1            0         0,1 -- типичные ожидания
PX Deq: Parse Reply                                                         2            1            0         0,4
PX Deq: Join ACK                                                            2            1            0         0,3
events in waitclass Other                                                   7            1            0         0,1
PX Deq: Table Q Normal                                                      2            0            0         0,2 -- ***
SQL*Net message to client                                                   1            0            0           0

*) из V$SQL_MONITOR можно видеть, что параллельное выполнение формально было downgraded — запросили 48, получили 2 параллельных процесса — при наличии свободных PX. Кроме того, все 3 процесса использовали один и тот же SQL_CHILD и QC выполнял Buffer Gets, т.е. работал в качестве Producer:

SQL> select *  from v$sql_monitor m where sql_id = '7qcd775rkqjv5' and sql_exec_id = 16777225;

STATUS          MODULE      REFRESH_COUNT PROCESS_NAME SQL_CHILD_ADDRESS  PX_MAXDOP PX_SERVERS_REQUESTED PX_SERVERS_ALLOCATED PX_SERVER# PX_SERVER_GROUP PX_SERVER_SET ELAPSED_TIME QUEUING_TIME   CPU_TIME    FETCHES BUFFER_GETS
--------------- ----------- ------------- ------------ ----------------- ---------- -------------------- -------------------- ---------- --------------- ------------- ------------ ------------ ---------- ---------- -----------
DONE (ALL ROWS)                         4 p001         000000103C030800                                                                2               1             1          643            0        999          0          19
DONE (ALL ROWS)                         4 p000         000000103C030800                                                                1               1             1          442            0          0          0          10
DONE (ALL ROWS) sqlplus.exe             5 ora          000000103C030800           2                   48                    2                                                  2203            0       1000          1          17

**) 2-х секундное ожидание PX Deq Credit: send blkd в статистике QC выглядит похоже на таймаут в отсутствии заметных объёмов данных в запросе

***) Ожидания PX Deq: Table Q Normal типичны для PX Slave, либо QC процессов в качестве Consumer:

Indicates that the slave wait for data to arrive on its input table queue. In a parallel execution environment we have a producer consumer model. One slave set works on the data ( e.g. read data from disk , do a join ) called the produces slave set and the other slave set waits to get the data that the can start the work

— что и следует из плана выполнения на шаге #1

Длительные «idle wait» ожидания из SQL трейсов процессов-соучастников:

$ cat orcl_p001_1807_PUZZL.tkprof     ### PX Slave trace - практически совпадающий для обоих параллельных процессов
...
Misses in library cache during parse: 0     ### запрос, выполняемый PX, найден в кэше
Optimizer mode: ALL_ROWS
Parsing user id: SYS   (recursive depth: 1) ### считается рекурсивным
Number of plan statistics captured: 1
...
Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  PX Deq: Execution Msg                           5        0.00          0.00
  PX Deq: Table Q Normal                          1        2.04          2.04 ### PX Slave (Consumer) ждёт от QC (Producer) данных выполнения сериальных операций с 2-х секундным таймаутом - строка 11 плана выполнения
  PX Deq Credit: send blkd                        1        0.00          0.00 ### типичное ожидание: PX Slave быстро пересылает данные -> QC
  ...

$ cat orcl_ora_13002_PUZZL.tkprof    ### QC trace
...
Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: SYS
Number of plan statistics captured: 1
...
Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  ...
  PX Deq:...                                                                  ### типичные операции при параллельном выполнении
  SQL*Net message to client                       1        0.00          0.00
  ...
  PX Deq Credit: send blkd                        1        2.04          2.04 ### QC не может послать сообщение / рез-таты сериальной операции по таймауту - строка 11 плана
  PX Deq: Table Q Normal                          2        0.00          0.00 ### QC (Consumer) ожидает данные от PX Slaves|Producers - строка 2 параллельного плана выполнения
  PX Deq:...                                                                  ### типичные ожидания параллельного выполнения
  PX Deq: Slave Session Stats                     2        0.00          0.00 ### получение статистики от PX Slaves процессов - предпоследние ожидания QC согласно трейсу
  enq: PS - contention                            1        0.00          0.00 ### Parallel Execution Server Process reservation and synchronization - последнее ожидание QC
  SQL*Net message from client                     1       15.91         15.91
*****************************************************************************

В сырых трейсах можно проследить взаимодействие процессов QC PX во времени:

$ cat orcl_ora_13002_PUZZL.trc ### QC trace
*** 2012-11-13 17:56:24.674
...
EXEC #139869591086880:c=1000,e=9908,p=0,cr=9,cu=0,mis=0,r=0,dep=0,og=1,plh=1345418991,tim=1352814984696947 ### выполнение сериальных операций
...
WAIT #139869591086880: nam='PX Deq: Execute Reply' ela= 183 sleeptime/senderid=200 passes=2 p3=0 obj#=-1 tim=1352814984697732 ### момент начала ожидания PX Deq Credit: send blkd

*** 2012-11-13 17:56:26.746
WAIT #139869591086880: nam='PX Deq Credit: send blkd' ela= 2048115 sleeptime/senderid=268500992 passes=2 qref=69746919200 obj#=-1 tim=1352814986745953 ### по P1 (sleeptime/senderid) ожидания можно найти кого ждёт | кто блокирует QC *)
WAIT #139869591086880: nam='PX Deq: Execute Reply' ela= 70 sleeptime/senderid=200 passes=1 p3=0 obj#=-1 tim=1352814986746162
...
WAIT #139869591086880: nam='PX Deq: Table Q Normal' ela= 50 sleeptime/senderid=200 passes=1 p3=0 obj#=-1 tim=1352814986746597
WAIT #139869591086880: nam='PX Deq: Table Q Normal' ela= 2 sleeptime/senderid=0 passes=0 p3=0 obj#=-1 tim=1352814986746633
...
WAIT #139869591086880: nam='PX Deq: Slave Session Stats' ela= 63 sleeptime/senderid=200 passes=2 p3=0 obj#=-1 tim=1352814986747489
WAIT #139869591086880: nam='PX Deq: Slave Session Stats' ela= 2 sleeptime/senderid=0 passes=0 p3=0 obj#=-1 tim=1352814986747526
WAIT #139869591086880: nam='enq: PS - contention' ela= 209 name|mode=1347616774 instance=1 slave ID=1 obj#=-1 tim=1352814986747783
...

*) QC ожидает:

SQL> select bitand(&&p1, 16711680) - 65535 as SNDRINST,
  2         decode(bitand(&&p1, 65535),
  3                65535,
  4                'QC',
  5                'P' || to_char(bitand(&&p1, 65535), 'fm000')) as SNDR
  6    from dual
  7   where bitand(&&p1, 268435456) = 268435456;
Enter value for p1: 268500992

  SNDRINST SNDR
---------- -----
         1 P000

, трейс которого показывает:

Unix process pid: 1805, image: oracle@host.test.ru (P000)
...
*** 2012-11-13 17:56:24.690
...
WAIT #140411998771728: nam='PX Deq: Execution Msg' ela= 71 sleeptime/senderid=268566527 passes=2 p3=69728110368 obj#=-1 tim=1352814984697430 ### P000 начал ожидать на событии PX Deq: Table Q Normal

*** 2012-11-13 17:56:26.746
WAIT #140411998771728: nam='PX Deq: Table Q Normal' ela= 2048598 sleeptime/senderid=10 passes=2 p3=0 obj#=-1 tim=1352814986746079
...

— P000 начал ожидать данные (PX Deq: Table Q Normal) от QC раньше, чем QC был готов передать данные (PX Deq Credit: send blkd):

tim=1352814984697430 < tim=1352814984697732

и по истечении 2-х секундного таймаута получил данные от QC (в точности аналогично ведёт себя 2-й параллельный процесс P001)

Интересно отметить, что в документе поддержки Tips to Reduce Waits for «PX DEQ CREDIT SEND BLKD» at Database Level [ID 738464.1] , для случая if a lot of data and message are exchanged between parallel processes —  т.е. противоположного рассматриваемому, описывается в точности совпадающие причины:

At database level you should check your parallel execution setup. Are there objects that  should not have a degree setting. As example a «alter index <indexname> rebuild parallel 4;» would cause a degree of 4 on that index, although the intention was to rebuild the index with parallel 4 , but do not change the degree

и методы уменьшения параллельных ожиданий — через уменьшение количества параллельных выполнений, вплоть до исключения :)

Длительность таймаута регулируется непростым параметром:

SQL> @param_ _parallel_server_sleep_time

NAME                         VALUE IS_DEF DSC
---------------------------- ----- ------ -------------------------------------------------
_parallel_server_sleep_time  10    TRUE   sleep time between dequeue timeouts (in 1/100ths)

The init.ora parameter _parallel_server_sleep_time determines how long you will sleep on this event. The default is 100 msec if there are no credits and 2000 msec if there are

Изменение _parallel_server_sleep_time (возможное только на уровне системы) действительно влияет на длительность таймаута / производительность запроса. Интересно, что при неаккуратном изменении параметра можно получить:

INST#1@ SQL> alter system set "_parallel_server_sleep_time"=1; -- на инстатсе #1

System altered.

INST#1@ SQL> select *
  2    from view_history
  3   where order_id = 4181494
  4     and start_dt >= sysdate - 20
  5     and sysdate - 20 < end_dt
  6  /

no rows selected

Elapsed: 00:00:00.15 -- выполняется заметно быстрее

INST#1@ SQL> @param_ _parallel_server_sleep_time      -- но показывает странные значения на локальной системе

NAME                                       VALUE
------------------------------------------ -----
_parallel_server_sleep_time                0

INST#2@ SQL> @param_ _parallel_server_sleep_time      -- и ещё более странные на (удалённом) инстатсе #2

NAME                                       VALUE
------------------------------------------ ----------
_parallel_server_sleep_time                3455936976

INST#2@ SQL> select *
  2    from view_history
  3   where order_id = 4181494
  4     and start_dt >= sysdate - 20
  5     and sysdate - 20 < end_dt
  6  /
   and start_dt >= sysdate - 20
                   *
ERROR at line 4:
ORA-00600: internal error code, arguments: [ksliwat: bad wait time], [18446744072870521296], [], [], [], [], [], [], [], [], [], []

— вплоть до проблем с параллельным выполнение любых запросов. Т.о. параметр не только разумно менять через spfile + restart, но и предварительно проконсультироваться с MOS также не помешает

Распределение Consumer/Producer хорошо показывает сессионный обзор V$PQ_TQSTAT за исключением полей WAITS и TIMEOUTS, в которых по-прежнему можно видеть хаотичный разброс цифр для одного и того же запроса:

SQL> select tq_id, server_type, num_rows, bytes, waits, timeouts, process from V$PQ_TQSTAT order by tq_id, process desc;

     TQ_ID SERVER_TYPE                      NUM_ROWS      BYTES      WAITS   TIMEOUTS PROCESS
---------- ------------------------------ ---------- ---------- ---------- ---------- ------------------
         0 Producer                                0         48          0          0 QC
         0 Consumer                                0         24          4          0 P001
         0 Consumer                                0         24          4          0 P000
         1 Consumer                                0         48          1          0 QC
         1 Producer                                0         24          0          0 P001
         1 Producer                                0         24          0          0 P000
...
SQL> select tq_id, server_type, num_rows, bytes, waits, timeouts, process from V$PQ_TQSTAT order by tq_id, process desc;

     TQ_ID SERVER_TYPE                      NUM_ROWS      BYTES      WAITS   TIMEOUTS PROCESS
---------- ------------------------------ ---------- ---------- ---------- ---------- ------------------
         0 Producer                                0         48          0          0 QC
         0 Consumer                                0         24      36032      36032 P001
         0 Consumer                                0         24      35023      35023 P000
         1 Consumer                                0         48          0          0 QC
         1 Producer                                0         24          0          0 P001
         1 Producer                                0         24          0          0 P000

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

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

RSS feed for comments on this post. TrackBack URI

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

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

Логотип WordPress.com

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

Фотография Twitter

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

Фотография Facebook

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

Google+ photo

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

Connecting to %s

Создайте бесплатный сайт или блог на WordPress.com.

%d такие блоггеры, как: