Oracle mechanics

21.03.2018

ASH_IO_WAITSBY.SQL

Filed under: Oracle,Scripts — Игорь Усольцев @ 00:46
Tags: ,

По причине ошибки ORA-00600: Internal Error Code, Arguments: [qmxtcsxmlt:xmltype] (Doc ID 2079499.1), характерной для использования функции XMLAgg в бд состояния MOUNTED (standby or non-standby), переписал скрипт ASH_IO_WAITS.SQL для поиска наиболее активных в WAIT_CLASS-ах ‘User I/O‘ и ‘System I/O‘ процессов/запросов на STANDBY и прочих MOUNTED системах

Например, при замедлившемся накате standby (в отсутствии Read Only пользовательских запросов) можно было наблюдать аномально интенсивную IO активность пользовательских процессов RFS в части control file sequential read и RFS write:

SQL> @ash_io_waitsby blocks 10 "1 = 1"
 
INST SQL_PROCESS   SUM(WAIT_COUNT) waits%  SUM(REQUESTS) reqs%   SUM(BLOCKS) blocks% event(waits:requests:blocks)
---- ------------- --------------- ------- ------------- ------- ----------- ------- ------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
   1 (USER)                 156134   73.56        156134   11.11     1269165   39.07 control file sequential read(11699:11699:1123994); RFS write(105538:105538:105538); RMAN backup & recovery I/O(29486:29486:29486); Data file init write(6877:6877:6877); control file parallel write(736:736:1472); Disk file operations I/O(1049:1049:1049); Disk file Mirror Read(641:641:641); Log archive I/O(108:108:108)
   1 (DBW.)                  14696    6.92       1207318   85.94     1207318   37.16 db file parallel write(14696:1207318:1207318)
   1 (PR..)                  17569    8.28         17569    1.25      523541   16.12 log file sequential read(3984:3984:506025); recovery read(13311:13311:13311); control file sequential read(120:120:4020); direct path write(91:91:91); control file parallel write(31:31:62); direct path read(31:31:31); Disk file operations I/O(1:1:1)
   1 (ARC.)                  16169    7.62         16169    1.15      234540    7.22 control file sequential read(8614:8614:226728); Log archive I/O(7104:7104:7104); control file parallel write(280:280:560); Disk file Mirror Read(106:106:106); Disk file operations I/O(40:40:40); log file sequential read(25:25:2)
   1 (CKPT)                   4624    2.18          4624    0.33        8932    0.27 control file parallel write(3301:3301:6602); control file sequential read(1007:1007:2014); Disk file Mirror Read(316:316:316)
   1 a5xcbum9zpyzn            1750    0.82          1750    0.12        2912    0.09 control file sequential read(1162:1162:2324); Disk file Mirror Read(588:588:588)
   1 6jaghrm3vy74f             769    0.36           769    0.05        1303    0.04 control file sequential read(534:534:1068); Disk file Mirror Read(235:235:235)
   1 89z2u0fdrdg66             397    0.19           397    0.03         761    0.02 control file sequential read(364:364:728); Disk file Mirror Read(33:33:33)
   1 (M...)                     50    0.02            50    0.00          92    0.00 control file sequential read(42:42:84); Disk file Mirror Read(8:8:8)
   1 7mgr3uwydqq8j              13    0.01            13    0.00          22    0.00 control file sequential read(9:9:18); Disk file Mirror Read(4:4:4)
 
10 rows selected

в сравнении с нормальным поведением, где RFS заметен лишь на 4-м месте с 5% прочитанных/записанных blocks:

SQL> @ash_io_waitsby blocks 10 "1 = 1"
 
