Tuesday, January 04, 2011

Database smart flash cache wait events

When you enable the database smart flash cache and start using it you will see new wait events related to that. These events help to find out if the problem is about the flash cache or not.

The ones I faced till now are "db flash cache single block physical read", "db flash cache multiblock physical read" and "write complete waits: flash cache". These are from a 11.2.0.1 database using the F5100 flash array as the database smart flash cache.

db flash cache single block physical read

"db flash cache single block physical read" is the flash cache equivalent of "db file sequential read". Read waits from the flash cache are not accounted for in the "db file sequential read" event and have their own wait event. The following is from an AWR report of 30 mins from a database using the database smart flash cache.


Top 5 Timed Foreground Events
    EventWaitsTime(s)Avg wait (ms)% DB timeWait Class
    db file sequential read649,57615,4692447.33User I/O
    DB CPU 10,451 31.98 
    db flash cache single block physical read11,217,3035,044015.43User I/O
    buffer busy waits71,3231,845265.65Concurrency
    log file switch (checkpoint incomplete)2,3052511090.77Configuration


    There are over 11 million "db flash cache single block physical read" waits which took about 0.44ms on average (AWR reports it as 0ms). "db file sequential read" waits are over 600,000. This means we had a high flash cache hit ratio, most of the reads were coming from the flash cache, not the disks.

    This is the wait event histogram from the same AWR report.




    % of Waits
    Event
    Total Waits
    <1ms
    <2ms
    <4ms
    <8ms
    <16ms
    <32ms
    <=1s
    >1s
    db flash cache single block physical read
    11.2M
    99.0
    .9
    .1
    .0
    .0
    .0
    .0


    99% of all flash cache single block reads were under 1ms, none of them are over 4ms.

    db flash cache multiblock physical read


    "db flash cache multiblock physical read" is the flash cache equivalent of "db file scattered read". It is the event we see when we are reading multiple blocks from the flash cache. The AWR report I am using in this post does not contain many multiblock operations but here is the event from the foreground wait events section.


    Event
    Waits
    %Time -outs
    Total Wait Time (s)
    Avg wait (ms)
    Waits /txn
    % DB time
    db flash cache multiblock physical read
    1,048
    0
    1
    1
    0.00
    0.00


    We had 1048 waits of 1ms on average.



     
    % of Waits
    Event
    Total Waits
    <1ms
    <2ms
    <4ms
    <8ms
    <16ms
    <32ms
    <=1s
    >1s
    db flash cache multiblock physical read
    1171
    83.2
    12.4
    3.2
    .9
    .3




    The wait event histogram shows that again most of the waits are below 1ms with some being up to 16ms.

    write complete waits: flash cache

    This is the wait event we see when DBWR is trying to write a block from the buffer cache to the flash cache and a session wants to modify that block. The session waits on this event and goes on with the update after DBWR finishes his job. You can find a good explanation and a good example for this in Guy Harrison's post. Here is the event and its histogram in the same AWR report I have.


    Event
    Waits
    %Time -outs
    Total Wait Time (s)
    Avg wait (ms)
    Waits /txn
    % DB time
    write complete waits: flash cache
    345
    0
    1
    4
    0.00
    0.00





    % of Waits
    Event
    Total Waits
    <1ms
    <2ms
    <4ms
    <8ms
    <16ms
    <32ms
    <=1s
    >1s
    write complete waits: flash cache
    345
    22.9
    23.2
    27.2
    19.7
    5.5
    .3
    1.2


    I had 345 waits in 30 mins with an average time of 4ms. But the important thing is the contribution of this event to DB time was only 1 second in a 30 minute workload.

    You can see that this event starts climbing up in some situations, especially if you are having a problem with your flash cache device and writes to it start to take longer.

    Here is one case where poor DBWR processes are struggling to write to the flash cache. Database control was showing high waits in the "Configuration" class and those waits were "write complete waits", "free buffer waits" and "write complete waits: flash cache". This was all because my flash cache device was a single conventional HDD, not even an SSD. After changing the db_flash_cache_file parameter to use the F5100 array this picture was not seen anymore.