IOUG Select Journal Editor’s Choice Award 2011

In May I received the IOUG Select Journal Editor’s Choice Award for my Systematic Oracle Latch Contention Troubleshooting article where I introduced my LatchProfX tool for advanced drilldown into complex latch contention problems (thanks IOUG and John Kanagaraj!).

As the relevant IOUG webpage hasn’t been updated yet, I thought to delay this announcement until the update was done – but I just found an official enough announcement (press release) by accident from Reuters site:

Woo-hoo! :-)

The article itself is here:

Thanks to IOUG crew, John Kanagaraj and everyone else who has read, used my stuff and given feedback! :-)

Knowing what you want to achieve before thinking of how to achieve it – a query optimization example

Today I received a question which was a good example of systematic problem solving approach. It was about getting a long-running query to run faster. It took a long time as the correlated subquery in the query was not unnested, was re-visited many times, causing the whole subquery subtree in the plan to be executed again and again). The main part of the question was this:

Is there a way to avoid “NOT IN” conversion to “NOT EXISTS” by optimizer … My sub query, I would like it to be fully instantiated as view and then execute it as a Hash Anti join.

The first part of the above question sounds like the type of question I hear quite frequently (e.g. how to force Oracle use an index or adjust some feature of the execution plan – without any extra context information). These kind of questions are often the result of the developer not being familiar with the data and hoping to optimize the query by adding some “silver bullet” hint.

But the second part of the above question (in bold) clearly shows that the asker had done his homework and knew exactly what he was trying to achieve. In other words, the asker knew the data model, the data (amount and distribution), understood what the query was trying to achieve and finally knew roughly how many rows would be returned from different tables for the given query predicates. And based on that knowledge and understanding of how Oracle SQL plan execution works, he knew that it’s not a good idea to use the nested FILTER operator for correlated subquery lookups, as if the parent query returns millions of rows, you’d potentially have to re-visit the subquery branch of execution plan tree millions of times too, revisiting the same blocks again and again, driving up (logical) IOs, CPU usage etc.

The asker also knew that Oracle can use a special variation of hash join for performing anti-joins (NOT IN, NOT EXISTS style subqueries get unnested and are executed using a join mechanism instead of correlated lookups using FILTER loop). The asker also knew that it’s much more efficient to join / compare millions of rows with a single hash join run (visit source tables only once) as opposed to millions of correlated lookups revisiting “random” index & table blocks again and again.

As a result, the asker formulated what he was trying to change in the execution plan and then thought how to achieve it. This is the systematic way for tuning a SQL statement and it requires you to understand the query, database capabilities and definitely the data this query is using. The problem was that regardless of the hints he tried, he couldn’t achieve the desired plan. (Note the “desired plan” – you know in advance what you want and use tools like hints for achieving that, not the other way around).

I came up with a small test case (as I often don’t remember things off the top of my head) to illustrate the correct hints for changing the plan the way he wanted:

SQL> CREATE TABLE t1 AS SELECT * FROM all_users;

Table created.

SQL> CREATE TABLE t2 AS SELECT * FROM all_users;

Table created.

SQL> CREATE TABLE t3 AS SELECT * FROM all_users;

Table created.

Now the minimal test query (its quite simplistic and note that it’s not even a correlated subquery as the subquery predicates do not reference parent query’s tables):

SELECT *
FROM t1
WHERE t1.user_id NOT IN (
    SELECT t2.user_id
    FROM t2, t3
    WHERE t2.username = t3.username
);

The CBO trace showed the final form of the query after transformations – and the uncorrelated NOT IN subquery was converted to a correlated NOT EXISTS subquery:

******* UNPARSED QUERY IS *******

SELECT /*+ */
    "SYS_ALIAS_1"."USERNAME" "USERNAME","SYS_ALIAS_1"."USER_ID" "USER_ID","SYS_ALIAS_1"."CREATED" "CREATED"
    FROM "SYSTEM"."T1" "SYS_ALIAS_1"
    WHERE NOT EXISTS (
        SELECT /*+ */ 0 FROM "SYSTEM"."T2" "T2","SYSTEM"."T3" "T3"
        WHERE "T2"."USER_ID"="SYS_ALIAS_1"."USER_ID" AND "T2"."USERNAME"="T3"."USERNAME"
    )