INST SQL_PROCESS   SUM(WAIT_COUNT) waits%  SUM(REQUESTS) reqs%   SUM(BLOCKS) blocks% event(waits:requests:blocks)
---- ------------- --------------- ------- ------------- ------- ----------- ------- -----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
   1 (ARC.)                   7091   19.18          7091    1.53      879177   51.71 log file sequential read(6817:6817:867577); control file sequential read(190:190:11482); control file parallel write(34:34:68); Disk file operations I/O(27:27:27); Disk file Mirror Read(18:18:18); Log archive I/O(5:5:5)
   1 (DBW.)                  11601   31.37        438684   94.52      438684   25.80 db file parallel write(11601:438684:438684)
   1 (PR..)                   5010   13.55          5010    1.08      246892   14.52 control file sequential read(1891:1891:161866); log file sequential read(662:662:82483); recovery read(1931:1931:1931); direct path write(295:295:295); control file parallel write(86:86:172); direct path read(123:123:123); Disk file Mirror Read(13:13:13); Disk file operations I/O(9:9:9)
   1 (USER)                   2627    7.10          2627    0.57       89009    5.23 control file sequential read(973:973:87244); RFS random i/o(854:854:854); control file parallel write(281:281:562); RFS write(261:261:261); Disk file Mirror Read(43:43:43); Disk file operations I/O(34:34:34); log file sequential read(165:165:10); log file single write(16:16:1)
   1 aw0n9k059ss1k            5895   15.94          5933    1.28       37251    2.19 direct path read(1304:1304:32622); db file sequential read(4589:4589:4589); db file parallel read(2:40:40)
   1 (CKPT)                   4239   11.46          4239    0.91        8327    0.49 control file parallel write(3495:3495:6990); control file sequential read(593:593:1186); Disk file Mirror Read(151:151:151)
   1 a5xcbum9zpyzn             196    0.53           196    0.04         324    0.02 control file sequential read(128:128:256); Disk file Mirror Read(68:68:68)
   1 bd502nbh9abbs              96    0.26            96    0.02         229    0.01 db file scattered read(3:3:136); db file sequential read(93:93:93)
   1 6jaghrm3vy74f              75    0.20            75    0.02         127    0.01 control file sequential read(52:52:104); Disk file Mirror Read(20:20:20); Disk file operations I/O(3:3:3)
   1 89z2u0fdrdg66              48    0.13            48    0.01          93    0.01 control file sequential read(45:45:90); Disk file Mirror Read(3:3:3)
 
10 rows selected

Более отчётливо проблема идентифицируется в выводе другого скрипта:

