LOB vs. SQL*Trace

Have you noticed this abnormality of SQL*Trace on reading LOB?

Here we have 2 tables t1 and t2 which have same volume but with different the data types - LOB vs. VARCHAR2.

create table t1(c1 int, c2 clob);

declare
	v_clob clob := rpad('x', 4000, 'x');
begin
	for idx in 1 .. 1000 loop
		insert into t1 values(idx, v_clob);
	end loop;
end;
/

create table t2(c1 int, c2 varchar2(4000));

declare
	v_varchar varchar2(4000) := rpad('x', 4000, 'x');
begin
	for idx in 1 .. 1000 loop
		insert into t2 values(idx, v_varchar);
	end loop;
end;
/

Reading t1.LOB takes 2 min.

UKJA@ukja102> select * from t1;

        C1                                                                      
----------                                                                      
C2                                                                              
--------------------------------------------------------------------------------
       583                                                                      
xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx
xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx
...

1000 rows selected.

Elapsed: 00:02:05.53
UKJA@ukja102> 

, while reading t2.VARCAR2 takes 10 sec.

UKJA@ukja102> select * from t2;

        C1                                                                      
----------                                                                      
C2                                                                              
--------------------------------------------------------------------------------
         5                                                                      
xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx
xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx
...
1000 rows selected.

Elapsed: 00:00:10.50

The performance difference between LOB and VARCHAR2 is not an issue here. The abnormality is observed in the report by SQL*Trace and tkprof. See following.

select * 
from
 t1

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     1001      0.14       0.09          0       1009          0        1000
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total     1003      0.14       0.09          0       1009          0        1000

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 61  

Rows     Row Source Operation
-------  ---------------------------------------------------
   1000  TABLE ACCESS FULL T1 (cr=1009 pr=0 pw=0 time=41472 us)


Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                    1002        0.00          0.00
  SQL*Net message from client                  1002        0.00          0.13
********************************************************************************

Reading t1.LOB took 2 min, but the tkprof report shows the time of just around 0.1 sec. Where has the actual 2 min gone?

Reading t2.VARCHAR2 shows what I expected. Around 10 sec waiting for the request of the client.

select * 
from
 t2

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       68      0.01       0.01          0       1005          0        1000
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total       70      0.01       0.02          0       1005          0        1000

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 61  

Rows     Row Source Operation
-------  ---------------------------------------------------
   1000  TABLE ACCESS FULL T2 (cr=1005 pr=0 pw=0 time=8348 us)


Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                      68        0.00          0.00
  SQL*Net more data to client                     2        0.00          0.00
  SQL*Net message from client                    68        0.51         10.46
********************************************************************************

Has Oracle just ignored the time spent on LOB reading? If so, it would be just a sign of bug. But look at following total time in the tkprof report on t1.LOB.

OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        5      0.01       0.00          0          0          0           0
Execute      6      0.00       0.00          0          0          0           0
Fetch     1007      0.14       0.09          0       1009          0        1003
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total     1018      0.15       0.09          0       1009          0        1003

Misses in library cache during parse: 2

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                  102009        0.00          0.31
  SQL*Net message from client                102009        0.03         32.35
  direct path read                           201000        0.06         58.51

...

Look at the times and elapsed time of the wait events! Very strange, isn’t it? The query itself does not include these values, but only the total time includes them. There should be some mismatch. Where does this mismatch happen?

This is the time when we should look into the raw trace file, which is not very common in the real life. See following.

PARSING IN CURSOR #1 len=16 dep=0 uid=61 oct=3 lid=61 tim=155701141356 hv=2245880055 ad='2e6260a8'
select * from t1
END OF STMT
PARSE #1:c=0,e=925,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,tim=155701141350
EXEC #1:c=0,e=56,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=155701142972
WAIT #1: nam='SQL*Net message to client' ela= 5 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=155701143147
WAIT #1: nam='SQL*Net message from client' ela= 358 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=155701143714
WAIT #1: nam='SQL*Net message to client' ela= 3 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=155701144019
FETCH #1:c=0,e=312,p=0,cr=4,cu=0,mis=0,r=1,dep=0,og=1,tim=155701144249
WAIT #1: nam='SQL*Net message from client' ela= 161 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=155701144584
WAIT #0: nam='direct path read' ela= 24239 file number=12 first dba=13915 block cnt=1 obj#=89468 tim=155701169489
WAIT #0: nam='direct path read' ela= 440 file number=12 first dba=13915 block cnt=1 obj#=89468 tim=155701170930
WAIT #0: nam='SQL*Net message to client' ela= 4 driver id=1413697536 #bytes=1 p3=0 obj#=89468 tim=155701171143
WAIT #0: nam='SQL*Net message from client' ela= 1273 driver id=1413697536 #bytes=1 p3=0 obj#=89468 tim=155701172643
WAIT #0: nam='direct path read' ela= 26168 file number=12 first dba=13915 block cnt=1 obj#=89468 tim=155701199245
WAIT #0: nam='direct path read' ela= 787 file number=12 first dba=13915 block cnt=1 obj#=89468 tim=155701200504
WAIT #0: nam='SQL*Net message to client' ela= 5 driver id=1413697536 #bytes=1 p3=0 obj#=89468 tim=155701200820
WAIT #0: nam='SQL*Net message from client' ela= 450 driver id=1413697536 #bytes=1 p3=0 obj#=89468 tim=155701201480
...

