Oracle mechanics

27.04.2016

Скрипт для асинхронных блокировок/блокеров из [истории] ASH

Filed under: Active Session History,Диагностика системы (instance),Oracle,Scripts — Игорь Усольцев @ 16:04
Tags: ,

Для ответа на вопрос типа «Кто кого блокировал 21 апреля в период между 03:00 и 03:30 ?» можно посмотреть в соответствующий AWR и определить:

1) собственно факт вероятного наличия проблемы:

              Snap Id      Snap Time      Sessions Curs/Sess Instances
            --------- ------------------- -------- --------- ---------
Begin Snap:    325799 21-Apr-16 03:00:50       672       2.9         2
  End Snap:    325800 21-Apr-16 03:30:06       613       2.9         2
   Elapsed:               29.28 (mins)
   DB Time:            2,157.33 (mins) -- тут

2) проблемное ENQUEUE ожидание:

Top 10 Foreground Events by Total Wait Time
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
                                           Total Wait       Wait   % DB Wait    
Event                                Waits Time (sec)    Avg(ms)   time Class   
------------------------------ ----------- ---------- ---------- ------ --------
DB CPU                                          50.8K              39.2         
enq: TX - row lock contention          907      26.2K   28850.95   20.2 Applicat -- вероятно, тут
latch: cache buffers chains      1,063,115     7905.4       7.44    6.1 Concurre
enq: UL - contention                38,803     4835.8     124.63    3.7 Applicat
db file sequential read          2,587,974     2225.1       0.86    1.7 User I/O

3) страждущий запрос(ы) по наименованию ожидания:

Top SQL with Top Events
-> Top SQL statements by DB Time along with the top events by DB Time  
   for those SQLs.
-> % Activity is the percentage of DB Time due to the SQL.
-> % Event is the percentage of DB Time due to the event that the SQL is 
   waiting on.
-> % Row Source is the percentage of DB Time due to the row source for the 
   SQL waiting on the event.
-> Executions is the number of executions of the SQL that were sampled in ASH.

                 SQL ID            Plan Hash           Executions     % Activity
----------------------- -------------------- -------------------- --------------
                                                                           % Row
Event                          % Event Top Row Source                     Source
------------------------------ ------- --------------------------------- -------
...
          73qhtmwmtat18           3503883833                   92          20.43 -- повезло - только один запрос
enq: TX - row lock contention    19.97 MERGE                               19.97 -- испытывал блокировки

4) блокирующие сессии:

Top Blocking Sessions
-> Blocking session activity percentages are calculated with respect to 
      waits on enqueues, latches and "buffer busy" only 
-> '% Activity' represents the load on the database caused by 
      a particular blocking session
-> '# Samples Active' shows the number of ASH samples in which the 
      blocking session was found active.
-> 'XIDs' shows the number of distinct transaction IDs sampled in ASH 
      when the blocking session was found active.

 Blocking Sid (Inst) % Activity Event Caused                      % Event
-------------------- ---------- ------------------------------ ----------
User                 Program                          # Samples Active     XIDs
-------------------- ------------------------------ ------------------ --------
   586,58065(     1)       9.95 enq: TX - row lock contention        9.92
XO                   python2.7@host...u (TNS V1-V3)       4/176 [  2%]        1

  1458, 5464(     1)       7.09 enq: TX - row lock contention        7.09
XO                   python2.7@host...u (TNS V1-V3)       2/176 [  1%]        0

  1059,24782(     1)       1.42 enq: TX - row lock contention        1.42
XO                   python2.7@host...u (TNS V1-V3)       9/176 [  5%]        6

— тут уже не очень понятно: нет связи между заблокированными сессиями и блокерами, отсутствует информация о CLIENT_IDENTIFIER, MODULE, ACTION (что может быть важно для OEBS систем, к примеру), о точном времени возникновения блокировок,…

Попробовал из тех же исходных для AWR отчёта данных (DBA_HIST_ACTIVE_SESS_HISTORY) сконструировать что-то более информативное, получился скрипт ASH_SQL_LOCK_HIST.SQL, позволяющий для начала просмотреть все блокировки, зафиксированные за период (по SNAP_ID), для чего скрипт запускается с условием «snap_id = 325800» и ограничением кол-ва ожиданий — не менее 10 — простой фильтр частоты ожиданий, чтобы не листать простыню:)

