After Randolf’s comment on my last post about identifying cursor SQL text from sql trace file I think one thing needs elaboration.
I mentioned earlier in this post that this cursor dumping technique works “as long as the cursor of interest is still open”.
So how do you know whether this cursor of interest is still open or has been closed and that slot reused by some other statement instead? You would not want to get misled to wrong SQL statement…
Luckily all the info you need is in SQL tracefile.
In 11g you would see “CLOSE #2” line appearing in tracefile when a cursor is closed.
Before 11g you would see “STAT #2” lines dumping out SQL plan execution stats – before 11g this is done when cursor is closed, so when you see STAT #2 lines, you know that at that location the cursor in slot #2 was closed.
There are few cases when the stat lines are not printed even if the cursor is closed – for example when the cursor’s library cache lookup (finding suitable shared cursor) happened before SQL trace was enabled. In this case the cursor would not use the extra instrumentation rowsources which generate the STAT lines.
In such case you would just grep the tracefile for PARSING IN CURSOR #2 after your WAIT #2’s. Whenever someone is parsing in a new cursor into slot #2, this means that existing cursor in slot #2 must have been closed somewhere between the PARSING IN CURSOR #2 line and last WAIT/FETCH/EXEC #2 line.
However, there’s one more special case; when the cursor was parsed in before SQL trace was enabled and another OPI call (like EXEC,FETCH) against this cursor is executed, then some Oracle versions actually retrieve the current SQL text and still dump it into trace just like before parsing. This means that if you just have lots of WAIT lines appearing in the trace for a SQL parsed in past, you won’t see the PARSING IN CURSOR lines dumped into tracefile, but if some OPI call is executed against this cursor, then the PARSING IN CURSOR line is dumped just before that OPI call.
I don’t in which exact version this appeared, but in my 10.2.0.1 test instance this feature gives such output (I ran a select from dba_objects which started fetching lots of rows and then enabled SQL trace from another session):
PARSING IN CURSOR #1 len=29 dep=0 uid=0 oct=3 lid=0 tim=558589701689 hv=3336193532 ad='24f2e864' select owner from dba_objects END OF STMT FETCH #1:c=0,e=5362,p=0,cr=102,cu=0,mis=0,r=500,dep=0,og=1,tim=558589701683 WAIT #1: nam='SQL*Net more data to client' ela= 23 driver id=1111838976 #bytes=2047 p3=0 obj#=39 tim=558589703066 WAIT #1: nam='SQL*Net message from client' ela= 57993 driver id=1111838976 #bytes=1 p3=0 obj#=39 tim=558589761409 WAIT #1: nam='SQL*Net message to client' ela= 3 driver id=1111838976 #bytes=1 p3=0 obj#=39 tim=558589761753 WAIT #1: nam='SQL*Net more data to client' ela= 13 driver id=1111838976 #bytes=2001 p3=0 obj#=39 tim=558589762331 FETCH #1:c=0,e=1193,p=0,cr=93,cu=0,mis=0,r=500,dep=0,og=1,tim=558589762865 WAIT #1: nam='SQL*Net message from client' ela= 60762 driver id=1111838976 #bytes=1 p3=0 obj#=39 tim=558589823801 WAIT #1: nam='SQL*Net message to client' ela= 2 driver id=1111838976 #bytes=1 p3=0 obj#=39 tim=558589824139 WAIT #1: nam='SQL*Net more data to client' ela= 19 driver id=1111838976 #bytes=2001 p3=0 obj#=39 tim=558589825284
Do you notice something missing?
The PARSE #1 and EXEC #1 lines are missing as the actual parsing and execute calls happened way before the SQL trace was enabled. But Oracle was helpful enough to dump out the SQL text when next OPI call (FETCH) was issued under SQL tracing mode (it “noticed” that the SQL text corresponding to cursor #1 had not been dumped to trace yet).
This is helpful, but of course can cause some confusion, as this PARSING IN CURSOR doesn’t really mean parsing as such (as parsing is done under PARSE call), the PARSING IN CURSOR should probably be named as “ABOUT TO PARSE CURSOR” or something like that.
