Using DTrace to understand why PL/SQL packages can be faster than stored procedures (kgiPinObject)


19.09.2016
by Kamil Stawiarski

I know – everyone knows, that PL/SQL packages are faster than stored procedures. If you’ll ask anyone at the training or in your dev team "what is better" – you’ll (almost) always hear: PL/SQL packages. But why exactly?

The documentation says:

The first time you invoke a package subprogram, Oracle Database loads the whole package into memory. Subsequent invocations of other subprograms in same the package require no disk I/O.

Source: http://docs.oracle.com/database/121/LNPLS/packages.htm#LNPLS00904

OK, it’s understandable and feels natural. But let’s try to think about it for a while.
I’ve created one procedure, one function and a package, containing those two. As simple as it can be:

SQL> create or replace function by2(x number) return number as
  2  begin
  3    return x*2;
  4  end;
  5  /

Function created.

SQL> create or replace procedure proc_by2 as
  2   x number;
  3  begin
  4    for i in 1..1000000 loop
  5      x:=by2(i);
  6    end loop;
  7  end;
  8  /

Procedure created.

SQL> create or replace package pkg_test_calls as
  2    function by2(x number) return number;
  3    procedure by2_proc;
  4  end;
  5  /

Package created.

SQL> ed
Wrote file afiedt.buf

  1  create or replace package body pkg_test_calls as
  2    function by2(x number) return number is
  3    begin
  4      return x*2;
  5    end by2;
  6    procedure by2_proc is
  7      vx number;
  8    begin
  9       for i in 1..1000000 loop
 10         vx:=by2(i);
 11       end loop;
 12    end;
 13* end;
 14  /

Package body created.

I think that for this simple example, using "set timing on" will be sufficient enough.

SQL> set timing on
SQL> exec proc_by2

PL/SQL procedure successfully completed.

Elapsed: 00:00:00.25
SQL> exec pkg_test_calls.by2_proc

PL/SQL procedure successfully completed.

Elapsed: 00:00:00.16
SQL> exec proc_by2

PL/SQL procedure successfully completed.

Elapsed: 00:00:00.23
SQL> exec pkg_test_calls.by2_proc

PL/SQL procedure successfully completed.

Elapsed: 00:00:00.16
SQL>

So why there is a difference here? I don’t see any place here for disk I/O. Both procedures were compiled and loaded into memory, so we can’t speak about subsequent loads.

To understand what has happened I’ve created a very simple DTrace script, which will count the number of function calls, made by server process, associated with my session. I’ve used DTrace ability to trace functions, based on PID provider.

This technique is called "User-space Probing" and can be done also on Linux, using dynamic tracing tools like Systemtap https://sourceware.org/systemtap/SystemTap_Beginners_Guide/userspace-probing.html

root@skiper:~# cat function_calls.d
#!/usr/sbin/dtrace -s
pid$1:::entry
/pid==$1/
{
        @fcount[probemod,probefunc]=count();
}

Let’s check the tail output for test with package and separate PL/SQL stored function/procedure.

root@skiper:~# tail -20 fcalls_proc_fun.out
  oracle                                              lnxmin                                                      1000000
  oracle                                              lnxmin_int                                                  1000000
  oracle                                              lnxmul                                                      1000000
  oracle                                              pfrinstr_BCTR                                               1000000
  oracle                                              pfrinstr_CVTIN                                              1000000
  oracle                                              pfrinstr_MULN                                               1000000
  oracle                                              sslnxmul                                                    1000000
  oracle                                              kgiPinObject                                                1000002
  oracle                                              pevm_ENTER                                                  1000002
  oracle                                              pevm_RET                                                    1000002
  oracle                                              pfrinstr_RET                                                1000002
  oracle                                              pfrust                                                      1000002
  oracle                                              pfrxca                                                      1000002
  oracle                                              pevm_CHK_INST                                               1000003
  oracle                                              pfrinstr_XCAL                                               1000003
  oracle                                              pfrinstr_XCAL_SCAL                                          1000003
  oracle                                              kglPinSetContext                                            1000004
  oracle                                              kglpnp                                                      1000006
  oracle                                              kss_get_owner                                               1000012
  oracle                                              kss_get_type                                                1000028
root@skiper:~# tail -20 fcalls_pkg.out
  oracle                                              pdz2M20_Audit_In_No_PDZ0_DEBUG                                  634
  oracle                                              dbgtrPrepareWrite                                               635
  oracle                                              pdz9M08_Type_Kind                                               689
  libc.so.1                                           setjmp                                                          717
  oracle                                              kghuwrlength                                                    755
  oracle                                              pdzgM07_Get                                                     774
  oracle                                              pdz7M12_Opcode                                                  792
  libc.so.1                                           memset                                                         1200
  oracle                                              lnxmul                                                      1000000
  oracle                                              pfrinstr_BCTR                                               1000000
  oracle                                              pfrinstr_CALL                                               1000000
  oracle                                              pfrinstr_CVTIN                                              1000000
  oracle                                              pfrinstr_MULN                                               1000000
  oracle                                              sslnxmul                                                    1000000
  oracle                                              lnxmin                                                      1000001
  oracle                                              lnxmin_int                                                  1000001
  oracle                                              pevm_ENTER                                                  1000002
  oracle                                              pevm_RET                                                    1000002
  oracle                                              pfrinstr_RET                                                1000002
  oracle                                              pfrust                                                      1000002

We don’t need a very detail investigation to notice the difference between those two executions.
I decided to check the execution times of 4 particular functions:

  • plsql_run
  • kglpnp
  • kglPinSetContext
  • kgiPinObject

The first one is responsible for the whole PL/SQL initialization and execution, so its time should be similar to what we can see in SQL*Plus timing. The next two should have something to do with maintaining the PL/SQL objects in library cache – "oradebug doc component" shows, that "kgl" components are responsible for LIBRARY CACHE:

ora-600:~ inter$ grep -i kgl ORA-600/scripts/oracle/components.doc
  LIBCACHE		       LIBCACHE (kgl, kql)

I’m guessing by the name, that the last one should be responsible for pining the PL/SQL object in library cache for the execution time.

Based on this I used a very simple DTrace script to check the execution time and number of executions of each function:

root@skiper:~# cat plsql_proc_fun_time.d
#!/usr/sbin/dtrace -s
#pragma D option quiet

uint64_t        kpoTime;
uint64_t        plsqlrunTime;
uint64_t        kglpnpTime;
uint64_t        contextTime;

BEGIN
{
  printf("%s\n","START PROFILING kgiPinObject, plsql_run, kglpnpi,kglPinSetContext execution times");
}

pid$1::kgiPinObject:entry
/pid==$1/
{
  self->t=timestamp;
}
pid$1::kgiPinObject:return
/pid==$1 && self->t>0/
{
  kpoTime+=timestamp-self->t;
  self->t=0;
  @stackKgi[ustack()]=count();
  kgiPinObjectExec++;
}
pid$1::plsql_run:entry
/pid==$1/
{
  self->pt=timestamp;
}
pid$1::plsql_run:return
/pid==$1 && self->pt>0/
{
  plsqlrunTime+=timestamp-self->pt;
  self->pt=0;
  plsql_runExec++;
}
pid$1::kglpnp:entry
/pid==$1/
{
  self->kt=timestamp;
}
pid$1::kglpnp:return
/pid==$1 && self->kt>0/
{
  kglpnpTime+=timestamp-self->kt;
  self->kt=0;
  @stackKgl[ustack()]=count();
  kglpnpExec++;
}
pid$1::kglPinSetContext:entry
/pid==$1/
{
  self->ct=timestamp;
}
pid$1::kglPinSetContext:return
/pid==$1 && self->ct>0/
{
  contextTime+=timestamp-self->ct;
  self->ct=0;
  @stackCtx[ustack()]=count();
  kglPinSetContextExec++;
}

