Guarantee restore points are useful to have in test environments which allows easy rollback of the database so test could be run again without having to have a new data sets for inserts that can cause primary key violation.
However it seems having a guarantee restore point can cause excessive db file sequential read waits on the undo tablespace for insert statements. This could alter the performance characteristics of test.
Following test case could be used to recreate this behavior. The test environment used here is 11gR2 (11.2.0.3.3).
Create the table for the test case
create table ses_lock (sid varchar2(100) primary key);
Open 3 sql plus session (called 1,2 and 3 from now on) and run the following pl/sql blocks on each one.
On session 1 create and hold a lock to start the concurrent insert process
declare
i pls_integer;
begin
i := dbms_lock.request(10);
end;
/
On session 2 run the PL/SQL for the insert statment
declare
i pls_integer;
begin
i := dbms_lock.request(10,DBMS_LOCK.S_MODE);
for i in 1 .. 100000
loop
insert into ses_lock values (dbms_random.string('x',36));
commit;
end loop;
i := dbms_lock.release(10);
end;
/
Run the same on sesison 3
declare
i pls_integer;
begin
i := dbms_lock.request(10,DBMS_LOCK.S_MODE);
for i in 1 .. 100000
loop
insert into ses_lock values (dbms_random.string('x',36));
commit;
end loop;
i := dbms_lock.release(10);
end;
/
and finaly on session 1 release the lock
declare
j pls_integer;
begin
j := dbms_lock.release(10);
end;
/
This will start concurrent insert into the table.
Investigating the active session history during this period for the insert sql shows that db file sequential reads are on datafile 14 which is the datafile where the table resides.
select inst_id,p1,p1text,sql_id,count(*)
from gv$active_session_history
where sample_time > to_date('2012-09-17 11:37','YYYY-MM-DD HH24:MI')
and event ='db file sequential read'
group by inst_id, p1, p1text, sql_id
order by 5 desc,1 ,2;
INST_ID P1 P1TEXT SQL_ID COUNT(*)
-------- --- ------ ------------- ---------
1 14 file# 7pj2bbx25m1rf 30
SQL> select sql_id,sql_text from v$sql where sql_id='7pj2bbx25m1rf';
SQL_ID SQL_TEXT
------------- ------------------------------------------------------------
7pj2bbx25m1rf INSERT INTO SES_LOCK VALUES (DBMS_RANDOM.STRING('x',36))
SQL> select file_id,tablespace_name from dba_data_files where file_id=14;
FILE_ID TABLESPACE_NAME
------- -----------------
14 BX2KTBS
Delete the rows in the table and create a guarantee restore point
SQL> delete from ses_lock;
200000 rows deleted.
SQL> commit;
It is possible to
create a guarantee restore point in 11gR2 without having flashback on. Before guarantee restore point is created
SQL> select flashback_on from v$database;
FLASHBACK_ON
-------------
NO
After guarantee restore point
SQL> create restore point first_restore guarantee flashback database;
SQL> select flashback_on from v$database;
FLASHBACK_ON
------------------
RESTORE POINT ONLY
Create 3 sql*plus sessions mentioned above and run the insert again.
Querying the active session history afterwards shows that during this test the db file sequential read waits were on the data file used for the undo tablespace and much higher number of waits compared to test without the guarantee restore point.
select inst_id,p1,p1text,sql_id,count(*)
from gv$active_session_history
where sample_time > to_date('2012-09-17 12:02','YYYY-MM-DD HH24:MI')
and event ='db file sequential read'
group by inst_id, p1, p1text, sql_id
order by 5 desc,1 ,2;
INST_ID P1 P1TEXT SQL_ID COUNT(*)
-------- --- ------ ------------- ---------
1 3 file# 7pj2bbx25m1rf 266
SQL> select file_id,tablespace_name from dba_data_files where file_id in (3,14);
FILE_ID TABLESPACE_NAME
-------- ---------------
3 UNDOTBS1
14 BX2KTBS
Dropped the restore point and ran the test again and this time there was no db file sequential waits and as soon as the restore point is created and test carried out see lots of db file sequential read waits on undo tablespace data file. Below is the output of querying active session history for the second test with restore point thus confirming that observed behavior is repeatable with the test case
select inst_id,p1,p1text,sql_id,count(*)
from gv$active_session_history
where sample_time > to_date('2012-09-17 12:20','YYYY-MM-DD HH24:MI')
and event ='db file sequential read'
group by inst_id, p1, p1text, sql_id
order by 5 desc,1 ,2;
INST_ID P1 P1TEXT SQL_ID COUNT(*)
-------- --- ------ ------------- ---------
1 3 file# 7pj2bbx25m1rf 193
-->
SQL tracing could also be used to demonstrate this problem. This is useful if the database is standard edition where use of active session history view is not an option because of license restrictions.
Enable sql tracing for the session
alter session set max_dump_file_size=UNLIMITED;
alter session set tracefile_identifier='before_grp';
alter session set events '10046 trace name context forever, level 12';
Run the insert statement, this time only using on session
declare
i pls_integer;
begin
i := dbms_lock.request(10,DBMS_LOCK.S_MODE);
for i in 1 .. 100000
loop
insert into ses_lock values (dbms_random.string('x',36));
commit;
end loop;
i := dbms_lock.release(10);
end;
/
Formatted trace file output shows no waits for db file sequential read wait event
SQL ID: dqhz25akp92bp Plan Hash: 0
INSERT INTO SES_LOCK VALUES (DBMS_RANDOM.STRING('x',36))
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 100000 14.95 14.77 0 2746 517465 100000
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 100001 14.95 14.77 0 2746 517465 100000
Misses in library cache during parse: 1
Optimizer mode: FIRST_ROWS
Parsing user id: 84 (recursive depth: 1)
Number of plan statistics captured: 1
Rows (1st) Rows (avg) Rows (max) Row Source Operation
---------- ---------- ---------- ---------------------------------------------------
0 0 0 LOAD TABLE CONVENTIONAL (cr=155 pr=5 pw=0 time=35733 us)
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
latch: In memory undo latch 1 0.00 0.00
log file switch completion 2 0.00 0.01
latch free 1 0.00 0.00
********************************************************************************
Delete all rows from the table and create restore point
SQL> delete from ses_lock;
100000 rows deleted.
SQL>commit;
Commit complete.
SQL> create restore point first_restore guarantee flashback database;
Run the test again
alter session set max_dump_file_size=UNLIMITED;
alter session set tracefile_identifier='after_grp';
alter session set events '10046 trace name context forever, level 12';
declare
i pls_integer;
begin
i := dbms_lock.request(10,DBMS_LOCK.S_MODE);
for i in 1 .. 100000
loop
insert into ses_lock values (dbms_random.string('x',36));
commit;
end loop;
i := dbms_lock.release(10);
end;
/
and formatted output of trace file shows high number of db file sequential read waits compared to previous test
SQL ID: dqhz25akp92bp Plan Hash: 0
INSERT INTO SES_LOCK VALUES (DBMS_RANDOM.STRING('x',36))
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 100000 20.71 22.50 3507 107 513257 100000
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 100001 20.71 22.50 3507 107 513257 100000
Misses in library cache during parse: 1
Optimizer mode: FIRST_ROWS
Parsing user id: 84 (recursive depth: 1)
Number of plan statistics captured: 1
Rows (1st) Rows (avg) Rows (max) Row Source Operation
---------- ---------- ---------- ---------------------------------------------------
0 0 0 LOAD TABLE CONVENTIONAL (cr=1 pr=0 pw=0 time=1844 us)
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 3507 0.11 3.78
log file switch (checkpoint incomplete) 3 0.00 0.00
latch: redo allocation 1 0.00 0.00
log file switch completion 1 0.06 0.06
********************************************************************************
Inspecting trace file itself could see details of the wait event and wait is on file#=3
WAIT #46953194410944: nam='db file sequential read' ela= 277 file#=3 block#=16505 blocks=1 obj#=0 tim=1349341486136362
WAIT #46953194410944: nam='db file sequential read' ela= 263 file#=3 block#=17317 blocks=1 obj#=0 tim=1349341486138981
WAIT #46953194410944: nam='db file sequential read' ela= 330 file#=3 block#=16955 blocks=1 obj#=0 tim=1349341486149736
WAIT #46953194410944: nam='db file sequential read' ela= 387 file#=3 block#=17076 blocks=1 obj#=0 tim=1349341486152818
WAIT #46953194410944: nam='db file sequential read' ela= 15 file#=3 block#=16839 blocks=1 obj#=0 tim=1349341486161143
File#=3 is the datafile used with the undo tablespace.
Drop the restore point and the db file sequential read event disappear, output below after restore point is dropped
SQL ID: dqhz25akp92bp Plan Hash: 0
INSERT INTO SES_LOCK VALUES (DBMS_RANDOM.STRING('x',36))
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 100000 15.44 14.60 0 67 593197 100000
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 100001 15.44 14.60 0 67 593197 100000
Misses in library cache during parse: 0
Optimizer mode: FIRST_ROWS
Parsing user id: 84 (recursive depth: 1)
Number of plan statistics captured: 1
Rows (1st) Rows (avg) Rows (max) Row Source Operation
---------- ---------- ---------- ---------------------------------------------------
0 0 0 LOAD TABLE CONVENTIONAL (cr=1 pr=0 pw=0 time=1613 us)
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
log file switch (checkpoint incomplete) 4 0.00 0.01
latch: cache buffers chains 1 0.00 0.00
Disk file operations I/O 1 0.00 0.00
********************************************************************************
SR was raised with Oracle and response was that "
this is similar to Bug 12921374 : GURANTEED RESTORE POINT CAUSES MANY PHYSICAL READS." However there has not been any movement on this bug since Feb 2012 and there's no solution or workaround. As a result of this SR a new bug report has been created which is available under "
Bug 14671654 : GUARANTEE RESTORE POINT PROVOKES HIGH"
The same test was carried out on 11.1.0.7 (11.1.0.7.12) and it didn't have the same behavior as 11gR2. So the issue is localized to 11gR2.(Update 2014/11/21-11.1 also exhibit the same behavior. Depending on when the table is created and when the restore point is created the location of the wait event on the trace file differ. Looking only at the insert statement may result in missing the high waits shown under the commit. Either way total number of waits for the test case on 11.1 is not different to that of 11.2)
Update 15 July 2013
The issue is also there on 12c (12.1.0.1). Below is the tkprof output after the same test done on a 12c.Before restore point creation
SQL ID: dqhz25akp92bp Plan Hash: 0
INSERT INTO SES_LOCK
VALUES
(DBMS_RANDOM.STRING('x',36))
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 100000 41.03 40.49 1 3272 515757 100000
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 100001 41.03 40.50 1 3272 515757 100000
Misses in library cache during parse: 1
Misses in library cache during execute: 1
Optimizer mode: ALL_ROWS
Parsing user id: 103 (recursive depth: 1)
Number of plan statistics captured: 1
Rows (1st) Rows (avg) Rows (max) Row Source Operation
---------- ---------- ---------- ---------------------------------------------------
0 0 0 LOAD TABLE CONVENTIONAL (cr=783 pr=7 pw=0 time=195740 us)
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
Disk file operations I/O 6 0.00 0.00
db file sequential read 3 0.00 0.00
latch: shared pool 8 0.00 0.00
log file switch (private strand flush incomplete)
1 0.01 0.01
control file sequential read 20 0.00 0.00
Data file init write 12 0.00 0.00
db file single write 1 0.00 0.00
control file parallel write 3 0.00 0.00
rdbms ipc reply 1 0.00 0.00
********************************************************************************
After restore point created
SQL ID: dqhz25akp92bp Plan Hash: 0
INSERT INTO SES_LOCK
VALUES
(DBMS_RANDOM.STRING('x',36))
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 100000 43.42 42.15 3484 660 512898 100000
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 100001 43.43 42.16 3484 660 512898 100000
Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 103 (recursive depth: 1)
Number of plan statistics captured: 1
Rows (1st) Rows (avg) Rows (max) Row Source Operation
---------- ---------- ---------- ---------------------------------------------------
0 0 0 LOAD TABLE CONVENTIONAL (cr=226 pr=0 pw=0 time=56775 us)
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 3484 0.28 0.47
log file switch (checkpoint incomplete) 1 0.01 0.01
log file switch completion 1 0.01 0.01
********************************************************************************
All the waits were on the undo tablespace same as before.
Update 14 July 2014
Same behavior is also observed on 11.2.0.4. Before guarantee restore point
SQL ID: dqhz25akp92bp Plan Hash: 0
INSERT INTO SES_LOCK
VALUES
(DBMS_RANDOM.STRING('x',36))
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.01 0.01 0 0 0 0
Execute 100000 72.74 81.65 6 3595 426842 100000
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 100001 72.75 81.66 6 3595 426842 100000
Misses in library cache during parse: 1
Misses in library cache during execute: 1
Optimizer mode: ALL_ROWS
Parsing user id: 50 (recursive depth: 1)
Number of plan statistics captured: 1
Rows (1st) Rows (avg) Rows (max) Row Source Operation
---------- ---------- ---------- ---------------------------------------------------
0 0 0 LOAD TABLE CONVENTIONAL (cr=164 pr=8 pw=0 time=103136 us)
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
enq: IV - contention 10 0.00 0.00
db file sequential read 6 0.00 0.02
Disk file operations I/O 1 0.00 0.00
row cache lock 7 0.00 0.00
latch: shared pool 4 0.00 0.00
latch: enqueue hash chains 3 0.00 0.00
latch free 3 0.00 0.00
latch: redo allocation 1 0.00 0.00
log file switch (checkpoint incomplete) 1 0.00 0.00
log file switch completion 1 0.00 0.00
********************************************************************************
After guarantee restore point created
SQL ID: dqhz25akp92bp Plan Hash: 0
INSERT INTO SES_LOCK
VALUES
(DBMS_RANDOM.STRING('x',36))
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 100000 82.15 94.40 5143 3615 434964 100000
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 100001 82.16 94.41 5143 3615 434964 100000
Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 50 (recursive depth: 1)
Number of plan statistics captured: 1
Rows (1st) Rows (avg) Rows (max) Row Source Operation
---------- ---------- ---------- ---------------------------------------------------
0 0 0 LOAD TABLE CONVENTIONAL (cr=5 pr=3 pw=0 time=13633 us)
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
row cache lock 3 0.00 0.00
Disk file operations I/O 3 0.00 0.00
db file sequential read 5143 0.52 2.31
KSV master wait 2 0.00 0.00
ASM file metadata operation 1 0.00 0.00
latch free 1 0.00 0.00
log file switch (checkpoint incomplete) 2 0.01 0.02
********************************************************************************Update 21 November 2014
Final reply from Oracle "this is not a bug but expected behavior when restore point is in use".