Do you see the mismatching happening here? CURSOR#1 is the query being executed(select * from t1), but suddenly wait event is reported as WAIT#0 not WAIT#1. This is why we have no wait time in the query itself.

Now comes the difficult part. What the hell is the WAIT#0? Where did it come from? Simple additional test case would give the hints to interpret this phenomenon. While session#1 is reading on t1.LOB, let’s monitor the session#1.

-- session #1(sid=140)
select * from t1;

UKJA@ukja102> -- session #2
UKJA@ukja102> col sql_id new_value v_sql_id
UKJA@ukja102> col prev_sql_id new_value v_prev_sql_id
UKJA@ukja102> col kglnaobj new_value v_kglnaobj
UKJA@ukja102>
UKJA@ukja102> select sql_id, prev_sql_id from v$session where sid = 140
  2  ;

SQL_ID        PREV_SQL_ID
------------- -------------
fa45sbd422h0k 27uhu2q2xuu7r

Elapsed: 00:00:00.01
UKJA@ukja102>-- Note that the CURRENT query is not shown in V$SQL
UKJA@ukja102> select sql_text from v$sql where sql_id = '&v_sql_id';
old   1: select sql_text from v$sql where sql_id = '&v_sql_id'
new   1: select sql_text from v$sql where sql_id = 'fa45sbd422h0k'

no rows selected

Elapsed: 00:00:00.00
UKJA@ukja102>-- The CURRENT query is reported as the PREVIOUS query
UKJA@ukja102> select sql_text from v$sql where sql_id = '&v_prev_sql_id';
old   1: select sql_text from v$sql where sql_id = '&v_prev_sql_id'
new   1: select sql_text from v$sql where sql_id = '27uhu2q2xuu7r'

SQL_TEXT
--------------------------------------------------------------------------------
select * from t1

Elapsed: 00:00:00.01
UKJA@ukja102>-- Although the current query is not existent in the v$sql, 
-- it should exist in the X$KGLOB - the mother of all LCOs
UKJA@ukja102> select kglhdnsp, kglnaobj from sys.xm$kglob where kglobt03 = '&v_sql_id';
old   1: select kglhdnsp, kglnaobj from sys.xm$kglob where kglobt03 = '&v_sql_id'
new   1: select kglhdnsp, kglnaobj from sys.xm$kglob where kglobt03 = 'fa45sbd422h0k'

  KGLHDNSP
----------
KGLNAOBJ
--------------------------------------------------------------------------------
         0
table_4_9_15d7b_0_0_

         0
table_4_9_15d7b_0_0_


Elapsed: 00:00:00.01
UKJA@ukja102>-- What does table_4_9_15d7b_0_0_ mean?
UKJA@ukja102> select object_name from dba_objects
  2  where object_id = to_dec(regexp_substr('&v_kglnaobj',  '[^_]+', 1, 4));
old   2: where object_id = to_dec(regexp_substr('&v_kglnaobj',  '[^_]+', 1, 4))
new   2: where object_id = to_dec(regexp_substr('table_4_9_15d7b_0_0_',  '[^_]+', 1, 4))

OBJECT_NAME
--------------------------------------------------------------------------------
T1

Above result means that

• When reading LOB, Oracle creates internal cursor which reads the LOB.
• Because this internal cursor is just another new cursor, the time spent on it is not included in the original query.
• This internal query does not show itself in the trace file. We can just infer it.
• Be careful when interpreting the tkprof report, especially when there is a big difference between the time of the individual queries and the total time.

And followings are related posts which describe the same phenomenon in the different ways.
http://kerryosborne.oracle-guy.com/2009/04/hidden-sql-why-cant-i-find-my-sql-text/
http://dioncho.wordpress.com/2009/04/20/lob-sql_id-and-lco/

About these ads