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

23 Comments

  1. Cristian says:

    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.

  2. osborne says:

    Glad to hear it helped you out. It drove me crazy for a couple of days.

    Kerry

  3. Dion Cho says:

    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. :)

  4. [...] leave a comment » Kerry Osborne wrote an interesting case on LOB here. [...]

  5. osborne says:

    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

  6. [...] 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 [...]

  7. abcd_1234 says:

    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 ?…

  8. osborne says:

    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

  9. 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

  10. Mark says:

    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.

  11. Paul says:

    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!

  12. Bart says:

    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

  13. osborne says:

    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

  14. Olivier says:

    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)

  15. osborne says:

    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

  16. EB says:

    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

  17. Jey says:

    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.

  18. osborne says:

    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

  19. Adric says:

    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

  20. osborne says:

    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:

    select inst_id,kgllkuse, kgllksnm, user_name, kglhdpar, kglnahsh, kgllksqlid, kglnaobj, kgllkest, decode(kgllkexc, 0, to_number(NULL), kgllkexc), kgllkctp
    from x$kgllk
    where kglhdnsp = 0 and kglhdpar != kgllkhdl;
    

    Eliminate the where clause and see if you can find it.

    Kerry

    • Adric says:

      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

Leave a Reply