In this post, I will use the seeks.d and iopattern DTrace scripts, which are available as part of the DTraceToolKit (This toolkit is an extremely useful collection of scripts created by Brendan Gregg), to view the I/O access patterns typical of Oracle. DTrace is able to capture data throughout the kernel and so the job of finding access patterns has been greatly simplified.
The system on which these examples are being run has redo logs on one disk, datafiles on another disk and the control file is on another disk.
To get system-wide access patterns, the iopattern script can be used. Sample output is as follows:
# ./iopattern
%RAN %SEQ  COUNT    MIN    MAX    AVG     KR     KW
100    0      7   4096   8192   7606      4     48
0    0      0      0      0      0      0      0
0    0      0      0      0      0      0      0
100    0      6   8192   8192   8192      0     48
0    0      0      0      0      0      0      0
0    0      0      0      0      0      0      0
100    0      6   8192   8192   8192      0     48
0    0      0      0      0      0      0      0
0    0      0      0      0      0      0      0
100    0      6   8192   8192   8192      0     48
0    0      0      0      0      0      0      0
This output was generated on an idle system (0.04 load). You can see that the iopattern script provides the percentage of random and sequential I/O on the system. During this monitoring period while the system was idle, all the I/O was random. The iopattern script also provides the number and total size of the I/O operations performed during the sample period, and it provides the minimum, maximum, and average I/O sizes.
Now, look at the output generated from the iopattern script during a period of heavy database load:
# ./iopattern
%RAN %SEQ  COUNT    MIN    MAX    AVG     KR     KW
92    8     69   4096   8192   6589    304    140
86   14     69   4096   8192   5995    228    176
82   18     67   4096   8192   5257     64    280
84   16     19   4096   8192   6036     40     72
77   23     22   4096   8192   4282      0     92
88   12     68   4096 1015808  21744   1120    324
97    3     67   4096   8192   7274    400     76
89   11     66   4096   8192   6392    276    136
90   10     71   4096   8192   6345    216    224
87   13     62   4096   8192   5879    184    172
90   10     10   4096   8192   6553     40     24
100    0     17   8192   8192   8192     88     48
87   13     33   4096 1048576  38353   1168     68
86   14     65   4096   8192   6049    236    148
As you can see from the above output, the majority of the I/O which occurs during this period is random. In my mind, this one indication that the type of I/O typical in an OLTP environment is random (as we would expect).
To get the I/O distribution for each disk, the seeks.d script can be used. This script measures the seek distance for disk events and generates a distribution plot. This script is based on the seeksize.d script provided with the DTraceToolKit and is available in the Solaris Internals volumes.
Sample output from the seeks.d script is show below:
# ./seeks.dTracing... Hit Ctrl-C to end.^C
Tracing... Hit Ctrl-C to end.
^C

cmdk0
        value  ------------- Distribution ------------- count
           -1 |                                         0
            0 |@@@@@@@@@@@@@@@@@@@@@                    43
            1 |                                         0
            2 |                                         0
            4 |                                         0
            8 |                                         0
           16 |                                         0
           32 |                                         0
           64 |                                         0
          128 |@@@@@@@@@@@@@                            26
          256 |@@@@@@                                   12
          512 |                                         0

sd1
        value  ------------- Distribution ------------- count
        32768 |                                         0
        65536 |@@@@@@@@@@@@@@@@@@@@                     1
       131072 |                                         0
       262144 |                                         0
       524288 |                                         0
      1048576 |@@@@@@@@@@@@@@@@@@@@                     1
      2097152 |                                         0
This output was generated when the system was idle as before. This output summarizes the seeks performed by each disk on the system. The sd1 disk in the output above is the disk on which my Oracle datafiles reside. The value column in the output indicates the size of the seek that was performed in bytes. This indicates some random I/O on this disk since the length of the seeks are quite large. The disk on which the redo logs are located does not show up in the output above since no I/O is being generated on that disk (sd2). Now, it is interesting to look at the output generated from the seeks.d script during a period when the database is under a heavy load.
# ./seeks.d
Tracing... Hit Ctrl-C to end.
^C

cmdk0
        value  ------------- Distribution ------------- count
           -1 |                                         0
            0 |@@@@@@@@@@@@@@@@@@@@@@@                  18
            1 |                                         0
            2 |                                         0
            4 |                                         0
            8 |                                         0
           16 |                                         0
           32 |                                         0
           64 |                                         0
          128 |@@@@@@@@@@@@@                            10
          256 |@@@@@                                    4
          512 |                                         0

sd2
        value  ------------- Distribution ------------- count
           -1 |                                         0
            0 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@           430
            1 |                                         0
            2 |                                         0
            4 |                                         0
            8 |@@@@@@@@                                 120
           16 |@                                        11
           32 |                                         3
           64 |                                         0
          128 |                                         0
          256 |                                         0
          512 |                                         0
         1024 |                                         0
         2048 |                                         0
         4096 |                                         0
         8192 |                                         0
        16384 |                                         0
        32768 |                                         0
        65536 |                                         6
       131072 |                                         0

sd1
        value  ------------- Distribution ------------- count
          512 |                                         0
         1024 |@@@                                      31
         2048 |                                         5
         4096 |                                         0
         8192 |                                         0
        16384 |                                         0
        32768 |                                         0
        65536 |@@                                       23
       131072 |@@@@@@@@                                 92
       262144 |@@@@@@@                                  73
       524288 |@                                        6
      1048576 |                                         4
      2097152 |@                                        14
      4194304 |@@@                                      29
      8388608 |@@@@                                     40
     16777216 |@@@@@                                    56
     33554432 |@@@@@@                                   65
     67108864 |                                         0
This time the disk on which the redo logs are located shows up as there is activity occurring on it. You can see that most of this activity is sequential as most of the events incurred a zero length seek. This makes sense as the log writer background process (LGWR) writes the redo log files in a sequential manner. However, you can see that I/O on the disk which contains the Oracle datafiles is random as seen by the distributed seek lengths (up to the 33554432 to 67108864 bucket).
The above post did not really contain any new information but I thought it would be cool to show a tiny bit of the possibility that DTrace has. This is one of the coolest tools I have used in the last year and is one of the many reasons why I have become a huge Solaris fan!

blog comments powered by Disqus

Published

25 November 2008

Category

oracle