Jared Still has created a poll about new metalink user interface. Give your opinion here.

Tanel Poder Administration, Oracle

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.

Tanel Poder Internals, Oracle, Oracle 11g, Performance, Troubleshooting

Have you experienced such situation before?

1. A performance issue happens in production – let say some batch job has ran way over time
2. You enable SQL trace on the problem session (while the problem is already ongoing)
3. In tracefile you see lots of waits (or execs or fetches) caused by cursor X
4. You grep for “PARSING IN CURSOR #X” above the waits in the tracefile but don’t find the corresponding parsing entry nor SQL text there (this is a “top-truncated” tracefile)
5. You really want to know which SQL corresponds to all those WAIT #X/FETCH #X lines

An example output would be here:

WAIT #2: nam='db file scattered read' ela= 25190 file#=1 block#=863 blocks=2 obj#=113 tim=548703769817
WAIT #2: nam='db file sequential read' ela= 51397 file#=1 block#=864 blocks=1 obj#=113 tim=548719015123
WAIT #2: nam='db file scattered read' ela= 348553 file#=1 block#=5969 blocks=8 obj#=113 tim=548732315966
WAIT #2: nam='db file scattered read' ela= 32275 file#=1 block#=5972 blocks=5 obj#=113 tim=548771073619

In above case the cursor #2 was causing all these WAIT lines. The problem is, that if the cursor #2 was parsed before the SQL trace was enabled, we won’t have the SQL statement dumped in the tracefile! Thus, by looking into the tracefile only, there’s no way to know which exact SQL statement is causing those waits.

If this was a single long-running SQL statement, you could easily look into v$session.sql_hash_value and map this to SQL text using v$sql. However things aren’t as simple when you have lots of PARSE,EXEC,FETCH calls of other statements happening in between (as the sql_hash_value would be constantly changing due each such call.

Also, other v$ (or x$) views don’t show you anything about the WAIT #X mapping to SQL statement as this stuff is not stored in SGA.

As a workaround, you could take the obj# and map it back to object number the (io) wait happened on and make some guesses about SQL statement from there. Or you could dump the datablock using file# and block# numbers, look at the data and make some further guesses about SQL statement, but guesses are no good as they can be wrong and misleading – and you would be dependent on luck in your troubleshooting. But you want to be systematic, right? ;-)

So, in case of the top-truncated tracefile, if you want to be sure which WAIT# (or FETCH#,EXEC#) lines correspond to which SQL statement, we need to use some other way than v$views or trying to guess based on bits in the tracefile.

Read more…

Tanel Poder Internals, Oracle, Performance, Troubleshooting