SQL> @ash_sql_lock_hist "snap_id = 325800" 10
 
INST#1 BLOCKED_CLIENT_ID          BLOCKED_SQL_ID CURRENT_OBJ#1                    WAITED_FOR                    BLOCKED_SIDS WAIT_COUNT MIN_WAITS_TIME MAX_WAITS_TIME INST#2 BLOCKING_CLIENT_ID        MODULE                                   ACTION BLOCKING_SQL_ID CURRENT_OBJ#2                    XID LOCK_TIME_LAG
------ -------------------------- -------------- -------------------------------- ----------------------------- ------------ ---------- -------------- -------------- ------ ------------------------- ---------------------------------------- ------ --------------- -------------------------------- --- -------------
     1 some_client_identifier_1#  73qhtmwmtat18  XO.T#000001                      enq: TX - row lock contention           14       1288 21.04 03:06:28 21.04 03:21:42      1 client_id_00002#          python2.7@host_3f.dbname.ru (TNS V1-V3)         2h6qwwngw190j   XO.SYS_C002106841                    -0 00:16:24
     1 some_client_identifier_1#  73qhtmwmtat18  XO.T#000001                      enq: TX - row lock contention           10        920 21.04 03:06:28 21.04 03:21:42      1 client_id_00002#          python2.7@host_1g.dbname.ru (TNS V1-V3)         66spdcvn07zjh   XO.T#000002_IDX_PARENT_00004_ID      -0 00:17:24
     1 client_id_00002#           1sw7txfkvp5zm  .                                enq: UL - contention                     7        432 21.04 03:00:47 21.04 03:29:53                                                                                                  .                                    
     1 some_client_identifier_1#  73qhtmwmtat18  XO.T#000001                      enq: TX - row lock contention            4        184 21.04 03:22:22 21.04 03:29:53      1 client_id_00002#          python2.7@host_2f.dbname.ru (TNS V1-V3)         0533kzj9ak9k8   XO.T#000002                      *   -0 00:08:52
     1 some_client_identifier_1#  73qhtmwmtat18  XO.T#000001                      enq: TX - row lock contention            3        108 21.04 03:00:47 21.04 03:06:38                                                                                                  .                                    
     1 some_client_identifier_1#  73qhtmwmtat18  XO.T#000001                      enq: TX - row lock contention            2         92 21.04 03:22:22 21.04 03:29:53      1 client_id_00002#          python2.7@host_1f.dbname.ru (TNS V1-V3)         70sf9jvynnnmg   .                                    -0 00:08:42
     2 (P...)                     7pkgg270tuhkt  XO.T#000002                      buffer busy waits                       15         74 21.04 03:03:15 21.04 03:05:56      2 (P...)                                                                    7pkgg270tuhkt   XO.T#000002                          +0 00:00:00
     1 client_id_00002#                          .                                log file sync                           54         71 21.04 03:00:57 21.04 03:29:53      1 (LGWR)                                                                                    .                                    -0 00:01:30
     2 (P...)                     7pkgg270tuhkt  XO.T#000002                      enq: SS - contention                    15         52 21.04 03:02:45 21.04 03:06:06      2 (P...)                                                                    7pkgg270tuhkt   XO.T#000002                          +0 00:00:00
     2 (P...)                     7pkgg270tuhkt  XO.T#002_TRANS                   buffer busy waits                       15         50 21.04 03:06:56 21.04 03:08:36      2 (P...)                                                                    7pkgg270tuhkt   XO.T#002_TRANS                       +0 00:00:00
     1 client_id_00002#           1sw7txfkvp5zm  .                                enq: UL - contention                     1         46 21.04 03:22:22 21.04 03:29:53      1 some_client_identifier_1# python2.7@host_1f.dbname.ru (TNS V1-V3)                         .                                    -0 00:08:01
     1 Notifier#                  5jm40cr1pn8xd  XO.T#000003_PK                   gc buffer busy acquire                  27         27 21.04 03:19:51 21.04 03:19:51      1 Notifier#                 python2.7@host_2e.dbname.ru (TNS V1-V3)         5jm40cr1pn8xd   XO.T#000003_PK                   *   +0 00:00:00
     1 Notifier#                  5jm40cr1pn8xd  .                                latch: cache buffers chains             21         26 21.04 03:06:08 21.04 03:18:31      1 Notifier#                 python2.7@host_1f.dbname.ru (TNS V1-V3)         5jm40cr1pn8xd   .                                *   +0 00:00:00
     1 some_client_identifier_1#                 .                                log file sync                           21         25 21.04 03:05:18 21.04 03:22:12      1 (LGWR)                                                                                    .                                    -0 00:00:20
     1 id0003#                                   .                                log file sync                           18         22 21.04 03:00:57 21.04 03:27:43      1 (LGWR)                                                                                    .                                    -0 00:02:10
     1 Notifier#                  5jm40cr1pn8xd  .                                latch: cache buffers chains             18         21 21.04 03:05:38 21.04 03:18:41      1 Notifier#                 python2.7@host_3e.dbname.ru (TNS V1-V3)         5jm40cr1pn8xd   .                                *   +0 00:00:00
     1 queue_processor#           5fu4gfd3t8ytd  XO.I_EXPORT_RATE_STATE_PRIORITY  gc buffer busy acquire                  20         20 21.04 03:01:07 21.04 03:01:07      1 queue_processor#          python2.7@host_1e.dbname.ru (TNS V1-V3)         5fu4gfd3t8ytd   XO.I_EXPORT_RATE_STATE_PRIORITY      +0 00:00:00
     1 Notifier#                  5jm40cr1pn8xd  .                                latch: cache buffers chains             14         19 21.04 03:05:38 21.04 03:18:31      1 Notifier#                 python2.7@host_1g.dbname.ru (TNS V1-V3)         5jm40cr1pn8xd   .                                *   +0 00:00:00
     2 (J...)                     9v6wmay96sk01  .                                cursor: pin S wait on X                 18         18 21.04 03:19:38 21.04 03:19:38      2 (J...)                                                                    9v6wmay96sk01   SYSTEM.DEF$_DESTINATION              +0 00:00:00
     1 Notifier#                  5jm40cr1pn8xd  .                                latch: cache buffers chains             15         17 21.04 03:06:08 21.04 03:22:42      1 Notifier#                 python2.7@host_2e.dbname.ru (TNS V1-V3)         5jm40cr1pn8xd   .                                *   -0 00:00:10
     1 Notifier#                                 XO.T_00004_PK2                   log file sync                           15         15 21.04 03:02:38 21.04 03:27:43      1 (LGWR)                                                                                    .                                    -0 00:01:00
     1 Notifier#                  5jm40cr1pn8xd  .                                latch: cache buffers chains             12         15 21.04 03:05:48 21.04 03:18:41      1 Notifier#                 python2.7@host_2g.dbname.ru (TNS V1-V3)         5jm40cr1pn8xd   .                                *   -0 00:00:10
     2 (LMS.)                                    .                                gcs log flush sync                       3         14 21.04 03:01:05 21.04 03:13:57      2 (LGWR)                                                                                    .                                    -0 00:02:20
     1 (SMON)                                    .                                local write wait                         1         14 21.04 03:02:48 21.04 03:08:39      1 (DBW.)                                                                                    .                                    -0 00:00:50
     1 Notifier#                  5jm40cr1pn8xd  .                                latch: cache buffers chains             12         13 21.04 03:05:58 21.04 03:18:31      1 Notifier#                 python2.7@host_3g.dbname.ru (TNS V1-V3)         5jm40cr1pn8xd   .                                *   +0 00:00:00
     1 Notifier#                  5jm40cr1pn8xd  XO.T#000002_IDX_PARENT_00004_ID  gc buffer busy acquire                  13         13 21.04 03:19:51 21.04 03:19:51      1 Notifier#                 python2.7@host_1f.dbname.ru (TNS V1-V3)         5jm40cr1pn8xd   XO.T#000002_IDX_PARENT_00004_ID  *   +0 00:00:00
     1 Notifier#                  5jm40cr1pn8xd  .                                latch: cache buffers chains             10         12 21.04 03:06:08 21.04 03:18:31      1 Notifier#                 python2.7@host_3f.dbname.ru (TNS V1-V3)         5jm40cr1pn8xd   .                                *   -0 00:00:10
     1 Notifier#                  5jm40cr1pn8xd  .                                latch: cache buffers chains             11         12 21.04 03:06:18 21.04 03:10:29      1 Notifier#                 python2.7@host_2f.dbname.ru (TNS V1-V3)         5jm40cr1pn8xd   .                                *   +0 00:00:00
     2 (P...)                     7pkgg270tuhkt  XO.T#002_INTERNAL                enq: SS - contention                    10         10 21.04 03:07:36 21.04 03:07:36      2 (P...)                                                                    7pkgg270tuhkt   XO.T#002_INTERNAL                    +0 00:00:00
 
