Summary of the problem: database hit high “Flashback buf free by RVWR” waits. The database had many nocached LOB’s columns in heavily accessed (transactional) tables.
Database version: 10.2.0.4 with flashback database turned on.
Metalink document 565535.1 recommends: “For optimal performance when enabling flashback database on a database with the LOB or SecureFiles LOB data types in use, use the CACHE setting”
Enabling cache for LOB’s helped.
But how is LOB caching related to “Flashback buf free by RVWR” waits?
After email exchange on oracle-l mail-list with Tanel Poder (http://blog.tanelpoder.com/) and Randolf Geist (thanks them very much for help) I made a test to show that flashback log writes can happen once for each row inserted into uncashed LOB column.
For that a single CLOB column table was created:
create table lobtest (lob1 CLOB)
LOB (lob1) store as TESTLOB_STORE (tablespace TESTLOB_STORE nocache) tablespace TESTLOB
The log_buffer was bumped to 20MB according to Metalink docID 565535.1
This pl/sql loop was used to insert 500 rows of size 4000 bytes:
select lob1 into c from lobtest2; -- a table containg one record with LOB value
for i in 1..500 loop
insert into lobtest (lob1) values (rpad(c, 4000, '1'));
Most of the tests yielded the following results:
|physical reads direct (lob)||0||500|
|physical writes direct (lob)||0||500|
|physical reads for flashback new||0||11|
|flashback log writes||17||519|
Note, 502 flashback log writes were generated after 500 rows insert.
A few tests did not have “flashback log writes” increased by 500. This inconsistency can be explained if oracle’s flashback is implemented along the following lines: a flashback to any point in time is done by employing both flashback logs and archive logs. Oracle creates “flashback barrier” (Oracle’s talk) each _flashback_barrier_interval seconds (default is half an hour.) On change it is enough to save block’s before image into flashback log only once for each “flashback barrier.” Test results when matched with timestamps of flashback log files support such explanation.
“flashback log writes” increase on each insert can be explained by the fact that uncashed LOB’s are modified using direct writes into datafiles:
direct modification of datafiles has to be protected from instance crash. When LOB operation modifies a block Oracle has to save the before image of the block to flashback log files. Else on instance crash the before image would be lost.
Oracle’s bug described in Metalink doc “Cannot Reuse a Corrupt Block in Flashback Mode, ORA-1578 [ID 729433.1]” backs this explanation. In short, this bug describes that after database containing nologging objects is restored and the nologging objects are dropped/truncated oracle still tries to save pre-images of corrupted blocks into flashback and fails. Note, those blocks are freed by drop/truncate but flashback process does not know that. It simply tries TO SAVE before image of a block when the block is chosen as write target. If the write is not buffered (i.e. the write is a direct write) then the flashback write must happen immediately, naturally.
BTW, the before mentioned bug article explains directly why “physical reads direct (lob)” statistics increases for each insert: if block is not in cache (and LOB is not by default) then before image needs to be read.