Flashback logging overhead: ‘db file sequential read’ on UNDO tablespace

By Franck Pachot

.
in my previous post I’ve reproduced an issue where some bulk insert into a GTT was generating too much undo. But the real case I encountered was worse: the insert was reading lot of UNDO. And lot of this undo was read from disk.

Jonathan Lewis has pointed me to a possible explanation he has given (here)

I’ve reproduced the testcase from the previous post after setting the database to do flashback logging. Here are the results, comparing tkprof with and without flashback logging, for the 3 kinds of inserts I’ve tested:

               count    cpu  elapsed  disk  query current   rows
              ------  ----- -------- ----- ------ -------  -----

• row-by-row insert:

FLASHBACK OFF 100000   24.18    25.11     0   1918  314937 100000
FLASHBACK ON  100000   21.50    21.51  2924   1930  317916 100000

• bulk insert:

FLASHBACK OFF    100    0.78     0.78     0   2009   68277 100000
FLASHBACK ON     100    0.88     0.90  1204   2016   69532 100000

• bull insert with APPEND_VALUES

FLASHBACK OFF    100    0.85     1.08     0   6908    7421 100000
FLASHBACK ON     100    1.02     1.68   502   6912    7945 100000

So it’s clear. In FLASHBACK ON we read the same number of blocks, but some of them involve a physical read, where it’s not the case when we don’t do flashback logging.

When Oracle creates new block that overwrite entirely what was stored before into it, then there is no need to read the previous values. The block is directly written in the buffer cache. They are counted as a buffer get, but there is nothing to read – so no disk read at all.

But when database is in FLASHBACK ON, or has a guaranteed restore point, then all overwritten blocks must be logged into the flashback logs because a flashback database has to write them back. So it must be read before being overwritten.

That concern blocks from dropped (or truncated) objects. And that concerns also the expired undo blocks that are reused. And in that case, because they expired after a while (undo_retention) there are good chance that they are not anymore in buffer cache. Consequence is disk reads from UNDO tablespace.

physical reads for flashback new

Here are the statistics of the 3 insert cases from previous blog, where I’ve added the ‘physical reads for flashback new’ one:

NAME                                   VALUE
--------------------------------- ----------
physical reads for flashback new        2924
redo entries                          203086
redo size                           36492404
undo change vector size             20673192
 
NAME                                   VALUE
--------------------------------- ----------
physical reads for flashback new        1204
redo entries                           31769
redo size                            9647772
undo change vector size              6867248
 
NAME                                   VALUE
--------------------------------- ----------
physical reads for flashback new         506
redo entries                            6506
redo size                            4105060
undo change vector size              2997752

When we generate 20673192 bytes into 8k blocks, we expect to write at least to 20673192/8192=2524 block. This matches the 2924 ‘physical reads for flashback new’. And it’s exactly the 2924 ‘disk’ reads that we see in the tkprof above.

Measuring the impact

Now back to the initial issue where I had lot of ‘db file sequential read’ on UNDO (file#=2)

Here are some statistics from a 1 hour Statspack:

Top 5 Timed Events                                                    Avg %Total
~~~~~~~~~~~~~~~~~~                                                   wait   Call
Event                                            Waits    Time (s)   (ms)   Time
----------------------------------------- ------------ ----------- ------ ------
db file sequential read                      9,896,083      14,338      1   32.8
 
Statistic                                      Total     per Second    per Trans
--------------------------------- ------------------ -------------- ------------
physical reads for flashback new           1,196,359          208.9         14.3
undo change vector size                7,100,240,724    1,240,000.1     84,960.6
flashback log write bytes             16,034,947,072    2,800,375.0    191,872.2
flashback log writes                          45,350            7.9          0.5

So from that we know that:

• 1,196,359/9,896,083=12% of ‘db file sequential read’ is for ‘physical reads for flashback new’
• and 16,034,947,072/7,100,240,724= half of flashback logging is for undo

This is the overhead of flashback logging. Reducing the undo generated (see previous block) can be a good recommendation. And besides the flashback logging issue, it will reduce the generated redo as well.