29 rows selected

— из чего, кроме подтверждения факта, что основным блокирующим ожиданием за период было enq: TX — row lock contention, можно видеть другие случаи блокирования типа:

— LGWR блокирует пользовательские процессы на log file sync
— LGWR блокирует LMS-процессы на gcs log flush sync
— SMON блокируется DBWriter процессом на local write wait, и т.д…

Сессии/ожидания разделены на BLOCKED / BLOCKING: сначала выводятся данные заблокированных сессиях (INST#1, BLOCKED_CLIENT_ID, BLOCKED_SQL_ID CURRENT_OBJ#1,..), затем информация об ожиданиях (WAITED_FOR, BLOCKED_SIDS, WAIT_COUNT, MIN_WAITS_TIME, MAX_WAITS_TIME), и далее — данные блокеров (INST#2, BLOCKING_CLIENT_ID, MODULE, ACTION,..)

Информация о блокерах берется по принципу абсолютно ближайшего появления в ASH записи о блокирующей сессии с параметрами, совпадающими с указанными при блокировке BLOCKING_INST_ID, BLOCKING_SESSION, BLOCKING_SESSION_SERIAL#, при этом в поле XID отражается наличие в этот момент у блокирующей сессии открытой транзакции (польза от этого поля сомнительна), а в поле LOCK_TIME_LAG — минимальная удалённость (TIMESTAMP INTERVAL) блокирующей сессии от момента блокировки — что может быть полезно

Основным полезным свойством скрипта является информация о ENQEQE блокерах, активность которых не обязательно отражается в ASH (например, когда блокер висит на SQL*Net message from client)

Возвращаясь к первоначальной проблеме и зная основное блокирующее ожидание, можно уточнить запрос только для TX блокировок:

SQL> @ash_sql_lock_hist "event = 'enq: TX - row lock contention' and snap_id = 325800" 0
 
INST#1 BLOCKED_CLIENT_ID          BLOCKED_SQL_ID CURRENT_OBJ#1 WAITED_FOR                    BLOCKED_SIDS WAIT_COUNT MIN_WAITS_TIME MAX_WAITS_TIME INST#2 BLOCKING_CLIENT_ID MODULE                                   ACTION BLOCKING_SQL_ID CURRENT_OBJ#2                    XID LOCK_TIME_LAG
------ -------------------------- -------------- ------------- ----------------------------- ------------ ---------- -------------- -------------- ------ ------------------ ---------------------------------------- ------ --------------- -------------------------------- --- -------------
     1 some_client_identifier_1#  73qhtmwmtat18  XO.T#000001   enq: TX - row lock contention           14       1288 21.04 03:06:28 21.04 03:21:42      1 client_id_00002#   python2.7@host_3f.dbname.ru (TNS V1-V3)         2h6qwwngw190j   XO.SYS_C002106841                    -0 00:16:24
     1 some_client_identifier_1#  73qhtmwmtat18  XO.T#000001   enq: TX - row lock contention           10        920 21.04 03:06:28 21.04 03:21:42      1 client_id_00002#   python2.7@host_1g.dbname.ru (TNS V1-V3)         66spdcvn07zjh   XO.T#000002_IDX_PARENT_00004_ID      -0 00:17:24
     1 some_client_identifier_1#  73qhtmwmtat18  XO.T#000001   enq: TX - row lock contention            4        184 21.04 03:22:22 21.04 03:29:53      1 client_id_00002#   python2.7@host_2f.dbname.ru (TNS V1-V3)         0533kzj9ak9k8   XO.T#000002                      *   -0 00:08:52
     1 some_client_identifier_1#  73qhtmwmtat18  XO.T#000001   enq: TX - row lock contention            3        108 21.04 03:00:47 21.04 03:06:38                                                                                           .                                    
     1 some_client_identifier_1#  73qhtmwmtat18  XO.T#000001   enq: TX - row lock contention            2         92 21.04 03:22:22 21.04 03:29:53      1 client_id_00002#   python2.7@host_1f.dbname.ru (TNS V1-V3)         70sf9jvynnnmg   .                                    -0 00:08:42
     1 process_completions#       0v9hzfun2nz9y  XO.T_00004    enq: TX - row lock contention            2          2 21.04 03:01:07 21.04 03:02:07      1 client_id_00002#   python2.7@host_3f.dbname.ru (TNS V1-V3)         0533kzj9ak9k8   XO.T#000002_IDX_PARENT_00004_ID  *   +0 00:01:50
     2 Simple#                    a1c2ggqq3thrw  BS.T_0000005  enq: TX - row lock contention            1          1 21.04 03:10:06 21.04 03:10:06      2 Simple#            python2.7@host_2e.dbname.ru (TNS V1-V3)         0rwjvwcz6dfsf   XS.SYS_C001741747                *   +0 00:00:00
     1 process_completions#       0v9hzfun2nz9y  XO.T_00004    enq: TX - row lock contention            1          1 21.04 03:16:51 21.04 03:16:51      1 client_id_00002#   python2.7@host_1e.dbname.ru (TNS V1-V3)         dxsshday3jyh9   XO.T#000002                          -0 00:00:30
     2 (J...)                     czbjavaavnum5  .             enq: TX - row lock contention            1          1 21.04 03:19:38 21.04 03:19:38      2 (J...)                                                             9f0j8pj4fvj7h   .                                *   +0 00:00:00
 
9 rows selected

— конкретизирующую проблему до CLIENT_IDENTIFIER и имён хостов / MODULE, ACTION и SQL_ID блокирующих сессий — если повезёт)

