Hi folks,
I have a query which has been running for 3 hours.
I decided to launch the snapper tool in ASH mode to see on what event the session is waiting for:
SQL>@snapper ash 20 1 184
Sampling SID 184 with interval 20 seconds, taking 1 snapshots...
-- Session Snapper v3.64 by Tanel Poder ( http://blog.tanelpoder.com )
---------------------------------------------------------------------------------------------
Active% | SQL_ID | SQL_CHILD | EVENT | WAIT_CLASS
---------------------------------------------------------------------------------------------
100% | 2ywsu2t98dbw0 | 0 | ON CPU | ON CPU
-- End of ASH snap 1, end=2014-02-20 15:07:41, seconds=20, samples_taken=96
We can notice that the session 184 is spending 100% of its time on CPU.
However each time I select the V$SESSION.EVENT column I see either "DB FILE SEQUENTIAL READ" or "DB FILE SCATTERED READ":
SQL>@sql_cur_stmt
SID PROG ADDRESS HASH_VALUE SQL_ID CHILD PLAN_HASH_VALUE EXECS AVG_ETIME EVENT SQL_TEXT
----- ---------- ---------------- ---------- ------------- ------ --------------- ---------- ----------- -------------------- -----------------------------------------
184 sqlplus.ex C000000634EC1B08 1384558464 2ywsu2t98dbw0 0 350077744 1 11,561.66 db file sequential r SELECT ALL A.NUSUR, SUM
1 row selected.
Elapsed: 00:00:00.03
SQL>@sql_cur_stmt
SID PROG ADDRESS HASH_VALUE SQL_ID CHILD PLAN_HASH_VALUE EXECS AVG_ETIME EVENT SQL_TEXT
----- ---------- ---------------- ---------- ------------- ------ --------------- ---------- ----------- -------------------- -----------------------------------------
184 sqlplus.ex C000000634EC1B08 1384558464 2ywsu2t98dbw0 0 350077744 1 11,561.66 db file sequential r SELECT ALL A.NUSUR, SUM
1 row selected.
Elapsed: 00:00:00.01
SQL>@sql_cur_stmt
SID PROG ADDRESS HASH_VALUE SQL_ID CHILD PLAN_HASH_VALUE EXECS AVG_ETIME EVENT SQL_TEXT
----- ---------- ---------------- ---------- ------------- ------ --------------- ---------- ----------- -------------------- -----------------------------------------
184 sqlplus.ex C000000634EC1B08 1384558464 2ywsu2t98dbw0 0 350077744 1 11,567.52 db file sequential r SELECT ALL A.NUSUR, SUM
1 row selected.
Elapsed: 00:00:00.03
SQL>@sql_cur_stmt
SID PROG ADDRESS HASH_VALUE SQL_ID CHILD PLAN_HASH_VALUE EXECS AVG_ETIME EVENT SQL_TEXT
----- ---------- ---------------- ---------- ------------- ------ --------------- ---------- ----------- -------------------- -----------------------------------------
184 sqlplus.ex C000000634EC1B08 1384558464 2ywsu2t98dbw0 0 350077744 1 11,567.52 db file sequential r SELECT ALL A.NUSUR, SUM
1 row selected.
Elapsed: 00:00:00.01
SQL>@sql_cur_stmt
SID PROG ADDRESS HASH_VALUE SQL_ID CHILD PLAN_HASH_VALUE EXECS AVG_ETIME EVENT SQL_TEXT
----- ---------- ---------------- ---------- ------------- ------ --------------- ---------- ----------- -------------------- -----------------------------------------
184 sqlplus.ex C000000634EC1B08 1384558464 2ywsu2t98dbw0 0 350077744 1 11,567.52 db file sequential r SELECT ALL A.NUSUR, SUM
1 row selected.
Elapsed: 00:00:00.03
SQL>@sql_cur_stmt
SID PROG ADDRESS HASH_VALUE SQL_ID CHILD PLAN_HASH_VALUE EXECS AVG_ETIME EVENT SQL_TEXT
----- ---------- ---------------- ---------- ------------- ------ --------------- ---------- ----------- -------------------- -----------------------------------------
184 sqlplus.ex C000000634EC1B08 1384558464 2ywsu2t98dbw0 0 350077744 1 11,573.38 db file sequential r SELECT ALL A.NUSUR, SUM
1 row selected.
Elapsed: 00:00:00.03
SQL>@sql_cur_stmt
SID PROG ADDRESS HASH_VALUE SQL_ID CHILD PLAN_HASH_VALUE EXECS AVG_ETIME EVENT SQL_TEXT
----- ---------- ---------------- ---------- ------------- ------ --------------- ---------- ----------- -------------------- -----------------------------------------
184 sqlplus.ex C000000634EC1B08 1384558464 2ywsu2t98dbw0 0 350077744 1 11,579.23 db file sequential r SELECT ALL A.NUSUR, SUM
1 row selected.
I do not understand why the snapper is showing only CPU TIME. I expected to see some I/O waits.
When I query the Oracle ASH view I get what snapper is showing:
SQL>select event, count(*) from v$active_session_history where session_id=184 group by event;
EVENT COUNT(*)
-------------------- ----------
db file sequential r 3
latch: cache buffers 8
null event 2
12166
Does someone have an idea on this?