Oracle mechanics

11.12.2013

Блокировки типа RC — Result Cache при использовании MTS

При использовании Multi-Threaded Server блокировки типа RC — Result Cache в AWR вполне ожидаемы при:

11.1.0.7.@ SQL> show parameter result_cache_mode

NAME                                 VALUE
------------------------------------ --------
result_cache_mode                    FORCE

Зависимости ожидания (wait tree) при этом представляют, в основном, логичную картину:

11.1.0.7.@ SQL> @ash_wait_tree "event = 'enq: RC - Result Cache: Contention'"

LVL BLOCKING_TREE       EVENT                              WAITS_COUNT SESS_COUNT AVG_WA
--- ------------------- ---------------------------------- ----------- ---------- ------
  1 FOREGROUND          enq: RC - Result Cache: Contention        3019         49    999 -- блокированные на кэше запросы ожидают:
  2   FOREGROUND        db file sequential read                   1243         13     50 -- ввод-вывод в процессе выполнения запроса/наполнения кэша
  2   FOREGROUND        read by other session                      844          1     69 -- --//--
  2   FOREGROUND        db file parallel read                      594          1     61 -- --//--
  2   FOREGROUND        db file scattered read                     230          9     59 -- --//--
  2   FOREGROUND        On CPU / runqueue                           37          8      0 -- ЦПУ при выполнении запроса/наполнения кэша
  2   FOREGROUND        virtual circuit wait                        14          2    146 -- ???
  2   FOREGROUND        log buffer space                             4          1     11 -- отложенная очистка блоков(delayed block cleanout)
  2   FOREGROUND        read by other session                        2          1     32
  3     FOREGROUND      db file sequential read                    834          4     69
  3     FOREGROUND      On CPU / runqueue                            5          2      0
  3     (LGWR)          control file parallel write                  4          1     24 -- и LGWR, её сдерживающий
  3     FOREGROUND      read by other session                        4          2     17
  3     FOREGROUND      read by other session                        1          1      9
  4       FOREGROUND    db file sequential read                      1          1      9 -- чтения нижнего уровня, завершения которых ждут на read by other session

— кроме ожидания virtual circuit wait, блокирующего доступ к кэшу на enq: RC — Result Cache: Contention

В ASH нашлись следы такой блокировующей сессии:

SQL> select *
  2    from v$active_session_history
  3   where (SAMPLE_ID, SESSION_ID) in
  4         (select SAMPLE_ID, BLOCKING_SESSION
  5            from v$active_session_history
  6           where event = 'enq: RC - Result Cache: Contention'
  7             and session_state = 'WAITING')
  8     and event = 'virtual circuit wait'
  9   order by sample_id
 10  /

SAMPLE_ID SESSION_ID SESSION_SERIAL# SQL_ID        SQL_OPCODE SQL_PLAN_OPERATION SQL_EXEC_ID EVENT                 WAIT_CLASS SESSION_STATE TIME_WAITED IN_CONNECTION_MGMT IN_PARSE IN_SQL_EXECUTION IN_BIND IN_CURSOR_CLOSE
--------- ---------- --------------- ------------- ---------- ------------------ ----------- --------------------- ---------- ------------- ----------- ------------------ -------- ---------------- ------- ---------------
112082164       1022            3369 fm0f8ma7yks73          3 SELECT STATEMENT      16777242 virtual circuit wait  Network    WAITING            151796 N                  N        N                N       N
112082165       1022            3369 fm0f8ma7yks73          3 SELECT STATEMENT      16777242 virtual circuit wait  Network    WAITING            154799 N                  N        N                N       N
112082166       1022            3369 fm0f8ma7yks73          3 SELECT STATEMENT      16777242 virtual circuit wait  Network    WAITING            212136 N                  N        N                N       N
112082167       1022            3369 fm0f8ma7yks73          3 SELECT STATEMENT      16777242 virtual circuit wait  Network    WAITING            189296 N                  N        N                N       N
112082168       1022            3369 fm0f8ma7yks73          3 SELECT STATEMENT      16777242 virtual circuit wait  Network    WAITING            204180 N                  N        N                N       N
112082169       1022            3369 fm0f8ma7yks73          3 SELECT STATEMENT      16777242 virtual circuit wait  Network    WAITING            225956 N                  N        N                N       N
112082170       1022            3369 fm0f8ma7yks73          3 SELECT STATEMENT      16777242 virtual circuit wait  Network    WAITING             71969 N                  N        N                N       N
112082171       1022            3369 fm0f8ma7yks73          3 SELECT STATEMENT      16777242 virtual circuit wait  Network    WAITING            118007 N                  N        N                N       N
112082172       1022            3369 fm0f8ma7yks73          3 SELECT STATEMENT      16777242 virtual circuit wait  Network    WAITING            205740 N                  N        N                N       N
112082173       1022            3369 fm0f8ma7yks73          3 SELECT STATEMENT      16777242 virtual circuit wait  Network    WAITING            199909 N                  N        N                N       N              