Соответствующий скрипт для текущей ASH — ASH_SQL_LOCK.SQL:

SQL> @sysdate
 
SYSDATE
-------------------
24.04.2016 19:37:07
 
SQL> @ash_sql_lock "sample_time > sysdate-1/24" 100
 
INST#1 BLOCKED_CLIENT_ID         BLOCKED_SQL_ID CURRENT_OBJ#1 WAITED_FOR                          BLOCKED_SIDS WAIT_COUNT MIN_WAITS_TIME MAX_WAITS_TIME INST#2 BLOCKING_CLIENT_ID                      MODULE                                   ACTION BLOCKING_SQL_ID CURRENT_OBJ#2 XID LOCK_TIME_LAG
------ ------------------------- -------------- ------------- ----------------------------------- ------------ ---------- -------------- -------------- ------ --------------------------------------- ---------------------------------------- ------ --------------- ------------- --- -------------
     1 some_client_identifier_1# 73qhtmwmtat18  XO.T#000001   enq: TX - row lock contention                 10       7211 24.04 18:41:22 24.04 19:37:11                                                                                                                .                 
     1 client_id_00002#          1sw7txfkvp5zm  .             enq: UL - contention                           4       2659 24.04 18:41:23 24.04 19:37:11                                                                                                                .                 
     1 client_id_00002#          1sw7txfkvp5zm  .             enq: UL - contention                           1        957 24.04 19:05:17 24.04 19:21:15      1 python2.7@host_3f.dbname.ru (TNS V1-V3) python2.7@host_3f.dbname.ru (TNS V1-V3)         05uqdabhzncdc   .                 -0 00:16:01
     1 id0003#                                  .             log file sync                                311        423 24.04 18:37:21 24.04 19:37:06      1 (LGWR)                                                                                                  .                 -0 00:01:11
     1 some_client_identifier_1#                .             log file sync                                168        332 24.04 18:40:19 24.04 19:35:45      1 (LGWR)                                                                                                  .                 -0 00:00:31
     1 Notifier#                                .             log file sync                                159        214 24.04 18:37:33 24.04 19:36:58      1 (LGWR)                                                                                                  .                 -0 00:01:03
     1 Notifier#                                .             gcs drm freeze in enter server mode           98        165 24.04 18:49:48 24.04 19:29:54      1 (LMON)                                                                                                  .                 -0 00:00:01
 