The execution plan uses a correlated FILTER loop for probing the subquery, even though the nature of this query doesn’t really require correlated access. As a result, the HASH JOIN in line #3 below and the table access rowsources under it were visited 26 times, in this case once per row returned from the parent query’s row sources (table T1in line #2):

------------------------------------------------------------------------------------------------------------------------------
| Id  | Operation           | Name | Starts | E-Rows | Cost (%CPU)| A-Rows |   A-Time   | Buffers |  OMem |  1Mem | Used-Mem |
------------------------------------------------------------------------------------------------------------------------------
|*  1 |  FILTER             |      |      1 |        |            |      0 |00:00:00.01 |     159 |       |       |          |
|   2 |   TABLE ACCESS FULL | T1   |      1 |     26 |     2   (0)|     26 |00:00:00.01 |       3 |       |       |          |
|*  3 |   HASH JOIN         |      |     26 |      1 |     5  (20)|     26 |00:00:00.01 |     156 |  1517K|  1517K|  301K (0)|
|*  4 |    TABLE ACCESS FULL| T2   |     26 |      1 |     2   (0)|     26 |00:00:00.01 |      78 |       |       |          |
|   5 |    TABLE ACCESS FULL| T3   |     26 |     26 |     2   (0)|    351 |00:00:00.01 |      78 |       |       |          |
------------------------------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   1 - filter( IS NULL)
   3 - access("T2"."USERNAME"="T3"."USERNAME")
   4 - filter("T2"."USER_ID"=:B1)

The pseudo-bind variable :B1 reported in predicate section gives a further clue that a correlated lookup loop is used, the FILTER operation takes the next parent query row’s USER_ID value and passes it in to the filter predicate on line #4 above with every loop iteration. The execution plan unparser (which generates human readable execution plan texts) uses a naming convention so that such FILTER loop variables are reported as bind variables – but the query doesn’t actually use any real (user supplied binds). It’s just how these query plan explainers report things…

Anyway, as I knew what kind of change we wanted to achieve, I recommended to use the following hints to see whether they give the desired result.

SELECT *
FROM t1
WHERE t1.user_id NOT IN (
    SELECT /*+ UNNEST HASH_AJ(t2) */
        t2.user_id
    FROM t2, t3
    WHERE t2.username = t3.username
);

And now the important part – this wasn’t a wild guess (like “let’s see, maybe it helps”). I deliberately recommended these hints as they control the features we wanted to change.

The resulting unparsed query text after transformations was following – the subquery was gone (no NOT IN or NOT EXISTS anymore) and the subquery was unnested and converted into an inline view (in bold), joined to the parent query (using the where condition in the bottom of the below output):

******* UNPARSED QUERY IS *******

SELECT "T1"."USERNAME" "USERNAME","T1"."USER_ID" "USER_ID","T1"."CREATED" "CREATED"
FROM
    (SELECT /*+ UNNEST */
        "T2"."USER_ID" "$nso_col_1"
        FROM "SYSTEM"."T2" "T2","SYSTEM"."T3" "T3"
        WHERE "T2"."USERNAME"="T3"."USERNAME"
    ) "VW_NSO_1"
   ,"SYSTEM"."T1" "T1"
WHERE
    "T1"."USER_ID"="VW_NSO_1"."$nso_col_1"

A little detour:

Note that the “unparsed” query text in CBO tracefile is FYI only. It is not the real query text actually executed! It doesn’t contain all the little details required for executing the query right and returning correct data. Unparsing means extracting information from the binary execution plan and converting it into human (or DBA) readable form, but some of the information gets lost in the process. If you ran the above unparsed query, you would get resultset of a regular join, not the NOT IN antijoin originally requested. This is why you should never assume that the unparsed query is the correct text to use in your application. It’s just FYI, for debugging.

One of the pieces present in binary execution plan, but not in the unparsed query, is highlighted below. See the HASH JOIN ANTI - this ANTI in the binary plan says that don’t use a regular join (returning matching rows) but do exactly the opposite (return non-matching rows).


