Cursor “no parse” execution trace

 

There are approximately 4 “types” of SQL cursor execution in Oracle.

hard parse
soft parse
softer soft parse
no parse

See http://alexzeng.wordpress.com/2012/12/31/oracle-core-hard-parse-soft-parse-soft-soft-parse-no-parse-at-all/
for instance.

However I was always wondering what is going under the hood for “no parse” case.
Your client (JDBC or whatever) should communicate somehow with your Oracle server.
It can’t be SQL statement itself otherwise some kind of parsing is unavoidable.
So it seems natural that you need to exchange some kind of identifier.

But what exact identifier/s are used in Oracle vs. client  communication.
I’ve read/heard several times that some kind of Oracle handles exists in sessions PGA area, etc. but never seen the details.

So I decided to trace it by myself.

It seems Wireshark is an ultimate tool to see what is going on on networking layer.

My Java testcase look like:

Connection con = dataSource.getConnection();
PreparedStatement ps = con.prepareStatement(SQL);
PreparedStatement ps2 = con.prepareStatement(SQL2);
for (int j=1; j<30; j++) {   //traverse 1st 30 param sets
..... set bind variables
for (int l=1;l<=8;l++) {
   ResultSet rs= ps.executeQuery();
   ResultSet rs2= ps2.executeQuery();
    while (rs.next()){
        System.out.print('.');
    }
    while (rs2.next()){
        System.out.print('.');
    }
   rs.close();
   rs2.close();
}
...
}

First of all no network round trip on  con.prepareStatement(SQL) step (it seems postponed to make simultaneously  prepare and execute phase)

1st execution of  ResultSet rs= ps.executeQuery() looks like below:
You easily can see text of my SELECT query here:cursor0

According to TNS protocol spec here:
http://thesprawl.org/research/oracle-tns-protocol/
0x03 is a code of TTI function call and ox5e is a subcode for query (SELECT) operation.

However the most interesting part is 2nd and all consequent executions (they should go as “no parse” variant)

Let’s compare 2nd and 3rd execution of:

ResultSet rs= ps.executeQuery();
ResultSet rs2= ps2.executeQuery();

2nd execution
cursor_comp1

3rd execution:

cursor_comp2

You can see 2 interesting parts here:

  • 1st part just after 0x03 ox53  – looks like a counter of consequent SQL executions for your session ( 0x07, 0x08, 0x09, 0x0a)
  • 2nd part 0x03 for one query and 2nd one 0x05  are repeatable for all executions (I have shown only 2 of them here)

So it seems our desirable cursor identifier and it is definitely not a sql_id or sql handler (as been claimed somewhere).
The most interesting question however what does it mean exactly.

Let’s do a CURSORDUMP as described here:
http://blog.tanelpoder.com/2009/07/09/identify-the-sql-statement-causing-those-wait-x-lines-in-a-top-truncated-sql-tracefile/
oradebug setospid 1820
oradebug dump cursordump 1

And the extract of result looks like:

Cursor#3(0xffff80ffbde11c48) state=BOUND curiob=0xffff80ffbde28a40
 curflg=4e fl2=0 par=0x0 ses=0x1fcbd8db0
----- Dump Cursor sql_id=6ndm9d5b9vg1t xsc=0xffff80ffbde28a40 cur=0xffff80ffbde11c48 -----

LibraryHandle:  Address=1fb2d5ae8 Hash=569dbc39 LockMode=N PinMode=0 LoadLockMode=0 Status=VALD
  ObjectName:  Name=SELECT /* NoParse_40Issue */ * FROM YYTEST WHERE (f1,f2,f3,f4,f5,f6,f7,f8,f9,f10,f11,f12,f13,f14,f15,f16,f17,f18,f19,f20,f21,f22,f23,f24,f25,f26,f27,f28,f29,f30,f31,f32,f33,f34,f35,f36,f37,f38,f39,f40) IN ((:f1,:f2,:f3,:f4,:f5,:f6,:f7,:f8,:f9,:f10,:f11,:f12,:f13,:f14,:f15,:f16,:f17,:f18,:f19,:f20,:f21,:f22,:f23,:f24,:f25,:f26,:f27,:f28,:f29,:f30,:f31,:f32,:f33,:f34,:f35,:f36,:f37,:f38,:f39,:f40))
    FullHashValue=258bfcabddf89e5c6a366969569dbc39 Namespace=SQL AREA(00) Type=CURSOR(00) Identifier=1453177913 OwnerIdn=85
  Statistics:  InvalidationCount=4 ExecutionCount=30 LoadCount=6 ActiveLocks=2 TotalLockCount=2 TotalPinCount=1
  Counters:  BrokenCount=1 RevocablePointer=1 KeepDependency=5 BucketInUse=1 HandleInUse=1 HandleReferenceCount=0
  Concurrency:  DependencyMutex=1fb2d5b98(0, 6, 0, 0) Mutex=1fb2d5c18(164, 99, 0, 6)
  Flags=RON/PIN/TIM/PN0/DBN/[10012841]
...............................
...................................
................................
Cursor#5(0xffff80ffbde11d68) state=BOUND curiob=0xffff80ffbdca1f80
 curflg=4e fl2=0 par=0x0 ses=0x1fcbd8db0
----- Dump Cursor sql_id=84mwtcmy0b3za xsc=0xffff80ffbdca1f80 cur=0xffff80ffbde11d68 -----

LibraryHandle:  Address=1fb2ce130 Hash=fc058fea LockMode=N PinMode=0 LoadLockMode=0 Status=VALD
  ObjectName:  Name=SELECT /* NoParse_40Issue */ * FROM YYTEST WHERE (f1,f2,f3,f4,f5,f6,f7,f8,f9,f10,f11,f12,f13,f14,f15,f16,f17,f18,f19,f20) IN ((:f1,:f2,:f3,:f4,:f5,:f6,:f7,:f8,:f9,:f10,:f11,:f12,:f13,:f14,:f15,:f16,:f17,:f18,:f19,:f20))
    FullHashValue=fa2532489a58f35a824f9964fc058fea Namespace=SQL AREA(00) Type=CURSOR(00) Identifier=4228222954 OwnerIdn=85
  Statistics:  InvalidationCount=4 ExecutionCount=29 LoadCount=6 ActiveLocks=2 TotalLockCount=2 TotalPinCount=1
  Counters:  BrokenCount=1 RevocablePointer=1 KeepDependency=5 BucketInUse=1 HandleInUse=1 HandleReferenceCount=0
  Concurrency:  DependencyMutex=1fb2ce1e0(0, 6, 0, 0) Mutex=1fb2ce260(164, 91, 0, 6)
  Flags=RON/PIN/TIM/PN0/DBN/[10012841]

 

So you can see that JDBC client  passes “slot number in open cursor array in UGA” for “no parse” execution
(see again : http://blog.tanelpoder.com/2009/07/09/identify-the-sql-statement-causing-those-wait-x-lines-in-a-top-truncated-sql-tracefile/)

 

 

 

 

 

Advertisements

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s