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 statmentdeclare
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 3declare
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 lockdeclare
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 pointSQL> 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 ------------- NOAfter guarantee restore point
SQL> create restore point first_restore guarantee flashback database; SQL> select flashback_on from v$database; FLASHBACK_ON ------------------ RESTORE POINT ONLYCreate 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 caseselect 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 eventSQL 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 pointSQL> 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 testSQL 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#=3WAIT #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=1349341486161143File#=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.
