Hidden SQL – why can’t I find my SQL Text?
I recently ran into an interesting issue that drove me crazy for a couple of days! A very frequently executed statement on a database was generating some waits on “SQL*Net more data from client”. ASH shows the statement, as does the V$SESSION view, but the statement never shows up in the V$SQL view nor in the AWR tables. Here’s a brief run down of how the investigation went.
The reason for looking at this in the first place was that the application was timing out for brief periods of time. So a quick look at an AWR report for the time period showed a significant amount of time being spent waiting on the “SQL*Net more data from client” event. This event was taking a much larger slice of the pie than we saw during periods of “normal” activity. Here’s a little excerpt from one of the AWR reports:
Top 5 Timed Foreground Events
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Avg
wait % DB
Event Waits Time(s) (ms) time Wait Class
------------------------------ ------------ ----------- ------ ------ ----------
DB CPU 2,045 57.7
SQL*Net more data from client 165,760 868 5 24.5 Network
db file sequential read 58,083 449 8 12.7 User I/O
log file sync 33,656 85 3 2.4 Commit
direct path read 22,026 42 2 1.2 User I/O
...
% of Waits
-----------------------------------------------
Total
Event Waits <1ms <2ms <4ms <8ms <16ms <32ms <=1s >1s
-------------------------- ----- ----- ----- ----- ----- ----- ----- ----- -----
SQL*Net break/reset to cli 833 95.1 .6 .2 .1 3.6 .4
SQL*Net message to client 7537K 100.0 .0
SQL*Net more data from cli 165K 87.5 .4 .1 .0 .0 7.1 4.8
SQL*Net more data to clien 410K 100.0 .0
Obviously this is not good. This is on an 11g system so the AWR report provides a nice little histogram section on the wait events. The histogram indicates that most of these events are under 1ms, but a significant percentage are in the 16ms – 1sec range. So the question was, what could be causing those waits.
No problem, just check the Active Session History, find the sql_id for the statement(s) waiting on this event, and then look in V$SQL for the text. But not so fast bucko!
SQL> !cat find_sql_waiting_on_event.sql
select event, sql_id, count(*),
avg(time_waited) avg_time_waited
from v$active_session_history
where event like nvl('&event','%more data from%')
group by event, sql_id
order by event, 3
/
SQL> @find_sql_waiting_on_event
Enter value for event:
EVENT SQL_ID COUNT(*)
------------------------------ ------------- ----------
SQL*Net more data from client dkc2kbj7kdsu7 21
SQL*Net more data from client 62
SQL*Net more data from client 40du2847gh6sq 156
SQL*Net more data from client 7vtb7h3kpfat0 2965
SQL> -- Ah there's the culpret, 7vtb7h3kpfat0
SQL>
SQL> @find_sql
Enter value for sql_text:
Enter value for sql_id: 7vtb7h3kpfat0
Enter value for plan_hash_value:
no rows selected
SQL> -- hmm, must have aged out of the shared pool (seems unlikely since ASH has it so many times)
SQL> -- but maybe it's in the AWR tables
SQL>
SQL> @find_sql_awr
Enter value for sql_text:
Enter value for sql_id: 7vtb7h3kpfat0
no rows selected
SQL> -- nope, not there either
So I tried a couple of things to see if I could prove to myself that it was never in V$SQL (and thus never in the AWR tables). First I tried coloring the statement with the dbms_workload_repository.add_colored_sql procedure. (See Dion Cho’s post on this feature for more info). No luck! Then I tried using Tanel Poder’s sample.sql script (more info on that here) to run a bunch of queries against the V$SQLAREA view to see if the statement ever showed up. It did not! I then traced (10046) a bunch of the sessions that were executing the statement, hoping that the trace files would have the statement text. They did not, nor was the SQL_ID even contained in any of the trace files!
Turns out it is never in the shared pool and it is never in the AWR tables. But it is captured by ASH and it shows up in the SQL_ID column in V$SESSION. Here’s a little more output from the system:
SQL> select username, sid, serial#, status, sql_id, event, seconds_in_wait
2 from v$session
3 where username like nvl('&username',username)
4 and sid like nvl('&sid',sid)
5 and sql_id='7vtb7h3kpfat0'
6* order by username, sid, serial#;
Enter value for username:
Enter value for sid:
USERNAME SID SERIAL# STATUS SQL_ID EVENT SECONDS_IN_WAIT
------------------------- ------ ---------- -------- ------------- ------------------------------ ---------------
XX_OWNER 4661 4929 INACTIVE 7vtb7h3kpfat0 SQL*Net message from client 823
XX_OWNER 4676 3835 INACTIVE 7vtb7h3kpfat0 SQL*Net message from client 0
XX_OWNER 4682 9170 INACTIVE 7vtb7h3kpfat0 SQL*Net message from client 16
XX_OWNER 4699 11522 INACTIVE 7vtb7h3kpfat0 SQL*Net message from client 537
XX_OWNER 4712 9592 INACTIVE 7vtb7h3kpfat0 SQL*Net message from client 93
XX_OWNER 4717 6659 INACTIVE 7vtb7h3kpfat0 SQL*Net message from client 814
XX_OWNER 4727 25467 INACTIVE 7vtb7h3kpfat0 SQL*Net message from client 155
XX_OWNER 4739 8796 INACTIVE 7vtb7h3kpfat0 SQL*Net message from client 17
XX_OWNER 4755 7327 INACTIVE 7vtb7h3kpfat0 SQL*Net message from client 9
XX_OWNER 4800 4002 INACTIVE 7vtb7h3kpfat0 SQL*Net message from client 11
XX_OWNER 4826 15699 INACTIVE 7vtb7h3kpfat0 SQL*Net message from client 153
XX_OWNER 4838 6283 INACTIVE 7vtb7h3kpfat0 SQL*Net message from client 68
XX_OWNER 4849 11468 INACTIVE 7vtb7h3kpfat0 SQL*Net message from client 1052
XX_OWNER 5089 8610 INACTIVE 7vtb7h3kpfat0 SQL*Net message from client 1
XX_OWNER 5091 7709 INACTIVE 7vtb7h3kpfat0 SQL*Net message from client 31
XX_OWNER 5168 4728 INACTIVE 7vtb7h3kpfat0 SQL*Net message from client 585
XX_OWNER 5185 8298 INACTIVE 7vtb7h3kpfat0 SQL*Net message from client 157
XX_OWNER 5186 6969 INACTIVE 7vtb7h3kpfat0 SQL*Net message from client 1197
XX_OWNER 5210 10830 INACTIVE 7vtb7h3kpfat0 SQL*Net message from client 0
XX_OWNER 5232 6509 INACTIVE 7vtb7h3kpfat0 SQL*Net message from client 1
XX_OWNER 5251 12231 INACTIVE 7vtb7h3kpfat0 SQL*Net message from client 155
XX_OWNER 5400 5217 INACTIVE 7vtb7h3kpfat0 SQL*Net message from client 697
XX_OWNER 5423 12903 INACTIVE 7vtb7h3kpfat0 SQL*Net message from client 5
XX_OWNER 5434 14154 INACTIVE 7vtb7h3kpfat0 SQL*Net message from client 191
XX_OWNER 5441 33222 INACTIVE 7vtb7h3kpfat0 SQL*Net message from client 3
XX_OWNER 5442 5669 INACTIVE 7vtb7h3kpfat0 SQL*Net message from client 217
26 rows selected.
SQL> -- so there are a lot of sessions that execute our statement and then wait
SQL> -- (sometimes for a long time) before the user requests another action
SQL>
SQL> -- Using Tanel's sample.sql script - does about 1000 queries against V$SQLAREA in a sec or so
SQL>
SQL> @sample sql_text v$sqlarea "sql_id = '7vtb7h3kpfat0'" 1000
no rows selected
SQL> -- doesn't look like we'll ever catch it in the shared pool
Grasping at straws, I started looking for any views that had a sql_id and/or sql_text field, and I found one that I hadn’t thought to look in – V$OPEN_CURSOR. Ah, that’s probably a good place to look since surely a cursor must be created for this statement. Sure enough, this turned out to provide the necessary clue.
SQL> select distinct * from v$open_cursor
2 where rownum < 10
3* and sql_id like '%fat%';
SADDR SID USER_NAME ADDRESS HASH_VALUE SQL_ID SQL_TEXT LAST_SQL_
---------------- ------ ------------------------------ ---------------- ---------- ------------- ----------------------------------------- ---------
SQL_EXEC_ID
-----------
0000000210ED3980 4750 XX_OWNER 000000021AFEB748 3847695136 7vtb7h3kpfat0 table_4_9_fbd5_0_0_0
00000002111EC2E8 5043 SIGNON 0000000219E02E80 1527693606 6pfatm1dhxh96 SELECT u.app_user_id, u.username, u.pass
word, u.first_name,
000000021163BDA8 5451 XX_OWNER 000000021AFEB748 3847695136 7vtb7h3kpfat0 table_4_9_fbd5_0_0_0
00000002114067E0 5242 XX_OWNER 000000021AFEB748 3847695136 7vtb7h3kpfat0 table_4_9_fbd5_0_0_0
00000002114372F0 5260 SIGNON 0000000219E02E80 1527693606 6pfatm1dhxh96 SELECT u.app_user_id, u.username, u.pass
word, u.first_name,
0000000210F06FD8 4769 XX_OWNER 000000021AFEB748 3847695136 7vtb7h3kpfat0 table_4_9_fbd5_0_0_0
0000000211439E38 5261 SIGNON 0000000219E02E80 1527693606 6pfatm1dhxh96 SELECT u.app_user_id, u.username, u.pass
word, u.first_name,
00000002111E97A0 5042 SIGNON 0000000219E02E80 1527693606 6pfatm1dhxh96 SELECT u.app_user_id, u.username, u.pass
word, u.first_name,
000000021161E190 5440 XX_OWNER 000000021AFEB748 3847695136 7vtb7h3kpfat0 table_4_9_fbd5_0_0_0
9 rows selected.
So the SQL_ID was present in the V$OPEN_CURSOR view and there was a value in the SQL_TEXT field. Unfortunately, it didn't provide the text of the original statement, but at least I now had something to work with. A quick google for table_4_9_fbd5_0_0_0 (which is what was in the SQL_TEXT field) turned up nothing, of course. But a little digging turned up this post on Ask Tom. You'll have to read down a ways in that post to find that the real culpret was LOBs. Also, see this post on the Oracle-l list (which is what I originally found that pointed me to the Ask Tom article).
So it appears that the issue is that LOBs are being accessed, which causes Oracle to generate a new SQL_ID for the LOB access part of the execution. Apparently, these types of statements do not get exposed via the V$SQL and V$SQLAREA views and thus do not get captured by AWR. There are other types of statements that exhibit this behavior as well, by the way. The Tom Kyte post talks about nested tables for example. So back to the question, what statement generated the SQL_ID with the missing sql_text in the first place? We'll the first clue came from the Tom Kyte post. Apparently the middle bit of the text in the V$OPEN_CURSOR view is a hex representation of the object_id of the object that is being accessed (in our case, "fbd5"). So if we convert it to decimal we can find the object that is contains the LOB, like so:
SQL> select owner, object_name, object_type
2 from dba_objects
3 where object_id = (select to_number('&hex_value','XXXXXX') from dual);
Enter value for hex_value: fbd5
OWNER OBJECT_NAME OBJECT_TYPE
------------------------------ ------------------------------ -------------------
XX_OWNER XXX_MY_TABLE TABLE
So now I know that I'm looking for a statement that is accessing XXX_MY_TABLE (note: names have been changed to protect the innocent). But how to find the statement, that's the question that was never answered in the Tom Kyte post. It was at about this point, while I was filling my coffee cup, that I had one of those ah-ha moments (usually I have them when I'm doing something else - not even actively thinking about the problem). Anyway, I got to thinking about the PREV_SQL_ID in the V$SESSION view. If a statement that accesses a LOB, immediately generates a new SQL_ID for the LOB access part of the execution, perhaps the original statement's SQL_ID would be in the PREV_SQL_ID field. And that's exactly what I found.
SQL> select username, sid, serial#, status, sql_id, prev_sql_id, event, seconds_in_wait
2 from v$session
3 where username like nvl('&username',username)
4 and sid like nvl('&sid',sid)
5 and sql_id='7vtb7h3kpfat0'
6* order by username, sid, serial#;
Enter value for username:
Enter value for sid:
USERNAME SID SERIAL# STATUS SQL_ID PREV_SQL_ID EVENT SECONDS_IN_WAIT
------------------------- ------ ---------- -------- ------------- ------------- ------------------------------ ---------------
XX_OWNER 4665 8707 INACTIVE 7vtb7h3kpfat0 78jdubkb65p2w SQL*Net message from client 1235
XX_OWNER 4745 9383 INACTIVE 7vtb7h3kpfat0 78jdubkb65p2w SQL*Net message from client 1
XX_OWNER 4792 23304 INACTIVE 7vtb7h3kpfat0 78jdubkb65p2w SQL*Net message from client 1235
XX_OWNER 4816 11098 INACTIVE 7vtb7h3kpfat0 78jdubkb65p2w SQL*Net message from client 0
XX_OWNER 4844 3050 INACTIVE 7vtb7h3kpfat0 78jdubkb65p2w SQL*Net message from client 773
XX_OWNER 4907 8184 INACTIVE 7vtb7h3kpfat0 78jdubkb65p2w SQL*Net message from client 232
XX_OWNER 4959 35967 INACTIVE 7vtb7h3kpfat0 78jdubkb65p2w SQL*Net message from client 633
XX_OWNER 5154 33701 INACTIVE 7vtb7h3kpfat0 78jdubkb65p2w SQL*Net message from client 25
XX_OWNER 5230 12792 INACTIVE 7vtb7h3kpfat0 78jdubkb65p2w SQL*Net message from client 510
XX_OWNER 5248 49715 INACTIVE 7vtb7h3kpfat0 78jdubkb65p2w SQL*Net message from client 456
XX_OWNER 5249 32300 INACTIVE 7vtb7h3kpfat0 78jdubkb65p2w SQL*Net message from client 147
XX_OWNER 5282 21331 INACTIVE 7vtb7h3kpfat0 78jdubkb65p2w SQL*Net message from client 182
XX_OWNER 5285 386 INACTIVE 7vtb7h3kpfat0 78jdubkb65p2w SQL*Net message from client 185
XX_OWNER 5295 792 INACTIVE 7vtb7h3kpfat0 78jdubkb65p2w SQL*Net message from client 40
XX_OWNER 5416 49780 INACTIVE 7vtb7h3kpfat0 78jdubkb65p2w SQL*Net message from client 7
XX_OWNER 5419 22645 INACTIVE 7vtb7h3kpfat0 78jdubkb65p2w SQL*Net message from client 890
XX_OWNER 5442 6200 INACTIVE 7vtb7h3kpfat0 78jdubkb65p2w SQL*Net message from client 1326
17 rows selected.
SQL> @find_sql_long
Enter value for sql_id: 78jdubkb65p2w
SQL_TEXT
----------------------------------------------------------------------
SELECT XYZ_COLUMN, BLAH ... FROM XXX_MY_TABLE ...
SQL> @find_sql
Enter value for sql_text:
Enter value for sql_id: 78jdubkb65p2w
SQL_ID CHILD PLAN_HASH EXECS AVG_ETIME AVG_LIO SQL_TEXT
------------- ------ ---------- ---------- ------------- ------------ -----------------------------------------
78jdubkb65p2w 0 147781538 9,534,632 .0006 11 SELECT XYZ_COLUMN, BLAH
78jdubkb65p2w 1 147781538 191 .0005 11
One last comment (and then I'll shut up):
I was surprised to find that the statement was short - only a few lines long. I was expecting a really long string that would not fit in a single SQL*Net packet. After all, we are waiting on the "SQL*Net more data FROM client" event, right? Which is supposed to be the time waited for an additional packet from the client when Oracle knows that more is coming. Clearly this was not the case. Rather it is waiting because Oracle is sending data back to the client that takes more than one packet (i.e. the LOB). You would expect that time would be logged under the "SQL*Net more data TO client" event in this case. However, it appears that time is logged to that event only until the packet is turned over to the network. It appears that Oracle then starts logging time to the "SQL*Net more data FROM client" event while it waits for the next response from the client. Therefore, the actual network transfer time is clocked to the wrong event. You can understand why the developers made this choice, because Oracle has no way of knowing how long it actually takes the packet to get to the client. It only knows how long the round trip takes. So maybe they should have named the event slightly differently, like "SQL*Net more data from client including the entire round trip network time" or something. Anyway, Tanel Poder has a post that briefly mentions this quirk of the SQL*Net events.
Note: this is somewhat speculative on my part as I have not tried to prove exactly where the "TO" event stops and the "FROM" event begins. But I am pretty sure Tanel is correct on this point.
So there you have it. Just a little story about wandering through the weeds on the way to enlightenment.
=============================
Note: This part was added after Dion Cho commented that he wasn't able to re-produce the behavior, so I gave it shot (I got close). Here's the output:
> sqlplus / as sysdba
SQL*Plus: Release 11.1.0.7.0 - Production on Mon Apr 20 14:59:25 2009
Copyright (c) 1982, 2008, Oracle. All rights reserved.
Connected to:
Oracle Database 11g Enterprise Edition Release 11.1.0.7.0 - Production
With the Partitioning, OLAP, Data Mining and Real Application Testing options
SQL> -- session (SID 124) connected as KSO issues "select xml_clob from test_lob"
...
SQL> -- what's going on?
SQL> @sessions
Enter value for username:
Enter value for sid:
USERNAME SID SERIAL# STATUS SQL_ID EVENT SECONDS_IN_WAIT
------------------------- ---- ---------- -------- ------------- ------------------------------ ---------------
KSO 124 2402 ACTIVE cu98u9ukjqj19 SQL*Net message from client 0
SYS 128 3580 ACTIVE bsbmyw5thg8qf SQL*Net message to client 0
SQL> -- KSO is running cu98u9ukjqj19, what's that doing?
SQL> @find_sql
Enter value for sql_text:
Enter value for sql_id: cu98u9ukjqj19
no rows selected
SQL> -- so that's probably the LOB access, let's check
SQL> select * from v$open_cursor where sql_id like 'cu98u9ukjqj19';
SADDR SID USER_NAME ADDRESS HASH_VALUE SQL_ID SQL_TEXT LAST_SQL_ SQL_EXEC_ID
-------- ---- ----------------------- -------- ---------- ------------- ------------------------------------- --------- -----------
DB1A69C8 124 KSO E0BD4C0C 2770027561 cu98u9ukjqj19 table_4_9_19a1d_0_0_0
SQL> -- yep, LOB access, let' see if we can find the original statement
SQL> @sessionsp
Enter value for username:
Enter value for sid:
USERNAME SID SERIAL# STATUS SQL_ID PREV_SQL_ID EVENT SECONDS_IN_WAIT
------------------------- ---- ---------- -------- ------------- ------------- ------------------------------ ---------------
KSO 124 2402 ACTIVE cu98u9ukjqj19 9babjv8yq8ru3 direct path read 0
SYS 128 3580 ACTIVE grdgy5dcmqd0f 9babjv8yq8ru3 SQL*Net message to client 0
SQL> -- says prev statement is 9babjv8yq8ru3
SQL> @find_sql
Enter value for sql_text:
Enter value for sql_id: 9babjv8yq8ru3
SQL_ID CHILD PLAN_HASH EXECS AVG_ETIME AVG_LIO SQL_TEXT
------------- ------ ---------- ---------- ------------- ------------ ------------------------------------------------------------
9babjv8yq8ru3 1 0 39 .01 54 BEGIN DBMS_OUTPUT.GET_LINES(:LINES, :NUMLINES); END;
SQL> -- oops, SQL*Plusism - need to turn off serveroutput
/*
-- go to other session here and set serveroutput off and re-run select statement
*/
SQL> -- wait a little while until the statement finishes
SQL> @sessionsp
Enter value for username:
Enter value for sid:
USERNAME SID SERIAL# STATUS SQL_ID PREV_SQL_ID EVENT SECONDS_IN_WAIT
------------------------- ---- ---------- -------- ------------- ------------- ------------------------------ ---------------
KSO 124 2402 INACTIVE djqbj30qjyngw SQL*Net message from client 74
SYS 128 3580 ACTIVE grdgy5dcmqd0f 9babjv8yq8ru3 SQL*Net message to client 0
SQL> -- note that the SQL_ID field has been wiped after the statement completes - need to look a little closer at this behavior
SQL> -- the java application I was looking at in production did not cause this behavior - i.e. the SQL_ID field would not be cleared
SQL> -- so finding the SQL_ID for the LOB access and the PREV_SQL_ID for the original statement didn't happen in my test case
SQL> -- although the PREV_SQL_ID field does contain the value for the original statement
SQL> @find_sql
Enter value for sql_text:
Enter value for sql_id: djqbj30qjyngw
SQL_ID CHILD PLAN_HASH EXECS AVG_ETIME AVG_LIO SQL_TEXT
------------- ------ ---------- ---------- ------------- ------------ ------------------------------------------------------------
djqbj30qjyngw 0 825212230 2 2.61 53,065 select xml_clob from test_lob
I’ve noticed same strange behaviour on one of my systems. Before your post i was only able to understand that problem was with LOB and i’ve found it through V$ACTIVE_SESSION_HISTORY and SQL_PLAN_HASH_VALUE field. Querying V$SQL_PLAN (with value in ASH) i’ve found (with my great surprise) a lot of different sql_id’s and querying V$SQL with one of those SQL_ID i’ve found the query on a LOB.
Thank you for this great post.
Glad to hear it helped you out. It drove me crazy for a couple of days.
Kerry
Kerry.
It’s very interesting case even though I could not reproduce your case(SQL*Net more data from client thing).
Anyway, query on x$kglob would have shown some data like:
select * from sys.x$kglob where kglobt03 = ”;
And library cache dump would show the depedent table for the LOB LCO.
But still, hard to decode. 🙂
[…] leave a comment » Kerry Osborne wrote an interesting case on LOB here. […]
Dion,
Thanks for the pointer on the x$kglob. I’m with you, I don’t want to look at any dumps unless I have too. I hadn’t tried to reproduce this issue until this morning after your comment. But I didn’t have too many problems doing so. The problems for me were all related to doing the test in SQL*Plus. The first was that SQL*Plus spits out DBMS_OUTPUT calls unless you set serveroutput off (so this wiped out the prev_sql_id field in v$session). The second issue is that when the statement completes, the sql_id field in v$session is wiped out. The entries still exist in v$open_cursor and the prev_sql_id field still has the original sql_id of the statement which generated the access to the lob. So in order to see the behavior we had in production, my SQL*Plus test required that I catch the session in the act of executing the statement. I haven’t had time to look into that yet. I have captured the data and will add it to the original post as I’m not sure how the formatting would work in the comments section.
Thanks for your comments.
Kerry
[…] Osborne wonders about Hidden SQL – why can’t I find my SQL Text?, beginning, “A very frequently executed statement on a database was generating some waits on […]
[…] followings are related posts which describe the same phenomenon in the different ways. http://kerryosborne.oracle-guy.com/2009/04/hidden-sql-why-cant-i-find-my-sql-text/ […]
It’s an awesome article …. I am in the same situation in trying to figure out why CPU is getting killed ….and troubleshooted based on your article. I was able to figure out the offending sql.
I am quite interested to know how you tuned that query after finding the bottleneck … Can you share that information ?…
Well, the app servers were several states way from the database servers. And the dedicated network connection between them was pretty slow. The statement was executed a lot. Several options for dealing with it presented themselves.
1. Get a bigger pipe.
2. Reducing frequency – Because the query was executed multiple times per transaction getting only one row at a time, it should have been possible to collapse it into a single multi-row get.
3. Move the app servers – to the datacenter where the database servers resided.
4. Move the data – to the datacenter where the app servers resided.
5. Alter the code – It turned out that the amount of data in the vast majority of the clob’s was only a couple of hundred bytes, but for some reason, SQL*Net padded the field to appx. 80K. Putting a to_char function around the column in the select statement caused the filed to not be padded. I think this may be related to the java variable type they were selecting into. At any rate, another possible solution would have been to alter the code to add the to_char function.
6. Alter the design to get rid of the XML/Clob – since the clob rarely had more than a couple of hundred bytes, there were many options. All the way from eliminating the XML altogether in favor of columns and rows, to just changing the clob to a varchar2.
In the end, the decision was number 4, moving the data closer to the app servers. This was done by replicating the data via Streams to another instance in the datacenter where the app servers are located. Not my favorite solution, but it required no code changes. We’re still discussion changing the code via to_char and redesign, but the wheels of justice turn slowly.
Kerry
Great article, Kerry! I’ve worked through this same problem, but you worked through it efficiently without all the dead-ends I tripped down. Wish I had found your article before I’d taken this on by myself, would have saved myself a ton of time! 🙂
Kellyn
Hi Kerry,
I had a similar case and followed your article. But, if the “unknown” sql took place a while ago:
– the session may be gone, therefore no info on prev_sql_id, or open cursor
– the session may still be connected, so you may still find the open cursor for the sql_id, but even if it’s there, the current sql id and prev sql id may already be for the sql executed long after the one we are looking for
Unless I’m missing somehting, in the above conditions, it is more of a guessing game. The most helpfull for me was that I was able to identify an open cursor with “table_…” and based on that the actual table containing the LOB column. That combined with some knowledge of the application gave me enough info to talk to the developers.
Thanks for this great post. Those darn “table_#~_@%_!?#” sql statements have really been annoying – they just sit there in v$open_cursor and tell you nothing.. prev_sql_id indeed!
Hi Kerry,
Big fan here, especially of Enkitec gurus. I wish I can get my hand on one of them Exadata boxes :(-
If you don’t mind me asking … Are the SQL scripts that you are running, find_sql.sql find_sql_long.sql find_sql_waiting_on_event.sql etc, in one of the whitepapers / presentations. I can see most but not all of them are in my_favorite_scripts_2010.zip
Hi Bart,
I don’t use find_sql_waiting_on_event.sql anymore as it was not returning what I thought it was when I wrote it. I now use Tanel’s sw.sql script. The other two are linked below (they are just hacks by the way but seem to do what I need):
find_sql.sql
find_sql_long.sql
Kerry
Hi Kerry,
I usualy read your blog, but this time, it was by chance that i found this very instructive post.
Very instructive because as usual you describe how you move forward.
Thanks again for all your very valuable stuff,
Can’t wait to attend your presentation at UKOUG 2012 🙂
Olivier
(One of the very few french guys attending ukoug)
Thanks Olivier. Sadly I’m not getting to do much blogging at the moment. But I appreciate the kind words. See you in a couple of weeks.
Kerry
Hii Kerry
I have same problem like you except there is no LOB.
IIS process(w3wp.exe) is calling a stored procedure frequently. sql text is “Begin PK_WH.SP_DATA_CLOSE(:v0, :v1, :v2, :v3, :v4, :v5); End;”
I have increased SDU on client and server side I am seeing correct SDU in sqlnet trace but nothing has changed.Server ve client(IIS Server) on same switch.have you any idea ?
Best Regards
Sorry EB I don’t.
Actually my sql statement is using multiple sql_id in 11g(11.2.0.3.0). It is causing big performance issue in my database. Can help me why it is taking multiple sql_id for single statement and how to fix the issue. we didn’t any changes in sql query.
It is Siebel application database.
Hi Jey,
I’d love to see a SQL statement who’s text doesn’t change but who’s SQL_ID does. Please send me some details.
Kerry
Kerry,
I’m looking into what appears to be a nearly identical scenario, with the significant deviation of the mystery SQL_ID never appearing in [g]v$open_cursor either. Have you ever encountered such a variant? I’m about at my wits end, trying to find a way to determine what’s actually occurring.
In case the version matters, I’m seeing this on an Oracle 11.2.0.3.6 64-bit database running on a Solaris 10 SPARC cluster. Thanx!
-Adric
Hi Adric,
V$OPEN_CURSOR hides a bunch of stuff. Try going after the underlying x$ (x$kgllk). The v$open_cursor view def looks like this:
Eliminate the where clause and see if you can find it.
Kerry
Interestingly, I’m still not able to find the SQL_ID even when querying x$kgllk without a where clause. I’m starting to suspect this is a very different scenario from the one you described, despite the superficial similarities.
-Adric