-----------------------------------------------------------------------------------------------------------------------------------
| Id  | Operation            | Name     | Starts | E-Rows | Cost (%CPU)| A-Rows |   A-Time   | Buffers |  OMem |  1Mem | Used-Mem |
-----------------------------------------------------------------------------------------------------------------------------------
|*  1 |  HASH JOIN ANTI      |          |      1 |      1 |     7  (15)|      0 |00:00:00.02 |       9 |  1023K|  1023K| 1176K (0)|
|   2 |   TABLE ACCESS FULL  | T1       |      1 |     26 |     2   (0)|     26 |00:00:00.01 |       3 |       |       |          |
|   3 |   VIEW               | VW_NSO_1 |      1 |     26 |     5  (20)|     26 |00:00:00.01 |       6 |       |       |          |
|*  4 |    HASH JOIN         |          |      1 |     26 |     5  (20)|     26 |00:00:00.01 |       6 |  1179K|  1179K| 1180K (0)|
|   5 |     TABLE ACCESS FULL| T2       |      1 |     26 |     2   (0)|     26 |00:00:00.01 |       3 |       |       |          |
|   6 |     TABLE ACCESS FULL| T3       |      1 |     26 |     2   (0)|     26 |00:00:00.01 |       3 |       |       |          |
-----------------------------------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   1 - access("T1"."USER_ID"="$nso_col_1")
   4 - access("T2"."USERNAME"="T3"."USERNAME")

When you look into the Starts column in the above plan, you see that now all the tables were scanned only once (that’s what hash joins do). So, no more revisiting the same blocks again and again for each row returned from table(s) in the parent query. Also, note the new VIEW row source which Oracle has injected in between the parent query and subquery tables – this is to make sure that the subquery tables don’t get merged with parent query and joined in a wrong order / possibly with the ANTI-join done in the wrong place. In the stored outline hints, such injection will show up as a NO_ACCESS hint (telling optimizer that the parent query block does not have access into a query block under it for merging its contents).

In any case, now my little test query visited much less buffers, did less work, did not repeatedly scan through the same tables again. Of course, this was just a synthetic test query – but nevertheless, applying the same hints on the real problem query made it run in 2 minutes instead of multiple hours.

Now, there are some outstanding questions here, like whether it’s a good idea to tune a query with hints and whether the optimizer statistics were representative of the reality and so on. Why didn’t optimizer come up with the best plan itself? Was this due to a bug, etc.

But all this isn’t the point of my blog post – my point is that whenever you want to systematically fix or improve something, you will have to know what you are trying to achieve first, also understand why should this actually work and then you’ll pick the best tools for achieving that goal (how). As the guy who asked the question had already done most of the work – figuring out how the plan should be executed for best efficiency – finding the way to achieve that was easy.

When manually optimizing SQL, this does require that you actually care about your work enough to take the time to undestand the capabilities of your database engine, the query and the data. Of course you have to be smart about where you optimize manually and where you should try to get Oracle to do the right thing by itself. Phew, I’ve got to write about that stuff some other day :-)

Update: Thanks to Jonathan Lewis’es comment I drilled down to this example further and it turns out that in this case just using UNNEST hint would be enough (and HASH_AJ is not needed) as after the unnesting is forced, the CBO figures the best (anti)join method out from there. Note that this post wasn’t about hints, it was about emphasizing that if you want to systematically tune a SQL statement execution plan, you should first figure out what it should be doing (which join order, -methods, access paths etc) and then find a way to achieve that – in my case it was done with hints.

P.S. I will schedule my Advanced Oracle SQL Tuning online course in september or october – stay tuned ;-)

For Exadata geeks

Just letting you know that we are all (almost) done with the Expert Oracle Exadata book work and it will be published in less than a month!!!

Expect (many) new blog entries soon! :-)

Running SELECT … INTO :bind_variable from SQL

I just wasted a few minutes troubleshooting one of my scripts – and realized that while SELECT … INTO :bind_variable does not error out when executed as top-level SQL, it doesn’t seem to populate the resulting bind variable:

SQL> VAR blah VARCHAR2(10)
SQL> SELECT dummy INTO :blah FROM dual;

D
-
X

SQL> print blah

BLAH
--------------------------------


 
See, the bind variable is empty…
Now, let’s run the same statement via PL/SQL engine:
 

SQL> EXEC SELECT dummy INTO :blah FROM dual;

PL/SQL procedure successfully completed.

SQL> print blah

BLAH
--------------------------------
X


 

…and it works…

Latch contention troubleshooting case study and Flashback Database performance issues with LOBs

