Oracle mechanics

09.03.2018

log file sequential read

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

Всплеск нагрузки на IO подсистему:

сопровождался, по нашим с Дмитрием Якубеней наблюдениям, дисбалансом в отчёте AWR — совершенно незначительные цифры пользовательской нагрузки (*):

Load Profile                    Per Second   Per Transaction  Per Exec  Per Call
~~~~~~~~~~~~~~~            ---------------   --------------- --------- ---------
             DB Time(s):              73.0               0.0      0.01      0.00
              DB CPU(s):              10.5               0.0      0.00      0.00
      Background CPU(s):               0.9               0.0      0.00      0.00
      Redo size (bytes):       6,734,104.6           3,153.3
  Logical read (blocks):       2,698,366.4           1,263.6
          Block changes:          41,001.2              19.2
 Physical read (blocks):          11,301.7               5.3
Physical write (blocks):           3,319.9               1.6
       Read IO requests:           4,417.3               2.1
      Write IO requests:             721.0               0.3
           Read IO (MB):              44.2               0.0                      -- *
          Write IO (MB):              13.0               0.0                      -- *
...

никак не коррелировали с Total (MB) нагрузкой AWR IO Profile (**):

IO Profile                  Read+Write/Second     Read/Second    Write/Second
~~~~~~~~~~                  ----------------- --------------- ---------------
            Total Requests:           8,084.8         6,700.4         1,384.4
         Database Requests:           5,138.3         4,417.3           721.0
        Optimized Requests:               0.0             0.0             0.0
             Redo Requests:           1,116.8           458.3           658.5
                Total (MB):             545.2           512.4            32.8  -- **
             Database (MB):              57.1            44.2            13.0
      Optimized Total (MB):               0.0             0.0             0.0
                 Redo (MB):             449.5           435.7            13.9  -- ***
          Database (blocks):          14,621.6        11,301.7         3,319.9
  Via Buffer Cache (blocks):           5,765.8         4,187.2         1,578.6
            Direct (blocks):           8,855.8         7,114.6         1,741.3

, основная часть которой была сосредоточена в районе Redo Read (***)

Подходящее ожидание log file sequential read, однако, занимало незначительное место в Top AWR/ASH:

SQL> select session_state,
  2         event,
  3         wait_class,
  4         count(*),
  5         round(RATIO_TO_REPORT(count(*)) OVER() * 100, 2) AS PCTTOT
  6    from v$active_session_history
  7   group by session_state, event, wait_class
  8   order by count(*) desc fetch first 7 rows only
  9  /
 
SESSION_STATE EVENT                                    WAIT_CLASS     COUNT(*)     PCTTOT
------------- ---------------------------------------- ------------ ---------- ----------
WAITING       log file sync                            Commit            76554      33,88
WAITING       db file sequential read                  User I/O          55232      24,44
ON CPU                                                                   30522      13,51
WAITING       log file sequential read                 System I/O         9414       4,17
WAITING       gc buffer busy release                   Cluster            6749       2,99
WAITING       db file parallel read                    User I/O           5836       2,58
WAITING       enq: TX - row lock contention            Application        3829       1,69
 
7 rows selected

, список SQL with Top Events:

                 SQL ID            Plan Hash           Executions     % Activity
----------------------- -------------------- -------------------- --------------
                                                                           % Row
Event                          % Event Top Row Source                     Source
------------------------------ ------- --------------------------------- -------
          8x5xmcz928ydq           3097918894                  384           7.47
CPU + Wait for CPU                5.11 INDEX - RANGE SCAN                   4.68
SELECT ... FOR UPDATE SKIP LOCKED
gc buffer busy release            1.30 FOR UPDATE                           1.30

          fvnurzypu04rm           4051889724                    5           4.07
log file sequential read          2.73 DELETE                               2.73 -- ****

          dc3tffcy516jk           4051889724                    3           2.81
log file sequential read          2.01 DELETE                               2.01 -- ****

