Oracle mechanics

10.10.2014

Планы выполнения запросов на RO Standby

Filed under: Active Session History,Oracle — Игорь Усольцев @ 02:42
Tags: ,

Хорошо известно, что перераспределение запросной активности на Standby db, открытую в режиме READ ONLY — чистое благо, по крайней мере покуда «всё идёт по плану»

Диагностика возникающих при этом проблем типа периодического замедления выполнения конкретных запросов, на ro-standby имеет особенности и может быть любопытна

Например, была получена достоверная информация, что запрос, посылаемый через dblink на standby:

SQL> @inst
 
INST_ID INSTANCE_NAME HOST_NAME VERSION    PLATFORM_NAME    DATABASE_STATUS DATABASE_ROLE    STATUS   OPEN_MODE
------- ------------- --------- ---------- ---------------- --------------- ---------------- -------- ---------
1*      myinst        myhost    11.2.0.3.0 Linux x86 64-bit ACTIVE          PHYSICAL STANDBY OPEN     READ ONLY

периодически вместо секунд выполняется десятки минут, что очевидно заслуживает пристального внимания

Информация о разделяемых курсорах показала только только «хорошие» планы с удовлетворительным временем выполнения (ELA_PER_EXEC в мкс):

SQL> @shared_cu cy539dmk1znum
 
EXECS LAST_LOAD_TIME LAST_ACTIVE_TIME ELA_PER_EXEC PLAN_HASH_VALUE OPTIMIZER_COST CHILD BIND_SENSE BIND_AWARE SHAREABLE  USE_FEEDBACK_STATS REASON1
----- -------------- ---------------- ------------ --------------- -------------- ----- ---------- ---------- ---------- ------------------ -------------------------
    2 09.10 13:44    09.10 13:47           3014928      2746810441             93     3 Y          N          Y          N                                           
    1 09.10 13:21    09.10 13:21           1176031      2746810441            121     1 Y          N          N          Y                  Optimizer mismatch(13)  |
    1 09.10 10:47    09.10 10:47            810410      2746810441            121     2 Y          N          N          Y                  Optimizer mismatch(13)  |
    1 08.10 12:45    08.10 12:45           3631688        14120519        1443782     0 Y          N          N          Y                  Optimizer mismatch(13)  |

, при этом несмотря на значения USE_FEEDBACK_STATS=’Y’ и REASON1=’Optimizer mismatch(13)’ из V$SQL_SHARED_CURSOR (отражающие, как видно, причину дальнейшего неиспользования курсоров 0-2, но не их генерации), под влиянием cardinality feedback был сгенерирован только последний дочерний курсор CHILD=3:

SQL> SELECT * FROM TABLE(dbms_xplan.display_cursor( 'cy539dmk1znum',3,format => '+note'));

PLAN_TABLE_OUTPUT
-------------------------------------
SQL_ID  cy539dmk1znum, child number 3
-------------------------------------
SELECT /*+ SHARED (1) SHARED (1) */   -- лишнее указание на удалённое (dblink) происхождение курсора из запроса с подсказками NO_PARALLEL
...
Note
-----
   - cardinality feedback used for this statement -- работает на standby

В dba_hist_sqlstat при этом смотреть безполезно (READ ONLY — мы можем найти там лишь статистику primary), а v$sqlstats показывает опять же вполне благостную картину (ELA_PER_EXEC, CPU_PER_EXEC, UIO_PER_EXEC — в микросекундах):

SQL> @v$sqlstats cy539dmk1znum
 
EXECS SQL_ID              PLAN ELA_PER_EXEC CPU_PER_EXEC GETS_PER_EXEC CONCURRENCY_PER_EXEC CLUSTER_PER_EXEC UIO_PER_EXEC READ_MB_PER_EXEC READS_PER_EXEC
----- ------------- ---------- ------------ ------------ ------------- -------------------- ---------------- ------------ ---------------- --------------
    5 cy539dmk1znum 2746810441      2329597        40994          1477                    0                0      2294994                7            472

