Oracle mechanics

06.05.2016

Кластерные ожидания внутри одного инстанса RAC и количество LMS-процессов

Filed under: Active Session History,Oracle,RAC,SGA — Игорь Усольцев @ 12:48
Tags:

Краткосрочный всплеск ожиданий типа Cluster:

Top 5 Foreground Events by Total Wait Time
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
                                           Total Wait       Wait   % DB Wait    
Event                                Waits Time (sec)    Avg(ms)   time Class   
------------------------------ ----------- ---------- ---------- ------ --------
gc buffer busy acquire           1,157,219      59.3K      51.23   42.6 Cluster  
gc cr grant 2-way                2,838,562      24.8K       8.72   17.8 Cluster 
gc current grant busy              382,881      11.5K      30.05    8.3 Cluster 
DB CPU                                          10.6K               7.6         
gc current grant 2-way             141,095     8458.2      59.95    6.1 Cluster

был вызван сформирован* в бОльшей части двумя SQL с типом команд SELECT (без FOR UPDATE), выполнявшимися на 2-м инстансе:

12.1.0.2@ SQL> @ash_sql_wait_tree "wait_class = 'Cluster'" 100 "where sample_time between to_date('19-APR-16 12.00.00','dd-mon-yy hh24.mi.ss') and to_date('19-APR-16 12.15.00','dd-mon-yy hh24.mi.ss')"
 
LVL INST_ID BLOCKING_TREE EVENT                     WAIT_CLASS WAITS_COUNT EXECS_COUNT AVG_WA SESS_COUNT DATA_OBJECT                    BLOCK_SID   MIN_STIME          MAX_STIME          SQL_OPNAME SQL_ID        TOP_LEVEL_SQL_ID SQL_PLAN_HASH_VALUE SQL_TEXT
--- ------- ------------- ------------------------- ---------- ----------- ----------- ------ ---------- ------------------------------ ----------- ------------------ ------------------ ---------- ------------- ---------------- ------------------- --------
  1       2 (USER)        gc buffer busy acquire    Cluster          32010        2739    997        927 U1.T#0000001_PK.               VALID i#2   19-APR-16 12.06.48 19-APR-16 12.11.16 SELECT     g9pjrdmbmqad5 g9pjrdmbmqad5              630930070 SELECT c
  1       2 (USER)        gc buffer busy acquire    Cluster           8351         748    786        533 U1.T#0000001_PK.               VALID i#2   19-APR-16 12.06.29 19-APR-16 12.11.17 SELECT     3mggnx6a2hagk 3mggnx6a2hagk             1893405434 SELECT t
  1       1 (USER)        gc cr multi block request Cluster           2973         955    178        272 U1.MV_00000_000000_00002.      UNKNOWN i#  19-APR-16 12.05.38 19-APR-16 12.11.35 SELECT     fyr519kqh6afs fyr519kqh6afs             3067871324 SELECT t
  1       2 (USER)        gc current grant busy     Cluster           1759         225    995        152 U2.I_00003_SERVICE_PRODUCT_ID. GLOBAL i#   19-APR-16 12.05.46 19-APR-16 12.11.35 INSERT     46nsws06ax5sr 46nsws06ax5sr             3585387344 INSERT I
...

Формально проблемы этих 2-х запросов были локализованы в промежутке 12:06:29 — 12:11:17 когда эти два SELECT-а блокировали, в основном, друг друга:

SQL> @ash_sql_wait_tree_temp "event = 'gc buffer busy acquire' and sql_id in ('g9pjrdmbmqad5','3mggnx6a2hagk')" 0 "where sample_time between to_date('19-APR-16 12.06.00','dd-mon-yy hh24.mi.ss') and to_date('19-APR-16 12.12.00','dd-mon-yy hh24.mi.ss')" 0
 
