Missing wait event

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.

Advertisements

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s