Session names array retrieval inside systemtap script (ksusdt).

Based on investigation byDenis Yurichev I found that symbol “ksusdt” points to the beginning of statname array (represented by v$statname).

So I’ve rewrite a script from my previous post as

global ltwhere
global is_init = 0;

function mylookupaddr:long (addr: long, symb: string) %{
/* pure */  /* pragma:vma */ /* pragma:symbols */

  unsigned end, begin = 0;
  unsigned long curaddr =0;

  struct _stp_module *m = NULL;
  struct _stp_section *sec = NULL;
  struct _stp_symbol *s = NULL;

	    m = _stp_kmod_sec_lookup(STAP_ARG_addr, &sec);
            end = sec->num_symbols;
            do {
                s = & sec->symbols[begin];
                if (strcmp(s->symbol, STAP_ARG_symb) == 0) {
                  curaddr = s->addr; 
                  break;
                }
              begin++;
            } while (begin +1 < end);

           STAP_RETVALUE = curaddr;

%}

function myderef:long (addr: long) %{
/* pure */  /* pragma:vma */ /* pragma:symbols */
  long* curaddr = (long *)STAP_ARG_addr;
  STAP_RETVALUE = *curaddr;
%}

function myderefchar:string (addr: long) %{
/* pure */  /* pragma:vma */ /* pragma:symbols */
  strlcpy (STAP_RETVALUE, (char *)STAP_ARG_addr, MAXSTRINGLEN); 
%}




probe begin {
 println("Starting lookup 0x878e9e0 ksusdt");
}

probe process("oracle").function("kksParseCursor").call {
       sqltext = user_string_warn(register("rbx"));
       printf(" function=%s arg1=%s \n ", probefunc(), sqltext );

     if (is_init == 0 ) {
       addr_ksudt = mylookupaddr(uaddr(), "ksusdt");
       addr_base = myderef(addr_ksudt);
       //by unknown for me reason user_ulong_warn(addr_ksudt);often does not work so I need a workaround above
        str1 = user_string_warn(addr_base);
        idx2 = strlen(str1);
        addr_base2 = addr_base+idx2 +2;  
       printf("ksusdt=0x%x addr_base 0x%x %s %s\n", addr_ksudt, addr_base, user_string_warn(addr_base),user_string_warn(addr_base2) );

       i=0; 
       while (i < 1000){
        addr_ksudt_next = addr_ksudt +i*16; //0x8906aa0 + i*16
        addr_base  = myderef(addr_ksudt_next);
        if (addr_base == 0 ) break;
        //symb = user_string_warn(addr_base);
        symb = myderefchar(addr_base);
        ltwhere[i] = symb;
  
        i++;       
       }
 }
}

It can be executed as
stap -g -x 2954 stat_name.tap
where 2954 is my session’s server side PID (PID of Oracle dedicated process).

Result looks like:

^C [0]->OS CPU Qt wait time 
 [1]->logons cumulative 
 [2]->logons current 
 [3]->opened cursors cumulative 
 [4]->opened cursors current 
 [5]->user commits 
 [6]->user rollbacks 
 [7]->user calls 
 [8]->recursive calls 
 [9]->recursive cpu usage 
.........
 [578]->Workload Capture: user logins 
 [579]->Workload Capture: unsupported user calls 
 [580]->Workload Capture: errors 
 [581]->Workload Replay: dbtime 
 [582]->Workload Replay: network time 
 [583]->Workload Replay: think time 
 [584]->Workload Replay: time gain 
 [585]->Workload Replay: time loss 
 [586]->Workload Replay: user calls 
 [587]->Workload Replay: deadlocks resolved 

statistic names after statistics#=587 use a bit different approach.
A quick analyses of ksusgnm (function used by Oracle internally when querying V$STATNAME/x$ksusd) shows a separate code branch for values > 0x24c (587).

Advertisements

Once again about systemtap

Inspired by AOT training
I was playing around with systemtap and gdb and have noticed quite a strange fact.

Some symbols are available in gdb but in systemtap script.
In my case it was “ksllwt” symbol which looks like a pointer to a first element of array for Oracle’s x$ksllw view (view that contains “where” locations for Oracle latches).

So

  
x/s ksllwt
0x86caccc :	"No latch"

 works perfectly for me in gdb.

However
Neither @var(“ksllwt@oracle”); nor @var(“ksllwt@/u01/app/oracle/product/11.2.0/dbhome_1/bin/oracle”);
work in systemtap script.

  
semantic error: unable to find global 'ksllwt' in /u01/app/oracle/product/11.2.0/dbhome_1/bin/oracle, in oracle: operator '@var' at latch.tap:7:15

Probably I should’ve give up at this point but occasionally I have tried
to do some kind of reverse lookup, i.e. find symbol by it’s address
So I did

 
       add1 = symname(141339852 ); // 0x86caccc - you can see this address above in gdb section 
       add2 = symname(142159808);  //0x8792FC0 -- this address is a result of objdump lookup for Oracle's binary.