7 rows selected

не показывает блокеров для многочисленных ENQUEUE блокировок, но эти блокировки текущие и за ними можно понаблюдать runtime-скриптом LOCK_TREE_LOCAL.SQL, например:

SQL> @lock_tree_local
 
BLOCKING_TREE        PROGRAM                                  USERNAME                      EVENT                         LAST_CALL_ET SECS_IN_WAIT BLOCK_SESSTAT PDML_ENABLED SQL_ID        OSUSER SPID  CLNT_HOST          CLNT_PID  CLNT_PORT SQL_TEXT REQ_ROWID
-------------------- ---------------------------------------- ----------------------------- ----------------------------- ------------ ------------ ------------- ------------ ------------- ------ ----- ------------------ -------- ---------- -------- ------------------
INST#1 SID#2053      python2.7@host_3e.dbname.ru (TNS V1-V3)  XO client_id_00002#           SQL*Net message from client            433          433 NO HOLDER     NO                         gt     9467  host_3e.dbname.ru  11041         46659 SELECT T AAIhgjAB0AANOQLAAA
  INST#1 SID#3271    python2.7@host_3e.dbname.ru (TNS V1-V3)  XO some_client_identifier_1#  enq: TX - row lock contention          434          434 VALID         NO           73qhtmwmtat18 gt     9706  host_3e.dbname.ru  10997         46876 MERGE IN AAIhftACFAAHK6OAA/
  INST#1 SID#496     python2.7@host_3e.dbname.ru (TNS V1-V3)  XO some_client_identifier_1#  enq: TX - row lock contention          433          433 VALID         NO           73qhtmwmtat18 gt     9749  host_3e.dbname.ru  10995         46964 MERGE IN AAIhftACFAAHK6OAA/
