Re: severe performance issues when flashback is on

From: <Laimutis.Nedzinskas_at_seb.lt>
Date: Thu, 20 Oct 2011 10:43:17 +0300
Message-ID: <OFDA3AD00C.548D9056-ONC225792F.002A1BCD-C225792F.002A6A94_at_seb.lt>



flashback is sloooow.

One aspect (LOB related) I blogged myself: http://laimisnd.wordpress.com/2011/03/25/lobs-and-flashback-database-performance/

That one and the orther aspects are very honestly written in this:

Flashback Database Best Practices & Performance [ID 565535.1]

Example:
"For batch direct load workloads, flashback can cause as much as 30% overhead in Oracle 10g.  In Oracle 11g, users can experience 2%-30% flashback overhead for batch direct workloads.  " I second that - recently we switched off flashback on one DW-alike database cause after tuning AWR was showing flashback events at the top.


Please consider the environment before printing this e-mail

                                                                                                                                              
  From:       LS Cheng <exriscer_at_gmail.com>                                                                                                   
                                                                                                                                              
  To:         Oracle Mailinglist <oracle-l_at_freelists.org>                                                                                     
                                                                                                                                              
  Date:       2011.10.19 21:22                                                                                                                
                                                                                                                                              
  Subject:    severe performance issues when flashback is on                                                                                  
                                                                                                                                              





Hi
I am currently reviweing some batch processes, most of them are INSERT... SELECT, in production environment where flashback is enabled the speed is quite slow compared with QA environment where flashback is off.

I traced one single INSERT SELECT statement and noticed that there are always tons of physical reads (db file sequential read) in the table segment
where I am inserting when flashback is on. Even I have a pretty lareg buffer
cache and running the same insert more than once (so the second execution can use buffer reads), the same test with flashback off works as expected. I
dont see any reasoning why db file sequential reads always occur.

I expected overheads with flashback but it just seems too much overhead, I did the same test in 11.2.0.2 and 10.2.0.5 and both shows similar behaviour.
Am I missing anything?

Thanks

a simple test when flashback is on with 11.2.0.2 Linux x64, these tables are
plain tables, no indexes:

create table t1
as
select * from dba_source
union all
select * from dba_source
union all
select * from dba_source
union all
select * from dba_source
union all
select * from dba_source
union all
select * from dba_source;

create table t2
as
select * from t1
where 1 = 0;

insert into t2
select * from t1;

Elapsed: 00:00:25.45

Statistics


        989  recursive calls
     165874  db block gets
      41894  consistent gets
      36232  physical reads
  121920148  redo size
        841  bytes sent via SQL*Net to client
        788  bytes received via SQL*Net from client
          3  SQL*Net roundtrips to/from client
         10  sorts (memory)
          0  sorts (disk)
     899628  rows processed

10046 tracefile

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


Parse        2      0.00       0.00          0          1
0           0
Execute      2     11.32      52.25      54331      86771     327219
1799256
Fetch        0      0.00       0.00          0          0
0           0

------- ------ -------- ---------- ---------- ---------- ----------

total 4 11.32 52.26 54331 86772 327219 1799256

Elapsed times include waiting on following events:

  Event waited on                             Times   Max. Wait  Total
Waited
  • Waited ----------
    db file sequential read 36759 1.06 30.21* --> this slows the insert* log buffer space 4 0.47 0.60 flashback buf free by RVWR 17 0.99 4.98 log file switch (checkpoint incomplete) 6 2.33 4.72 log file switch completion 4 0.11 0.30 SQL*Net message to client 2 0.00 0.00 SQL*Net message from client 2 0.00 0.00 db file scattered read 212 0.53 3.06
    • second execution

Elapsed: 00:00:26.86

Statistics


        189  recursive calls
     161345  db block gets
      44974  consistent gets
      18099  physical reads
  121684968  redo size
        844  bytes sent via SQL*Net to client
        788  bytes received via SQL*Net from client
          3  SQL*Net roundtrips to/from client
          1  sorts (memory)
          0  sorts (disk)
     899628  rows processed


without flashback:
Elapsed: 00:00:08.12

Statistics


        831  recursive calls
     146925  db block gets
      41943  consistent gets
          2  physical reads
  121923948  redo size
        830  bytes sent via SQL*Net to client
        788  bytes received via SQL*Net from client
          3  SQL*Net roundtrips to/from client
          1  sorts (memory)
          0  sorts (disk)
     899628  rows processed

Elapsed: 00:00:10.65

Statistics


        180  recursive calls
     143188  db block gets
      44656  consistent gets
          0  physical reads
  121702204  redo size
        839  bytes sent via SQL*Net to client
        788  bytes received via SQL*Net from client
          3  SQL*Net roundtrips to/from client
          1  sorts (memory)
          0  sorts (disk)
     899628  rows processed

10046 tracefile

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


Parse        2      0.00       0.00          0          1
0           0
Execute      2      3.83      18.74          2      86469     290113
1799256
Fetch        0      0.00       0.00          0          0
0           0

------- ------ -------- ---------- ---------- ---------- ----------

total 4 3.84 18.74 2 86470 290113 1799256

Elapsed times include waiting on following events:

  Event waited on                             Times   Max. Wait  Total
Waited
  • Waited ----------
    Disk file operations I/O 2 0.00 0.00 db file sequential read 2 0.00 0.00 log buffer space 11 0.78 2.90 log file switch completion 6 0.40 0.87 log file switch (checkpoint incomplete) 8 3.70 10.56 SQL*Net message to client 2 0.00 0.00 SQL*Net message from client 2 0.00 0.00
--
http://www.freelists.org/webpage/oracle-l





--
http://www.freelists.org/webpage/oracle-l
Received on Thu Oct 20 2011 - 02:43:17 CDT

Original text of this message