and immediately got

 
  _2__STRING.1380.0  
  ksllwt

So it works in opposite direction.

I decided to borrow 🙂 a bit of code from _stp_kallsyms_lookup function in sym.c sytemtap code (this function is behind of symname function) and implement some stap script with embedded C (that mean you need to run it in “guru” mode – “-g” switch)
and here is this script. By the way I use kksParseCursor Oracle’s function to attach the script to some user space probe but I guess I can be any Oracle function with the same lookup result.
This script collects values of x$ksllw.ksllwnam values into an associative array “ltwhere” and then print collected values on exit (by Ctrl-C)

Below is a full text of my script

global ltwhere
global is_init = 0;

function mylookupaddr:long (addr: long, symb: string) %{
/* pure */  /* pragma:vma */ /* pragma:symbols */

  unsigned end, begin = 0;
  unsigned long curaddr =0;

  struct _stp_module *m = NULL;
  struct _stp_section *sec = NULL;
  struct _stp_symbol *s = NULL;

	    m = _stp_kmod_sec_lookup(STAP_ARG_addr, &sec);
            end = sec->num_symbols;
            do {
                s = & sec->symbols[begin];
                if (strcmp(s->symbol, STAP_ARG_symb) == 0) {
                  curaddr = s->addr; 
                  break;
                }
              begin++;
            } while (begin +1 < end);

           STAP_RETVALUE = curaddr;

%}

function myderef:long (addr: long) %{
/* pure */  /* pragma:vma */ /* pragma:symbols */
  long* curaddr = (long *)STAP_ARG_addr;
  STAP_RETVALUE = *curaddr;
%}

function myderefchar:string (addr: long) %{
/* pure */  /* pragma:vma */ /* pragma:symbols */
  strlcpy (STAP_RETVALUE, (char *)STAP_ARG_addr, MAXSTRINGLEN); 
%}

probe begin {
 println("Starting lookup 0x8792fc0  ksllwt");
}

probe process("oracle").function("kksParseCursor").call {
       sqltext = user_string_warn(register("rbx"));
       printf(" function=%s arg1=%s \n ", probefunc(), sqltext );

     if (is_init == 0 ) {
       addr_ksllwt = mylookupaddr(uaddr(), "ksllwt");
       addr_base = myderef(addr_ksllwt);
  
       i=0; 
       while (addr_base !=0 && i %s \n", idx, ltwhere[idx]);
 }
}

You need to run it in guru mode because of embedded C
like stap -g -x 3097 latch1.tap

And here is the result of the execution:

Starting lookup 0x8792fc0  ksllwt
 function=kksParseCursor arg1=SELECT /* SessParse */ * FROM YYTEST WHERE rownum No latch 
 [1]->FILE:/ade/b/1640894963/oracle/rdbms/src/hdir/kywm2.h LINE:134 ID:kywmcrpln: creating new WLM plan 
 [2]->FILE:/ade/b/1640894963/oracle/rdbms/src/hdir/kywm2.h LINE:137 ID:kywmadclsfr: adding classifier list 
 [3]->FILE:/ade/b/1640894963/oracle/rdbms/src/hdir/kywm2.h LINE:140 ID:kywmsbmtpc: adding PC list 
 [4]->FILE:/ade/b/1640894963/oracle/rdbms/src/hdir/kywm2.h LINE:143 ID:kywmsbmtpln: submitting plan 
 [5]->FILE:/ade/b/1640894963/oracle/rdbms/src/hdir/kywm2.h LINE:146 ID:kywmdelpln: deleting plan 
 [6]->FILE:/ade/b/1640894963/oracle/rdbms/src/hdir/kywm2.h LINE:149 ID:kywmfree: freeing KYWM SGA 
 [7]->FILE:/ade/b/1640894963/oracle/rdbms/src/hdir/kywm2.h LINE:152 ID:kywmabtpln: aborting plan 
 [8]->FILE:/ade/b/1640894963/oracle/rdbms/src/hdir/kywm2.h LINE:155 ID:kywmchkpln: checking plan 
 [9]->FILE:/ade/b/1640894963/oracle/rdbms/src/hdir/ksl2.h LINE:2119 ID:kslwt 
 [10]->FILE:/ade/b/1640894963/oracle/rdbms/src/hdir/ksl2.h LINE:2122 ID:ksl_rm_from_pwq 
 [11]->FILE:/ade/b/1640894963/oracle/rdbms/src/hdir/ksl2.h LINE:2125 ID:kslpstevent:get 
 [12]->FILE:/ade/b/1640894963/oracle/rdbms/src/hdir/ksl2.h LINE:2128 ID:kslpstevent:reget 
 [13]->FILE:/ade/b/1640894963/oracle/rdbms/src/hdir/ksl2.h LINE:2131 ID:ksliwat:add:nowait 
 [14]->FILE:/ade/b/1640894963/oracle/rdbms/src/hdir/ksl2.h LINE:2134 ID:ksliwat:remove 
 [15]->FILE:/ade/b/1640894963/oracle/rdbms/src/hdir/ksl2.h LINE:2137 ID:ksliwat:add:wait 
 [16]->FILE:/ade/b/1640894963/oracle/rdbms/src/hdir/ksl2.h LINE:2140 ID:kslael 
 [17]->FILE:/ade/b/1640894963/oracle/rdbms/src/hdir/ksl2.h LINE:2143 ID:ksltbl 
 [18]->FILE:/ade/b/1640894963/oracle/rdbms/src/hdir/ksl2.h LINE:2147 ID:ksl_tst_latch_errors1 
 [19]->FILE:/ade/b/1640894963/oracle/rdbms/src/hdir/ksl2.h LINE:2150 ID:ksl_tst_latch_errors2 
 [20]->FILE:/ade/b/1640894963/oracle/rdbms/src/hdir/ksl2.h LINE:2153 ID:ksl_tst_latch_errors3 
............
[493]->FILE:/ade/b/1640894963/oracle/rdbms/src/hdir/kso2.h LINE:268 ID:ksosp_scrub:1 
 [494]->FILE:/ade/b/1640894963/oracle/rdbms/src/hdir/kso2.h LINE:272 ID:ksosp_forknew 
 [495]->FILE:/ade/b/1640894963/oracle/rdbms/src/hdir/kso2.h LINE:276 ID:kso_new_process:1 
 [496]->FILE:/ade/b/1640894963/oracle/rdbms/src/hdir/kso2.h LINE:280 ID:kso_new_process:2 
 [497]->FILE:/ade/b/1640894963/oracle/rdbms/src/hdir/kso2.h LINE:284 ID:kso_stop_watchdogs 
 [498]->FILE:/ade/b/1640894963/oracle/rdbms/src/hdir/kso2.h LINE:288 ID:kso_delete_process:1 
 [499]->FILE:/ade/b/1640894963/oracle/rdbms/src/hdir/kso2.h LINE:292 ID:kso_watchdog_main:1 
 [500]->FILE:/ade/b/1640894963/oracle/rdbms/src/hdir/kso2.h LINE:296 ID:kso_fork:1 

It almost the same result as SELECT * FROM x$ksllw gives you
except some lengthy prefix FILE: xxx LINE: yyy ID: which I guess quite easy to parse and remove but I have not managed to do it yet.

I still was unable to unwind logic behind @var as was kindly suggested by @Frank Ch. Eigler
in comments to https://fritshoogland.wordpress.com/2014/04/27/systemtap-revisited/ but I found a workaround at least 🙂

There are some limitations of the script related to MAXACTION limit of systemtap, so I show only 1st 500 values. Currently I’m thinking about a workaround, any ideas are very welcome :).

