Learning is not a spectator sport

February 5, 2013

Lob CACHE vs NOCACHE – impact on flashback logging

Filed under: Uncategorized — connormcdonald @ 6:55 pm

 

I was doing some work for a client, and LOB processing seemed incredibly slow.  After some poking around, it appears that LOB processing is quite sensitive when it comes to flashback mode in the database. Test bench is a simple table with three clobs. 4kb will be insert into each clob in 5000 individual inserts. The "wait" option is applied to the commit to ensure that the standard PLSQL commit optimizations do not come into play.

Database is 11.2.0.1 running in flashback mode.

SQL> create table t_nocache ( x1 clob, x2 clob, x3 clob )
  2    lob ( x1 ) store as ( nocache )
  3    lob ( x2 ) store as ( nocache )
  4    lob ( x3 ) store as ( nocache )
  5    ;

Table created.

SQL> set timing on
SQL> begin
  2  for i in 1 .. 5000 loop
  3    insert into t_nocache values (rpad('x',4000,'x'),rpad('x',4000,'x'),rpad('x',4000,'x'));
  4    commit WRITE WAIT IMMEDIATE;
  5  end loop;
  6  end;
  7  /

PL/SQL procedure successfully completed.

Elapsed: 00:00:13.21

So for NOCACHE, the elapsed time is 13 seconds, and then we can inspect where the time was lost:

SQL> @sessev
Sid required: 17

EVENT                                        TOTAL_WAITS TOTAL_TIMEOUTS       SECS PCT        MAX_WAIT
-------------------------------------------- ----------- -------------- ---------- -------- ----------
Data file init write                                   2              0          0 00.00%            0
events in waitclass Other                              2              0          0 00.00%            0
db file single write                                   2              0          0 00.00%            0
control file parallel write                           14              0          0 00.00%            0
CPU                                                                              0 00.00%            0
log file switch (checkpoint incomplete)                2              0        .01 00.11%            1
log file switch completion                             3              0        .01 00.11%            0
control file sequential read                          70              0        .01 00.11%            0
Disk file operations I/O                              11              0        .04 00.44%            1
db file sequential read                              563              0        .13 01.44%            2
buffer busy waits                                      1              0        .25 02.77%           25
direct path write                                  14996              0       1.19 13.16%            2
log file sync                                       4999              0       1.82 20.13%            7
direct path read                                   14865              0       2.24 24.78%            4
flashback log file sync                            14999              0       3.34 36.95%            9

15 rows selected.

SQL> select * from V$FLASHBACK_DATABASE_STAT;

BEGIN_TIME           END_TIME             FLASHBACK_DATA    DB_DATA  REDO_DATA ESTIMATED_FLASHBACK_SIZE
-------------------- -------------------- -------------- ---------- ---------- ------------------------
05-feb-2013 15:37:02 05-feb-2013 15:42:06      125911040  126820352  136450048                        0

Test 1 – CACHE lob

SQL> create table t_cache ( x1 clob, x2 clob, x3 clob )
  2    lob ( x1 ) store as ( cache )
  3    lob ( x2 ) store as ( cache )
  4    lob ( x3 ) store as ( cache )
  5    ;

SQL> set timing on
SQL> begin
  2  for i in 1 .. 5000 loop
  3    insert into t_cache values (rpad('x',4000,'x'),rpad('x',4000,'x'),rpad('x',4000,'x'));
  4    commit WRITE WAIT IMMEDIATE;
  5  end loop;
  6  end;
  7  /

PL/SQL procedure successfully completed.

Elapsed: 00:00:07.89

So for CACHE, the elapsed time is 8 seconds, and then we can inspect where the time was lost:

SQL> @sessev
Sid required: 17

EVENT                                        TOTAL_WAITS TOTAL_TIMEOUTS       SECS PCT        MAX_WAIT
-------------------------------------------- ----------- -------------- ---------- -------- ----------
Data file init write                                   1              0          0 00.00%            0
control file sequential read                          35              0          0 00.00%            0
control file parallel write                            7              0          0 00.00%            0
events in waitclass Other                              1              0          0 00.00%            0
flashback log file sync                                1              0          0 00.00%            0
CPU                                                                              0 00.00%            0
db file single write                                   1              0          0 00.00%            0
Disk file operations I/O                               8              0        .02 00.38%            1
log file switch completion                             1              0         .1 01.88%           10
buffer busy waits                                      1              0        .25 04.71%           25
log file switch (checkpoint incomplete)                2              0        .45 08.47%           45
log file sync                                       4998              0       1.24 23.35%            6
db file sequential read                             7136              0       1.24 23.35%            4
db file scattered read                              8415              0       2.01 37.85%            2

14 rows selected.

There is an increase in scattered read (ie, bringing blocks into the cache) but the flashback log sync wait has vanished.


SQL> select * from V$FLASHBACK_DATABASE_STAT;

BEGIN_TIME           END_TIME             FLASHBACK_DATA    DB_DATA  REDO_DATA ESTIMATED_FLASHBACK_SIZE
-------------------- -------------------- -------------- ---------- ---------- ------------------------
05-feb-2013 15:37:02 05-feb-2013 15:44:18      128581632  129851392  208777728                        0

Flashback log size growth is minimal (ie it was already 125MB from the previous test, and had grown to 128M). Presumably as the flashback process kicks in from time to time in background, this would be expected to grow, but it is no longer synchronous to the foreground process.

About these ads

3 Comments »

  1. Great! Recently my customer asked me about possible ways to reduce flashback log amount. It seems that we can do something now.
    Thank you.

    Comment by Yuri — February 5, 2013 @ 7:07 pm

  2. Nice finding, have You tried with securefiles lobs ?
    Regards
    GregG

    Comment by goryszewskig — February 6, 2013 @ 7:58 pm

  3. [...] Connon McDonald has written about Lob CACHE vs NOCACHE – impact on flashback logging. [...]

    Pingback by Latest data Industry news round up, Log Buffer #306 — February 8, 2013 @ 10:45 pm


RSS feed for comments on this post. TrackBack URI

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s

The WordPress Classic Theme. Blog at WordPress.com.

Follow

Get every new post delivered to your Inbox.

Join 80 other followers

%d bloggers like this: