Wednesday, June 02, 2010

this is nice

PARSING IN CURSOR #1 len=48 dep=0 uid=0 oct=3 lid=0 tim=1275528151753957 hv=3285711733 ad='50739908' sqlid='797w17b1xgyvp'
SELECT XMLQUERY('0' RETURNING CONTENT) FROM dual
END OF STMT
PARSE #1:c=30000,e=101615,p=0,cr=40,cu=0,mis=1,r=0,dep=0,og=1,plh=1388734953,tim=1275528151753956
EXEC #1:c=0,e=37,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=1388734953,tim=1275528151754077
WAIT #1: nam='SQL*Net message to client' ela= 2 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1275528151754152
WAIT #1: nam='SQL*Net message from client' ela= 244 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1275528151754466
WAIT #0: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1275528151754539
WAIT #0: nam='SQL*Net message from client' ela= 146 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1275528151755204
WAIT #0: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1275528151755247
WAIT #0: nam='SQL*Net message from client' ela= 436 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1275528151755712
WAIT #1: nam='SQL*Net message to client' ela= 5 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1275528151755951
FETCH #1:c=0,e=314,p=0,cr=3,cu=0,mis=0,r=1,dep=0,og=1,plh=1388734953,tim=1275528151756057
STAT #1 id=1 cnt=1 pid=0 pos=1 obj=0 op='FAST DUAL  (cr=0 pr=0 pw=0 time=3 us cost=2 size=0 card=1)'
WAIT #1: nam='SQL*Net message from client' ela= 506 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1275528151756693
WAIT #0: nam='SQL*Net message to client' ela= 0 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1275528151756736
LOBREAD: c=0,e=29,p=0,cr=0,cu=0,tim=1275528151756757
WAIT #0: nam='SQL*Net message from client' ela= 59 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1275528151756840
LOBREAD: c=0,e=3,p=0,cr=0,cu=0,tim=1275528151756870
WAIT #0: nam='SQL*Net message to client' ela= 0 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1275528151756890
WAIT #0: nam='SQL*Net message from client' ela= 31 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1275528151756938
LOBREAD: c=0,e=2,p=0,cr=0,cu=0,tim=1275528151756966
WAIT #0: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1275528151756987

*** 2010-06-02 18:22:34.315
WAIT #0: nam='SQL*Net message from client' ela= 2558422 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1275528154315425
LOBARRTMPFRE: c=0,e=23,p=0,cr=0,cu=0,tim=1275528154315542
XCTEND rlbk=0, rd_only=1, tim=1275528154315594
CLOSE #3:c=0,e=20,dep=0,type=0,tim=1275528154315664
CLOSE #1:c=0,e=9,dep=0,type=0,tim=127552815431569

3 comments:

Jeff said...

Some time ago, I requested an enhancement to help correlate direct path read/write with lob read/write.

I'm sad to say that they (i.e., Server Technologies) didn't implement anything new. But I can't blame them since it's a pretty difficult problem to solve.

With this all they've done is replace a 'direct path read' with a LOBREAD. It has no more information than the previous WAIT line that had a zero cursor slot number.

I suspect you'll now see LOBWRITE instead of direct path write.

The reason it's a difficult problem to solve is evident when you consider that an application could execute a query that returns more than one lob locator. If it alternates between reading from both locators, then it's impossible (well, almost) to tell what's going on.

Vladimir Begun said...

I guess, to get a bit more holistic picture, one has to review OCI/jdbc streaming/dbms_lob API to get a bit clear understanding of what was introduced.

This is how chunk reads do look in sqlplus:

CREATE TABLE t (c CLOB);
...
VAR c CLOB
EXEC SELECT c INTO :c FROM t;
SET LONG 300000
PRINT c