Steve Bamber has written up a case study of library cache latch contention troubleshooting of an Apex application with LatchProf. I’m happy that others also see the value and have had success with my new LatchProf based latch contention troubleshooting approach which takes into account both sides of the contention story (latch waiters and latch holders/blockers) as opposed to the guesswork used previously (hey if it’s shared pool latch contention – is must be about bad SQL not using bind variables …. NOT always…)

Anyway, I’m happy. If you have success stories with LatchProf, please let me know!

As a second topic of interest, Laimutis Nedzinskas has written some good notes about the effect and overhead of Flashback Database option when you are using and modifying (nocache) LOBs. We’ve exchanged some mails on this topic and yeah, my clients have sure seen some problems with this combination as well. You basically want to keep your LOBs cached when using FB database…

Oracle Troubleshooting TV Show: Season 1, Episode 01 ;-)

Ok, it’s official – the first and only Oracle Troubleshooting TV show is live now!

The first show is almost 2 hours about the ORA-4031 errors and shared pool hacking. It’s a recording of the US/EMEA timezone online hacking session I did some days ago.

There are a couple of things to note:

  1. The text still isn’t as sharp as in the original recording, but it’s much better than in my previous upload attempts and is decently readable. I’ll try some more variations with my next shows so I hope the text quality will get better! Or maybe I should just switch to GUI tools or powerpoint slides? ;-)
  2. You probably should view this video in full screen (otherwise the text will be tiny and unreadable)
  3. There’s advertising in the beginning (and maybe end) of this show! I’ll see how much money I’ll make out of this – maybe these shows start contributing towards the awesome beer selection I’ll have in my fridge some day (right now I have none). Viewing a 30-sec advert is small price to pay for 2 hours of kick-ass shared pool hacking content !!!
  4. You can download the scripts and tools used in the demos from http://tech.e2sn.com/oracle-scripts-and-tools/
  5. Make sure you check out my online Oracle troubleshooting seminars too (this April and May already)

View the embedded video below or go to my official Oracle Troubleshooting TV show channel:

http://tanelpoder.blip.tv

Enjoy!

MOATS: The Mother of All Tuning Scripts!

People talk about the Oracle SQL Developer 3 being out, which is cool, but I have something even cooler for you today ;-)

I finally figured out how to convert my screen-recordings to uploadable videos, so that the text wouldn’t get unreadable and blurry.

So, here’s the first video, about a tool called MOATS, which we have built together with fellow OakTable Network member and a PL/SQL wizard Adrian Billington (of oracle-developer.net).

Here’s the video, it’s under 3 minutes long. Play the video in full screen for best results (and if it’s too slow loading, change it to lower resolution from HD mode):

Check it out and if you like MOATS, you can download it from Adrian’s website site (current version 1.05) and make sure you read the README.txt file in the zip!

Also thanks to Randolf Geist for finding and fixing some bugs in our alpha code… Note that MOATS is still kind of beta right now…

P.S. I will post my ORA-4031 and shared pool hacking video real soon now, too! :-)

P.P.S. Have you already figured out how it works?! ;-)

Update: Now you can suggest new features and improvement requests here:

An index of my TPT scripts

A lot of people have asked me whether there’s some sort of index or “table of contents” of my TPT scripts (there’s over 500 scripts in the tpt_public.zip file – http://tech.e2sn.com/oracle-scripts-and-tools )

I have planned to create such index for years, but never got to it. I probably never will :) So a good way to extract the descriptions of some scripts is this (run the command in the directory where you extracted my scripts to):

Note: the single and double-quotes may get messed up when the browser tries to be smart and replace them with nicer looking characters (which Unix doesn’t recognize then). When copying & pasting this command, make sure that the single & double-quotes are the regular ones Unix shell can accept):