в AWR указывал на два неочевидно подозрительных DELETE с совпадающими PHV (****), которые, возможно, и заслуживали внимания, но в списках SQL ordered by … эти DELETE проходили далеко не на первых местах(

Определить пользовательские процессы, ответственные за возросший IO (Redo Read), помогли утилиты pidstat/atop — и это были сессии, выполнявшие вышеуказанные DELETE со следующим мониторингом:

SQL> @ash_sqlmon2 fvnurzypu04rm 4051889724
 
LAST_PLSQL         SQL_ID        PLAN_HASH_VALUE   ID PLAN_OPERATION                            COST TEMP_SPACE MAX_PGA_ALLOCATED    ASH_ROWS WAIT_PROFILE
------------------ ------------- --------------- ---- ----------------------------------- ---------- ---------- -----------------  ---------- -------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Main Query         fvnurzypu04rm      4051889724    0   DELETE STATEMENT                        9312                                          
>>>                                                 1     DELETE                                                        193015808        8556 log file sequential read(5657); enq: TX - row lock contention(1770); ON CPU(1030); control file sequential read(88); Disk file Mirror Read(5); KSV master wait(3); Disk file operations I/O(2); log buffer space(1)
                                                    2       FILTER                                                                            
                                                    3         PARTITION RANGE ITERATOR          9312                                          
                                                    4           PARTITION LIST SINGLE           9312                                          
                                                    5             TABLE ACCESS FULL             9312                                          
SQL Summary                                    0      ASH fixed 12 execs from 12 sessions                                                8556  ash rows were fixed from 25.01.2018 13:24:25 to 25.01.2018 14:02:14
SQL Summary by PHV fvnurzypu04rm      4051889724      ASH rows: 8556; Dist.Execs: 12

и странной статистикой V$SQL / V$SQLSTATS:

SQL> @shared_cu12 fvnurzypu04rm 0
 
INST EXECS USERS_OPENING LAST_LOAD_TIME       ROWS_PER_EXEC 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 CURSOR_STATUS       PLAN_HASH_VALUE FULL_PLAN_HASH_VALUE OPTIMIZER_COST CHILD BIND_SENSE BIND_AWARE SHAREABLE  CF  REOPT REOPT_HINTS V$SQL.Adapt XML.Adapt SPD_Valid SPD_Used  DS_LEVEL DOP DOP_REASON NOT_SHARED_BY REASON
---- ----- ------------- -------------------- ------------- ------------ ------------ --------------- ------------- -------------- ------------ ------------- ------------ -------------- ------------------- --------------- -------------------- -------------- ----- ---------- ---------- ---------- --- ----- ----------- ----------- --------- --------- --------- -------- --- ---------- ------------- -------------------------------------...
   1    60             5 2018-01-25/10:51:41            778    751740336     86181800               1          4089             10       278345            29         2683              0 VALID                    4051889724           1273588868           9312     0 Y          N          Y              N                 N                                                                               Rolling Invalidate Window Exceeded(3)
                                                                                                                                                                                                                                                                                                                                                                                                               Rolling Invalidate Window Exceeded(2)
...
 
--------------------------------------------------------------
SQL_ID=fvnurzypu04rm Shared Pool GV$SQLSTATS
--------------------------------------------------------------
 
INST        EXECS SQL_ID              PLAN ELA_PER_EXEC CPU_PER_EXEC GETS_PER_EXEC CONC_PER_EXEC CLU_PER_EXEC UIO_PER_EXEC READ_MB_PER_EXEC READS_PER_EXEC DISK_READS_PER_EXEC WRITES_MB_PER_EXEC WRITES_PER_EXEC DIRECT_WRITES_PER_EXEC ROWS_PER_EXEC PX_PER_EXEC
---- ------------ ------------- ---------- ------------ ------------ ------------- ------------- ------------ ------------ ---------------- -------------- ------------------- ------------------ --------------- ---------------------- ------------- -----------
   1           60 fvnurzypu04rm 4051889724    751740336     86181800          4089            29         2683       278345            50350          56772                   0                  0               0                      0           778           0
 
--------------------------------------------------------------
ASH TOP5 SQL_ID=fvnurzypu04rm Executions by Elapsed Time
--------------------------------------------------------------
 
   INST_ID SQL_ID        SQL_PLAN_HASH_VALUE SQL_EXEC_ID   CHILD_ID   ASH_ROWS         PX DURATIONs                 MIN_SAMPLE_TIME           MAX_SAMPLE_TIME
---------- ------------- ------------------- ----------- ---------- ---------- ---------- ------------------------- ------------------------- -------------------------
         1 fvnurzypu04rm          4051889724    16777833          0       1487          0 +000000000 00:24:51.663   25-JAN-18 01.40.39.918 PM 25-JAN-18 02.05.31.581 PM
         1 fvnurzypu04rm          4051889724    16777834          0       1196          0 +000000000 00:19:59.536   25-JAN-18 01.43.47.621 PM 25-JAN-18 02.03.47.157 PM
         1 fvnurzypu04rm          4051889724    16777835          0       1196          0 +000000000 00:19:59.338   25-JAN-18 01.50.57.406 PM 25-JAN-18 02.10.56.744 PM
         1 fvnurzypu04rm          4051889724    16777836          0       1195          0 +000000000 00:19:58.607   25-JAN-18 01.56.38.666 PM 25-JAN-18 02.16.37.273 PM
         1 fvnurzypu04rm          4051889724    16777837          0        966          0 +000000000 00:16:08.786   25-JAN-18 02.00.40.527 PM 25-JAN-18 02.16.49.313 PM
         1 fvnurzypu04rm          4051889724    16777832          0        867          0 +000000000 00:14:29.499   25-JAN-18 01.38.07.320 PM 25-JAN-18 01.52.36.819 PM
         1 fvnurzypu04rm          4051889724    16777843          0        630          0 +000000000 00:10:31.622   25-JAN-18 02.06.17.691 PM 25-JAN-18 02.16.49.313 PM
         1 fvnurzypu04rm          4051889724    16777830          0        558          0 +000000000 00:09:19.182   25-JAN-18 01.38.07.320 PM 25-JAN-18 01.47.26.502 PM
         1 fvnurzypu04rm          4051889724    16777831          0        423          0 +000000000 00:07:03.581   25-JAN-18 01.38.07.320 PM 25-JAN-18 01.45.10.901 PM
         1 fvnurzypu04rm          4051889724    16777844          0        285          0 +000000000 00:04:45.261   25-JAN-18 02.12.04.052 PM 25-JAN-18 02.16.49.313 PM
         1 fvnurzypu04rm          4051889724    16777845          0         18          0 +000000000 00:00:17.050   25-JAN-18 02.16.32.263 PM 25-JAN-18 02.16.49.313 PM
 
11 rows selected

, из которой формально непонятно, чем занимались запросы больщую часть своего небыстрого среднего выполнения ELA_PER_EXEC ~ 751 секунд, за исключением CPU_PER_EXEC ~ 86 секунд и UIO_PER_EXEC ~ 0.28 секунд — и это ещё одна неконсистентность, связанная, вероятно, с wait_class-ом System I/O пользовательского в этом случае ожидания log file sequential read, характерного более для системных процессов и учитываемого по иным правилам:

SQL> @ash_sql_wait_tree "event = 'log file sequential read'" 0 "where sample_time > sysdate-1/24"
 
LVL INST_ID BLOCKING_TREE EVENT                     WAIT_CLASS  IN_SQL_EXECUTION SQL_CHILD_NUMBER TOP_LEVEL_CALL_NAME WAITS_COUNT EXECS_COUNT AVG_WA SESS_COUNT BLOCK_SID     SQL_ID        TOP_LEVEL_SQL_ID SQL_PLAN_HASH_VALUE SQL_EXEC_ID SQL_PLAN_LINE_ID SQL_PLAN_OPERATION
--- ------- ------------- ------------------------- ----------- ---------------- ---------------- ------------------- ----------- ----------- ------ ---------- ------------- ------------- ---------------- ------------------- ----------- ---------------- ------------------
  1       1 (USER)        log file sequential read  System I/O  Y                               0 V8 Bundled Exec            5841          11    180         11 NO HOLDER i#  fvnurzypu04rm fvnurzypu04rm             4051889724           1                1 DELETE            
  1       1 (USER)        log file sequential read  System I/O  Y                               4 V8 Bundled Exec            3872           7    183          7 NO HOLDER i#  dc3tffcy516jk dc3tffcy516jk             4051889724           1                1 DELETE            
  1       1 (USER)        log file sequential read  System I/O  Y                               4 V8 Bundled Exec            3872           7    183          7 NO HOLDER i#  dc3tffcy516jk dc3tffcy516jk             4051889724           1                1 DELETE            
  1       1 (ARC.)        log file sequential read  System I/O  N                               0                             495           0    174          2 NO HOLDER i#                                                   0           0                                    
  1       2 (ARC.)        log file sequential read  System I/O  N                               0                             284           0    128          3 NO HOLDER i#                                                   0           0                                    
  1       1 (TT..)        log file sequential read  System I/O  N                               0 LOGOFF                      223           0    164          2 NO HOLDER i#                                                   0           0                                    
  1       2 (TT..)        log file sequential read  System I/O  N                               0 VERSION2                     51           0    183          1 NO HOLDER i#                                                   0           0                                    
  1       2 (TT..)        log file sequential read  System I/O  N                               0 LOGOFF                       42           0    154          1 NO HOLDER i#                                                   0           0                                    
  1       1 (ARC.)        log file sequential read  System I/O  N                               0 LOGOFF                       23           0    140          2 NO HOLDER i#                                                   0           0                                    
  1       2 (ARC.)        log file sequential read  System I/O  N                               0 LOGOFF                        6           0    104          2 NO HOLDER i#                                                   0           0                                    
  1       2 (LGWR)        log file sequential read  System I/O  N                               0                               1           0     75          1 NO HOLDER i#                                                   0           0                                    
 
11 rows selected

Далее, из трейса пользовательских процессов следовало:

=====================
PARSING IN CURSOR #139801865763520 len=87 dep=0 uid=33 oct=7 lid=33 tim=29797546307342 hv=2879394547 ad='2746e3bcf0' sqlid='fvnurzypu04rm'
delete from t_partner_some_stat where source_id = :src_id and dt between :dt1 and :dt2
END OF STMT
BINDS #139801865763520:
...
oer 8102.2 - obj# 4856336, rdba: 0xc70f2f19(afn 796, blk# 995097)
kdk key 8102.2:
  ncol: 2, len: 13
  key: (13):  05 c4 03 1e 54 33 06 c5 51 7b 1f 00 00
  mask: (4096):
...
dbkedDefDump(): Starting a non-incident diagnostic dump (flags=0x0, level=3, mask=0x0)
----- Error Stack Dump -----
----- Current SQL Statement for this session (sql_id=fvnurzypu04rm) -----
delete from t_partner_some_stat where source_id = :src_id and dt between :dt1 and :dt2

----- Call Stack Trace -----
...
REDO RECORD - Thread:1 RBA: 0x0277d7.0079d80a.0120 LEN: 0x0054 VLD: 0x01 CON_UID: 0
SCN: 0x0828.bf1c99d7 SUBSCN:  7 01/25/2018 10:56:15
CHANGE #1 MEDIA RECOVERY MARKER CON_ID:0 SCN:0x0000.00000000 SEQ:0 OP:18.3 ENC:0 FLG:0x0000
Reuse redo entry
Range reuse: pdb = 0 tsn=29 base=0x1040d100 nblks=256
...
WAIT #139801865763520: nam='log file sequential read' ela= 12475 log#=161751 block#=7991296 blocks=2048 obj#=4856336 tim=29798745384894
WAIT #139801865763520: nam='log file sequential read' ela= 748 log#=161751 block#=7995392 blocks=2048 obj#=4856336 tim=29798745389447
WAIT #139801865763520: nam='log file sequential read' ela= 11679 log#=161751 block#=7997440 blocks=2048 obj#=4856336 tim=29798745401318
WAIT #139801865763520: nam='log file sequential read' ela= 183406 log#=161751 block#=7999488 blocks=2048 obj#=4856336 tim=29798745584984
WAIT #139801865763520: nam='log file sequential read' ela= 7524 log#=161751 block#=8015872 blocks=2048 obj#=4856336 tim=29798745606276
WAIT #139801865763520: nam='log file sequential read' ela= 23999 log#=161751 block#=8026112 blocks=2048 obj#=4856336 tim=29798745638289
WAIT #139801865763520: nam='log file sequential read' ela= 7159 log#=161751 block#=8028160 blocks=2048 obj#=4856336 tim=29798745647535
...
fatal error occurred while scanning redo
ORA-01013: user requested cancel of current operation
Error 1013 occurred while dumping log
ORA-01013: user requested cancel of current operation
EXEC #139801865763520:c=183473000,e=1200019534,p=0,cr=36,cu=5,mis=0,r=0,dep=0,og=1,plh=4051889724,tim=29798746326810
ERROR #139801865763520:err=1013 tim=29798746326833
...

1. причиной, запускающей сканирование REDO RECORD/log file sequential read была OERR: ORA-8102 «index key not found, obj# %s, file %s, block %s (%s)» (Doc ID 8102.1), и заканчивалось всё ORA-01013 — тут можно строить предположения/умозаключения

2. log file sequential read — в отличие от db file sequential read, не одноблочное чтение, читает интенсивно, в основном, пачками по blocks=2048 (максимум) и, учитывая используемый стандартный размер блока лог-файла в 512 байт, за одно ожидание читается 1 Мбайт логов — аналогично FULL SCAN)