— только для хорошего плана № 2746810441

Замечательно, что на standby заполняется ASH, откуда можно узнать, что план этот — не единственный:

SQL> select sql_id, sql_plan_hash_value, count(a.sample_time)
  2    from v$active_session_history a
  3   where sql_id = 'cy539dmk1znum'
  4   group by sql_id, sql_plan_hash_value
  5  /
 
SQL_ID        SQL_PLAN_HASH_VALUE COUNT(A.SAMPLE_TIME)
------------- ------------------- --------------------
cy539dmk1znum          2746810441                   13
cy539dmk1znum          2498032420                    3
cy539dmk1znum          2332369835                 9291 -- вот более активный план

, но вот беда — ни в v$sql_plan, ни в dba_hist_sql_plan (которая у нас с primary) плохого плана не оказалось:

SQL> select distinct plan_hash_value
  2    from (select plan_hash_value
  3            from v$sql_plan
  4           where sql_id = 'cy539dmk1znum'
  5          union all
  6          select plan_hash_value
  7            from dba_hist_sql_plan
  8           where sql_id = 'cy539dmk1znum')
  9   where plan_hash_value in (2746810441, 2498032420, 2332369835)
 10  /
 
PLAN_HASH_VALUE
---------------
     2746810441

Пришлось поправить скрипт ASH_SQLMON2.SQL для отображения имеющихся в ASH данных о выполнении запросов, для которых единственным источником сведений о плане выполнения является собственно ASH, и запросы такие обозначены как Main Query w/o saved plan

Скрипт показал самое интересное в первых 4-х строках, где выполнение запроса с «неизвестным планом»:)

SQL> @ash_sqlmon2 cy539dmk1znum "" ""
 
LAST_PLSQL                 SQL_ID        PLAN_HASH_VALUE   ID PLAN_OPERATION                                                ASH_ROWS WAIT_PROFILE
-------------------------- ------------- --------------- ---- ------------------------------------------------------------- -------- ---------------------------------------------------------
Main Query w/o saved plan  cy539dmk1znum      2332369835   11            MAT_VIEW ACCESS FULL                                   9278 direct path read(9049); ON CPU(213); reliable message(16)
Main Query w/o saved plan  cy539dmk1znum      2332369835   14               MAT_VIEW ACCESS BY LOCAL INDEX ROWID                  13 db file sequential read(8); db file parallel read(5)
Main Query w/o saved plan  cy539dmk1znum      2498032420   11            MAT_VIEW ACCESS BY LOCAL INDEX ROWID                      2 db file sequential read(2)
Main Query w/o saved plan  cy539dmk1znum      2498032420   12             INDEX RANGE SCAN                                         1 db file sequential read(1)
Main Query                 cy539dmk1znum      2746810441    0   SELECT STATEMENT                                                     
                                                            1     SORT ORDER BY                                                      
                                                            2       NESTED LOOPS OUTER                                               
                                                            3         NESTED LOOPS OUTER                                             
                                                            4           VIEW                                                         
                                                            5             UNION-ALL                                                  
                                                            6               HASH GROUP BY                                            
                                                            7                 VIEW                                                   
                                                            8                   UNION-ALL                                            
                                                            9                     FILTER                                             
                                                           10                       PARTITION RANGE ALL                              
                                                           11                         MAT_VIEW ACCESS BY LOCAL INDEX ROWID        17 db file parallel read(11); db file sequential read(6)
                                                           12                           INDEX RANGE SCAN                           2 db file sequential read(2)
                                                           13                     FILTER                                             
                                                           14                       PARTITION RANGE ALL                              
                                                           15                         MAT_VIEW ACCESS BY LOCAL INDEX ROWID           
                                                           16                           INDEX RANGE SCAN                             
                                                           17               HASH GROUP BY                                            
                                                           18                 VIEW                                                   
                                                           19                   UNION-ALL                                            
                                                           20                     FILTER                                             
                                                           21                       MAT_VIEW ACCESS BY INDEX ROWID                   
                                                           22                         INDEX RANGE SCAN                               
                                                           23                     FILTER                                             
                                                           24                       MAT_VIEW ACCESS BY INDEX ROWID                   
                                                           25                         INDEX RANGE SCAN                               
                                                           26           MAT_VIEW ACCESS BY INDEX ROWID                               
                                                           27             INDEX UNIQUE SCAN                                          
                                                           28         VIEW PUSHED PREDICATE                                          
                                                           29           NESTED LOOPS OUTER                                           
                                                           30             TABLE ACCESS BY INDEX ROWID                                
                                                           31               INDEX UNIQUE SCAN                                        
                                                           32             TABLE ACCESS BY INDEX ROWID                                
                                                           33               INDEX UNIQUE SCAN

— начиная с Main Query и ниже идёт скучная ASH-статистика выполнения с быстрым планом 2746810441, а вот в первой строке блистает операция MAT_VIEW ACCESS FULL, наблюдавшаяся в ASH 9278 раз, абсолютный лидер!

Это, конечно, не даёт полной информации ни об изменённом плане 2332369835, ни о причинах такого изменения, но ключ — весьма существенный, позволяющий, например, получить распределение проблемной операции по времени:

SQL> select trunc(sample_time, 'hh24'), count(*)
  2    from v$active_session_history
  3   where sql_id = 'cy539dmk1znum'
  4     and sql_plan_hash_value = 2332369835
  5     and sql_plan_operation = 'MAT_VIEW ACCESS'
  6     and sql_plan_options = 'FULL'
  7   group by trunc(sample_time, 'hh24')
  8   order by count(*) desc
  9  /
 
TRUNC(SAMPLE_TIME,'HH24')   COUNT(*)
------------------------- ----------
09.10.2014 9:00:00              5548
09.10.2014 10:00:00             3730

, убедиться что на то же время приходилось окончание доооолгого обновления проблемного матвью:

SQL> select last_start_date, last_run_duration from dba_scheduler_jobs where job_name like '%MY_PROBLEM_MATVIEW%';
 
LAST_START_DATE                      LAST_RUN_DURATION
------------------------------------ --------------------------
09-OCT-14 02.00.02.149497 AM +04:00  +000000000 08:27:08.875496

, и даже убедиться, что подобные проблемы наблюдались на primary, и что любопытно — в то же самое время:)

SQL> select trunc(sample_time, 'hh24'), count(*)
  2    from dba_hist_active_sess_history
  3    join dba_objects
  4      on current_obj# = object_id
  5   where snap_id >= 58297
  6     and object_name = 'MY_PROBLEM_MATVIEW'
  7     and sql_plan_operation = 'MAT_VIEW ACCESS'
  8     and sql_plan_options = 'FULL'
  9   group by trunc(sample_time, 'hh24')
 10   order by 1
 11  /
 
TRUNC(SAMPLE_TIME,'HH24')   COUNT(*)
------------------------- ----------
09.10.2014 7:00:00               121
09.10.2014 8:00:00               154
09.10.2014 9:00:00              6090 -- ya-ya
09.10.2014 10:00:00             2482
09.10.2014 11:00:00             1628
09.10.2014 12:00:00              305
09.10.2014 13:00:00              837
09.10.2014 14:00:00              771
09.10.2014 15:00:00              940

Остаётся сущая малость — найти и исключить причины изменения плана выполнения в конце обновления матвью, но это уже о другом)

2 комментария »

  1. Игорь, нашел причину? Что было?

    комментарий от jimroll — 10.10.2014 @ 17:26 | Ответить

    • да, конечно — мелкие погрешности в реализации Out-of-Place Materialized View Refresh на версии до 12c

      но тут важна была не причина, важен процесс)

      комментарий от Игорь Усольцев — 10.10.2014 @ 21:38 | Ответить


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