Today’s little quiz – just for fun, but prompted by a few comments in this posting on OTN:
drop table t1;
create table t1
as
select
rownum id,
rpad(rownum,10) small_vc,
rpad('x',100) padding
from
all_objects
where
rownum <= 10000
;
alter table t1 add constraint t1_pk primary key(id);
begin
dbms_stats.gather_table_stats(
ownname => user,
tabname =>'T1',
partname => null,
estimate_percent => 100,
block_sample => true,
method_opt => 'for all columns size 1',
degree => null,
granularity => 'default',
cascade => true,
stattab => null
);
end;
/
Shortly after creating this data set, I ran a simple query, with sql_trace enabled, and got this result from the tkprof output.
********************************************************************************
select
small_vc
from
t1
where
id = 5000
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 2 0.18 0.18 0 49927 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 0.18 0.18 0 49927 0 1
Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 55
Rows Row Source Operation
------- ---------------------------------------------------
1 TABLE ACCESS BY INDEX ROWID T1 (cr=49927 pr=0 pw=0 time=184817 us)
1 INDEX UNIQUE SCAN T1_PK (cr=2 pr=0 pw=0 time=44 us)(object id 94955)
********************************************************************************
Note that the execution plan shown has the title “Row Source Operation” so it is a real reflection of what actually happened. The two fetches is a construct of the way SQL plus works – I ran the statement just once in the lifetime of this trace file.
So how does fetching a single row by unique index result in 50,000 buffer gets ? (Hint – an index can only reach a height of 24 ; trying to get to 25 causes an ORA-00600 error).
Oracle Scratchpad 
The answer is in the title ;) Something like this in a second session:
begin for i in 1..50000 loop update t1 set small_vc = small_vc where id = 5000; end loop; end; /Comment by Timur Akhmadeev — May 14, 2009 @ 8:48 am BST May 14,2009 |
Timur,
Fantastic response time !
You must have had Google Earth looking over my shoulder while I was typing, because that’s virtually identical to the text I used (mine set small_vc to null to reduce the undo and redo slightly).
The consistent gets were mostly “consistent gets – examination” of undo blocks which, combined with a few “IMU CR rollbacks” led to 50,000 “data blocks consistent reads – undo records applied”
Comment by Jonathan Lewis — May 14, 2009 @ 8:57 am BST May 14,2009 |
Jonathan, there’s no magic, I saw your response in the OTN thread with a link to the blog post :)
PS. There’s small mistake in a test case – some lines are missing.
Comment by Timur Akhmadeev — May 14, 2009 @ 9:15 am BST May 14,2009 |
Timur,
Thanks, now fixed. It was the usual “less than” problem.
Comment by Jonathan Lewis — May 14, 2009 @ 9:41 am BST May 14,2009 |
When I wrote this note the thread had only just started – and I had assumed that it was going to be another case of the run-time plan being different from the “explain plan” version.
It turned out that the possibility I had suggested in this note really was happening to the OP, so if you haven’t reviewed the OTN thread since my first comments you might want to take another look at how it developed.
Comment by Jonathan Lewis — May 22, 2009 @ 7:57 pm BST May 22,2009 |
Jonathan,
what would you say in case of
1) one query, UPDATE by single PK value, is executing for more than 4 hours
2) no TX contention
3) most significant wait event is ‘db file sequential read’ (more than 4 hours, ~1M total occurences in session)
4) V$TRANSACTION.LOG_IO is increasing permanently and fast (more than 20M currently)
5) V$TRANSACTION.CR_CHANGE is slightly increasing (~5K currently)
6) probably some other activities were done in this transaction, but their contribution in terms of elapsed time and used resources may be neglected
7)
SQL> select max(undoblks) from v$undostat; MAX(UNDOBLKS) ------------- 47748) no other active transactions are taking place
9) UPDATE operates on data dictionary table SYS.SNAP$
?
TIA.
Comment by Timur Akhmadeev — June 11, 2009 @ 10:56 am BST Jun 11,2009 |
Timur,
Are you saying that this update statement executes just once to update one row by unique key ? (There is no PK on sys.snaps$, by the way, just one unique key).
First I’d look in v$session to check if this really was the executing statement
Then I’d check in v$sql_plan (dbms_xplan.display_cursor) to check that the execution plan was as stated
Then I’d check in v$sql to see that it was executed just once
Then take a snapshot of x$kcbsw to see what type of logical I/O was being done, at the same time taking a snapshot of v$sesstat for that session to see if the two agreed. (And check if the figures from v$sesstat agree with the log_io from v$transaction – I’ve got one example where v$transaction over-reports).
Then I’d sit back and think for a bit.
sys.snap$ has a long column and two clob columns – so who know how nasty a single row update could get ;) (especially if your system tablespace is using ASSM and your block size is bigger than 8KB).
Comment by Jonathan Lewis — June 11, 2009 @ 4:40 pm BST Jun 11,2009 |
Jonathan,
thank you for feedback.
This query was not executed just once, it has been executing for more than 10 hours already on a customer’s test non-RAC 10.2.0.4 @ Solaris 10 environment :) The query is
so, no CLOBs to update. A query is reported as currently being executed by an active session of a job, and it’s plan in v$sql_plan is update by UQ index. Maybe v$sql.sql_id reports wrong info – that’s possible.
Thanks again for your suggestions.
Comment by Timur Akhmadeev — June 11, 2009 @ 5:37 pm BST Jun 11,2009 |
Timur,
You should always take great care to ensure that you’ve presented the significant facts when describing a problem.
What you said sounded like “a single update that should be for a single row accessed by primary key has done a huge amount of work”.
What you meant was “why has this update statement executed 6 million times in the last 4 hours”.
Comment by Jonathan Lewis — June 11, 2009 @ 6:28 pm BST Jun 11,2009 |
Jonathan, I’m sorry if I my description was obscure.
>What you said sounded like “a single update that should be for a single row accessed by primary key has done a huge amount of work”.
That is in short what I wanted to say.
>What you meant was “why has this update statement executed 6 million times in the last 4 hours”.
Could you please point me to my words which lead to this conclusion? So if it’s my inconsistency I wouldn’t repeat it next time.
Comment by Timur Akhmadeev — June 11, 2009 @ 7:51 pm BST Jun 11,2009 |
Timur,
Now I’m very confused – in your follow-up post, after I asked “are you saying this statement executes just once” you replied “this query was not executed just once, it has been executing for …”
It sounds like we’re back to something unusual – so I’d be looking at the stats that I listed in my earlier reply.
Comment by Jonathan Lewis — June 11, 2009 @ 9:28 pm BST Jun 11,2009 |
My intention was to say “it is executing (right now). it isn’t finished (yet)”. Sorry for confusing you.
Comment by Timur Akhmadeev — June 12, 2009 @ 5:49 pm BST Jun 12,2009 |