LVL INST_ID BLOCKING_TREE EVENT                   WAIT_CLASS WAITS_COUNT EXECS_COUNT AVG_WA SESS_COUNT DATA_OBJECT        BLOCK_SID   MIN_STIME           MAX_STIME           SQL_OPNAME SQL_ID        SQL_PLAN_HASH_VALUE SQL_TEXT
--- ------- ------------- ----------------------- ---------- ----------- ----------- ------ ---------- ------------------ ----------- ------------------- ------------------- ---------- ------------- ------------------- --------
  1       2 (USER)        gc buffer busy acquire  Cluster          32010        2739    997        927 U1.T#0000001_PK.   VALID i#2   19-APR-16 12.06.48  19-APR-16 12.11.16  SELECT     g9pjrdmbmqad5           630930070 SELECT c
  1       2 (USER)        gc buffer busy acquire  Cluster           8351         748    786        533 U1.T#0000001_PK.   VALID i#2   19-APR-16 12.06.29  19-APR-16 12.11.17  SELECT     3mggnx6a2hagk          1893405434 SELECT t
  1       2 (USER)        gc buffer busy acquire  Cluster            123          48    883         48 U1.T#000004_PK.    VALID i#2   19-APR-16 12.08.26  19-APR-16 12.10.28  SELECT     g9pjrdmbmqad5           630930070 SELECT c
  1       2 (USER)        gc buffer busy acquire  Cluster              3           3    564          3 U1.T#0000001_PK.   UNKNOWN i#  19-APR-16 12.11.18  19-APR-16 12.11.18  SELECT     3mggnx6a2hagk          1893405434 SELECT t
  1       2 (USER)        gc buffer busy acquire  Cluster              3           3      0          3 U1.T#0000001_PK.   UNKNOWN i#  19-APR-16 12.08.28  19-APR-16 12.09.52  SELECT     g9pjrdmbmqad5           630930070 SELECT c
  2       2   (USER)      gc cr grant 2-way       Cluster         109888          15   1137         14 U1.T#0000001_PK.   UNKNOWN i#  19-APR-16 12.06.28  19-APR-16 12.11.17  SELECT     3mggnx6a2hagk          1893405434 SELECT t
  2       2   (USER)      gc cr grant 2-way       Cluster           5885          10   1262          9 U1.T#0000001_PK.   UNKNOWN i#  19-APR-16 12.06.47  19-APR-16 12.10.59  SELECT     g9pjrdmbmqad5           630930070 SELECT c
  2       2   (USER)      gc cr request           Cluster            275           2      0          2 U1.T#0000001_PK.   UNKNOWN i#  19-APR-16 12.09.56  19-APR-16 12.10.19  SELECT     3mggnx6a2hagk          1893405434 SELECT t
...
  3       2     (USER)    gc cr grant 2-way       Cluster             34           3   7821          3 U1.T#0000001_PK.   UNKNOWN i#  19-APR-16 12.09.54  19-APR-16 12.11.16  SELECT     3mggnx6a2hagk          1893405434 SELECT t
  3       2     (USER)    gc cr grant 2-way       Cluster             30           1    821          1 ..                 UNKNOWN i#  19-APR-16 12.10.29  19-APR-16 12.10.29  INSERT     8matphjwpgg7k          3315836126 INSERT I
  3       2     (USER)    gc current grant busy   Cluster             30           1    738          1 ..                 GLOBAL i#   19-APR-16 12.10.30  19-APR-16 12.10.30  INSERT     8matphjwpgg7k          3315836126 INSERT I
  3       2     (USER)    gc cr grant 2-way       Cluster             13           1   3876          1 U1.T#0000001_PK.   UNKNOWN i#  19-APR-16 12.07.53  19-APR-16 12.07.56  SELECT     g9pjrdmbmqad5           630930070 SELECT c
  3       2     (USER)    gc cr grant 2-way       Cluster              9           2      0          2 U1.T#000004_PK.    UNKNOWN i#  19-APR-16 12.09.35  19-APR-16 12.10.21  SELECT     4070v7j7ypfg5          4193855473 SELECT t
  3       2     (USER)    gc cr grant 2-way       Cluster              2           1      0          1 U1.SYS_C001075911. UNKNOWN i#  19-APR-16 12.09.22  19-APR-16 12.09.23  SELECT     bv6m76wdmfb2j           735916521 SELECT t