PARSING IN CURSOR #3084558788 len=22 dep=0 uid=86 oct=3 lid=86 tim=1294978494973726 hv=3106221664 ad='64eed5bc' sqlid='6nzcznawkabm0'
SELECT :c c FROM DUAL
END OF STMT
PARSE #3084558788:c=0,e=122,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=1388734953,tim=1294978494973724
BINDS #3084558788:
Bind#0
oacdty=112 mxl=4000(4000) mxlc=00 mal=00 scl=00 pre=00
oacflg=01 fl2=1000000 frm=01 csi=873 siz=4000 off=0
kxsbbbfp=b7d81228 bln=4000 avl=150 flg=05
value=Unhandled datatype (112) found in kxsbndinf
Dump of memory from 0xB7D81228 to 0xB7D812BE
...
EXEC #3084558788:c=0,e=438,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=1388734953,tim=1294978494974300
WAIT #3084558788: nam='SQL*Net message to client' ela= 2 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1294978494974348
WAIT #3084558788: nam='SQL*Net message from client' ela= 211 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1294978494974608
WAIT #3084558788: nam='SQL*Net message to client' ela= 2 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1294978494974676
FETCH #3084558788:c=0,e=51,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,plh=1388734953,tim=1294978494974707
STAT #3084558788 id=1 cnt=1 pid=0 pos=1 obj=0 op='FAST DUAL (cr=0 pr=0 pw=0 time=5 us cost=2 size=0 card=1)'
WAIT #3084558788: nam='SQL*Net message from client' ela= 117 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1294978494974940
WAIT #0: nam='direct path read' ela= 27 file number=4 first dba=35427 block cnt=1 obj#=80501 tim=1294978494975080
WAIT #0: nam='direct path read' ela= 30 file number=4 first dba=35427 block cnt=1 obj#=80501 tim=1294978494975185
WAIT #0: nam='SQL*Net message to client' ela= 2 driver id=1650815232 #bytes=1 p3=0 obj#=80501 tim=1294978494975231
LOBREAD: c=0,e=279,p=2,cr=2,cu=0,tim=1294978494975268
WAIT #0: nam='SQL*Net message from client' ela= 79 driver id=1650815232 #bytes=1 p3=0 obj#=80501 tim=1294978494975387
WAIT #0: nam='direct path read' ela= 17 file number=4 first dba=35427 block cnt=1 obj#=80501 tim=1294978494975466
WAIT #0: nam='direct path read' ela= 16 file number=4 first dba=35427 block cnt=1 obj#=80501 tim=1294978494975534
WAIT #0: nam='SQL*Net message to client' ela= 2 driver id=1650815232 #bytes=1 p3=0 obj#=80501 tim=1294978494975609
LOBREAD: c=0,e=214,p=2,cr=2,cu=0,tim=1294978494975639
WAIT #0: nam='SQL*Net message from client' ela= 7801 driver id=1650815232 #bytes=1 p3=0 obj#=80501 tim=1294978494983503
WAIT #0: nam='direct path read' ela= 26 file number=4 first dba=35427 block cnt=1 obj#=80501 tim=1294978494983660
WAIT #0: nam='direct path read' ela= 17 file number=4 first dba=35427 block cnt=1 obj#=80501 tim=1294978494983733
WAIT #0: nam='SQL*Net message to client' ela= 2 driver id=1650815232 #bytes=1 p3=0 obj#=80501 tim=1294978494983765
LOBREAD: c=0,e=221,p=2,cr=2,cu=0,tim=1294978494983797

> With this all they've done is replace a 'direct path read' with a LOBREAD.

It's not just one thing instead of the other, it's a good new addition to what was already available. Which is potentially extensible. It, at least, would let people to get exactly what's going on at API level. Also, LOB% cannot replace wait event information. It was clear from the original example as well there is no p1,2,3 there for LOB.

You may or may not find it useful. I do. :-)

Locators, being at least precise enough, for the write calls are visible in ash/awr through pseudo cursors ('table_%'). Reads are more dim. Although, I agree on possible difficulties, it's possible to figure things out.

Vladimir Begun said...

[the long post aren't supported, continuing...]

Also, object# from direct path read shows the lob being read. Example:

SQL> SELECT object_name FROM dba_objects WHERE object_id = 80501;

OBJECT_NAME
-------------------------
SYS_LOB0000080500C00002$$

SQL> SELECT table_name, column_name FROM user_lobs WHERE segment_name = 'SYS_LOB0000080500C00002$$';

TABLE_NAME COLUMN_NAM
---------- ----------
T C

I'm using 11.2.0.2.