INST#1 SID#1851      python2.7@host_3e.dbname.ru (TNS V1-V3)  XO client_id_00002#           SQL*Net message from client            434          434 NO HOLDER     NO                         gt     9464  host_3e.dbname.ru  11040         46656 SELECT T AAIhgjAB0AANOQJAAA
  INST#1 SID#2724    python2.7@host_3e.dbname.ru (TNS V1-V3)  XO some_client_identifier_1#  enq: TX - row lock contention          434          434 VALID         NO           73qhtmwmtat18 gt     9701  host_3e.dbname.ru  10996         46871 MERGE IN AAIhftACEAAMhOZAA0
  INST#1 SID#2317    python2.7@host_3e.dbname.ru (TNS V1-V3)  XO some_client_identifier_1#  enq: TX - row lock contention          434          434 VALID         NO           73qhtmwmtat18 gt     9686  host_3e.dbname.ru  11000         46857 MERGE IN AAIhftACEAAMhOZAA0

— вплоть до ROWID и OSUSER, CLNT_HOST, CLNT_PID, CLNT_PORT клиентского соединения

С другой стороны, скрипт позволяет мониторить не только enqueue блокировки:

SQL> @ash_sql_lock "sample_time > sysdate-1/24" 100
 
INST#1 BLOCKED_CLIENT_ID          BLOCKED_SQL_ID WAITED_FOR                          BLOCKED_SIDS WAIT_COUNT MIN_WAITS_TIME MAX_WAITS_TIME INST#2 BLOCKING_CLIENT_ID MODULE                                   ACTION                         BLOCKING_SQL_ID CURRENT_OBJ#2           XID LOCK_TIME_LAG
------ -------------------------- -------------- ----------------------------------- ------------ ---------- -------------- -------------- ------ ------------------ ---------------------------------------- ------------------------------ --------------- ----------------------- --- -------------
     1 some_client_identifier_1#  73qhtmwmtat18  enq: TX - row lock contention                 30      24259 25.04 16:43:05 25.04 17:35:48                                                                                                                   .                           
     2 (P...)                     337zmt20uw186  cursor: pin S wait on X                      129       5391 25.04 16:59:45 25.04 17:08:19      2 (P...)             APEX/APEX:APP 106:24                     Processes - point: BEFORE_BOX  337zmt20uw186   .                           +0 00:00:00
     1 client_id_00002#           1sw7txfkvp5zm  enq: UL - contention                           5       4231 25.04 16:43:05 25.04 17:40:44                                                                                                                   .                           
     1 some_client_identifier_1#  73qhtmwmtat18  enq: TX - row lock contention                  1        915 25.04 17:25:29 25.04 17:40:45      1 client_id_00002#   python2.7@host_1f.dbname.ru (TNS V1-V3)                                 awr850u08k4yc   XO.I_EXPORT_NEXT_EXPORT *   +0 00:00:00
     1 some_client_identifier_1#                 log file sync                                279        892 25.04 16:45:27 25.04 17:40:24      1 (LGWR)                                                                                                     .                           -0 00:00:21
     1 id0003#                                   log file sync                                431        561 25.04 16:43:30 25.04 17:42:41      1 (LGWR)                                                                                                     .                           -0 00:00:53
     1 Notifier#                                 log file sync                                227        337 25.04 16:44:04 25.04 17:41:57      1 (LGWR)                                                                                                     .                           -0 00:00:22
     1 (J...)                     9f0j8pj4fvj7h  gc buffer busy acquire                        14        308 25.04 16:55:08 25.04 16:55:39      1 (J...)                                                                                     9f0j8pj4fvj7h   SYS.CDEF$               *   +0 00:00:00
     1 (J...)                     9f0j8pj4fvj7h  gc buffer busy acquire                        10        250 25.04 16:55:08 25.04 16:55:39      1 (J...)                                                                                     9f0j8pj4fvj7h   SYS.CDEF$               *   +0 00:00:00
     2 (LMS.)                                    gcs log flush sync                             3        190 25.04 16:43:45 25.04 17:43:01      2 (LGWR)                                                                                                     .                           -0 00:01:13
     1 Notifier#                                 gcs drm freeze in enter server mode           87        185 25.04 16:52:20 25.04 17:42:35      1 (LMON)                                                                                                     .                           -0 00:00:01
     1 (LMS.)                                    gcs log flush sync                             3        152 25.04 16:44:15 25.04 17:41:13      1 (LGWR)                                                                                                     .                           -0 00:00:24
     1 (LGWR)                                    LGWR any worker group                          1        112 25.04 16:43:30 25.04 17:41:48      1 (LG..)                                                                                                     .                           +0 00:00:00