PS
There are some oddities I still need to explain/understand in my embedded C function/s but I hope to cover it in a separate post.

PPS
My test environment is:

uname -a
Linux osboxes 3.10.0-514.26.2.el7.x86_64 #1 SMP Tue Jul 4 15:04:05 UTC 2017 x86_64 x86_64 x86_64 GNU/Linux
Oracle 11.2.0.1

A new method of understanding what’s going on inside Oracle database

As has been shown in my previous blog, session stats is located in a flat array structure near session address with offset 0x140. So we can set up an access watch point for memory area of the particular stats value and then “disass” a bit code around.

Let’s demonstrate it on “session cursor cache hits” example, statistic# = 498 for this particulate session stat.

I’ve set up a watch point as
awatch *(0x00000001889EDAC8+0x140+8*498)

After several execution of my SQL statement (actually 3 times)
I hit my watch point at kkspsc0+372

   0x00000000083f7e02 :	call   0x85f3ef4 <kgscFindCursor>
   0x00000000083f7e07 :	add    rsp,0x10
   0x00000000083f7e0b :	mov    QWORD PTR [rbp-0xa0],rax
   0x00000000083f7e12 :	test   rax,rax
   0x00000000083f7e15 :	je     0x83f7e6f 
   0x00000000083f7e17 :	mov    rdx,QWORD PTR [rip+0x25a5afa]        # 0xa99d918 
   0x00000000083f7e1e :	mov    rax,QWORD PTR [rip+0x2e7863]        # 0x86df688 
   0x00000000083f7e25 :	mov    rcx,QWORD PTR [rip+0x2e88ac]        # 0x86e06d8 
   0x00000000083f7e2c :	movsxd r8,DWORD PTR [rip+0x57c3f91d]        # 0x60037750
   0x00000000083f7e33 :	mov    rbx,QWORD PTR [rax+rdx*1]
   0x00000000083f7e37 :	movzx  esi,WORD PTR [rcx+rbx*1+0x24]
   0x00000000083f7e3c :	mov    rdi,QWORD PTR [rip+0x25a5bed]        # 0xa99da30 
   0x00000000083f7e43 :	mov    DWORD PTR [rbp-0x44],0x1
   
   --- below set stats 498 session cursor cache hits
