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 😉