Основная конкуренция при этом наблюдалась на ожиданиях gc buffer busy acquire и gc cr grant 2-way и локализовалась в районе DBA file#=33 block#=18:

SQL> select event, current_obj#, current_file#, current_block#, current_row#, p1text, p1, p2text, p2,
  2         count(*)
  3    from gv$active_session_history
  4   where inst_id = 2
  5     and sample_time between
  6         to_date('19-APR-16 12.06.00', 'dd-mon-yy hh24.mi.ss') and
  7         to_date('19-APR-16 12.12.00', 'dd-mon-yy hh24.mi.ss')
  8     and event in ('gc buffer busy acquire', 'gc cr grant 2-way')
  9     and wait_class = 'Cluster'
 10     and sql_id in ('g9pjrdmbmqad5', '3mggnx6a2hagk')
 11   group by event, current_obj#, current_file#, current_block#, current_row#, p1text, p1, p2text, p2
 12  having count(*) > 25
 13   order by count(*) desc
 14  /
 
EVENT                  CURRENT_OBJ# CURRENT_FILE# CURRENT_BLOCK# CURRENT_ROW# P1TEXT  P1 P2TEXT         P2   COUNT(*)
---------------------- ------------ ------------- -------------- ------------ ------- -- ------ ---------- ----------
gc buffer busy acquire         4065            33             18            0 file#   33 block#         18      40114
gc buffer busy acquire         5988            30         849619            0 file#   30 block#     849619        123
gc cr grant 2-way              4065            33             18            0         33                18         98
gc buffer busy acquire         4065            32         560323            0 file#   32 block#     560323         72
gc cr grant 2-way              4065            30        3873236            0         30           3873236         26

, являющегося index root block первичного ключа OLTP таблицы:

SQL> SELECT header_file, header_block+1 as INDEX_ROOT_BLOCK FROM dba_segments WHERE segment_name='T#0000001_PK';
 
HEADER_FILE INDEX_ROOT_BLOCK
----------- ----------------
         33               18

с частыми и быстрыми DML типа INSERT / UPDATE:

SQL> @v$sqlstats2 27ac18cjnjqct 0 -- INSERT INTO t#0000001...
 
--------------------------------------------------------------
SQL_ID=27ac18cjnjqct Shared Pool statistics by PLAN_HASH_VALUE
--------------------------------------------------------------
 
INST  EXECS LAST_LOAD_TIME       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
---- ------ -------------------- ------------------- ------------ ------------ --------------- ------------- -------------- ------------ ------------- ------------ -------------- -------------- ------------- --------------- -------------------- ------------ ------ ---------- ---------- ----- ----- ----------------- --------- ---------------- -----------
   2  33243 2016-04-19/07:23:49  19.04.2016 18:16:07         2318          574               1            26              1          934            10          756              0              0             1      2908605169            415290653            1      4 N          N          N     N
 
SQL> @v$sqlstats2 dvwn5yaz5sjuk 0 -- UPDATE t#0000001...
 
--------------------------------------------------------------
SQL_ID=dvwn5yaz5sjuk Shared Pool statistics by PLAN_HASH_VALUE
--------------------------------------------------------------
 
INST  EXECS LAST_LOAD_TIME       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
---- ------ -------------------- ------------------- ------------ ------------ --------------- ------------- -------------- ------------ ------------- ------------ -------------- -------------- ------------- --------------- -------------------- ------------ ------ ---------- ---------- ----- ----- ----------------- --------- ---------------- -----------
   2 403592 2016-04-19/08:00:39  19.04.2016 18:16:55          114           42               1             4              0            1             0            0              0              0             1      3528182018           1316175699            3      2 Y          N          N     N