$ grep -i Purpose: *.sql | awk -F: ‘{ printf(“%20s %-50s\n”, $1, $3) }’
            bhla.sql      Report which blocks are in buffer cache, protected by a cache
         bufprof.sql      Display buffer gets done by a session and their reason
            calc.sql      Basic calculator and dec/hex converter       
        channels.sql      Report KSR channel message counts by channel endpoints
        curheaps.sql      Show main cursor data block heap sizes and their contents
             dba.sql      Convert Data Block Address (a 6 byte hex number) to file#, block#
             ddl.sql      Extracts DDL statements for specified objects
              df.sql  Show Oracle tablespace free space in Unix df style
        diag_sid.sql      Display current Session Wait info            
        diag_sid.sql      An easy to use Oracle session-level performance snapshot utility
           disco.sql      Generates commands for disconnecting selected sessions
     getplusparm.sql      get sqlplus parameter value (such linesize, pagesize, sqlcode,
            grpn.sql      Quick group by query for aggregating Numeric columns
            hash.sql      Show the hash value, SQL_ID and child number of previously
             i2h.sql      Advanced Oracle Troubleshooting Seminar demo script
              im.sql      Display In-Memory Undo (IMU) buffer usage    
            init.sql Initializes sqlplus variables for 156 character terminal
       kglbroken.sql                                                   
       kglbroken.sql      Report broken kgl locks for an object this can be used for 
            kill.sql      Generates commands for killing selected sessions
              la.sql      Show which latch occupies a given memory address and its stats
     lastchanged.sql      Detect when a datablock in table was last changed
       latchprof.sql      Perform high-frequency sampling on V$LATCHHOLDER
   latchprof_old.sql      Perform high-frequency sampling on V$LATCHHOLDER
      latchprofx.sql      Perform high-frequency sampling on V$LATCHHOLDER
              lh.sql      Show latch holding SIDs and latch details from V$LATCHHOLDER
             lhp.sql      Perform high-frequency sampling on V$LATCHHOLDER
            lhpx.sql      Perform high-frequency sampling on V$LATCHHOLDER
     lotshparses.sql      Generate Lots of hard parses and shared pool activity 
    lotshparses2.sql      Generate Lots of hard parses and shared pool activity 
        lotslios.sql      Generate Lots of Logical IOs for testing purposes
        lotspios.sql      Generate Lots of Physical IOs for testing purposes
     lotssparses.sql      Generate Lots of soft parses and library cache/mutex activity 
    lotssparses2.sql      Generate Lots of soft parses and library cache/mutex activity 
       mutexprof.sql      Display KGX mutex sleep history from v$mutex_sleep_history
       nonshared.sql      Print reasons for non-shared child cursors from v$sql_shared_cursor
      nonshared2.sql      Show the reasons why more child cursors were created instead of
      ostackprof.sql      Take target process stack samples and show an execution profile
            pmem.sql      Show process memory usage breakdown – lookup by process SPID
     pmem_detail.sql      Show process memory usage breakdown details – lookup by process SPID
        prefetch.sql      Show KCB layer prefetch                      
          pvalid.sql      Show valid parameter values from V$PARAMETER_VALID_VALUES
        rowcache.sql      Show parent rowcache entries mathcing an object name
              rs.sql      Display available Redo Strands               
               s.sql      Display current Session Wait and SQL_ID info (10g+)
          sample.sql      Sample any V$ view or X$ table and display aggregated results
      sampleaddr.sql      High-frequency sampling of contents of a SGA memory address
             ses.sql      Display Session statistics for given sessions, filter by
            ses2.sql      Display Session statistics for given sessions, filter by
        sgastatx.sql      Show shared pool stats by sub-pool from X$KSMSS
            smem.sql      Show process memory usage breakdown – lookup by session ID
     smem_detail.sql      Show process memory usage breakdown details – lookup by session ID
         snapper.sql      An easy to use Oracle session-level performance snapshot utility
     snapper3.15.sql      An easy to use Oracle session-level performance snapshot utility
      snapper_v1.sql      An easy to use Oracle session-level performance snapshot utility
      snapper_v2.sql      An easy to use Oracle session-level performance snapshot utility
            stat.sql      Execute SQL statement in script argument and report basic
              sw.sql      Display current Session Wait info            
             sw2.sql      Display current Session Wait info            
             swg.sql      Display given Session Wait info grouped by state and event
             swo.sql      Display current Session Wait info            
          topsql.sql      Show TOP SQL ordered by user-provided criteria
            usql.sql      Show another session’s SQL directly from library cache
           usqlx.sql      Show another session’s SQL directly from library cache
        waitprof.sql      Sample V$SESSION_WAIT at high frequency and show resulting 
              xb.sql      Explain a SQL statements execution plan with execution 
            xde2.sql      Describe X$ tables, column offsets and report indexed fixed table
              xm.sql      Explain a SQL statements execution plan directly from library cache
             xma.sql      Explain a SQL statements execution plan directly from library cache
            xmai.sql      Explain a SQL statements execution plan with execution 
             xms.sql      Explain your last SQL statements execution plan with execution 
            xmsh.sql      Explain a SQL statements execution plan with execution 
            xmsi.sql      Explain a SQL statements execution plan with execution

 

LOBREAD SQL Trace entry in Oracle 11.2 (and tracing OPI calls with event 10051)

A few days ago I looked into a SQL Tracefile of some LOB access code and saw a LOBREAD entry there. This is a really welcome improvement (or should I say, bugfix of a lacking feature) for understanding resource consumption by LOB access OPI calls. Check the bottom of the output below:

*** 2011-03-17 14:34:37.242
WAIT #47112801352808: nam='SQL*Net message from client' ela= 189021 driver id=1413697536 #bytes=1 p3=0 obj#=99584 tim=1300390477242725
WAIT #0: nam='gc cr multi block request' ela= 309 file#=10 block#=20447903 class#=1 obj#=99585 tim=1300390477243368
WAIT #0: nam='cell multiblock physical read' ela= 283 cellhash#=379339958 diskhash#=787888372 bytes=32768 obj#=99585 tim=1300390477243790
WAIT #0: nam='SQL*Net message to client' ela= 2 driver id=1413697536 #bytes=1 p3=0 obj#=99585 tim=1300390477243865
[...snipped...]
WAIT #0: nam='SQL*Net more data to client' ela= 2 driver id=1413697536 #bytes=2048 p3=0 obj#=99585 tim=1300390477244205
WAIT #0: nam='SQL*Net more data to client' ela= 4 driver id=1413697536 #bytes=2048 p3=0 obj#=99585 tim=1300390477244221
WAIT #0: nam='gc cr multi block request' ela= 232 file#=10 block#=20447911 class#=1 obj#=99585 tim=1300390477244560
WAIT #0: nam='cell multiblock physical read' ela= 882 cellhash#=379339958 diskhash#=787888372 bytes=32768 obj#=99585 tim=1300390477245579
WAIT #0: nam='SQL*Net more data to client' ela= 16 driver id=1413697536 #bytes=2020 p3=0 obj#=99585 tim=1300390477245685
WAIT #0: nam='SQL*Net more data to client' ela= 6 driver id=1413697536 #bytes=2048 p3=0 obj#=99585 tim=1300390477245706
WAIT #0: nam='SQL*Net more data to client' ela= 5 driver id=1413697536 #bytes=1792 p3=0 obj#=99585 tim=1300390477245720
LOBREAD: c=1000,e=2915,p=8,cr=5,cu=0,tim=1300390477245735

In past versions of Oracle the CPU (c=) usage figures and other stats like number of physical/logical reads of the LOB chunk read OPI call were just lost – they were never reported in the tracefile. In past only the most common OPI calls, like PARSE, EXEC, BIND, FETCH (and recently CLOSE cursor) were instrumented with SQL Tracing. But since 11.2(.0.2?) the LOBREAD’s are printed out too. This is good, as it reduces the amount of guesswork needed to figure out what are those WAITs for cursor #0 – which is really a pseudocursor.

Why cursor#0? It’s because normally, with PARSE/EXEC/BIND/FETCH, you always had to specify a cursor slot number you operated on (if you fetch from cursor #5, it means that Oracle process went to slot #5 in the open cursor array in your session’s UGA and followed the pointers to shared cursor’s executable parts in library cache from there). But LOB interface works differently – if you select a LOB column using your query (cursor), then all your application gets is a LOB LOCATOR (sort of a pointer with LOB item ID and consistent read/version SCN). Then it’s your application which must issue another OPI call (LOBREAD) to read the chunks of that LOB out from the database. And the LOB locator is independent from any cursors, it doesn’t follow the same cursor API as regular SQL statements (as it requires way different functionality compared to a regular select or update statement).

So, whenever a wait happened in your session due to an access using a LOB locator, then there’s no specific cursor responsible for it (as far as Oracle sees internally) and that’s why a fake, pseudocursor #0 is used.

Note that on versions earlier than 11.2(.0.2?) when the LOBREAD wasn’t printed out to trace – you can use OPI call tracing (OPI stands for Oracle Program Interface and is the server-side counterpart to OCI API in the client side) using event 10051. First enable SQL Trace and then the event 10051 (or the other way around if you like):

SQL> @oerr 10051

ORA-10051: trace OPI calls

SQL> alter session set events '10051 trace name context forever, level 1';

Session altered.

Now run some LOB access code and check the tracefile:

*** 2011-03-17 14:37:07.178
WAIT #47112806168696: nam='SQL*Net message from client' ela= 6491763 driver id=1413697536 #bytes=1 p3=0 obj#=99585 tim=1300390627178602
OPI CALL: type=105 argc= 2 cursor=  0 name=Cursor close all
CLOSE #47112806168696:c=0,e=45,dep=0,type=1,tim=1300390627178731
OPI CALL: type=94 argc=28 cursor=  0 name=V8 Bundled Exec
=====================
PARSING IN CURSOR #47112802701552 len=19 dep=0 uid=93 oct=3 lid=93 tim=1300390627179807 hv=1918872834 ad='271cc1480' sqlid='3wg0udjt5zb82'
select * from t_lob
END OF STMT
PARSE #47112802701552:c=1000,e=1027,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=3547887701,tim=1300390627179805
EXEC #47112802701552:c=0,e=29,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=3547887701,tim=1300390627179884
WAIT #47112802701552: nam='SQL*Net message to client' ela= 2 driver id=1413697536 #bytes=1 p3=0 obj#=99585 tim=1300390627179939
WAIT #47112802701552: nam='SQL*Net message from client' ela= 238812 driver id=1413697536 #bytes=1 p3=0 obj#=99585 tim=1300390627418785
OPI CALL: type= 5 argc= 2 cursor= 26 name=FETCH
WAIT #47112802701552: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=99585 tim=1300390627418945
FETCH #47112802701552:c=0,e=93,p=0,cr=5,cu=0,mis=0,r=1,dep=0,og=1,plh=3547887701,tim=1300390627418963
WAIT #47112802701552: nam='SQL*Net message from client' ela= 257633 driver id=1413697536 #bytes=1 p3=0 obj#=99585 tim=1300390627676629
OPI CALL: type=96 argc=21 cursor=  0 name=LOB/FILE operations
WAIT #0: nam='SQL*Net message to client' ela= 2 driver id=1413697536 #bytes=1 p3=0 obj#=99585 tim=1300390627676788
[...snip...]
WAIT #0: nam='SQL*Net more data to client' ela= 2 driver id=1413697536 #bytes=1792 p3=0 obj#=99585 tim=1300390627677054
LOBREAD: c=0,e=321,p=0,cr=5,cu=0,tim=1300390627677064

Check the bold and especially the red string above.  Tracing OPI calls gives you some extra details of what kind of tasks are executed in the session. The “LOB/FILE operations” call indicates that whatever lines come after it (unlike SQL trace call lines where all the activity happens before a call line is printed (with some exceptions of course)) are done for this OPI call (until a next OPI call is printed out). OPI call tracing should work even on ancient database versions…

By the way, if you are wondering, what’s the cursor number 47112801352808 in the “WAIT #47112801352808″ above? Shouldn’t the cursor numbers be small numbers?

Well, in 11.2.0.2 this was also changed. Before that, the X in CURSOR #X (and PARSE #X, BIND #X, EXEC #X, FETCH #X) represented the slot number in your open cursor array (controlled by open_cursors) in your session’s UGA. Now, the tracefile dumps out the actual address of that cursor. 47112801352808 in HEX is 2AD94DC9FC68 and it happens to reside in the UGA of my session.

Naturally I asked Cary Millsap about whether he had spotted this LOBREAD already and yes, Cary’s way ahead of me – he said that Method-R’s mrskew tool v2.0, which will be out soon, will support it too.

It’s hard to not end up talking about Cary’s work when talking about performance profiling and especially Oracle SQL trace, so here are a few very useful bits which you should know about:

If you want to understand the SQL trace & profiling stuff more, then the absolute must document is Cary’s paper on the subject – Mastering Performance with Extended SQL Trace:

Also, if you like to optimize your work like me (in other words: you’re proactively lazy ;-) and you want to avoid some boring “where-the-heck-is-this-tracefile-now” and “scp-copy-it-over-to-my-pc-for-analysis” work then check out Cary’s MrTrace plugin (costs ~50 bucks and has a 30-day trial) for SQL Developer. I’ve ended up using it myself regularly although I still tend to avoid GUIs:

Implicit datatype conversion in the parsing phase – something new I learned today!

Wow, I wasn’t aware that Oracle can also do an implicit datatype conversion for literal strings during parsing phase!

SQL> @desc t
           Name                            Null?    Type
           ------------------------------- -------- ----------------------------
    1      A                                        NUMBER(38)

SQL> select * from t where a = '1' || RPAD('0',5,'0');

no rows selected

SQL> @x
Display execution plan for last statement for this session from library cache...

PLAN_TABLE_OUTPUT
------------------------------------------------------------------------------------------------
SQL_ID  d7r6md8wfu74d, child number 0
-------------------------------------
select * from t where a = '1' || RPAD('0',5,'0')

Plan hash value: 1601196873

--------------------------------------------------------
| Id  | Operation         | Name | E-Rows | Cost (%CPU)|
--------------------------------------------------------
|   0 | SELECT STATEMENT  |      |        |     2 (100)|
|*  1 |  TABLE ACCESS FULL| T    |      1 |     2   (0)|
--------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   1 - filter("A"=100000)

You see what happened? The expression ’1′ || RPAD(’0′,5,’0′) has been evaluated, which returns a string. And this string ’100000′ has been converted to a NUMBER 100000 during parsing phase .. otherwise you would see quotes around the number above with a TO_NUMBER() function around it (so that Oracle could compare the NUMBER column “A” to the same datatype)…

I add a TO_CHAR() around the column A just for demoing that a varchar datatype (as the original “literal” in my query is) will be shown with quotes like every normal string:

SQL> select * from t where to_char(a) = '1'||rpad('0',5,'0');

no rows selected

SQL> @x
Display execution plan for last statement for this session from library cache...

PLAN_TABLE_OUTPUT
----------------------------------------------------------------------------
SQL_ID  7yf6j8fdyrvk7, child number 0
-------------------------------------
select * from t where to_char(a) = '1'||rpad('0',5,'0')

Plan hash value: 1601196873

--------------------------------------------------------
| Id  | Operation         | Name | E-Rows | Cost (%CPU)|
--------------------------------------------------------
|   0 | SELECT STATEMENT  |      |        |     2 (100)|
|*  1 |  TABLE ACCESS FULL| T    |      1 |     2   (0)|
--------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   1 - filter(TO_CHAR("A")='100000')

Let’s see whether this trick is somehow done also for bind variables:

SQL> var x varchar2(10)
SQL> exec :x:= '1' || RPAD('0',5,'0');

PL/SQL procedure successfully completed.

SQL> print x

X
--------------------------------
100000

SQL> select * from t where a = :x;

no rows selected

SQL> @x
Display execution plan for last statement for this session from library cache...

PLAN_TABLE_OUTPUT
-------------------------------------------------------------------------------------
SQL_ID  45f39y7580bdp, child number 2
-------------------------------------
select * from t where a = :x

Plan hash value: 1601196873

--------------------------------------------------------
| Id  | Operation         | Name | E-Rows | Cost (%CPU)|
--------------------------------------------------------
|   0 | SELECT STATEMENT  |      |        |     2 (100)|
|*  1 |  TABLE ACCESS FULL| T    |      1 |     2   (0)|
--------------------------------------------------------

Peeked Binds (identified by position):
--------------------------------------

   1 - (VARCHAR2(30), CSID=873): '100000'

Predicate Information (identified by operation id):
---------------------------------------------------

   1 - filter("A"=TO_NUMBER(:X))

Apparently not! And this kind of makes sense – as if this string to number conversion is done during parse phase – Oracle doesn’t know what the actual value is yet (in the bind variable memory) so it can’t convert it to number in advance either :-)

This is a little interesting detail… I didn’t know that in addition to the implicit datatype conversion during query execution (using TO_CHAR, TO_NUMBER functions etc) Oracle can sometimes convert a string literal to number datatype under the hood during the parse time!

P.S. I tested this on Oracle 11.2.0.2 with optimizer_features_enable set from 11.2.0.2 to all the way back to 8.0.0 and the behavior was the same. I didn’t find any mention of this conversion in the CBO tracefile although after a filter pushdown transformation (FPD) the string literal was already shown as a number datatype. If anyone still has access to ancient Oracle database versions (like 9.2 and 10.1 ;-) then let me know whether you see the same results!