И ещё одно несоответствие, статистика AWR/DBA_HIST_SYSTEM_EVENT за проблемный период фиксировала не более 200 ожиданий log file sequential read в секунду в течение проблемного периода, т.е. не более 200 MB/sec — что в 2+ раза меньше зафиксированного выше значения Redo Read AWR и, как минимум, на порядок меньше наблюдаемого скачка IO — с учётом/фиксацией этого ожидания в пользовательском варианте определённо есть проблемы

Проблема в итоге была решена стандартный рекомендованным способом — online перестройкой logical corrupted index partition, список которых был получен из ASH:

SQL> select distinct current_obj#
       from v$active_session_history
      where sql_id in ('fvnurzypu04rm', 'dc3tffcy516jk') -- проблемные DELETE
        and event = 'log file sequential read'
     /

— а индекс этот был построен online при интенсивной OLTP нагрузке незадолго до возникновения проблем (без видимых ошибок)

P.S. Tkprof проблемного запроса также любопытен:

SQL ID: fvnurzypu04rm Plan Hash: 4051889724

delete from t_partner_some_stat
where
 source_id = :src_id and dt between :dt1 and :dt2


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        0      0.00       0.00          0          0          0           0
Execute      1    183.47    1200.01          0         36          5           0 -- без дисковой активности
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        1    183.47    1200.01          0         36          5           0

Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 33
Number of plan statistics captured: 1

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
         0          0          0  DELETE  T_PARTNER_SOME_STAT (cr=0 pr=0 pw=0 time=285 us) -- время операций занижено
         1          1          1   FILTER  (cr=35 pr=0 pw=0 time=588 us)
         1          1          1    PARTITION RANGE ITERATOR PARTITION: KEY KEY (cr=35 pr=0 pw=0 time=586 us cost=9312 size=142587 card=5281)
         1          1          1     PARTITION LIST SINGLE PARTITION: KEY KEY (cr=35 pr=0 pw=0 time=357 us cost=9312 size=142587 card=5281)
         1          1          1      TABLE ACCESS FULL T_PARTNER_SOME_STAT PARTITION: KEY KEY (cr=35 pr=0 pw=0 time=306 us cost=9312 size=142587 card=5281)


Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  enq: TX - row lock contention                   1      177.33        177.33
  Disk file operations I/O                      379        0.00          0.06
  db file sequential read                         1        0.00          0.00
  log buffer space                                1        0.00          0.00
  Disk file Mirror Read                         140        0.00          0.17
  control file sequential read                 9913        0.25         11.67 -- также класса System I/O и также выпадает из расчётов
  KSV master wait                               891        0.01          0.90
  ASM file metadata operation                   467        0.00          0.03
  log file sequential read                    14398        0.62        821.20 -- , как и основное по времени ожидание
  latch free                                      1        0.01          0.01

********************************************************************************
Реклама

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

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

RSS feed for comments on this post. TrackBack URI

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

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

Логотип WordPress.com

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

Google+ photo

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

Фотография Twitter

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

Фотография Facebook

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

w

Connecting to %s

Блог на WordPress.com.

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