, при этом блокирующая сессия ожидает virtual circuit wait в фазе выполнения, не относящейся ни к CONNECTION_MGMT, ни к PARSE, ни к SQL_EXECUTION, ни к BIND, ни к CURSOR_CLOSE

Поскольку по окончании блокировки вплоть до завершения выполнения эта блокирующая сессия не ожидала более ничего другого:

SQL> select distinct sql_plan_operation,
  2                  event, wait_class,
  3                  in_connection_mgmt,
  4                  in_parse,
  5                  in_sql_execution,
  6                  in_bind,
  7                  in_cursor_close
  8    from v$active_session_history
  9   where (session_id, session_serial#, sql_id, sql_exec_id)
 10          in ((1022, 3369, 'fm0f8ma7yks73', 16777242))
 11     and sample_id > 112082173
 12  /

SQL_PLAN_OPERATION  EVENT                 WAIT_CLASS  IN_CONNECTION_MGMT IN_PARSE IN_SQL_EXECUTION IN_BIND IN_CURSOR_CLOSE
------------------- --------------------- ----------- ------------------ -------- ---------------- ------- ---------------
SELECT STATEMENT    virtual circuit wait  Network     N                  N        N                N       N

— блокировка, предположительно, возникает на этапе FETCH, что можно проверить, например, по трейсу:

SQL> alter system set events 'sql_trace [sql:fm0f8ma7yks73] level 12';           -- для запроса на уровне системы

System altered.

SQL ID: fm0f8ma7yks73
Plan Hash: 2765240953

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        0      0.00       0.00          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch      344      0.03       0.21         65       2314          0        2406 -- основное время выполнения приходится на Fetch из бд
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total      345      0.04       0.21         65       2314          0        2406

Rows     Row Source Operation
-------  ---------------------------------------------------
   2406  RESULT CACHE  7yfhd6dcrnt5dgqg9dvu5uu3xx (cr=2314 pr=65 pw=0 time=0 us)
   2406   SORT ORDER BY (cr=2314 pr=65 pw=0 time=0 us cost=6 size=9350 card=50)
   2406    FILTER  (cr=2314 pr=65 pw=0 time=12930 us)                           -- неточная статистика в части времени
   2406     PARTITION RANGE ITERATOR PARTITION: KEY KEY (cr=2314 pr=65 pw=0 time=12930 us cost=5 size=9350 card=50)
   2406      TABLE ACCESS BY LOCAL INDEX ROWID PARTITION: KEY KEY (cr=2314 pr=65 pw=0 time=12930 us cost=5 size=9350 card=50)
   2406       INDEX SKIP SCAN PARTITION: KEY KEY (cr=17 pr=17 pw=0 time=0 us cost=4 size=0 card=1)(object id 2303527)

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                     344        0.00          0.00
  db file sequential read                        65        0.02          0.18 -- собственно чтение, около 180 мс, 65 чтений по 3 мс
  virtual circuit wait                          686        0.00          0.91 -- основное время, по количеству ожиданий равное удвоенному кол-ву SQL*Net roundtrip
  SQL*Net message from client                   343        0.00          0.02

— стоит обратить внимание, что время выполнения запроса 0.21 сек., показываемое в выводе tkprof 11.1 не учитывает дествительное время FETCH результатов запроса, включающее время, проведённое на virtual circuit wait, что можно увидеть в сыром трейсе:

PARSING IN CURSOR #22 len=567 dep=0 uid=40 oct=3 lid=40 tim=1386755130905788 hv=2414436579 ad='69b1549f0' sqlid='fm0f8ma7yks73'
...
FETCH #22:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=6,dep=0,og=1,plh=2765240953,tim=1386755132092161

— между [первым] PARSING и последним FETCH 1386755132092161 — 1386755130905788 = 1186373 мкс ~ 1,19 сек., что соответствует секции ожиданий tkprof, и заметно превышает время Fetch (из бд) из первой секции обработанного трейса

Как это происходит можно/проще посмотреть по статистике плана выполнения из DBA_HIST_ACTIVE_SESS_HISTORY:

SQL> @ash_sqlmon_hist fm0f8ma7yks73 2765240953 "" 30000

ID PLAN_OPERATION                                 WAIT_PROFILE
-- ---------------------------------------------- ----------------------------------------------------------------------------------------------------------------------------
 0   SELECT STATEMENT                             virtual circuit wait(484); ON CPU(3);                           -- здесь блокируем результат запроса на время возврата 1-му клиенту
 1     RESULT CACHE                               enq: RC - Result Cache: Contention(407); ON CPU(4);             -- тут ждём кэш результатов
 2       SORT ORDER BY                            ON CPU(10); direct path read temp(3); direct path write temp(2);
 3         FILTER
 4           PARTITION RANGE ITERATOR
 5             TABLE ACCESS BY LOCAL INDEX ROWID  db file sequential read(269); read by other session(259); db file parallel read(187); ON CPU(10); db file scattered read(5);
 6               INDEX SKIP SCAN                  db file sequential read(92); ON CPU(1); read by other session(1);

Поскольку, как уже писал, virtual circuit wait включает в себя аналог сетевого ожидания SQL*Net message from/to client, описанная выше блокировка кэша результата запроса типично возникает при недостаточном размере arraysize на значительных выборках

Что подтверждается статистикой выполнения запроса:

SQL> select round(st.executions)                     as execs,
  2         st.sql_id,
  3         st.plan_hash_value                       as plan,
  4         round(st.elapsed_time / st.executions)   as ela_per_exec,
  5         round(st.rows_processed / st.executions) as rows_per_exec,
  6         round(st.fetches / st.executions)        as fetch_per_exec,
  7         round(st.rows_processed / st.fetches)    as rows_per_fetch
  8    from gv$sqlstats st
  9   where sql_id in ('fm0f8ma7yks73')
 10     and st.executions > 0
 11  /

EXECS SQL_ID              PLAN ELA_PER_EXEC ROWS_PER_EXEC FETCH_PER_EXEC ROWS_PER_FETCH
----- ------------- ---------- ------------ ------------- -------------- --------------
   87 fm0f8ma7yks73 2706411405      4447611         14342           2049              7

И в общем случае (для любых запросов) virtual circuit wait а абсолютном большинстве случаев соответствует головной операции плана SELECT STATEMENT, т.е. фазе FETCH (результатов запроса в направлении клиента):

SQL> select nvl2(sql_exec_id, 'In SQL Exec', 'No SQL Exec') as SQL_EXEC,
  2         sql_plan_operation,
  3         in_connection_mgmt,
  4         in_parse,
  5         in_sql_execution,
  6         in_bind,
  7         in_cursor_close,
  8         count(*),
  9         round(avg(time_waited) / 1000) as avg_time_waited_ms
 10    from v$active_session_history
 11   where event = 'virtual circuit wait'
 12     and session_state = 'WAITING'
 13   group by nvl2(sql_exec_id, 'In SQL Exec', 'No SQL Exec'),
 14            sql_plan_operation,
 15            in_connection_mgmt,
 16            in_parse,
 17            in_sql_execution,
 18            in_bind,
 19            in_cursor_close
 20   order by count(*) desc
 21  /
SQL_EXEC      SQL_PLAN_OPERATION  IN_CONNECTION_MGMT IN_PARSE IN_SQL_EXECUTION IN_BIND IN_CURSOR_CLOSE   COUNT(*) AVG_TIME_WAITED_MS
------------- ------------------- ------------------ -------- ---------------- ------- --------------- ---------- ------------------
In SQL Exec   SELECT STATEMENT    N                  N        N                N       N                     2118                 17 -- основные ожидания
In SQL Exec                       N                  N        Y                N       N                       19                180 -- погрешность
In SQL Exec   MERGE STATEMENT     N                  N        Y                N       N                        5                163

и при массовом использовании низкого arraysize может занимать значительную часть DB time:

Top 5 Timed Foreground Events
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
                                                           Avg
                                                          wait   % DB
Event                                 Waits     Time(s)   (ms)   time Wait Class
------------------------------ ------------ ----------- ------ ------ ----------
virtual circuit wait                241,432      36,290    150   44.7 Network
...

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

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

RSS feed for comments on this post.

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

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

Логотип WordPress.com

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

Фотография Twitter

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

Фотография Facebook

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

Google+ photo

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

Connecting to %s

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

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