Ok, I think it’s time to write another blog entry. I’ve been traveling and dealing with jetlag from 10-hour time difference, then traveling some more, spoken at conferences, drank beer, had fun, then traveled some more, trained customers, hacked some Exadatas and now I’m back home.

Anyway, do you know what is the SQL_EXEC_ID in V$SESSION and ASH views?

Oh yeah, it’s the “SQL Execution ID” just like the documentation says … all clear. Um … is it? I’d like to know more about it – what does it actually stand for?! Is it session level, instance level or a RAC-global counter? And why does it start from 16 million, not 1?

SQL> SELECT sql_exec_id FROM v$session WHERE sid = USERENV('SID');

SQL_EXEC_ID
-----------
   16777216

This number 16777216 looks strangely familiar – indeed, it’s 2^24.

When I run the same query again (incrementing the SQL_EXEC_ID counter for the same SQL), I see the counter going up by 1:

SQL> SELECT sql_exec_id FROM v$session WHERE sid = USERENV('SID');

SQL_EXEC_ID
-----------
   16777217

SQL> SELECT sql_exec_id FROM v$session WHERE sid = USERENV('SID');

SQL_EXEC_ID
-----------
   16777218

SQL> SELECT sql_exec_id FROM v$session WHERE sid = USERENV('SID');

SQL_EXEC_ID
-----------
   16777219

SQL> SELECT sql_exec_id FROM v$session WHERE sid = USERENV('SID');

SQL_EXEC_ID
-----------
   16777220

Further executions of the same query keep incrementing this counter, one by one – even if I run this same SQL from another session in the same instance. So, this SQL_EXEC_ID is not a session-scope value for each SQL_ID, it’s at least instance-wide. It looks like the counting starts from 2^24 (the bit representing 2^24 is set) and ignoring that bit for now, the counting works normally, one by one, starting from zero.

Note that changing even a single character in the SQL text (see the extra space in the end before the semi-colon) causes the SQL_ID to change and a different SQL_EXEC_ID counter to be reported (which starts from “zero” again). A separate SQL_EXEC_ID counter is maintained in shared pool for each SQL_ID:

SQL> SELECT sql_exec_id FROM v$session WHERE sid = USERENV('SID') ;

SQL_EXEC_ID
-----------
   16777216

So, obviously, when I have just restarted my instance and still see 16777216 as the starting SQL_EXEC_ID for any SQL I execute, it must mean that the full SQL_EXEC_ID value contains something else than just the execution number of this SQL_ID. Whenever I see such familiar values (like powers of 2), then I like to look into the values in hex format to see whether some higher order bits are used for some special purpose. Let’s run a new SQL statement:

SQL> SELECT sql_exec_id, TO_CHAR(sql_exec_id,'XXXXXXXX') hex FROM v$session WHERE sid = USERENV('SID') ;

SQL_EXEC_ID HEX
----------- ---------
   16777216   1000000

SQL> SELECT sql_exec_id, TO_CHAR(sql_exec_id,'XXXXXXXX') hex FROM v$session WHERE sid = USERENV('SID') ;

SQL_EXEC_ID HEX
----------- ---------
   16777217   1000001

SQL> SELECT sql_exec_id, TO_CHAR(sql_exec_id,'XXXXXXXX') hex FROM v$session WHERE sid = USERENV('SID') ;

SQL_EXEC_ID HEX
----------- ---------
   16777218   1000002

Indeed, it looks like the 25th bit (2^24) is always pre-set to 1, while the least significant 24 bits represent how many times this SQL ID has been executed in an instance (I have tested this with a loop – the 24 least significant bits do get used fully for representing the SQL ID’s execution count in the instance and once it reaches 0xFFFFFF – or 0x1FFFFFF with that pre-set 25th bit, it wraps to 0×1000000 – the 25th bit still remaining set!). So the SQL_EXEC_ID can reliably only track 2^24 – 1 SQL executions in an instance and then the counter wraps to beginning. This is why you should include SQL_EXEC_START (date datatype with 1 sec precision) column in your performance monitoring queries as well, to distinguish between SQL executions with a colliding SQL_EXEC_ID. As long as you’re executing your SQL statement less than 16.7 million times per second per instance, this should be fine :-)

Anyway, so what’s the magic 25th bit then? Well, in RAC it would be very hard to somehow coordinate the incrementing of a single counter globally (that’s why you want to keep your sequences cached in RAC), I figure that there are different counters for the same SQL ID in different RAC instances. Let’s check – I will log in to another RAC node (node 2) and run this:

SQL> SELECT sql_exec_id, TO_CHAR(sql_exec_id,'XXXXXXXX') hex FROM v$session WHERE sid = USERENV('SID') ;

SQL_EXEC_ID HEX
----------- ---------
   33554433   2000001

SQL> SELECT sql_exec_id, TO_CHAR(sql_exec_id,'XXXXXXXX') hex FROM v$session WHERE sid = USERENV('SID') ;

SQL_EXEC_ID HEX
----------- ---------
   33554434   2000002

SQL> SELECT sql_exec_id, TO_CHAR(sql_exec_id,'XXXXXXXX') hex FROM v$session WHERE sid = USERENV('SID') ;

SQL_EXEC_ID HEX
----------- ---------
   33554435   2000003

Whoa – the SQL Execution ID in the 2nd instance starts from 33 Million! And when you convert the value to hex, you’ll see that now the 26th bit is set – showing that this SQL was executed in instance #2!

So, it very much looks like that while the 24 least significant bits are used for the SQL execution ID counter, the more significant bits are used for showing which instance_id ran that SQL. Assuming that 32 bits are used for the whole SQL_EXEC_ID value, then up to 8 higher order bits could be used for storing the instance_id – supporting up to 256-node RAC clusters. This is very useful when analyzing past ASH data as you can aggregate data (count min/max exec ID difference to get the execution counts in a time range) either in each separate instance or globally – by stripping out the instance_id part from the value.

I haven’t tested the instance_id part with 256-node RAC clusters (as Santa Claus is cutting back due to poor economy), but at least on an 8-node full rack Exadata all 8 instance_ids were reported properly. Note that for serial queries, the SQL_EXEC_ID shows you the instance_id of the instance where the session is logged on to, but for inter-instance parallel query, you will see the instance_id of the query coordinator for all PX slaves, regardless of in which instances they run. Here’s a little script from a 8-node Exadata cluster to show it. I’ll leave it up to you to fully figure it out what, how and why it’s doing, but basically what it shows is that the SQL_EXEC_ID consists of the query coordinator’s instance_id value and the execution number for a SQL_ID in the instance where the query coordinator session was logged in:

SQL> SELECT qc_instance_id, MIN(TO_CHAR(sql_exec_id,'XXXXXXXX'))
  2  , MAX(TO_CHAR(sql_exec_id,'XXXXXXXX'))
  3* FROM gv$active_session_history GROUP BY qc_instance_id order by 1
SQL> /

QC_INSTANCE_ID MIN(TO_CH MAX(TO_CH
-------------- --------- ---------
             1   1000000   100540F
             2   2000000   20009BF
             3   3000000   300541E
             4   4000000   40000DD
             5   5000000   50C5035
             6   6000000   600018C
             7   7000000   700023D
             8   8000000   8000755
                 1000000   803DF3B

9 rows selected.

That’s all for today – more cool stuff is coming, I promise :-)

And oh, next week I’ll start another run of my Advanced Oracle Troubleshooting seminar, so check it out! ;-)

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.