==>   0x00000000083f7e4a :	mov    QWORD PTR [rdi+r8*8+0x140],rsi  

You can clearly see that if call 0x85f3ef4 returns none-zero value we pass through check 0x00000000083f7e15 : je 0x83f7e6f and do session cursor cache hits” value update.

Where session stats live

Here is a side effect of my cursor execution examination:

I have established my Oracle client session(sid =69, ospid=2945).
Found my session address as:

SELECT saddr FROM v$session WHERE sid =69;
SADDR
0000000188936D38

Then I have shown the session stats as:

SELECT value FROM v$sesstat WHERE sid=69 ORDER BY statistic#;
SELECT value FROM v$sesstat WHERE sid=69 ORDER BY statistic#;
0
1
1
333
3
0
0
37
5560
15
0
1169
0
15
20
60
0
0
0
34
0
41
80
1516223276
1516223276
639480
949904
1
0
0
0

after that I’ve attached to my session by gdb as

gdb attach 2945

then run the follow command

(gdb) x/100g 0x0000000188936D38+0x140

and voila

0x188936e78:	0	1
0x188936e88:	1	333
0x188936e98:	3	0
0x188936ea8:	0	37
0x188936eb8:	5560	15
0x188936ec8:	0	0
0x188936ed8:	0	15
0x188936ee8:	20	60
0x188936ef8:	0	0
0x188936f08:	0	344489
0x188936f18:	0	417346
0x188936f28:	80	1516223276
0x188936f38:	1516223276	639480
0x188936f48:	949904	1
0x188936f58:	0	0
0x188936f68:	0	1319256
0x188936f78:	2498904	0
0x188936f88:	0	0
0x188936f98:	0	30
0x188936fa8:	0	29
0x188936fb8:	0	0
0x188936fc8:	0	0
0x188936fd8:	52	0

You can see the same numbers.

That means session statistics are located in PGA near session address with offset 0x140. The data structure seems a simple 8-byte array where statistics arranged in order of their STATISTIC# number

PS
These 2 works gave me a clue
Dynamic tracing tools : Easier access to session/process address [ksupga_] A very detailed investigation of KSUPGA_.
SystemTap into Oracle for Fun and Profit here session’s current wait event has been discover as a memory offset to v$session.SADDR

Parsing functions results

The goal of this post is investigation of return results for various parsing functions.
I’m going to consider

  • kksParseCursor – an entry point of all parsing activity
  • kgscFindCursor – “softer soft parse” function

It is interesting to know what is the result of parsing SQL statement, what is passing further to the next(execution) layer after parsing has finished.

kgscFindCursor

Let’s start with “softer soft parse” case.
let’s repeat debug session from my previous post “soft parse and softer soft parse”
Let’s take a look at 4th already “cached” execution.

---------------------------4TH EXECUTION -------------------------------------
Breakpoint 1, 0x00000000083f7a26 in kksParseCursor ()
0x7ffe2c731ba0:	"SELECT /* SessParse */ * FROM YYTEST WHERE rownum <=2"
...............................................
...............................................
Breakpoint 3, 0x00000000085f3fc6 in kgscFindCursor ()
0x7fb8f62308a0:	"ou\210\224{̝\037\203ʭ\241", 
0x7fff54e52a10:	"ou\210\224{̝\037\203ʭ\241", 
$417 = 0x10

Breakpoint 4, 0x00000000085f3fcd in kgscFindCursor ()
$418 = 0x0

Breakpoint 5, 0x00000000083f7e07 in kkspsc0 ()
$419 = 0x7fb8f6230880   (result of kgscFindCursor)
(gdb) 

Here you can see that for successful lookup kgscFindCursor returns some address
(for unsuccessful lookup result is 0x0).
But what does it exactly mean , that address?

Let’s follow again a method described here:
http://blog.tanelpoder.com/2009/07/09/identify-the-sql-statement-causing-those-wait-x-lines-in-a-top-truncated-sql-tracefile/

ALTER SESSION SET EVENTS ‘immediate trace name cursordump level 1’;

----- Dump Cursor sql_id=a3bfahfuts07x xsc=0x7fb8f6230880 cur=(nil) -----

