How to detect when a cursor was closed from SQL trace output?

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.

This entry was posted in Oracle and tagged , , , . Bookmark the permalink.

9 Responses to How to detect when a cursor was closed from SQL trace output?

  1. Jeff Holt says:

    Some “parsing” is also done during the EXEC, such as validating the execution plan of statements that require an execution plan.

    I think a good name for PARSING IN CURSOR is CURSOR ATTRIBUTES or ATTRIBUTES FOR CURSOR. I had toyed with the name TEXT FOR CURSOR but that is too specific given the recursive depth and authentication attributes given.

  2. Tanel Poder says:

    yep agreed, this section has other useful info in addition to SQL text…

  3. Tanel Poder says:

    ..or just CURSOR INFO :)

  4. Paresh says:

    Hi,

    Could you please point me to a good tutorial to understand 10046 trace file in-depth.

    Thanks in Advance.

  5. Tanel Poder says:

    The best source, going deep into the topic is Cary Millsap’s and Jeff Holt’s Optimizing Oracle Performance book.

    Otherwise, I think there’s a metalink note about it (search for “reading 10046 trace”) and a google search returned few hits with some details like this one:

    http://oradbatips.blogspot.com/2007/06/tip-48-reading-10046-trace.html

  6. Raj says:

    Hi Tanel

    Neat Compilation I should say.
    Wanted your help to know if a table is suffering from row migration from any block dump? [ the reason I want to know this from dumps is that I work on a Datawarehouse database of size 200TB
    and tables on it are very big ..to the tune of 500GB to 1 TB, so its impossible to do a ‘analyze table list chained rows into chained_rows’ for the following reasons:
    (a) analyze statement…cannot be parallelized , only dbms_stats can be parallezied, so I cannot accelerate this activity.
    (b) also tables undergo batch jobs every now and then so I would like to keep this table free of any routine maitenace activity.

    Thank you for your invaluable blogs as always.

  7. Tanel Poder says:

    There’s still part 2 to come but I don’t know when I have time for it :(

  8. Norbert says:

    @Tanel Poder
    The book “Secret ORACLE – Unleashing the Full Potential of the ORACLE DBMS by Leveraging Undocumented Features” covers the Oracle10g and Oracle11g Release 1 SQL trace file formats. “Optimizing Oracle Performance” was published in 2003 and as such only covers Oracle9i.
    Purchases directly from the publisher at http://www.lulu.com are preferred.

Leave a Reply

Your email address will not be published. Required fields are marked *

You may use these HTML tags and attributes: <a href="" title=""> <abbr title=""> <acronym title=""> <b> <blockquote cite=""> <cite> <code> <del datetime=""> <em> <i> <q cite=""> <strike> <strong>