Oracle 11.2.0.1 for Windows is out for some time. I’ve installed it on my 32-bit Windows XP machine because I like Windows – just to check that it’s actually working fine. Playing with TPC-H test using Hammerora I’ve noticed an anomaly in the way Oracle reports IO waits for some queries.
Here is a test case for reproducing the issue:
drop table t cascade constraints purge;
create table t nologging as
with t1 as (select * from all_objects where rownum <= 5000)
select t11.*
from t1 t11, t1 t12
where rownum <= 10e6;
exec dbms_stats.gather_table_stats(user, 't')
alter session set "_serial_direct_read"=false;
compute sum of total_waits on report
compute sum of time_waited on report
break on report
select event, time_waited, total_waits
from v$session_event
where sid = userenv('sid')
order by 2 desc;
set autotrace on exp stat timing on
select /*+ full(t) no_parallel(t) */ count(*) from t;
set autotrace off timing off
select event, time_waited, total_waits
from v$session_event
where sid = userenv('sid')
order by 2 desc;
Note that I explicitly disabled “direct path read” in serial execution mode with “_serial_direct_read” for 11gR2; also I’m asking Oracle not to consider parallel execution for T access.
Here are results of running the case on a 10.2.0.4P35 on the same machine:
EVENT TIME_WAITED TOTAL_WAITS
---------------------------------------------------------------- -------------------- --------------------
db file scattered read 1411 4094
control file sequential read 497 1010
Data file init write 438 537
db file sequential read 371 668
control file parallel write 13 150
events in waitclass Other 6 54
SQL*Net message from client 5 24
db file single write 1 50
enq: RO - fast object reuse 0 2
direct path write 0 2
direct path write temp 0 2
SQL*Net message to client 0 25
log file sync 0 3
-------------------- --------------------
sum 2742 6621
13 rows selected.
COUNT(*)
--------------------
10000000
1 row selected.
Elapsed: 00:00:14.31
Execution Plan
----------------------------------------------------------
Plan hash value: 2966233522
-------------------------------------------------------------------
| Id | Operation | Name | Rows | Cost (%CPU)| Time |
-------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | 26742 (1)| 00:05:21 |
| 1 | SORT AGGREGATE | | 1 | | |
| 2 | TABLE ACCESS FULL| T | 9983K| 26742 (1)| 00:05:21 |
-------------------------------------------------------------------
Statistics
----------------------------------------------------------
1 recursive calls
0 db block gets
121248 consistent gets
90719 physical reads
0 redo size
411 bytes sent via SQL*Net to client
399 bytes received via SQL*Net from client
2 SQL*Net roundtrips to/from client
0 sorts (memory)
0 sorts (disk)
1 rows processed
EVENT TIME_WAITED TOTAL_WAITS
---------------------------------------------------------------- -------------------- --------------------
db file scattered read 2658 10829
db file sequential read 595 2695
control file sequential read 497 1010
Data file init write 438 537
control file parallel write 13 150
events in waitclass Other 6 54
SQL*Net message from client 6 40
db file single write 1 50
direct path write 0 2
direct path write temp 0 2
SQL*Net message to client 0 41
enq: RO - fast object reuse 0 2
log file sync 0 4
-------------------- --------------------
sum 4214 15416
13 rows selected.
Everything looks good – a statement was executed in about 15 seconds and v$session_event reports wait time close to this value. So, we spent ~13 seconds waiting for IO under “db file scattered read”.
Here are results from 11.2.0.1:
EVENT TIME_WAITED TOTAL_WAITS
---------------------------------------------------------------- -------------------- --------------------
db file scattered read 1253 1004
SQL*Net message from client 7 24
enq: RO - fast object reuse 1 1
db file sequential read 1 1
events in waitclass Other 0 8
enq: KO - fast object checkpoint 0 1
SQL*Net message to client 0 25
Disk file operations I/O 0 4
log file sync 0 2
-------------------- --------------------
sum 1262 1070
9 rows selected.
COUNT(*)
--------------------
10000000
1 row selected.
Elapsed: 00:00:20.00
Execution Plan
----------------------------------------------------------
Plan hash value: 2966233522
-------------------------------------------------------------------
| Id | Operation | Name | Rows | Cost (%CPU)| Time |
-------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | 34325 (1)| 00:06:52 |
| 1 | SORT AGGREGATE | | 1 | | |
| 2 | TABLE ACCESS FULL| T | 10M| 34325 (1)| 00:06:52 |
-------------------------------------------------------------------
Statistics
----------------------------------------------------------
1 recursive calls
0 db block gets
125832 consistent gets
125826 physical reads
0 redo size
422 bytes sent via SQL*Net to client
419 bytes received via SQL*Net from client
2 SQL*Net roundtrips to/from client
0 sorts (memory)
0 sorts (disk)
1 rows processed
EVENT TIME_WAITED TOTAL_WAITS
---------------------------------------------------------------- -------------------- --------------------
db file scattered read 1253 1004
enq: KO - fast object checkpoint 11 2
SQL*Net message from client 7 40
enq: RO - fast object reuse 1 1
db file sequential read 1 1
log file sync 0 2
SQL*Net message to client 0 41
Disk file operations I/O 0 4
events in waitclass Other 0 12
-------------------- --------------------
sum 1273 1107
9 rows selected.
And that looks strange.
* The statement took 20 seconds to execute, but there were less than a second of accounted waits
* The “enq: KO – fast object checkpoint” wait appeared – this is usually mean we are using PX over a table and we are asking Oracle to force a segment level checkpoint. However, I didn’t ask parallel execution to happen…
* … And I didn’t ask to use “direct path read” in serial mode either
So, where is the time lost? I don’t know. It looks like a bug to me. What makes it even worse than a “usual bug” is because of this you may incorrectly find a query as CPU bound in the ASH – when in fact it is IO bound. Well, at least now you won’t be surprised.
Remember, this was all done on Windows.