LibraryHandle:  Address=8753f6e0 Hash=b59c00fd LockMode=N PinMode=0 LoadLockMode=0 Status=VALD 
  ObjectName:  Name=SELECT /* SessParse */ * FROM YYTEST WHERE rownum <=2

    FullHashValue=9488756f1f9dcc7ba1adca83b59c00fd Namespace=SQL AREA(00) Type=CURSOR(00) Identifier=3046899965 OwnerIdn=91 
  Statistics:  InvalidationCount=1 ExecutionCount=9 LoadCount=3 ActiveLocks=1 TotalLockCount=7 TotalPinCount=1 
  Counters:  BrokenCount=1 RevocablePointer=1 KeepDependency=1 KeepHandle=1 BucketInUse=5 HandleInUse=5 
  Concurrency:  DependencyMutex=8753f790(0, 0, 0, 0) Mutex=8753f808(10, 59, 0, 6) 
  Flags=RON/PIN/TIM/PN0/DBN/[10012841] 
  WaitersLists:  
    Lock=8753f770[8753f770,8753f770] 
    Pin=8753f780[8753f750,8753f750] 
  Timestamp:  Current=01-11-2018 20:52:25 
  LibraryObject:  Address=7f257160 HeapMask=0000-0001-0001 Flags=EXS[0000] Flags2=[0000] PublicFlags=[0000] 
    ChildTable:  size='16' 
      Child:  id='0' Table=7f258060 Reference=7f257ab0 Handle=8753f2e0 
    Children:  
      Child:  childNum='0' 
        LibraryHandle:  Address=8753f2e0 Hash=0 LockMode=N PinMode=0 LoadLockMode=0 Status=VALD 
          Name:  Namespace=SQL AREA(00) Type=CURSOR(00) 
          Statistics:  InvalidationCount=1 ExecutionCount=4 LoadCount=2 ActiveLocks=1 TotalLockCount=7 TotalPinCount=11 
          Counters:  BrokenCount=2 RevocablePointer=2 KeepDependency=0 KeepHandle=0 BucketInUse=0 HandleInUse=0 
          Concurrency:  DependencyMutex=8753f390(0, 0, 0, 0) Mutex=8753f808(10, 59, 0, 6) 
          Flags=RON/PIN/PN0/EXP/[10012111] 
          WaitersLists:  
            Lock=8753f370[8753f370,8753f370] 
            Pin=8753f380[8753f350,8753f350] 
          LibraryObject:  Address=7f256160 HeapMask=0000-0001-0001 Flags=EXS[0000] Flags2=[0000] PublicFlags=[0000] 
          NamespaceDump:  
            Child Cursor:  Heap0=0x17f256248 Heap6=0x1798cb868 Heap0 Load Time=01-11-2018 21:02:41 Heap6 Load Time=01-11-2018 21:02:41 
  NamespaceDump:  
    Parent Cursor:  sql_id=a3bfahfuts07x parent=0x17f257248 maxchild=1 plk=y ppn=n    kkscs=0x17f257750 nxt=(nil) flg=18 cld=0 hd=0x18753f2e0 par=0x17f257248
   Mutex 0x17f257750(0, 0) idn 3000000000
   ct=1 hsh=0 unp=(nil) unn=0 hvl=7f258040 nhv=0 ses=(nil)
   hep=0x17f2577e0 flg=80 ld=1 ob=0x17f256160 ptr=0x1798cb868 fex=0x1798cac08
cursor instantiation=0x7fb8f6230880 used=1515704578 exec_id=0 exec=2
 child#0(0x18753f2e0) pcs=0x17f257750
  clk=0x1871eb3c8 ci=0x17f256248 pn=(nil) ctx=0x1798cb868
 kgsccflg=1 llk[0x7fb8f6230388,0x7fb8f6230d88] idx=fe
 xscflg=10001c fl2=80040001 fl3=22000 fl4=0
 Frames pfr (nil) siz=11624 efr (nil) siz=11608
 

You can see the kgscFindCursor returns some address that is called cursor instantiation=0x7fb8f6230880.

kksParseCursor

Here ia a result of my next debug session

Breakpoint 5, 0x00000000085f3fcd in kgscFindCursor ()
$44 = 0x0

Breakpoint 6, 0x00000000083f7e07 in kkspsc0 ()
$45 = 0x7f08c4a31280
(gdb) finish
Run till exit from #0  0x00000000083f7e07 in kkspsc0 ()
0x00000000083f7ab2 in kksParseCursor ()
(gdb) p/x $rax
$46 = 0x1798c8c60  
(gdb) finish
Run till exit from #0  0x00000000083f7ab2 in kksParseCursor ()

Breakpoint 7, 0x00000000084db7dc in opiosq0 ()
(gdb) p/x $rax
$47 = 0x1798c8c60

I have stopped in kkspsc0 (function that call kgscFindCursor) and then
run twice till exit (gdb command finish). First time I stopped in kksParseCursor and second time I stopped in opiosqo just after kksParseCursor execution and examined return code of kksParseCursor function. You can see it is some address again 0x1798c8c60. Cursor dump gives you a clue again.

----- Dump Cursor sql_id=a3bfahfuts07x xsc=0x7f08c4a31280 cur=0x7f08c4a11a38 -----

LibraryHandle:  Address=871f6418 Hash=b59c00fd LockMode=N PinMode=0 LoadLockMode=0 Status=VALD 
  ObjectName:  Name=SELECT /* SessParse */ * FROM YYTEST WHERE rownum <=2

    FullHashValue=9488756f1f9dcc7ba1adca83b59c00fd Namespace=SQL AREA(00) Type=CURSOR(00) Identifier=3046899965 