END
{
  printa(@stackKgi);
  printa(@stackKgl);
  printa(@stackCtx);
  printf("kgiPinObject executed %d times, waited in ms: %d\n",kgiPinObjectExec,kpoTime/1000000);
  printf("kglpnp executed %d times, waited in ms: %d\n",kglpnpExec, kglpnpTime/1000000);
  printf("kglPinSetContext executed %d times, waited in ms: %d\n",kglPinSetContextExec, contextTime/1000000);
  printf("plsql_run executed %d times, waited in ms: %d\n",plsql_runExec, plsqlrunTime/1000000);
  sm=kpoTime+kglpnpTime+contextTime;
  printf("kgiPinObject+kglpnp+kglPinSetContext = %d ms \n",sm/1000000);
}

Please notice, that this script will seriously affect the execution times, because monitoring can change the monitored object 😉

So right now the execution time for package looks like this:

SQL> exec pkg_test_calls.by2_proc

PL/SQL procedure successfully completed.

Elapsed: 00:00:00.18
SQL>

And this is the output of my Dtrace script:

root@skiper:~# ./plsql_proc_fun_time.d 3450
START PROFILING kgiPinObject, plsql_run, kglpnpi,kglPinSetContext execution times
^C


              oracle`kgiPinObject+0xb8
              oracle`pfrinstr_XCAL_SCAL+0x87
              oracle`pfrrun_no_tool+0x12a
              oracle`pfrrun+0x4c0
              oracle`plsql_run+0x288
              oracle`peicnt+0x15f
              oracle`kkxexe+0x2f3
              oracle`opiexe+0x32c3
              oracle`kpoal8+0xa3d
              oracle`opiodr+0x433
              oracle`ttcpip+0x593
              oracle`opitsk+0x6cc
              oracle`opiino+0x3c5
              oracle`opiodr+0x433
              oracle`opidrv+0x33b
              oracle`sou2o+0x7a
              oracle`opimai_real+0x265
              oracle`ssthrdmain+0x22e
              oracle`main+0xa4
              oracle`0x6e80c2b
                1


              oracle`kglpnp+0x140
              oracle`pfri7_inst_body_common+0x88
              oracle`pfri3_inst_body+0x43
              oracle`pfrrun+0x685
              oracle`plsql_run+0x288
              oracle`peicnt+0x15f
              oracle`kkxexe+0x2f3
              oracle`opiexe+0x32c3
              oracle`kpoal8+0xa3d
              oracle`opiodr+0x433
              oracle`ttcpip+0x593
              oracle`opitsk+0x6cc
              oracle`opiino+0x3c5
              oracle`opiodr+0x433
              oracle`opidrv+0x33b
              oracle`sou2o+0x7a
              oracle`opimai_real+0x265
              oracle`ssthrdmain+0x22e
              oracle`main+0xa4
              oracle`0x6e80c2b
                1

              oracle`kglpnp+0x140
              oracle`pfri8_inst_spec+0x83
              oracle`pfri1_inst_spec+0x43
              oracle`pfrrun+0x5e2
              oracle`plsql_run+0x288
              oracle`peicnt+0x15f
              oracle`kkxexe+0x2f3
              oracle`opiexe+0x32c3
              oracle`kpoal8+0xa3d
              oracle`opiodr+0x433
              oracle`ttcpip+0x593
              oracle`opitsk+0x6cc
              oracle`opiino+0x3c5
              oracle`opiodr+0x433
              oracle`opidrv+0x33b
              oracle`sou2o+0x7a
              oracle`opimai_real+0x265
              oracle`ssthrdmain+0x22e
              oracle`main+0xa4
              oracle`0x6e80c2b
                1

              oracle`kglpnp+0x140
              oracle`pevm_CHK_INST+0x49
              oracle`pfrinstr_XCAL_SCAL+0x87
              oracle`pfrrun_no_tool+0x12a
              oracle`pfrrun+0x4c0
              oracle`plsql_run+0x288
              oracle`peicnt+0x15f
              oracle`kkxexe+0x2f3
              oracle`opiexe+0x32c3
              oracle`kpoal8+0xa3d
              oracle`opiodr+0x433
              oracle`ttcpip+0x593
              oracle`opitsk+0x6cc
              oracle`opiino+0x3c5
              oracle`opiodr+0x433
              oracle`opidrv+0x33b
              oracle`sou2o+0x7a
              oracle`opimai_real+0x265
              oracle`ssthrdmain+0x22e
              oracle`main+0xa4
                1

              oracle`kglpnp+0x140
              oracle`pfri7_inst_body_common+0x118
              oracle`pfri3_inst_body+0x43
              oracle`pfrrun+0x685
              oracle`plsql_run+0x288
              oracle`peicnt+0x15f
              oracle`kkxexe+0x2f3
              oracle`opiexe+0x32c3
              oracle`kpoal8+0xa3d
              oracle`opiodr+0x433
              oracle`ttcpip+0x593
              oracle`opitsk+0x6cc
              oracle`opiino+0x3c5
              oracle`opiodr+0x433
              oracle`opidrv+0x33b
              oracle`sou2o+0x7a
              oracle`opimai_real+0x265
              oracle`ssthrdmain+0x22e
              oracle`main+0xa4
              oracle`0x6e80c2b
                1


              oracle`kglPinSetContext+0x76
              oracle`pevm_CHK_INST+0x49
              oracle`pfrinstr_XCAL_SCAL+0x87
              oracle`pfrrun_no_tool+0x12a
              oracle`pfrrun+0x4c0
              oracle`plsql_run+0x288
              oracle`peicnt+0x15f
              oracle`kkxexe+0x2f3
              oracle`opiexe+0x32c3
              oracle`kpoal8+0xa3d
              oracle`opiodr+0x433
              oracle`ttcpip+0x593
              oracle`opitsk+0x6cc
              oracle`opiino+0x3c5
              oracle`opiodr+0x433
              oracle`opidrv+0x33b
              oracle`sou2o+0x7a
              oracle`opimai_real+0x265
              oracle`ssthrdmain+0x22e
              oracle`main+0xa4
                1

              oracle`kglPinSetContext+0x76
              oracle`kgiind+0x431
              oracle`pfri8_inst_spec+0x83
              oracle`pfri1_inst_spec+0x43
              oracle`pfrrun+0x5e2
              oracle`plsql_run+0x288
              oracle`peicnt+0x15f
              oracle`kkxexe+0x2f3
              oracle`opiexe+0x32c3
              oracle`kpoal8+0xa3d
              oracle`opiodr+0x433
              oracle`ttcpip+0x593
              oracle`opitsk+0x6cc
              oracle`opiino+0x3c5
              oracle`opiodr+0x433
              oracle`opidrv+0x33b
              oracle`sou2o+0x7a
              oracle`opimai_real+0x265
              oracle`ssthrdmain+0x22e
              oracle`main+0xa4
                1

              oracle`kglPinSetContext+0x76
              oracle`kglpndl+0xd23
              oracle`kss_del_cb+0x19d
              oracle`kssdel+0xf2
              oracle`kssdch_int+0x326
              oracle`ksudlc+0xf6
              oracle`kss_del_cb+0x106
              oracle`kssdel+0xf2
              oracle`ksupop+0x23a
              oracle`opiodr+0x4b1
              oracle`ttcpip+0x593
              oracle`opitsk+0x6cc
              oracle`opiino+0x3c5
              oracle`opiodr+0x433
              oracle`opidrv+0x33b
              oracle`sou2o+0x7a
              oracle`opimai_real+0x265
              oracle`ssthrdmain+0x22e
              oracle`main+0xa4
              oracle`0x6e80c2b
                2
