Symptom
- Insert into select * from … running slowly after delete and restart
- Multi-block operation waiting on single block wait events
Cause
- The operation was restarted before the delete was committed.
Solution
- There is no easy solution you can only wait for it to finish or kill and restart the restart after the delete has been committed. Of course had the delete been committed before the restart, there would not have been a problem.
Investigation
I was asked to help a team member with an investigation of a query that was apparently running much slower than usual. My first thoughts were that this would be a plan change or the use of different bind variables. The problem was with a specific insert statement. I asked my team member whether the plan had changed, but he said that he could not find any history of the SQL in the AWR repository. The product had apparently told him that it was not a new SQL statement and that it ran every day. A quick look at the SQL showed that it had a date literal in it, hence a new SQL ID every day and hence the lack of history.
In further discussions with my team member, he mentioned that the product had performed a delete on a table and after that had started the batch which contained the relevant SQL statement, although they had apparently committed the delete before starting the batch. This started me thinking about the construction of read consistent images. I took a quick look at the SQL monitor report for the SQL and there is the tell-tale sign of this, a multi-block operation mainly waiting on single block reads. There are of course other possible reasons why this would happen, but the construction of read consistent images is the one I have come across most.
Below are sections of two ASH reports, the first from a “good” run of the SQL and the second from the problem run:
Top SQL with Top Row SourcesDB/Inst: ... 05:30 to 06:30
SQL ID FullPlanHash PlanHash
----------------------- -------------------- --------------------
Sampled #
of Executions % Activity
-------------------- --------------
Row Source % RwSrc Top Event % Event
---------------------------------------- ------- ----------------------- -------
<sql id> ... ...
1 100.00
TABLE ACCESS - BY LOCAL INDEX ROWID BATC 68.06 db file sequential read 57.07
INSERT INTO ...
Top SQL with Top Row SourcesDB/Inst: ... 07:00 to 12:00
SQL ID FullPlanHash PlanHash
----------------------- -------------------- --------------------
Sampled #
of Executions % Activity
-------------------- --------------
Row Source % RwSrc Top Event % Event
---------------------------------------- ------- ----------------------- -------
<sql id> ... ...
1 100.00
INDEX - FAST FULL SCAN 84.78 db file sequential read 83.14
INSERT INTO ...The first shows a table access by an index which is waiting on “db file sequential read” as you would expect. You are reading a single block from the table and so you wait on a single block read wait event. However the second shows an index fast full scan, a multi-block operation, waiting on the same single block wait event. How can this be? Enabling tracing on the relevant session shows what is happening:
WAIT #47705201250352: nam='db file sequential read' ela= 9934 file#=1618
block#=71127 blocks=1 obj#=0 tim=...
WAIT #47705201250352: nam='db file sequential read' ela= 4547 file#=1617
block#=97600 blocks=1 obj#=0 tim=...
WAIT #47705201250352: nam='db file sequential read' ela= 11676 file#=1614
block#=128733 blocks=1 obj#=0 tim=...
WAIT #47705201250352: nam='db file sequential read' ela= 8433 file#=2
block#=37420 blocks=1 obj#=0 tim=...
WAIT #47705201250352: nam='db file sequential read' ela= 269 file#=2
block#=59795 blocks=1 obj#=0 tim=...
WAIT #47705201250352: nam='db file sequential read' ela= 3552 file#=1618
block#=38205 blocks=1 obj#=0 tim=...
WAIT #47705201250352: nam='db file sequential read' ela= 4409 file#=1614
block#=46275 blocks=1 obj#=0 tim=...
WAIT #47705201250352: nam='db file sequential read' ela= 5508 file#=1615
block#=93465 blocks=1 obj#=0 tim=...
WAIT #47705201250352: nam='db file sequential read' ela= 1976 file#=1617
block#=97271 blocks=1 obj#=0 tim=...
WAIT #47705201250352: nam='db file sequential read' ela= 5394 file#=1615
block#=70019 blocks=1 obj#=0 tim=...
WAIT #47705201250352: nam='db file sequential read' ela= 262 file#=1614
block#=99165 blocks=1 obj#=0 tim=...
WAIT #47705201250352: nam='db file sequential read' ela= 481 file#=1614
block#=99164 blocks=1 obj#=0 tim=...
WAIT #47705201250352: nam='db file sequential read' ela= 8268 file#=1614
block#=3798 blocks=1 obj#=0 tim=...
WAIT #47705201250352: nam='db file sequential read' ela= 6201 file#=1617
block#=45215 blocks=1 obj#=0 tim=...
WAIT #47705201250352: nam='db file sequential read' ela= 4051 file#=1617
block#=5005 blocks=1 obj#=0 tim=...
WAIT #47705201250352: nam='db file sequential read' ela= 690 file#=1617
block#=5004 blocks=1 obj#=0 tim=...
WAIT #47705201250352: nam='db file sequential read' ela= 5989 file#=1617
block#=101175 blocks=1 obj#=0 tim=...
WAIT #47705201250352: nam='db file sequential read' ela= 7722 file#=2
block#=43595 blocks=1 obj#=0 tim=...
WAIT #47705201250352: nam='db file sequential read' ela= 8271 file#=1618
block#=106772 blocks=1 obj#=0 tim=...
WAIT #47705201250352: nam='db file sequential read' ela= 7931 file#=1618
block#=370436 blocks=1 obj#=0 tim=...
WAIT #47705201250352: nam='db file sequential read' ela= 1440 file#=1615
block#=121171 blocks=1 obj#=0 tim=...
WAIT #47705201250352: nam='db file sequential read' ela= 577 file#=1615
block#=121170 blocks=1 obj#=0 tim=...
WAIT #47705201250352: nam='db file sequential read' ela= 8091 file#=2
block#=91595 blocks=1 obj#=0 tim=...
WAIT #47705201250352: nam='db file sequential read' ela= 406 file#=1617
block#=46332 blocks=1 obj#=0 tim=...As you can see, all the waits are on obj# 0, but there is never any object with and object_id of 0:
select count(*) from dba_objects where object_id = 0;
COUNT(*)
----------
0What therefore is obj# 0? I can’t find a MOS note that states it is always a rollback segment, but if you look at the tablespace it is accessing, it is clear that it must be:
select tablespace_name, contents
from dba_tablespaces
where tablespace_name in (
select distinct tablespace_name
from dba_data_files
where file_id in ( 1614,1615,1616,1617,2,1618 ) );
TABLESPACE_NAME CONTENTS
------------------------------ ---------
UNDOTBS1 UNDOThus the index fast full scan is having to perform single block reads to construct a read consistent image. This results in a much slower operation and hence the SQL statement runs much slower.
From subsequent discussions with the product, it appears that there was a previous run of the batch on the day which encountered a problem. They needed to delete some data because of this and then restart the batch. Unfortunately the delete was not committed until after the batch had started and thus the transaction containing the relevant SQL needed to construct read consistent images as of a time before the commit which would involve undoing the delete. The relevant SQL is not a simple insert statement, but an “insert into select …” and the select included accessing tables that had had the delete performed on them.