OwnerIdn=91 
  Statistics:  InvalidationCount=1 ExecutionCount=15 LoadCount=3 ActiveLocks=1 TotalLockCount=8 TotalPinCount=1 
  Counters:  BrokenCount=1 RevocablePointer=1 KeepDependency=1 KeepHandle=1 BucketInUse=6 HandleInUse=6 
  Concurrency:  DependencyMutex=871f64c8(0, 0, 0, 0) Mutex=871f6540(132, 74, 0, 6) 
  Flags=RON/PIN/TIM/PN0/DBN/[10012841] 
  WaitersLists:  
    Lock=871f64a8[871f64a8,871f64a8] 
    Pin=871f64b8[871f6488,871f6488] 
  Timestamp:  Current=01-08-2018 17:40:49 
  LibraryObject:  Address=7f1e4750 HeapMask=0000-0001-0001 Flags=EXS[0000] Flags2=[0000] PublicFlags=[0000] 
    ChildTable:  size='16' 
      Child:  id='0' Table=7f1e5650 Reference=7f1e50a0 Handle=871eef88 
    Children:  
      Child:  childNum='0' 
        LibraryHandle:  Address=871eef88 Hash=0 LockMode=N PinMode=S LoadLockMode=0 Status=VALD 
          Name:  Namespace=SQL AREA(00) Type=CURSOR(00) 
          Statistics:  InvalidationCount=1 ExecutionCount=10 LoadCount=2 ActiveLocks=1 TotalLockCount=8 TotalPin
Count=18 
          Counters:  BrokenCount=2 RevocablePointer=2 KeepDependency=0 KeepHandle=0 BucketInUse=0 HandleInUse=0 
          Concurrency:  DependencyMutex=871ef038(0, 0, 0, 0) Mutex=871f6540(132, 74, 0, 6) 
          Flags=RON/PIN/PN0/EXP/[10012111] 
          WaitersLists:  
            Lock=871ef018[871ef018,871ef018] 
            Pin=871ef028[871eeff8,871eeff8] 
          LibraryObject:  Address=7f1e3750 HeapMask=0000-0001-0001 Flags=EXS[0000] Flags2=[0000] PublicFlags=[0000] 
            DataBlocks:  
              Block:  #='0' name=CCUR^b59c00fd pins=0 Change=NONE   
                Heap=871e01d0 Pointer=7f1e3838 Extent=7f1e3720 Flags=I/-/P/A/-/- 
                FreedLocation=0 Alloc=2.945312 Size=3.937500 LoadTime=4327686840 
              Block:  #='6' name=SQLA^b59c00fd pins=0 Change=NONE   
                Heap=7f1e4e70 Pointer=798c8c60 Extent=798c8000 Flags=I/-/P/A/-/E 
                FreedLocation=0 Alloc=8.218750 Size=11.859375 LoadTime=0 
          NamespaceDump:  
            Child Cursor:  Heap0=0x17f1e3838 Heap6=0x1798c8c60 Heap0 Load Time=01-08-2018 18:57:18 Heap6 Load Time=01-08-2018 18:57:18 

So you can see that return value of kksCursorParse function is a Heap6 child cursor address. Heap6=0x1798c8c60.
In Oracle’s documentation you could see little of information
regarding this Heap6.
V$SQLAREA
Number of child cursors that are present in the cache and have their context heap (KGL heap 6) loaded

V$SQL_SHARED_MEMORY
Each child object has a number of parts, one of which is the context heap, which holds, among other things, the query plan.

So I can interpret it as kksParseCursor returns address of child cursor context heap (Heap6) address.

Summary

  • kksParseCursor – returns address of child cursor context heap (Heap 6)
  • kgscFindCursor – returns cursor instantiation address (in a case of successful lookup)

Once again about soft parse and “softer soft parse”

In a great book of Jonathan Lewis http://www.apress.com/9781430239543 you can read in particular about “session cached” cursor execution. Some code “shortcut” also has been mentioned there that allowed to avoid expensive library cache lookup.

That type of execution has been widely discussed many times:
https://asktom.oracle.com/pls/asktom/f?p=100:11:0::::P11_QUESTION_ID:801662252143
https://www.freelists.org/post/oracle-l/SESSION-CACHED-CURSORS,6

I was always curious about what is that “shortcut” means exactly.

It seems I’ve managed to find a place in Oracle Corp. code where that piece of code is located. After some digging I finally found the function – kgscFindCursor
Somewhere inside you can see the following piece of code

   
   0x00000000085f3fba :	lea    rdi,[rbx+0x18]
   0x00000000085f3fbe :	mov    rsi,r13
   0x00000000085f3fc1 :	mov    edx,0x10
   0x00000000085f3fc6 :	call   _intel_fast_memcmp 
   0x00000000085f3fcb :	test   eax,eax

_intel_fast_memcmp is a variant of memcmp function that takes 3 arguments

int memcmp( const void * memptr1, const void * memptr2, size_t num );

According to calling convention:
$rdi is a 1st argument
$rsi is a 2nd argument
$rdx(or $edx) is a 3rd argument