kgiPinObject executed 1 times, waited in ms: 0
kglpnp executed 4 times, waited in ms: 0
kglPinSetContext executed 4 times, waited in ms: 0
plsql_run executed 1 times, waited in ms: 172
kgiPinObject+kglpnp+kglPinSetContext = 0 ms

And this is the execution time of procedure call:

SQL> exec proc_by2

PL/SQL procedure successfully completed.

Elapsed: 00:00:24.38

And the result of my DTrace script for this execution:

root@skiper:~# ./plsql_proc_fun_time.d 3450
START PROFILING kgiPinObject, plsql_run, kglpnpi,kglPinSetContext execution times
^C


              oracle`kgiPinObject+0xb8
              oracle`pfrinstr_XCAL_SCAL+0x87
              oracle`pfrrun_no_tool+0x12a
              oracle`pfrrun+0x4c0
              oracle`plsql_run+0x288
              oracle`peicnt+0x15f
              oracle`kkxexe+0x2f3
              oracle`opiexe+0x32c3
              oracle`kpoal8+0xa3d
              oracle`opiodr+0x433
              oracle`ttcpip+0x593
              oracle`opitsk+0x6cc
              oracle`opiino+0x3c5
              oracle`opiodr+0x433
              oracle`opidrv+0x33b
              oracle`sou2o+0x7a
              oracle`opimai_real+0x265
              oracle`ssthrdmain+0x22e
              oracle`main+0xa4
              oracle`0x6e80c2b
          1000002


              oracle`kglpnp+0x140
              oracle`pfri7_inst_body_common+0x88
              oracle`pfri3_inst_body+0x43
              oracle`pfrrun+0x685
              oracle`plsql_run+0x288
              oracle`peicnt+0x15f
              oracle`kkxexe+0x2f3
              oracle`opiexe+0x32c3
              oracle`kpoal8+0xa3d
              oracle`opiodr+0x433
              oracle`ttcpip+0x593
              oracle`opitsk+0x6cc
              oracle`opiino+0x3c5
              oracle`opiodr+0x433
              oracle`opidrv+0x33b
              oracle`sou2o+0x7a
              oracle`opimai_real+0x265
              oracle`ssthrdmain+0x22e
              oracle`main+0xa4
              oracle`0x6e80c2b
                2

              oracle`kglpnp+0x140
              oracle`pfri8_inst_spec+0x83
              oracle`pfri1_inst_spec+0x43
              oracle`pfrrun+0x5e2
              oracle`plsql_run+0x288
              oracle`peicnt+0x15f
              oracle`kkxexe+0x2f3
              oracle`opiexe+0x32c3
              oracle`kpoal8+0xa3d
              oracle`opiodr+0x433
              oracle`ttcpip+0x593
              oracle`opitsk+0x6cc
              oracle`opiino+0x3c5
              oracle`opiodr+0x433
              oracle`opidrv+0x33b
              oracle`sou2o+0x7a
              oracle`opimai_real+0x265
              oracle`ssthrdmain+0x22e
              oracle`main+0xa4
              oracle`0x6e80c2b
                2

              oracle`kglpnp+0x140
              oracle`pevm_CHK_INST+0x49
              oracle`pfrinstr_XCAL_SCAL+0x87
              oracle`pfrrun_no_tool+0x12a
              oracle`pfrrun+0x4c0
              oracle`plsql_run+0x288
              oracle`peicnt+0x15f
              oracle`kkxexe+0x2f3
              oracle`opiexe+0x32c3
              oracle`kpoal8+0xa3d
              oracle`opiodr+0x433
              oracle`ttcpip+0x593
              oracle`opitsk+0x6cc
              oracle`opiino+0x3c5
              oracle`opiodr+0x433
              oracle`opidrv+0x33b
              oracle`sou2o+0x7a
              oracle`opimai_real+0x265
              oracle`ssthrdmain+0x22e
              oracle`main+0xa4
          1000002


              oracle`kglPinSetContext+0x76
              oracle`kgiind+0x431
              oracle`pfri8_inst_spec+0x83
              oracle`pfri1_inst_spec+0x43
              oracle`pfrrun+0x5e2
              oracle`plsql_run+0x288
              oracle`peicnt+0x15f
              oracle`kkxexe+0x2f3
              oracle`opiexe+0x32c3
              oracle`kpoal8+0xa3d
              oracle`opiodr+0x433
              oracle`ttcpip+0x593
              oracle`opitsk+0x6cc
              oracle`opiino+0x3c5
              oracle`opiodr+0x433
              oracle`opidrv+0x33b
              oracle`sou2o+0x7a
              oracle`opimai_real+0x265
              oracle`ssthrdmain+0x22e
              oracle`main+0xa4
                1

              oracle`kglPinSetContext+0x76
              oracle`kglpndl+0xd23
              oracle`kss_del_cb+0x19d
              oracle`kssdel+0xf2
              oracle`kssdch_int+0x326
              oracle`ksudlc+0xf6
              oracle`kss_del_cb+0x106
              oracle`kssdel+0xf2
              oracle`ksupop+0x23a
              oracle`opiodr+0x4b1
              oracle`ttcpip+0x593
              oracle`opitsk+0x6cc
              oracle`opiino+0x3c5
              oracle`opiodr+0x433
              oracle`opidrv+0x33b
              oracle`sou2o+0x7a
              oracle`opimai_real+0x265
              oracle`ssthrdmain+0x22e
              oracle`main+0xa4
              oracle`0x6e80c2b
                2

              oracle`kglPinSetContext+0x76
              oracle`pevm_CHK_INST+0x49
              oracle`pfrinstr_XCAL_SCAL+0x87
              oracle`pfrrun_no_tool+0x12a
              oracle`pfrrun+0x4c0
              oracle`plsql_run+0x288
              oracle`peicnt+0x15f
              oracle`kkxexe+0x2f3
              oracle`opiexe+0x32c3
              oracle`kpoal8+0xa3d
              oracle`opiodr+0x433
              oracle`ttcpip+0x593
              oracle`opitsk+0x6cc
              oracle`opiino+0x3c5
              oracle`opiodr+0x433
              oracle`opidrv+0x33b
              oracle`sou2o+0x7a
              oracle`opimai_real+0x265
              oracle`ssthrdmain+0x22e
              oracle`main+0xa4
          1000001