, не оставившими следов в DBA_HIST_SQLSTAT, и стало быть не испытавшими заметного замедления в проблемный период

При этом указанные кластерные ожидания В ЦЕЛОМ также испытали всплеск в строго ограниченный промежуток времени:

SQL> select inst_id, trunc(sample_time, 'mi'), count(*)
  2    from gv$active_session_history
  3   where wait_class = 'Cluster'
  4     and sample_time between
  5         to_date('19-APR-16 12.00.00', 'dd-mon-yy hh24.mi.ss') and
  6         to_date('19-APR-16 12.15.00', 'dd-mon-yy hh24.mi.ss')
  7   group by inst_id, trunc(sample_time, 'mi')
  8   order by inst_id, trunc(sample_time, 'mi')
  9  /
 
INST_ID TRUNC(SAMPLE_TIME,'MI')   COUNT(*)
------- ----------------------- ----------
      1 19.04.2016 12:00:00            118
      1 19.04.2016 12:01:00             71
      1 19.04.2016 12:02:00             70
      1 19.04.2016 12:03:00             70
      1 19.04.2016 12:04:00             80
      1 19.04.2016 12:05:00            661
      1 19.04.2016 12:06:00           4058 -- на 1-м инстансе меньший
      1 19.04.2016 12:07:00           5901
      1 19.04.2016 12:08:00           5758
      1 19.04.2016 12:09:00           5856
      1 19.04.2016 12:10:00           6868
      1 19.04.2016 12:11:00           4528
      1 19.04.2016 12:12:00             98
      1 19.04.2016 12:13:00             52
      1 19.04.2016 12:14:00            118
      2 19.04.2016 12:00:00             31
      2 19.04.2016 12:01:00             24
      2 19.04.2016 12:02:00             28
      2 19.04.2016 12:03:00             30
      2 19.04.2016 12:04:00             95
      2 19.04.2016 12:05:00            631
      2 19.04.2016 12:06:00           3920
      2 19.04.2016 12:07:00          11662 -- на 2-м инстансе бОльший
      2 19.04.2016 12:08:00          14954
      2 19.04.2016 12:09:00          31898
      2 19.04.2016 12:10:00          35449
      2 19.04.2016 12:11:00          12827
      2 19.04.2016 12:12:00            233
      2 19.04.2016 12:13:00            227
      2 19.04.2016 12:14:00            191
 
30 rows selected

С другой стороны из процессов типа BACKGROUND в тот же период самым задействоваными оказались процессы 2-го инстанса вообще и LMS — в особенности:

SQL> @ash_sql_wait_tree_temp "session_type = 'BACKGROUND'" 0 "where sample_time between to_date('19-APR-16 12.06.00','dd-mon-yy hh24.mi.ss') and to_date('19-APR-16 12.12.00','dd-mon-yy hh24.mi.ss')" 0
 
LVL INST_ID BLOCKING_TREE EVENT                         WAIT_CLASS WAITS_COUNT EXECS_COUNT AVG_WA SESS_COUNT DATA_OBJECT BLOCK_SID       MIN_STIME                  MAX_STIME                  SQL_OPNAME  SQL_ID        TOP_LEVEL_SQL_ID SQL_PLAN_HASH_VALUE SQL_TEXT
--- ------- ------------- ----------------------------- ---------- ----------- ----------- ------ ---------- ----------- --------------- -------------------------- -------------------------- ----------- ------------- ---------------- ------------------- --------
  1       2 (LMS.)        On CPU / runqueue                                960           0      0          3 ..          NOT IN WAIT i#  19-APR-16 12.06.00.276 PM  19-APR-16 12.11.58.672 PM                                                               0 
  1       2 (M...)        gc current grant busy         Cluster             81           9   1057          9 ..          GLOBAL i#       19-APR-16 12.06.57.422 PM  19-APR-16 12.11.00.462 PM  INSERT      2g9g42n7afpfs 2g9g42n7afpfs             2051770604 
  1       2 (ARC.)        control file sequential read  System I/O          75           0     80          5 ..          UNKNOWN i#      19-APR-16 12.11.14.512 PM  19-APR-16 12.11.52.662 PM                                                               0 
  1       2 (LG..)        log file parallel write       System I/O          67           0     58          2 ..          NO HOLDER i#    19-APR-16 12.06.03.276 PM  19-APR-16 12.11.59.672 PM                                                               0 
