A Session Busy Doing What? – Work of Course!

I was recently called out to look at a batch job exceeding it’s usual execution time. Ordinarily a quick look at the wait events would tell me what I needed to know, however due to a poor execution plan (caused by incorrect statistics) the query nicely highlighted how not all work can be classified as a wait. Below is a reproduction of the scenario I’m describing.

Create some test tables.

CREATE TABLE tab1 AS
SELECT ROWNUM rn, 'xxxxx' pad1, 'yyyyy' pad2
  FROM dual CONNECT BY LEVEL <= 25000;

CREATE TABLE tab2 AS
SELECT ROWNUM rn, 'xxxxx' pad1, 'yyyyy' pad2
  FROM dual CONNECT BY LEVEL <= 25000;

exec dbms_stats.gather_table_stats(null,'tab1');
exec dbms_stats.gather_table_stats(null,'tab2');

A test query is below, it has been hinted to ensure it repeatedly scans the same blocks in memory.

SELECT /*+ USE_NL(tab1 tab2) ORDERED */ COUNT(*)
FROM 	tab1
INNER JOIN tab2 ON tab1.rn = tab2.rn;

------------------------------------------------------------------------------------
| Id  | Operation           | Name | Rows  | Bytes |TempSpc| Cost (%CPU)| Time     |
------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT    |      |     1 |    10 |       |   477K  (6)| 01:35:30 |
|   1 |  SORT AGGREGATE     |      |     1 |    10 |       |            |          |
|*  2 |   NESTED LOOPS      |      | 24859 |   242K|   477K|   477K  (6)| 01:35:30 |
|   3 |    TABLE ACCESS FULL| TAB1 | 24918 |   121K|       |    21   (5)| 00:00:01 |
|   4 |    TABLE ACCESS FULL| TAB2 |     1 |     5 |       |    19   (6)| 00:00:01 |
------------------------------------------------------------------------------------

First off run the query to get it parsed and charge the buffer cache and then reset the session and run it again.

-- may want to ctrl^c once this has run for a few seconds
SELECT /*+ USE_NL(tab1 tab2) ORDERED */ COUNT(*)
FROM 	tab1
INNER JOIN tab2 ON tab1.rn = tab2.rn;

-- conn fresh session
conn /

SELECT sid FROM v$mystat WHERE ROWNUM = 1;

SELECT /*+ USE_NL(tab1 tab2) ORDERED */ COUNT(*)
FROM 	tab1
INNER JOIN tab2 ON tab1.rn = tab2.rn;

From another session check what the original session is up to:

SELECT sid, status, event, state 
FROM v$session 
WHERE sid = &sid_of_other_session;

       SID STATUS   EVENT                               STATE
---------- -------- ----------------------------------- -------------------
       149 ACTIVE   SQL*Net message to client           WAITED SHORT TIME

SELECT event, time_waited 
FROM v$session_event 
WHERE sid = &sid_of_other_session;

EVENT                               TIME_WAITED
----------------------------------- -----------
SQL*Net message to client                     0
SQL*Net message from client                1111

No wait events are being recorded yet “top” shows the session to be the number 1 session on the box with 78% of CPU resources.

  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND                            
28008 oracle    25   0  344m  20m  18m R 78.3  2.7   5:57.28 oracle      

The missing link is that an Oracle instance does not count logical IO as a wait – it is work. V$SESSTAT is where we have visibility of this work.

SELECT n.name, s.value 
FROM v$sesstat s, v$statname n
WHERE s.sid = &sid_of_other_session 
AND n.statistic# = s.statistic#
AND n.name = 'consistent gets'
ORDER BY s.value;

NAME                                                                  VALUE
---------------------------------------------------------------- ----------
consistent gets                                                     1975123