kgiPinObject executed 1000002 times, waited in ms: 19482
kglpnp executed 1000006 times, waited in ms: 3532
kglPinSetContext executed 1000004 times, waited in ms: 3676
plsql_run executed 1 times, waited in ms: 24380
kgiPinObject+kglpnp+kglPinSetContext = 26692 ms

As you can see, the numbers are accurate enough to make some conclusions: execution time of function kgiPinObject is almost 80% of the whole execution time!

So the reason why PL/SQL packages are faster in subsequent invocations of other subprograms is not the "disk I/O", but penalty due to the need to pin/lock the foreign object in Library Cache each time, when I want to execute it.

So the practical knowledge "the lightning kills" did not change, but now at least I know, that it’s not because Zeus is mad at me 😉

P.S.
If you want to meet true experts in PL/SQL, you have to visit Poland, 7/8 OCTOBER 2016 at POUG (Pint with Oracle Users Group). Details can be found in here: http://poug.org/en/
Name of the function, which executes kgiPinObject will give -10% for the ticket 😉

Search:


Kontakt

Database Whisperers sp. z o. o. sp. k.
Al. Jerozolimskie 200
Wejście B, III piętro/ pokój 342
02-486 Warszawa
NIP: 5272744987
REGON:362524978
+48 508 943 051
+48 661 966 009
info@ora-600.pl

Newsletter zapisz się żeby być na bieżąco