— на втором месте заметен проблемный запрос 337zmt20uw186* с множеством ожиданий cursor: pin S wait on X параллельных slave процессов (P…) — но эти блокировки синхронные (в смысле совпадения времени ASH записей блокера и блокирующего) и хорошо фиксируются другими инструментами, а вот для асинхронных (LOCK_TIME_LAG != 0) блокировок log file sync, gcs log flush sync,… скрипт, как и для enqueue блокировок, может быть очень даже полезен

*) запрос этот выполнялся с несколькими планами разной степени успешности и испытывал конкуренцию (CONC_PER_EXEC) по причинам (возможно, избыточного) параллельного (PARSES_PER_EXEC) выполнения:

SQL> @v$sqlstats2 337zmt20uw186
 
--------------------------------------------------------------
SQL_ID=337zmt20uw186 Shared Pool statistics by PLAN_HASH_VALUE
--------------------------------------------------------------
 
INST EXECS LAST_ACTIVE_TIME    ELA_PER_EXEC CPU_PER_EXEC PARSES_PER_EXEC GETS_PER_EXEC READS_PER_EXEC UIO_PER_EXEC CONC_PER_EXEC CLU_PER_EXEC PLSQL_PER_EXEC FETCH_PER_EXEC ROWS_PER_EXEC PLAN_HASH_VALUE FULL_PLAN_HASH_VALUE AVG_CBO_COST     CHILDS BIND_SENSE BIND_AWARE REOPT ADAPT SQL_PLAN_BASELINE SQL_PATCH OUTLINE_CATEGORY SQL_PROFILE
---- ----- ------------------- ------------ ------------ --------------- ------------- -------------- ------------ ------------- ------------ -------------- -------------- ------------- --------------- -------------------- ------------ ---------- ---------- ---------- ----- ----- ----------------- --------- ---------------- -----------
   1     0 25.04.2016 11:24:22    461141218    405347000              27     204803882        2464454     46769921       6428408      5122886              0              0             0      1416607241           3036451826        82090          1 N          N          N     N                                                  
   2     1 25.04.2016 13:26:10     76835117     10227000             102       1837024           8775       503731      66920706       177013              0              1            75      1046418063            658730756        90756          3 N          N          Y     N                                                  
   2     8 25.04.2016 15:39:47    167275942     14663000              83       2993181          28161      2893227     150010425      1747260          39390              1             5      1416607241           3036451826        82083         29 N          N          Y     N                                                  
   2     2 25.04.2016 15:40:41     41141772      6802500              53       1114518           3222       679116      33819190       213486              0              1             3      1940027346           1831466370        82623          4 N          N          Y     N                                                  
   2     1 25.04.2016 17:01:32    434525005     56630000              70       6386460        3745248    268591148     110549056       505167              0              1          6986      2817525490           4051642748        82042          3 N          N          Y     N                                                                       
 