so it seems we compare 16 bytes of 2 memory areas.

Let have a look on algorithm in more details:

I’ve attached with gdb debugger to my Oracle session (gdb attach 1238 [1238 is a pid of the server process of my session] ) and set the following breakpoints:

   
set pagination off

b kksParseCursor
command
x/s $rbx
c
end

kksParseCursor seems an entry point for SQL parsing

 
b kgscFindCursor
command
x/s $rbx
c
end

kgscFindCursor – is an entry point for session cursor look up

b *kgscFindCursor+210
command
x/s $rdi
x/s $rsi
p/x $rdx
c
end

This break point (above) is just before memcpy call, so we can see memory area we are going to compare in advance.
$rdi – 1st pointer
$rsi – 2nd pointer
$rdx – how many bytes to compare (16 = 0x10)

b *kgscFindCursor+217
command
p/x $rax
c
end

and this break point just after comparison.
$rax register contains result of the function call.

b *kkspsc0+305
command
p/x $rax
end

And this break point set just after execution of kgscFindCursor function to see its result.

b kkshGetNextChild
command
c
end

and finally this function will be called only if a simple soft parse has happened.

The result of my debug session is the following (interpretation will be a bit later):

 
--------------  1ST EXECUTION  ----------------------------------
Breakpoint 1, 0x00000000083f7a26 in kksParseCursor ()
0x7ffe2c731ba0:	"SELECT /* SessParse */ * FROM YYTEST WHERE rownum <=2"

Breakpoint 2, 0x00000000085f3ef8 in kgscFindCursor ()
0x2:	
Breakpoint 3, 0x00000000085f3fc6 in kgscFindCursor () 0x7f9192bd8a98: "\034\217\256%\253\026\033\323\020z\227\311\301\322\f\035(A_\207\001" 0x7ffe2c72ffd0: "ou\210\224{̝\037\203ʭ\241", $1 = 0x10 Breakpoint 4, 0x00000000085f3fcd in kgscFindCursor () $2 = 0xffffffff Breakpoint 3, 0x00000000085f3fc6 in kgscFindCursor () 0x7f9192bdcac8: "o\022FX\251\213\233\f\025\242 \t\222\274\337\346X\017`\207\001" 0x7ffe2c72ffd0: "ou\210\224{̝\037\203ʭ\241", $3 = 0x10 Breakpoint 4, 0x00000000085f3fcd in kgscFindCursor () $4 = 0xffffffff Breakpoint 3, 0x00000000085f3fc6 in kgscFindCursor () 0x7f9192bd7ed0: "W^\336\351\064\065ҧ\342/\005\233\067\365h\001\030\224)\207\001" 0x7ffe2c72ffd0: "ou\210\224{̝\037\203ʭ\241", $5 = 0x10 Breakpoint 4, 0x00000000085f3fcd in kgscFindCursor () $6 = 0xffffffff Breakpoint 3, 0x00000000085f3fc6 in kgscFindCursor () 0x7f9192bd9050: "\326\062\264K\032\071Z\\\372åBz,Gt\240\264\204\207\001" 0x7ffe2c72ffd0: "ou\210\224{̝\037\203ʭ\241", $7 = 0x10 Breakpoint 4, 0x00000000085f3fcd in kgscFindCursor () $8 = 0x1 Breakpoint 3, 0x00000000085f3fc6 in kgscFindCursor () 0x7f9192bebbf8: "L\324I\016\317\316\023\271\231\031L\033\226\354\342\213P\202'\207\001" 0x7ffe2c72ffd0: "ou\210\224{̝\037\203ʭ\241", $9 = 0x10 Breakpoint 4, 0x00000000085f3fcd in kgscFindCursor () $10 = 0xffffffff Breakpoint 3, 0x00000000085f3fc6 in kgscFindCursor () 0x7f9192bea208: "MIy\212\356\202r.ٌ\235\311\035\215<(\220p'\207\001" 0x7ffe2c72ffd0: "ou\210\224{̝\037\203ʭ\241", $11 = 0x10 Breakpoint 4, 0x00000000085f3fcd in kgscFindCursor () $12 = 0xffffffff (result of memcmp) Breakpoint 5, 0x00000000083f7e07 in kkspsc0 () $13 = 0x0 (result of kgscFindCursor) (gdb) Continuing. Breakpoint 6, 0x0000000001941812 in kkshGetNextChild () .....................................

Above you can see a result of 1st execution,
Each execution of memcpy is “unsuccessful”
(Breakpoint 4, 0x00000000085f3fcd in kgscFindCursor ()
$10 = 0xffffffff) , i.e. returns non-zero value.

------------------ 2ND EXECUTION ------------------------- 

Breakpoint 1, 0x00000000083f7a26 in kksParseCursor ()
0x7ffe2c731ba0:	"SELECT /* SessParse */ * FROM YYTEST WHERE rownum <=2"