SQL> @ash_wait_tree4stby "program like 'oracle@% (TNS V1-V3)'" -- session_type = 'FOREGROUND'
LVL BLOCKING_TREE                  EVENT                             WAITS_COUNT SESS_COUNT     AVG_WAIT_TIME_MS EST_WAITS   EST_AVG_LATENCY_MS
--- ------------------------------ --------------------------------  ----------- ---------- -------------------- --------- --------------------
  1 FOREGROUND                     RFS write                             106199         42                   987     41133                  820 -- *
  1 FOREGROUND                     control file sequential read            7613         46                   740     19275                  363 -- *
  1 FOREGROUND                     enq: CF - contention                    3390         38                   947       166                  997
  1 FOREGROUND                     SQL*Net vector data from client         1804         43                   158     70948                   25
  1 FOREGROUND                     Disk file operations I/O                1012         36                   993       109                  977 -- *
  1 FOREGROUND                     control file parallel write              661         40                   953       574                  699 -- *
  1 FOREGROUND                     Disk file Mirror Read                    383         29                   699      1664                  222
  1 FOREGROUND                     RFS close                                234         19                   982        39                  959
  1 FOREGROUND                     Log archive I/O                          108         17                   997        38                  893
  1 FOREGROUND                     RFS create                                58          1                  1000        58                 1000
  1 FOREGROUND                     Data Guard: RFS disk I/O                  30          1                  1000        30                 1000
  1 FOREGROUND                     RFS ping                                   5          2                     0     31404                    0
  1 FOREGROUND                     RFS dispatch                               2          2                     1    167199                    0
  2   (ARC                         control file sequential read            2594          3                   608     21594       118
  2   FOREGROUND                   control file sequential read             293         16                   787       541       468
  2   FOREGROUND                   control file parallel write              246         22                  1037       726       285
  2   (ARC                         control file parallel write              147          2                  1048       264       421
  2   (ARC                         enq: CF - contention                      45          1                  1226         2      1000
  2   FOREGROUND                   Log archive I/O                           24          5                  1154         7      1000
  2   (PR0                         direct path write                         16          1                   176       316        51
  2   (PR0                         control file sequential read              11          1                    57       325        34
  2   (PR0                         direct path read                           6          1                    75       177        34
  2   (TNS                         control file parallel write                5          2                  1306        14       313
  2   FOREGROUND                   RFS close                                  3          2                  1135         6       500
  3     FOREGROUND                 control file sequential read              45          1                   814        71       506
 
25 rows selected

— где заметно увеличение как ср.длительности IO ожиданий, фиксируемой в V$ACTIVE_SESSION_HISTORY.TIME_WAITED — столбец AVG_WAIT_TIME_MS (*), так и оценки по методике разработчиков ASH — EST_AVG_LATENCY_MS — сотни мс!, что ненормально и подтверждается iostat(**):

avg-cpu:  %user   %nice %system %iowait  %steal   %idle
           2.62    0.00    0.33   29.22    0.00   67.82

Device:         rrqm/s   wrqm/s     r/s     w/s    rMB/s    wMB/s avgrq-sz avgqu-sz   await  svctm  %util
sdz               0.00     0.00    0.00    0.00     0.00     0.00     0.00     0.00    0.00   0.00   0.00
sdy               0.00     0.00    1.00    0.00     0.00     0.00     1.00     0.01    7.50   7.50   0.75
sdaa              0.00     0.00    0.00    0.00     0.00     0.00     0.00     0.00    0.00   0.00   0.00
sdab              0.00     0.00    0.00    0.00     0.00     0.00     0.00     0.00    0.00   0.00   0.00
sdp              12.00     1.00   67.50  161.00     5.12     7.46   112.78    82.83  395.32   4.09  93.55
sdl              15.00     1.00  107.50  157.50    10.64     5.65   125.87    32.05  125.16   3.48  92.20
sdg              15.00     1.00   76.00  181.00    10.01     6.52   131.72    69.98  280.34   3.72  95.60
sdd              13.50     0.50   58.50  123.00     6.42     4.51   123.33    71.94  341.99   5.17  93.90
sdm              14.50     3.50   78.00  184.00     8.64     7.15   123.44    41.89  168.83   3.44  90.10
sdo              20.00     0.50  105.00  201.00    12.06     6.48   124.08    83.01  342.38   3.17  96.95
sdb              15.00     6.50   84.50  176.00     8.13     4.91   102.57   252.66 1052.77   3.84 100.00 -- **
sdt              19.00     7.00   81.50   54.50     9.87     2.57   187.35   219.66  535.99   7.35 100.00 -- **
sdi               9.00     1.50   75.50  186.00     5.16     7.67   100.50    38.52  216.95   3.00  78.55
sdw              12.00     2.00   76.50  183.50     6.46     6.01    98.28   109.63  442.21   3.75  97.40
sdv              16.00     1.00   90.00  183.00     9.89     6.44   122.49   102.11  433.99   3.66 100.00 -- **
sds              10.50     1.00   84.00  168.00     7.66     6.40   114.29    29.46  126.25   2.97  74.75
sdq              22.50     4.50   69.50  143.50     8.60     4.14   122.52    98.57  390.70   4.60  97.90
sdr              18.00     7.00   68.00  198.50    10.45     7.49   137.86   166.59  795.57   3.75 100.00 -- **
sdc              12.00     1.00   71.50  189.50     9.52     7.51   133.62   127.89  660.01   3.83 100.00 -- **
sdu              12.50     1.00   89.50  163.00     9.18     6.59   127.94    48.84  200.45   3.42  86.40
sde              12.50     1.50   71.50  182.50     6.80     6.64   108.39    52.54  235.79   3.42  86.75
sdk              15.50     4.50   70.00   93.50     8.03     3.63   145.98    89.62  270.91   5.98  97.85
sdf              17.50     2.00   92.50  159.50    11.88     6.68   150.83    38.79  168.57   3.47  87.55
sda              12.00     2.00   80.00  185.50     8.09     7.58   120.86    32.71  129.09   2.89  76.75
sdn              10.50     1.00   65.00  188.50     6.18     8.44   118.17    36.99  224.55   3.20  81.05
sdx              15.50     0.00   77.50  184.50     9.95     6.62   129.59    47.03  272.31   3.57  93.45
sdh              10.00     2.50   83.50  133.00     8.15     4.99   124.27    18.49   90.93   3.00  64.95
sdj              15.00     0.50   82.50  240.00     9.61     8.74   116.50   108.52  485.47   3.10 100.00
Реклама

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

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

RSS feed for comments on this post. TrackBack URI

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

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

Логотип WordPress.com

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

Google+ photo

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

Фотография Twitter

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

Фотография Facebook

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

Connecting to %s

Блог на WordPress.com.

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