SQL> @shared_cu12s_noxml 337zmt20uw186 0
 
INST_ID PLAN_HASH_VALUE OPTIMIZER_MODE LAST_ACTIVE_TIME    BIND_SENSE BIND_AWARE FEEDBACK_STATS REOPT ADAPT PQ_SLAVE_MISMATCH REASON#1                REASON#2                    FIX_CONTROL#1          CURSOR_COUNT  PHV_COUNT FPHV_COUNT EXECS USERS_OPENING
------- --------------- -------------- ------------------- ---------- ---------- -------------- ----- ----- ----------------- ----------------------- --------------------------- ---------------------- ------------ ---------- ---------- ----- -------------
      2      1416607241 ALL_ROWS       25.04.2016 13:03:39 N          N          N              N           Y                 PQ Slave mismatch(2)    Optimizer mismatch(12)      -2122921431          0           16          1          1     0             0
      2      1416607241 ALL_ROWS       25.04.2016 15:39:47 N          N          Y              Y           N                 Optimizer mismatch(12)  Different Call Duration(0)  -2122921431          0            6          1          1     6             0
      2      1416607241 ALL_ROWS       25.04.2016 15:39:47 N          N          N              N           N                 PQ Slave mismatch(2)    Optimizer mismatch(12)      -2122921431          0            5          1          1     0             0
      2      1416607241 ALL_ROWS       25.04.2016 13:01:33 N          N          N              N           N                 Optimizer mismatch(12)  Different Call Duration(0)  -2122921431          0            2          1          1     2             0
      2      2817525490 ALL_ROWS       25.04.2016 17:01:32 N          N          N              N           Y                 PQ Slave mismatch(2)    Optimizer mismatch(12)      -2122921431          0            2          1          1     0             0
      2      1940027346 ALL_ROWS       25.04.2016 15:40:41 N          N          Y              Y           N                 Optimizer mismatch(12)  Different Call Duration(0)  -2122921431          0            2          1          1     2             0
      2      1940027346 ALL_ROWS       25.04.2016 15:40:41 N          N          N              N           Y                 PQ Slave mismatch(2)    Optimizer mismatch(12)      -2122921431          0            2          1          1     0             0
      1      1416607241 ALL_ROWS       25.04.2016 11:24:22 N          N          N              N           N                                                                                                       1          1          1     0             0
      2      1046418063 ALL_ROWS       25.04.2016 13:26:10 N          N          N              N           N                 PQ Slave mismatch(2)    Optimizer mismatch(12)      -2122921431          0            1          1          1     0             0
      2      2817525490 ALL_ROWS       25.04.2016 14:35:35 N          N          Y              Y           N                 Optimizer mismatch(12)  Different Call Duration(0)  -2122921431          0            1          1          1     1             0
      2      1046418063 ALL_ROWS       25.04.2016 13:23:31 N          N          N              N           Y                 PQ Slave mismatch(2)    Optimizer mismatch(12)      -2122921431          0            1          1          1     0             0
      2      1046418063 ALL_ROWS       25.04.2016 13:26:10 N          N          Y              Y           N                 Optimizer mismatch(12)  Different Call Duration(0)  -2122921431          0            1          1          1     1             0

— что подтверждается учащённым REASON#1 = PQ Slave mismatch(2), в дополнении к Statistics Feedback (FEEDBACK_STATS + REOPT + Optimizer mismatch(12)), а судя по ненулевому содержимому FIX_CONTROL#1 в последнем выводе (12c: hardcoded подсказка _fix_control и новая проблема High Version Count) запрос ещё и использует подсказки OPT_PARAM(‘_fix_control’…) в тексте, что и подтверждает текст запроса:

SQL> select sql_fulltext from gv$sqlarea where sql_id = '337zmt20uw186';

...SELECT /*+  PARALLEL(6)  OPT_PARAM('_fix_control' '8571403:0')  */...

— «цели ясны, задачи определены», в смысле, найденная проблема/задача — из области SQL Plan Management

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

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

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 такие блоггеры, как: