Oracle mechanics

19.09.2014

ASH-трассировка PL/SQL

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

К примеру, в AWR-отчёте бд ERP-системы на первом месте видно продолжающееся/неоконченное выполнение процедуры, лидирующей по использованному DB Time с большим отрывом от ближайшего преследователя — 72% против 18%:

SQL ordered by Elapsed Time           DB/Inst: OEBS/OEBS1  Snaps: 73249-73250

        Elapsed                  Elapsed Time
        Time (s)    Executions  per Exec (s)  %Total   %CPU    %IO    SQL Id
---------------- -------------- ------------- ------ ------ ------ -------------
        36,572.3              0           N/A   72.5   45.7   41.0 5t39uchjqpyfm
Module: XLAACCUP
BEGIN xla_accounting_pkg.unit_processor_batch(:errbuf,:rc,:A0,:A1,:A2,:A3,:A4,:A

         9,246.2             15        616.41   18.3   29.4   65.5 0vjcg5zp30z2x

Для быстрой оценки такого рода проблем написал скрипт ash_plsqlmon_hist.sql, который по истории ASH вначале показывает суммарный вклад запросов и PL/SQL блоков по частоте попадания в историю ASH (ASH_ROWS), кол-во зафиксированных неповторяющихся выполнений (EXECS), затем — мин/мах время наблюдения(с соответствующими названиями столбцов) и общий профиль ожиданий (WAIT_PROFILE) примерно так:

SQL> --                 SQL_ID of pl/sql block   start_snap_id [stop_snap_id(=start_snap_id by default)]
SQL> @ash_plsqlmon_hist 5t39uchjqpyfm            73250

***** Summary by SQL execs *****

SQL_ID        SQL_PLAN_HASH_VALUE   ASH_ROWS      EXECS MIN_TIME MAX_TIME SQL_TEXT  WAIT_PROFILE
------------- ------------------- ---------- ---------- -------- -------- --------- ---------------------------------------------------------------------------------------------------------------------------
0vjcg5zp30z2x          3765917430        842         20 08:32:35 09:00:00 MERGE ... ON CPU(299); db file sequential read(293); db file scattered read(231); log buffer space(12); log file switch completion(7)
1urr1xwyc7m5w                   0        436        435 08:31:05 08:46:18 INSERT... ON CPU(436)
dccfw9vf6th9a           346358028        404         20 08:32:25 08:53:19 DELETE... db file sequential read(198); ON CPU(196); log buffer space(10)
3cmfvy8xdx6gv                   0        158         19 08:34:25 08:45:47 BEGIN ... ON CPU(158)
cuzx7rp43k50g          2595291681        131         20 08:31:55 08:47:28 UPDATE... ON CPU(103); db file sequential read(24); log buffer space(4)
00g6srrvhy1fq                   0        131         19 08:31:45 08:40:37 BEGIN ... ON CPU(131)
8wqh9r3nya4hv           199134991        125         10 08:33:05 09:00:00 INSERT... db file sequential read(116); log file switch completion(5); ON CPU(2); gc current grant 2-way(1); write complete waits(1)
1ap1rr3npc6s9          3569326159        122         21 08:30:05 08:41:07 SELECT... db file sequential read(63); db file parallel read(42); ON CPU(17)
fwpd5tbgffy68          2750738566        113         76 08:30:55 08:46:08 SELECT... ON CPU(77); db file sequential read(32); db file parallel read(3); read by other session(1)
830t900unhbmu          1726105946        108         11 08:30:05 08:32:35 SELECT... db file sequential read(96); ON CPU(12)
fpjcgvudxsran          2595291681        102         19 08:40:26 08:48:18 UPDATE... ON CPU(97); log buffer space(5)
gsj6516ntm9ra           411733077         75         12 08:32:55 09:00:00 SELECT... direct path write temp(34); direct path read temp(29); ON CPU(12)
...

63 rows selected

— из чего, например, можно отметить относительно тяжёлый (по заметности в ASH) MERGE с порядковым номером 0vjcg5zp30z2x, детали выполнения которого можно найти во второй части вывода скрипта, в частности — два TABLE ACCESS FULL + собственно нелёгкую операцию MERGE, и прочие детали:

***** SQL Plan/PLSQL execs details *****

SQL_PLSQL    SQL_ID        PLAN_HASH_VALUE   ID PLAN_OPERATION                                 OBJECT_OWNER  OBJECT_NAME        QBLOCK_NAME      EXECS   ASH_ROWS WAIT_PROFILE
------------ ------------- --------------- ---- ---------------------------------------------- ------------- ------------------ ----------- ---------- ---------- ----------------------------------------------------------------------------------------------
SQL Query    0vjcg5zp30z2x      3765917430    0   MERGE STATEMENT
                                              1     MERGE                                      XLA           XLA_AE_LINES_GT    MRG$1               20        487 ON CPU(281); db file sequential read(187); log buffer space(12); log file switch completion(7)
                                              2       VIEW
                                              3         HASH JOIN                                                               SEL$1                3          4 ON CPU(4)
                                              4           TABLE ACCESS FULL                    XLA           XLA_AE_HEADERS_GT  SEL$1
                                              5           TABLE ACCESS FULL                    XLA           XLA_AE_LINES_GT    SEL$1               18        351 db file scattered read(231); db file sequential read(106); ON CPU(14)
SQL Query    1419r7jykqmp9       934323017    0   SELECT STATEMENT
...
PL/SQL       00g6srrvhy1fq               0    0 APPS.XLA_ACCOUNTING_PKG.UNIT_PROCESSOR_BATCH"                                                       19        131 ON CPU(131)
PL/SQL       3cmfvy8xdx6gv               0    0 APPS.XLA_ACCOUNTING_PKG.UNIT_PROCESSOR_BATCH"                                                       19        158 ON CPU(158)
SQL w/o plan 324f92mdb27r6      3692582569    6 INSERT INTO XLA_AE_LINES_GT (AE_HEADER_ID ,TEM                                                       1          1 db file sequential read(1)
SQL w/o plan dqxst6vjrbchq      1090499795    2                                                                                                      3          3 ON CPU(3)
SQL w/o plan a21b0wuncw9t8      3397468612    4                                                                                                      3          3 ON CPU(3)
...

1016 rows selected

В дополнение, после запросов с ASH-статистикой планов выполнения (SQL Query), перечислена статистика выполнения PL/SQL блоков и различный попадающий в ASH мусор типа записей запросов с ненайденными планами SQL w/o plan

Другой свежий пример из бд со смешанной OLTP(+DWH/reports) нагрузкой:

              Snap Id      Snap Time      Sessions Curs/Sess
            --------- ------------------- -------- ---------
Begin Snap:    297824 12-Sep-14 16:30:10       602       2.2
  End Snap:    297826 12-Sep-14 17:30:03       615       2.2
   Elapsed:               59.88 (mins)
   DB Time:            1,798.80 (mins)

SQL ordered by Elapsed Time   DB/Inst: SDB/sdb1  Snaps: 297824-297826

          Elapsed                  Elapsed Time
          Time (s)    Executions  per Exec (s)  %Total   %CPU    %IO    SQL Id
  ---------------- -------------- ------------- ------ ------ ------ -------------
          67,764.5          8,186          8.28   62.8   35.9     .1 8nrjyx5jb5j1g
  Module: python2.7@ (TNS V1-V3)
   declare resource_busy exception; pragma exception_i
...
          59,209.8        375,731          0.16   54.9   37.3     .0 2wxhu10032thc
  Module: python2.7@ (TNS V1-V3)
  SELECT NVL(BUDGET, 0) FROM GTO.V_CLIENT_DIA_DISCOUNTS D RIGHT JOIN DUAL ON
   CLIENT_ID = :B2 AND DT = TRUNC(:B1 )

           3,601.0              1      3,600.99    3.3   55.6   19.5 1mbx3m11g17vn
...

— опять же в топе AWR некий PL/SQL блок 8nrjyx5jb5j1g и запрос 2wxhu10032thc

Скрипт по текущим данным ASH подтверждает, что основной вклад в успех PL/SQL блока вносит частовыполняемый запрос 2wxhu10032thc:

SQL> @ash_plsqlmon 8nrjyx5jb5j1g

***** Summary by SQL execs *****

SQL_ID        SQL_PLAN_HASH_VALUE   ASH_ROWS    EXECS MIN_TIME MAX_TIME SQL_TEXT  WAIT_PROFILE
------------- ------------------- ---------- -------- -------- -------- --------- --------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
2wxhu10032thc           349250770      93934    92989 16:47:52 18:25:04 SELECT... ON CPU(93119); gc buffer busy acquire(572); latch: cache buffers chains(97); gc cr multi block request(62); latch: row cache objects(40); gc cr block 2-way(10); latch: undo global data(7); latch free(
bxyukmfdfaz2f          1481142953       4858     4651 16:47:52 18:25:03 SELECT... ON CPU(4683); latch: row cache objects(115); db file sequential read(20); gc current block 2-way(19); latch free(7); gc cr block busy(6); latch: cache buffers chains(4); gc current block congested(1);
8ubrykptawra1          1685801271       1799     1476 16:47:53 18:25:05 SELECT... gc current grant busy(1476); ON CPU(240); enq: TX - row lock contention(64); latch: enqueue hash chains(6); latch: ges resource hash list(4); db file sequential read(2); cursor: pin S(2); gc current b
c126tuq8pd9tx          1785015817       1508      757 16:47:52 18:24:58 SELECT... gc cr block 2-way(758); gc current block 2-way(446); ON CPU(167); db file sequential read(51); gc cr block busy(38); gc cr grant 2-way(29); gc current block congested(7); gc cr block congested(7); cur
8nrjyx5jb5j1g                   0       1286      768 16:47:52 18:25:03 declare.. ON CPU(816); ON CPU(314); latch: row cache objects(75); latch: enqueue hash chains(33); latch: ges resource hash list(24); gc current grant busy(8); gc buffer busy release(3); latch: cache buffers cha
2f2k6jtdtk1cq          1706332032       1187      645 16:47:52 18:24:58 UPDATE... ON CPU(708); buffer busy waits(179); enq: TX - index contention(73); library cache: mutex X(60); latch: ges resource hash list(29); gc current grant busy(29); buffer deadlock(24); gc buffer busy acqui
...

24 rows selected

***** SQL Plan/PLSQL execs details *****

SQL_PLSQL    SQL_ID        PLAN_HASH_VALUE         ID PLAN_OPERATION                                                                     OBJECT_NAME         QBLOCK_NAME      EXECS   ASH_ROWS WAIT_PROFILE
------------ ------------- --------------- ---------- ---------------------------------------------------------------------------------  ------------------- ------------- -------- ---------- --------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
...
SQL Query    2wxhu10032thc       349250770          0   SELECT STATEMENT                                                                                                        141        160 ON CPU(159); latch free(1)
                                                    1     NESTED LOOPS OUTER                                                                                 SEL$58C0AD50         2          2 ON CPU(2)
                                                    2       FAST DUAL                                                                                        SEL$58C0AD50         1          1 ON CPU(1)
                                                    3       VIEW                                                                                             SEL$F5BB74E1
                                                    4         VIEW                                                                                           SEL$A96BBA6F         1          1 ON CPU(1)
                                                    5           SORT ORDER BY                                                                                SEL$A96BBA6F        18         18 ON CPU(18)
                                                    6             SORT GROUP BY                                                                                                 105        105 ON CPU(105)
                                                    7               NESTED LOOPS OUTER                                                                                            1          1 ON CPU(1)
                                                    8                 VIEW                                                                                   SEL$B7E8C768         3          3 ON CPU(3)
                                                    9                   NESTED LOOPS                                                                         SEL$B7E8C768         2          2 ON CPU(2)
                                                   10                     NESTED LOOPS                                                                                            2          2 ON CPU(2)
                                                   11                       NESTED LOOPS                                                                                          1          1 ON CPU(1)
                                                   12                         VIEW                                                       V_DATES             SEL$4               31         31 ON CPU(31)
                                                   13                           COUNT                                                                        SEL$4                3          3 ON CPU(3)
                                                   14                             CONNECT BY WITHOUT FILTERING                                                                   43         43 ON CPU(43)
                                                   15                               FAST DUAL                                                                SEL$4
                                                   16                         VIEW                                                       V_DIR_CLIENTS       SEL$6               17         17 ON CPU(17)
                                                   17                           FILTER                                                                       SEL$6                2          2 ON CPU(2)
                                                   18                             SORT GROUP BY                                                                                  50         50 ON CPU(50)
                                                   19                               VIEW                                                                     SEL$541EEDC0         5          5 ON CPU(5)
                                                   20                                 WINDOW SORT                                                            SEL$541EEDC0       141        141 ON CPU(141)
                                                   21                                   NESTED LOOPS OUTER                                                                        2          2 ON CPU(2)
                                                   22                                     NESTED LOOPS OUTER                                                                      6          6 ON CPU(6)
                                                   23                                       HASH JOIN OUTER                                                                    6967       7007 ON CPU(6967); latch: row cache objects(40)
                                                   24                                         VIEW                                                           SEL$A0D20652         3          3 ON CPU(3)
                                                   25                                           MERGE JOIN CARTESIAN                                         SEL$A0D20652         1          1 ON CPU(1)
                                                   26                                             NESTED LOOPS
                                                   27                                               TABLE ACCESS BY INDEX ROWID          T_CLIENT            SEL$A0D20652         5          5 ON CPU(5)
                                                   28                                                 INDEX UNIQUE SCAN                  T_CLIENT_PK         SEL$A0D20652         9         10 ON CPU(9); gc current block 2-way(1)
                                                   29                                               TABLE ACCESS BY INDEX ROWID          T_CLIENT            SEL$A0D20652         5          5 ON CPU(5)
                                                   30                                                 INDEX RANGE SCAN                   T_CLIENT_CLASS_IDX  SEL$A0D20652        15         18 ON CPU(15); gc cr grant 2-way(2); db file sequential read(1)
                                                   31                                             BUFFER SORT                                                                    12         12 ON CPU(12)
                                                   32                                               VIEW                                 V_DATES             SEL$10              11         11 ON CPU(11)
                                                   33                                                 COUNT                                                  SEL$10               2          2 ON CPU(2)
                                                   34                                                   CONNECT BY WITHOUT FILTERING                                             16         16 ON CPU(16)
                                                   35                                                     FAST DUAL                                          SEL$10
                                                   36                                         VIEW                                                           SEL$12            1875       1875 ON CPU(1875)
                                                   37                                           SORT GROUP BY                                                SEL$12           78417      78424 ON CPU(78424)
                                                   38                                             MAT_VIEW ACCESS FULL                   MV_CLIENT_DISCOUNT  SEL$12            4896       5728 ON CPU(4963); gc buffer busy acquire(572); latch: cache buffers chains(97); gc cr multi block request(62); gc cr block 2-way(10); latch: undo global data(7); latch free(6); gc cr block busy(5); read b
...
PL/SQL       8nrjyx5jb5j1g               0          0 GTO.PK_TARIFFICATION.PROCESS_ORDER                                                                                        768        818 ON CPU(816); library cache: mutex X(2)
PL/SQL       8nrjyx5jb5j1g               0          0 declare          resource_busy exception;          pragma exception_i                                                     311        468 ON CPU(314); latch: row cache objects(75); latch: enqueue hash chains(33); latch: ges resource hash list(24); gc current grant busy(8); gc buffer busy release(3); latch free(2); latch: cache buffers c
PL/SQL                          1593018354          0 GTO.PK_TARIFFICATION.PROCESS_ORDER                                                                                          0          1 ON CPU(1)
PL/SQL                                   0          0 GTO.PK_TARIFFICATION.PROCESS_ORDER                                                                                          1        302 ON CPU(278); library cache: mutex X(16); cursor: pin S(3); latch: ges resource hash list(3); latch free(1); KJC: Wait for msg sends to complete(1)
...
129 rows selected

, который в свою очередь бОльшую часть времени посвящает операциям SORT GROUP BY -> MAT_VIEW ACCESS FULL с последующим HASH JOIN OUTER над небольшим ~2MB матвью MV_CLIENT_DISCOUNT. Вклад сбственно PL/SQL составляющих при этом относительно ничтожен

Запрос 2wxhu10032thc в действительности, недолгий <= 200ms, но назойливый частовыполняемый ~ 100 rps:

SQL> @dba_hist_sqlstat "sql_id = '2wxhu10032thc' and snap_id between 297825 and 297826"

INST BEGIN_SNAP_ID BEGIN_SNAP_TIME    EXECS SQL_ID              PLAN  COST PARSE_PER_EXEC ELA_PER_EXEC CPU_PER_EXEC GETS_PER_EXEC READS_PER_EXEC WRITES_PER_EXEC DIRECT_WRITES_PER_EXEC ROWS_PER_EXEC FETCHES_PER_EXEC IOWAITS_PER_EXEC CLWAITS_PER_EXEC_US APWAITS_PER_EXEC CCWAITS_PER_EXEC PLSQL_PER_EXEC
---- ------------- --------------- -------- ------------- ---------- ----- -------------- ------------ ------------ ------------- -------------- --------------- ---------------------- ------------- ---------------- ---------------- ------------------- ---------------- ---------------- --------------
   1        297825 12.09 17:00       189974 2wxhu10032thc  349250770   595          0,001       167014        59332           462              0               0                      0             1                1                5                1775                0                0             29
   1        297824 12.09 16:30       185757 2wxhu10032thc  349250770   595          0,001       147943        58213           421              0               0                      0             1                1                3                   9                0                0             25

— время выполнения которого определяется чтением, сортировкой и hash-соединением 400+ буферов из кэша (GETS_PER_EXEC), что неотчётливо отражается в приведённой статистике выполнения, но явно следует из статистики ASH

К сожалению, в этом логически непростом запросе исключить FTS с помощью JPPD не удалось: Oracle категорически противился сообщениями типа:

JPPD:     JPPD bypassed: View contains a group by.

— несмотря на версию 11.2.0.3, однако, если всё-таки исключить сканирование и избыточное кол-во consistent get (а заодно и группировку) другим способом (всё-таки это matview), можно снизить кол-во GETS_PER_EXEC до 30- , соответственно, время выполнения запроса до ~ 10 мс, что заметно снизит DB Time, и паразитный (но отнюдь не безобидный) Load Average сервера бд по крайней мере в разы

Ну и + RESULT_CACHE в помощь)

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

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

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