...

, которые в свою очередь показывали логичную классическую карту блокировок:

SQL> @ash_sql_wait_tree_temp "inst_id = 2 and program like 'oracle@host-db_f.dbdomain.ru (LMS%'" 0 "where sample_time between to_date('19-APR-16 12.06.00','dd-mon-yy hh24.mi.ss') and to_date('19-APR-16 12.12.00','dd-mon-yy hh24.mi.ss')"
 
LVL INST_ID BLOCKING_TREE EVENT                    WAIT_CLASS WAITS_COUNT EXECS_COUNT AVG_WA SESS_COUNT DATA_OBJECT      BLOCK_SID       MIN_STIME           MAX_STIME           SQL_OPNAME SQL_ID        SQL_PLAN_HASH_VALUE SQL_TEXT
--- ------- ------------- ------------------------ ---------- ----------- ----------- ------ ---------- ---------------- --------------- ------------------- ------------------- ---------- ------------- ------------------- ------------------------------
  1       2 (LMS.)        On CPU / runqueue                           960           0      0          3 ..               NOT IN WAIT i#  19-APR-16 12.06.00  19-APR-16 12.11.58                                             0 
  1       2 (LMS.)        gcs log flush sync       Other               16           0      2          3 ..               VALID i#2       19-APR-16 12.07.42  19-APR-16 12.11.59                                             0 
  2       2   (LGWR)      LGWR any worker group    Other               14           0    162          1 ..               VALID i#2       19-APR-16 12.11.24  19-APR-16 12.11.59                                             0 
  2       2   (LGWR)      target log write size    Other               11           0      5          1 ..               NO HOLDER i#    19-APR-16 12.11.36  19-APR-16 12.11.58                                             0 
  3       2     (LG..)    log file parallel write  System I/O          24           0    126          1 ..               NO HOLDER i#    19-APR-16 12.11.24  19-APR-16 12.11.59                                             0 
  3       2     (LG..)    On CPU / runqueue                             6           0      0          1 ..               NOT IN WAIT i#  19-APR-16 12.11.38  19-APR-16 12.11.42                                             0 
  3       2     (LG..)    LGWR wait for redo copy  Other                3           0      6          1 ..               VALID i#2       19-APR-16 12.11.36  19-APR-16 12.11.36                                             0 
  4       2       (J...)  gc current grant busy    Cluster              3           1    175          1 U1.MV#00000006.  GLOBAL i#       19-APR-16 12.11.35  19-APR-16 12.11.35  DELETE     57zs3144d5tgc           533047381 delete from "U1"."MV#00000006"
  4       2       (J...)  On CPU / runqueue                             3           1      0          1 ..               NOT IN WAIT i#  19-APR-16 12.11.36  19-APR-16 12.11.36  DELETE     57zs3144d5tgc           533047381 delete from "U1"."MV#00000006"
  4       2       (J...)  On CPU / runqueue                             3           1      0          1 U1.MV#00000006.  NOT IN WAIT i#  19-APR-16 12.11.37  19-APR-16 12.11.37  DELETE     57zs3144d5tgc           533047381 delete from "U1"."MV#00000006"
 
10 rows selected

— процессы LMS на gcs log flush sync ждали LGWR
— процесс LGWR на LGWR any worker group ждал своих worker-ов (LG..),
— которые кроме своих прямых обязанностей (log file parallel write, On CPU) ждали Job-процессы на LGWR wait for redo copy

Т.о. в период проблем процессы LMS функционировали в привычном порядке за исключением кол-ва ожиданий WAITS_COUNT:

SQL> select REGEXP_REPLACE(REGEXP_SUBSTR(program, '\([^\)]+\)'), '([[:digit:]])', '.') as program,
  2         count(distinct program) as pid_count,
  3         trunc(sample_time, 'mi'),
  4         count(*)
  5    from gv$active_session_history
  6   where sample_time between
  7         to_date('19-APR-16 12.00.00', 'dd-mon-yy hh24.mi.ss') and
  8         to_date('19-APR-16 12.20.00', 'dd-mon-yy hh24.mi.ss')
  9     and program like '%(LMS%'
 10     and inst_id = 2
 11   group by REGEXP_REPLACE(REGEXP_SUBSTR(program, '\([^\)]+\)'), '([[:digit:]])', '.'),
 12            trunc(sample_time, 'mi')
 13   order by trunc(sample_time, 'mi')
 14  /
 
PROGRAM   PID_COUNT TRUNC(SAMPLE_TIME,'MI')   COUNT(*)
-------- ---------- ----------------------- ----------
(LMS.)            3 19.04.2016 12:00:00             35
(LMS.)            3 19.04.2016 12:01:00             16
(LMS.)            3 19.04.2016 12:02:00             18
(LMS.)            3 19.04.2016 12:03:00             16
(LMS.)            3 19.04.2016 12:04:00             26
(LMS.)            3 19.04.2016 12:05:00             69
(LMS.)            3 19.04.2016 12:06:00            173 -- начало
(LMS.)            3 19.04.2016 12:07:00            166 -- .
(LMS.)            3 19.04.2016 12:08:00            173 -- .
(LMS.)            3 19.04.2016 12:09:00            168 -- .
(LMS.)            3 19.04.2016 12:10:00            167 -- .
(LMS.)            3 19.04.2016 12:11:00            129 -- окончение проблем
(LMS.)            3 19.04.2016 12:12:00             25
(LMS.)            3 19.04.2016 12:13:00             21
(LMS.)            3 19.04.2016 12:14:00             37
(LMS.)            3 19.04.2016 12:15:00             50
(LMS.)            3 19.04.2016 12:16:00             22
(LMS.)            3 19.04.2016 12:17:00             23
(LMS.)            3 19.04.2016 12:18:00             11
(LMS.)            3 19.04.2016 12:19:00             14

— , которое приближалось к максимальному 180 (3×60) для рассчитанного системой кол-ва LMS-процессов:

12.1.0.2@ SQL> @param gcs_server_processes
 
NAME                  VALUE  IS_DEF   IS_MOD     DSC
--------------------- ------ -------- ---------- --------------------------------------------------
gcs_server_processes  3      TRUE     FALSE      number of background gcs server processes to start

что наводит на документ Best Practices and Recommendations for RAC databases using very large SGA (e.g. 100 GB) (Doc ID 1619155.1) (вполне применимый к большинству современных инстансов, включая наши по размеру SGA), где кроме прочего можно найти определённые указания для исключения описанного выше дефицита LMS:

f.      Set gcs_server_processes to the twice the default number of lms processes that are allocated.
        The default number of lms processes depends on the number of CPUs/cores that the server has,
        so please refer to the gcs_server_processes init.ora parameter section in the Oracle Database Reference Guide
        for the default number of lms processes for your server.  Please make sure that the total number of lms processes
        of all databases on the server is less than the total number of CPUs/cores on the server

*) причиной краткосрочного всплеска кластерных ожиданий была нештатная OLTP нагрузка на другие объекты бд, вызвавшая нештатный Load Average

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

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

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