Breakpoint 2, 0x00000000085f3ef8 in kgscFindCursor ()
0x2:	
Breakpoint 3, 0x00000000085f3fc6 in kgscFindCursor () 0x7f9192bd8a98: "\034\217\256%\253\026\033\323\020z\227\311\301\322\f\035(A_\207\001" 0x7ffe2c72ffd0: "ou\210\224{̝\037\203ʭ\241", $27 = 0x10 Breakpoint 4, 0x00000000085f3fcd in kgscFindCursor () $28 = 0xffffffff ......................................... Breakpoint 3, 0x00000000085f3fc6 in kgscFindCursor () 0x7f9192be60b8: "\264\311M}\373\274\360#\355r\002QȖ\340\252 8'\207\001" 0x7ffe2c72ffd0: "ou\210\224{̝\037\203ʭ\241", $39 = 0x10 Breakpoint 4, 0x00000000085f3fcd in kgscFindCursor () $40 = 0x1 Breakpoint 5, 0x00000000083f7e07 in kkspsc0 () $41 = 0x0 (gdb) Continuing. Breakpoint 6, 0x0000000001941812 in kkshGetNextChild () ......................

3RD execution is almost the same as 2ND one

---------------------------4TH EXECUTION -------------------------------------
Breakpoint 1, 0x00000000083f7a26 in kksParseCursor ()
0x7ffe2c731ba0:	"SELECT /* SessParse */ * FROM YYTEST WHERE rownum <=2"

Breakpoint 2, 0x00000000085f3ef8 in kgscFindCursor ()
0x2:	
Breakpoint 3, 0x00000000085f3fc6 in kgscFindCursor () 0x7f9192bd8a98: "\034\217\256%\253\026\033\323\020z\227\311\301\322\f\035(A_\207\001" 0x7ffe2c72ffd0: "ou\210\224{̝\037\203ʭ\241", $87 = 0x10 Breakpoint 4, 0x00000000085f3fcd in kgscFindCursor () $88 = 0xffffffff Breakpoint 3, 0x00000000085f3fc6 in kgscFindCursor () 0x7f9192bdcac8: "o\022FX\251\213\233\f\025\242 \t\222\274\337\346X\017`\207\001" 0x7ffe2c72ffd0: "ou\210\224{̝\037\203ʭ\241", $89 = 0x10 Breakpoint 4, 0x00000000085f3fcd in kgscFindCursor () $90 = 0xffffffff Breakpoint 3, 0x00000000085f3fc6 in kgscFindCursor () 0x7f9192bd7ed0: "W^\336\351\064\065ҧ\342/\005\233\067\365h\001\030\224)\207\001" 0x7ffe2c72ffd0: "ou\210\224{̝\037\203ʭ\241", $91 = 0x10 Breakpoint 4, 0x00000000085f3fcd in kgscFindCursor () $92 = 0xffffffff Breakpoint 3, 0x00000000085f3fc6 in kgscFindCursor () 0x7f9192bd9050: "\326\062\264K\032\071Z\\\372åBz,Gt\240\264\204\207\001" 0x7ffe2c72ffd0: "ou\210\224{̝\037\203ʭ\241", $93 = 0x10 Breakpoint 4, 0x00000000085f3fcd in kgscFindCursor () $94 = 0x1 Breakpoint 3, 0x00000000085f3fc6 in kgscFindCursor () 0x7f9192bebbf8: "L\324I\016\317\316\023\271\231\031L\033\226\354\342\213P\202'\207\001" 0x7ffe2c72ffd0: "ou\210\224{̝\037\203ʭ\241", $95 = 0x10 Breakpoint 4, 0x00000000085f3fcd in kgscFindCursor () $96 = 0xffffffff Breakpoint 3, 0x00000000085f3fc6 in kgscFindCursor () 0x7f9192bea208: "MIy\212\356\202r.ٌ\235\311\035\215<(\220p'\207\001" 0x7ffe2c72ffd0: "ou\210\224{̝\037\203ʭ\241", $97 = 0x10 Breakpoint 4, 0x00000000085f3fcd in kgscFindCursor () $98 = 0xffffffff Breakpoint 3, 0x00000000085f3fc6 in kgscFindCursor () 0x7f9192be3ad8: "ou\210\224{̝\037\203ʭ\241", 0x7ffe2c72ffd0: "ou\210\224{̝\037\203ʭ\241", $99 = 0x10 Breakpoint 4, 0x00000000085f3fcd in kgscFindCursor () $100 = 0x0 (result of memcmp) Breakpoint 5, 0x00000000083f7e07 in kkspsc0 () $101 = 0x7f9192be3ab8 (result of kgscFindCursor) (gdb) Continuing.

4TH execution is a different:
1. you can see that last comparison via memcmp was successful.
2. you can see that kgscFindCursor returns some none zero value (some address)
3. you don’t see any further “child lists traversing”.

So my interpretation is the following.
1. During “session cached cursor” execution you are still traversing some linked list of memory structures (I believe it is members of some hash bucket).
2. if you find exact match you bypass any other checks and go almost directly to the execution phase.