12c I/O debug

By my count there are 109 new v$ and gv$ dynamic performance views in 12c (so far) – and Glen Fawcett has posted a short note on a group that may be of particular benefit to anyone who finds they really have to delve into esoteric I/O problems from time to time. For the less exotic, there’s v$io_outliers and v$lgwrio_outliers which give details about any very slow I/Os – for the more exotic there’s v$kernel_io_outliers – which is the really fascinating one.

Here’s a short session capture focused on v$io_outliers:

SQL> select function_name, wait_event, count(*) from v$io_outlier group by function_name, wait_event;

FUNCTION_NAME      WAIT_EVENT                                                         COUNT(*)
------------------ ---------------------------------------------------------------- ----------
Direct Writes                                                                                1
DBWR                                                                                        11
Buffer Cache Reads db file parallel read                                                     1
Others             control file parallel write                                              32
Others                                                                                      34
Buffer Cache Reads                                                                          10

6 rows selected.

SQL> select io_size, io_latency from v$io_outlier
  2  where wait_event = 'control file parallel write'
  3  order by io_latency;

   IO_SIZE IO_LATENCY
---------- ----------
        16        514
        16        533
        16        545
        16        552
        16        557
        16        588
        16        629
        16        632
        16        639
        16        654
        16        717
        16        739
        16        793
        16        851
        16        859
        16        872
        16        965
        16       1074
        16       1261
        16       1513
        16       2020
        16       2699
        16       3756
        16       3986
        16       4379
        16       4518
        16       4757
        16       4908
        16       9817
        16      10279
        16      13883
        16    2924040

32 rows selected.

SQL> select * from v$event_histogram where event = 'control file parallel write';

WAIT_TIME_MILLI WAIT_COUNT LAST_UPDATE_TIME                        CON_ID
--------------- ---------- ----------------------------------- ----------
              1       6903 02-JUL-13 08.34.51.556059 AM +01:00          0
              2      67990 02-JUL-13 08.36.06.643280 AM +01:00          0
              4       5839 02-JUL-13 08.36.00.635787 AM +01:00          0
              8        909 02-JUL-13 08.32.17.999903 AM +01:00          0
             16        404 02-JUL-13 08.26.17.019774 AM +01:00          0
             32        375 02-JUL-13 08.20.16.049842 AM +01:00          0
             64        316 02-JUL-13 08.25.35.997658 AM +01:00          0
            128        154 02-JUL-13 07.50.17.522235 AM +01:00          0
            256         43 02-JUL-13 07.50.17.268394 AM +01:00          0
            512         37 02-JUL-13 07.50.21.405903 AM +01:00          0
           1024         31 01-JUL-13 01.46.43.419938 PM +01:00          0
           2048          3 02-JUL-13 07.50.14.716905 AM +01:00          0
           4096          2 01-JUL-13 06.47.38.055541 AM +01:00          0
           8192          5 02-JUL-13 06.12.18.501807 AM +01:00          0
          16384          2 01-JUL-13 01.09.21.839019 PM +01:00          0
          32768          1 30-JUN-13 02.39.07.008164 AM +01:00          0
          65536          0                                              0
         131072          0                                              0
         262144          0                                              0
         524288          0                                              0
        1048576          0                                              0
        2097152          0                                              0
        4194304          1 01-JUL-13 11.17.20.600514 AM +01:00          0

23 rows selected.

Unfortunately, although the figures are close, a quick check on the v$event_histogram ranges ending 4096, 8192, 16384 and 32767 don’t quite match the precision figures given in v$io_outlier – there’s a little slippage across the boundaries.

Footnote: looking at the gv$ definitions – v$lgwrio_outlier and v$io_outlier differ only in whether they include or exclude “io_component_id” number 2 (the lgwr component).