Profiling parsing ANSI and Old Oracle SQL

1 Background
2 Observations
3 Output
3.1 Oracle 12.1.0.2
3.2 Oracle 11.2.0.1
3.3 Profile without parsing
3.4 Other comments

Background

Below is the output of the Oracle profiling of a number of basic ANSI SQL statements, and a number of Old Oracle SQL statements. The objective of the below was to spot whether Oracle did anything materially different when parsing ANSI SQL, relative to when parsing "Old Oracle" SQL.

The shell scripts shown in the tables below running SQL*Plus were run on my Centos 7 Pentium I7 machine, with the database accessed by the SQL*Plus sessions being in a VBox virtual machine hosted by the same physical machine. Each shell script submitted 10,000 identical SQL statements, which were each textually different to each other to force the database to parse each statement.

As the statements were all doing the same thing, joining two very small tables, most of the Oracle server process time would be spent parsing statements, so in profiling the server process one can get some idea what Oracle is doing when parsing the statement.

A couple of xterms were used on the database virtual machine when the host ran the SQL*Plus shell script

one running top, to identify the user oracle server process pid once the shell script had started throwing SQL statements at the database
the other running perf record -p <pid> with the pid identified by the session.

Once the shell script had finished sending it's 10,000 SQL statements to the database, the perf record was stopped, and perf report was used to get the profile pasted below.

Observations

Although the ANSI and "Old Oracle" profiles are different, there does not appear to be any evidence of any translation function to convert one "version" of SQL into another. Within an Oracle version, Oracle appears to do broadly the same sort of thing, though spend differing amounts of time in different functions, depending on the SQL statement being parsed.
For this single SQL statement test, the "Old Oracle" statement appeared to be parsed marginally quicker than the two ANSI equivalents. At some point in time I will try some other SQL statements to see whether this is a repeatable pattern, or just a feature of the SQL statement I chose for this test.
Interestingly enough, examining a 10053 trace of the optimisation (Oracle 12.1.0.2 only examined), the optimiser considered a few more transformations ("join factorization", "new (cbqt) star transformation", "table expansion" and "vector transformation") for the two ANSI statements than it considered for the "Old Oracle" statement, which
1. probably accounts for at least some of the extra time spent parsing the ANSI statements, and
2. makes me wonder whether in recent years some optisations have been built for ANSI SQL, which have not been "back ported" to "Old Oracle".
Oracle 12 appears to be significantly slower than Oracle 11 in parsing the SQL statement I chose, and
- Oracle 11 used kksCheckToFreeCursorStat, __intel_new_memcpy and qkshtTokenToEnum which do not appear in the Oracle 12 profiles,
- similarly, Oracle 12 used the function __intel_ssse3_rep_memcpy which doesn't appear in the Oracle 11 profile, so it might be that it is used in 12.1.0.2 where 11.2.0.1 uses __intel_new_memcpy
- interestingly Oracle 12 spent much more time in the functions qksceGenOutlineOptParamHints and kghalf than Oracle 11 did.

The Output

Although I ran each of the scripts below a number of times (changine the comment in the SQL statements generate between each run of the script), and the profiles produced by each script run were very similar to each other. In particular the profile produce by a rerun was repeatable enough that one could fairly readily identify which SQL statement had been (re)run - that is to say that the profile for a given SQL statement was distinctive.

Oracle 12.1.0.2

ANSI 1		ANSI 2		Old Oracle
#!/usr/bin/ksh # time for (( i=0; i<10000; i++ )) do cat <<eof SELECT /* Unique comment $i / count() FROM scott.emp e JOIN scott.dept d USING (deptno); eof done \|sqlplus -s rik/rik@o12102nc exit 0		#!/usr/bin/ksh # time for (( i=0; i<10000; i++ )) do cat <<eof SELECT /* Unique comment $i / count() FROM scott.emp e JOIN scott.dept d ON d.deptno = e.deptno; eof done \|sqlplus -s rik/rik@o12102nc exit 0		#!/usr/bin/ksh # time for (( i=0; i<10000; i++ )) do cat <<eof SELECT /* Unique comment $i / count() FROM scott.emp e, scott.dept d WHERE e.deptno = d.deptno; eof done \|sqlplus -s rik/rik@o12102nc exit 0
Run 1 Timings	Run 2 Timings	Run 1 Timings	Run 2 Timings	Run 1 Timings	Run 2 Timings
real 0m19.05s user 0m3.24s sys 0m7.17s	real 0m19.02s user 0m3.26s sys 0m7.01s	real 0m18.97s user 0m3.31s sys 0m7.08s	real 0m19.05s user 0m3.32s sys 0m7.00s	real 0m18.09s user 0m3.36s sys 0m7.13s	real 0m18.03s user 0m3.41s sys 0m6.97s
Samples: 36K of event 'cpu-clock', Event count (approx.): 9181500000 56.83% oracle_11916_o1 [vsyscall] [.] 0x000000000000014c 11.88% oracle_11916_o1 [kernel.kallsyms] [k] _spin_unlock_irqrestore 2.00% oracle_11916_o1 [kernel.kallsyms] [k] pcnet32_wio_read_csr 1.50% oracle_11916_o1 oracle [.] qksceGenOutlineOptParamHints 1.32% oracle_11916_o1 oracle [.] kghalf 1.01% oracle_11916_o1 [kernel.kallsyms] [k] pcnet32_wio_write_csr 0.70% oracle_11916_o1 oracle [.] __intel_new_memset 0.55% oracle_11916_o1 [kernel.kallsyms] [k] __do_softirq 0.54% oracle_11916_o1 oracle [.] qksbgGetVal 0.53% oracle_11916_o1 oracle [.] qksceGetParam 0.43% oracle_11916_o1 oracle [.] kghalp 0.42% oracle_11916_o1 oracle [.] kgghteGetEle 0.41% oracle_11916_o1 libc-2.12.so [.] __strncpy_ssse3 0.40% oracle_11916_o1 oracle [.] kghfnd_in_free_lists 0.38% oracle_11916_o1 oracle [.] kghalo 0.35% oracle_11916_o1 oracle [.] __intel_ssse3_rep_memcpy 0.30% oracle_11916_o1 oracle [.] qkexrXformOpn 0.27% oracle_11916_o1 oracle [.] kghbshrt 0.23% oracle_11916_o1 oracle [.] qksxaBuildXml 0.23% oracle_11916_o1 oracle [.] kghprmalo 0.22% oracle_11916_o1 oracle [.] qksbgGetAltered 0.22% oracle_11916_o1 oracle [.] xplMakeNode 0.20% oracle_11916_o1 oracle [.] kghini 0.20% oracle_11916_o1 oracle [.] qkaqkn 0.19% oracle_11916_o1 oracle [.] kggmsHash16 0.17% oracle_11916_o1 oracle [.] kghgex 0.16% oracle_11916_o1 oracle [.] qkshtStmtInf0 0.16% oracle_11916_o1 oracle [.] kksCompileHeapStats 0.16% oracle_11916_o1 oracle [.] qkexrXformOpn_Opt 0.16% oracle_11916_o1 oracle [.] kghaddex 0.15% oracle_11916_o1 oracle [.] kkoUpdateFroAnn 0.15% oracle_11916_o1 oracle [.] qkshtQBInf0 0.14% oracle_11916_o1 oracle [.] kgghash 0.14% oracle_11916_o1 oracle [.] qeaeCnt 0.14% oracle_11916_o1 oracle [.] kksmal 0.14% oracle_11916_o1 oracle [.] qksbgGetCursorVal 0.14% oracle_11916_o1 oracle [.] xplCompact 0.13% oracle_11916_o1 oracle [.] kokegCheckOpnForGC 0.13% oracle_11916_o1 oracle [.] kghssc_putcbn 0.13% oracle_11916_o1 oracle [.] qkacol 0.13% oracle_11916_o1 oracle [.] kggecAlloc 0.13% oracle_11916_o1 oracle [.] qksxaGetSingleAnnotation 0.12% oracle_11916_o1 oracle [.] kkfdtbl 0.12% oracle_11916_o1 oracle [.] qkaTraverseQkn		Samples: 38K of event 'cpu-clock', Event count (approx.): 9505250000 54.75% oracle_13020_o1 [vsyscall] [.] 0x000000000000014c 11.85% oracle_13020_o1 [kernel.kallsyms] [k] _spin_unlock_irqrestore 1.86% oracle_13020_o1 [kernel.kallsyms] [k] pcnet32_wio_read_csr 1.45% oracle_13020_o1 oracle [.] kghalf 1.03% oracle_13020_o1 [kernel.kallsyms] [k] pcnet32_wio_write_csr 0.96% oracle_13020_o1 oracle [.] qksbgGetVal 0.91% oracle_13020_o1 oracle [.] qksceGenOutlineOptParamHints 0.60% oracle_13020_o1 oracle [.] __intel_new_memset 0.45% oracle_13020_o1 libc-2.12.so [.] __strncpy_ssse3 0.45% oracle_13020_o1 oracle [.] kghalp 0.43% oracle_13020_o1 oracle [.] __intel_ssse3_rep_memcpy 0.42% oracle_13020_o1 oracle [.] qksbgGetAltered 0.40% oracle_13020_o1 [kernel.kallsyms] [k] __do_softirq 0.38% oracle_13020_o1 oracle [.] kghfnd_in_free_lists 0.38% oracle_13020_o1 oracle [.] qkexrXformOpn 0.36% oracle_13020_o1 oracle [.] qksceGetParam 0.35% oracle_13020_o1 oracle [.] kgghteGetEle 0.34% oracle_13020_o1 oracle [.] kghalo 0.27% oracle_13020_o1 oracle [.] kghprmalo 0.22% oracle_13020_o1 oracle [.] xplMakeNode 0.22% oracle_13020_o1 oracle [.] kghini 0.21% oracle_13020_o1 oracle [.] kgghash 0.19% oracle_13020_o1 oracle [.] qkshtQBInf0 0.18% oracle_13020_o1 oracle [.] kggmsHash16 0.18% oracle_13020_o1 oracle [.] kghaddex 0.18% oracle_13020_o1 oracle [.] qksxaBuildXml 0.18% oracle_13020_o1 oracle [.] kghbshrt 0.18% oracle_13020_o1 oracle [.] kghgex 0.17% oracle_13020_o1 oracle [.] qksbgGetCursorVal 0.17% oracle_13020_o1 oracle [.] kksCompileHeapStats 0.16% oracle_13020_o1 oracle [.] kksmal 0.16% oracle_13020_o1 oracle [.] qkaMarkQkn 0.16% oracle_13020_o1 oracle [.] qkexrXformOpn_Opt 0.15% oracle_13020_o1 oracle [.] kggecAlloc 0.15% oracle_13020_o1 oracle [.] qkshtStmtInf0 0.14% oracle_13020_o1 oracle [.] xplGenXpl 0.14% oracle_13020_o1 oracle [.] kqrpre1 0.14% oracle_13020_o1 oracle [.] kkoipt 0.13% oracle_13020_o1 oracle [.] kspgsp 0.13% oracle_13020_o1 oracle [.] qkacol 0.13% oracle_13020_o1 oracle [.] qkshtTabInf0 0.13% oracle_13020_o1 oracle [.] xplCompact 0.13% oracle_13020_o1 oracle [.] kkoUpdateFroAnn 0.13% oracle_13020_o1 oracle [.] qkaqkn		Samples: 39K of event 'cpu-clock', Event count (approx.): 9880750000 52.63% oracle_11905_o1 [vsyscall] [.] 0x000000000000014c 12.64% oracle_11905_o1 [kernel.kallsyms] [k] _spin_unlock_irqrestore 2.54% oracle_11905_o1 oracle [.] qksbgGetVal 2.22% oracle_11905_o1 [kernel.kallsyms] [k] pcnet32_wio_read_csr 1.73% oracle_11905_o1 oracle [.] qksbgGetAltered 1.20% oracle_11905_o1 oracle [.] kghalf 1.12% oracle_11905_o1 oracle [.] qksceGenOutlineOptParamHints 0.88% oracle_11905_o1 [kernel.kallsyms] [k] pcnet32_wio_write_csr 0.77% oracle_11905_o1 oracle [.] kgghteGetEle 0.50% oracle_11905_o1 oracle [.] __intel_new_memset 0.46% oracle_11905_o1 oracle [.] kgghash 0.40% oracle_11905_o1 oracle [.] qkexrXformOpn 0.39% oracle_11905_o1 oracle [.] __intel_ssse3_rep_memcpy 0.39% oracle_11905_o1 [kernel.kallsyms] [k] __do_softirq 0.38% oracle_11905_o1 oracle [.] qksceGetParam 0.29% oracle_11905_o1 libc-2.12.so [.] __strncpy_ssse3 0.28% oracle_11905_o1 oracle [.] kghalp 0.27% oracle_11905_o1 oracle [.] kqrpre1 0.26% oracle_11905_o1 oracle [.] kghalo 0.25% oracle_11905_o1 oracle [.] opitca 0.23% oracle_11905_o1 oracle [.] xplMakeNode 0.22% oracle_11905_o1 oracle [.] kghfnd_in_free_lists 0.22% oracle_11905_o1 oracle [.] kghfrmrg 0.20% oracle_11905_o1 oracle [.] xplCompact 0.19% oracle_11905_o1 oracle [.] kghprmalo 0.18% oracle_11905_o1 oracle [.] kggmsHash16 0.18% oracle_11905_o1 oracle [.] kksmal 0.17% oracle_11905_o1 oracle [.] kghfrf 0.17% oracle_11905_o1 oracle [.] qkshtQBInf0 0.17% oracle_11905_o1 oracle [.] qolHintCompact 0.17% oracle_11905_o1 oracle [.] qksxaBuildXml 0.16% oracle_11905_o1 oracle [.] kksCompileHeapStats 0.16% oracle_11905_o1 oracle [.] xplGenXpl 0.16% oracle_11905_o1 oracle [.] qkshtStmtInf0 0.15% oracle_11905_o1 oracle [.] kghbshrt 0.14% oracle_11905_o1 oracle [.] _intel_fast_memcmp 0.13% oracle_11905_o1 oracle [.] kksRuntimeHeapStats 0.13% oracle_11905_o1 oracle [.] kspges 0.13% oracle_11905_o1 oracle [.] qksxaGetSingleAnnotation 0.13% oracle_11905_o1 oracle [.] kggsmAddString 0.13% oracle_11905_o1 oracle [.] kghfre 0.12% oracle_11905_o1 oracle [.] qkadrv2Post 0.12% oracle_11905_o1 oracle [.] kkeCostToTime 0.12% oracle_11905_o1 oracle [.] kspgzp

Oracle 11.2.0.1

ANSI 1		ANSI 2		Old Oracle
#!/usr/bin/ksh # time for (( i=0; i<10000; i++ )) do cat <<eof SELECT /* Unique comment $i / count() FROM scott.emp e JOIN scott.dept d USING (deptno); eof done \|sqlplus -s rik/rik@ora11 exit 0		#!/usr/bin/ksh # time for (( i=0; i<10000; i++ )) do cat <<eof SELECT /* Unique comment $i / count() FROM scott.emp e JOIN scott.dept d ON d.deptno = e.deptno; eof done \|sqlplus -s rik/rik@ora11 exit 0		#!/usr/bin/ksh # time for (( i=0; i<10000; i++ )) do cat <<eof SELECT /* Unique comment $i / count() FROM scott.emp e, scott.dept d WHERE e.deptno = d.deptno; eof done \|sqlplus -s rik/rik@ora11 exit 0
Run 1 Timings	Run 2 Timings	Run 1 Timings	Run 2 Timings	Run 1 Timings	Run 2 Timings
real 0m15.69s user 0m3.31s sys 0m7.00s	real 0m14.80s user 0m3.27s sys 0m6.90s	real 0m15.71s user 0m3.26s sys 0m7.08s	real 0m14.46s user 0m3.14s sys 0m6.93s	real 0m15.17s user 0m3.28s sys 0m7.09s	real 0m14.88s user 0m3.36s sys 0m7.25s
Samples: 28K of event 'cpu-clock', Event count (approx.): 7017500000 74.54% oracle [vsyscall] [.] 0x000000000000014c 13.22% oracle [kernel.kallsyms] [k] _spin_unlock_irqrestore 2.62% oracle [kernel.kallsyms] [k] pcnet32_wio_read_csr 1.25% oracle [kernel.kallsyms] [k] pcnet32_wio_write_csr 0.41% oracle oracle [.] qksbgGetAltered 0.36% oracle oracle [.] qksbgGetVal 0.27% oracle oracle [.] kghalf 0.20% oracle [kernel.kallsyms] [k] __do_softirq 0.19% oracle oracle [.] kgghteGetEle 0.19% oracle oracle [.] qksceGenOutlineOptParamHints 0.18% oracle oracle [.] __intel_new_memset 0.18% oracle oracle [.] kksCheckToFreeCursorStat 0.12% oracle oracle [.] kgghash 0.11% oracle oracle [.] kghalp 0.10% oracle oracle [.] qksceGetParam 0.10% oracle oracle [.] qolGenTransformHints 0.09% oracle oracle [.] audTransFro 0.09% oracle oracle [.] opitca 0.09% oracle oracle [.] kspgzp 0.07% oracle libc-2.12.so [.] __strncpy_ssse3 0.07% oracle oracle [.] kghfnd 0.06% oracle oracle [.] qksxaBuildXml 0.06% oracle oracle [.] qcplgte_multibyte 0.05% oracle oracle [.] __intel_new_memcpy 0.05% oracle oracle [.] kggsmInitCompact 0.05% oracle oracle [.] kslfre 0.04% oracle oracle [.] kksEndOfCompile 0.04% oracle oracle [.] xplComputeRowHash 0.04% oracle libc-2.12.so [.] _setjmp 0.04% oracle oracle [.] kghbshrt 0.04% oracle oracle [.] kghssgai 0.04% oracle oracle [.] qksxaGetSingleAnnotation 0.04% oracle oracle [.] kggecAlloc 0.04% oracle oracle [.] kghssc_putcbn 0.04% oracle oracle [.] kqrpre1 0.04% oracle oracle [.] qertbIAllocate 0.04% oracle oracle [.] qkshtTokenToEnum 0.04% oracle oracle [.] qkssmAddString 0.04% oracle oracle [.] xplMakeNode 0.03% oracle libc-2.12.so [.] __gettimeofday 0.03% oracle oracle [.] _intel_fast_memcmp 0.03% oracle oracle [.] audpre 0.03% oracle oracle [.] kghaddex 0.03% oracle oracle [.] kslgetl		Samples: 29K of event 'cpu-clock', Event count (approx.): 7283250000 74.60% oracle [vsyscall] [.] 0x000000000000014c 13.39% oracle [kernel.kallsyms] [k] _spin_unlock_irqrestore 2.53% oracle [kernel.kallsyms] [k] pcnet32_wio_read_csr 1.28% oracle [kernel.kallsyms] [k] pcnet32_wio_write_csr 0.41% oracle oracle [.] qksbgGetVal 0.35% oracle oracle [.] kghalf 0.32% oracle oracle [.] qksbgGetAltered 0.30% oracle [kernel.kallsyms] [k] __do_softirq 0.21% oracle oracle [.] qksceGenOutlineOptParamHints 0.18% oracle oracle [.] __intel_new_memset 0.17% oracle oracle [.] kgghteGetEle 0.16% oracle oracle [.] kksCheckToFreeCursorStat 0.13% oracle oracle [.] opitca 0.12% oracle oracle [.] kgghash 0.10% oracle oracle [.] __intel_new_memcpy 0.09% oracle oracle [.] kghfnd 0.08% oracle oracle [.] audTransFro 0.08% oracle oracle [.] kggsmInitCompact 0.08% oracle oracle [.] qksceGetParam 0.07% oracle libc-2.12.so [.] __strncpy_ssse3 0.06% oracle oracle [.] kspgzp 0.06% oracle oracle [.] qolGenTransformHints 0.06% oracle oracle [.] kspges 0.06% oracle oracle [.] qksxaBuildXml 0.05% oracle [vdso] [.] __vdso_gettimeofday 0.05% oracle oracle [.] _intel_fast_memcmp 0.05% oracle oracle [.] kghalp 0.05% oracle oracle [.] kksmal 0.05% oracle oracle [.] qkshtTokenToEnum 0.05% oracle oracle [.] kghsupmm 0.04% oracle oracle [.] kksCompileHeapStats 0.04% oracle oracle [.] qolunl 0.04% oracle oracle [.] xplCompact 0.04% oracle oracle [.] xplRowHash 0.03% oracle oracle [.] appget 0.03% oracle oracle [.] kggecAlloc 0.03% oracle oracle [.] kkopmPlanBaselineCheck2 0.03% oracle oracle [.] kmgs_is_parval_set 0.03% oracle oracle [.] qcplgte_multibyte 0.03% oracle oracle [.] qkaTraverseQknDescendents 0.03% oracle oracle [.] qkexrXformOpn 0.03% oracle oracle [.] xplMakeNode 0.03% oracle oracle [.] kgwsclr 0.03% oracle oracle [.] __PGOSF221_kggmsHash16		Samples: 28K of event 'cpu-clock', Event count (approx.): 7084500000 78.09% oracle [vsyscall] [.] 0x000000000000014c 13.52% oracle [kernel.kallsyms] [k] _spin_unlock_irqrestore 2.83% oracle [kernel.kallsyms] [k] pcnet32_wio_read_csr 1.25% oracle [kernel.kallsyms] [k] pcnet32_wio_write_csr 0.23% oracle [kernel.kallsyms] [k] __do_softirq 0.17% oracle oracle [.] qksbgGetVal 0.15% oracle oracle [.] qksbgGetAltered 0.14% oracle oracle [.] kksCheckToFreeCursorStat 0.12% oracle oracle [.] kghalf 0.09% oracle oracle [.] qksceGenOutlineOptParamHints 0.06% oracle oracle [.] __intel_new_memcpy 0.06% oracle oracle [.] __intel_new_memset 0.06% oracle oracle [.] kgghteGetEle 0.05% oracle oracle [.] kgghash 0.04% oracle libc-2.12.so [.] __strncpy_ssse3 0.04% oracle oracle [.] opitca 0.04% oracle oracle [.] qkshtTokenToEnum 0.04% oracle oracle [.] kghalp 0.04% oracle oracle [.] kghfnd 0.04% oracle oracle [.] kspgzp 0.03% oracle oracle [.] kqrpre1 0.03% oracle oracle [.] kslgetl 0.03% oracle oracle [.] qcplgte_multibyte 0.03% oracle [vdso] [.] __vdso_gettimeofday 0.02% oracle oracle [.] audTransFro 0.02% oracle oracle [.] kghssc_putcbn 0.02% oracle oracle [.] kkopmPlanBaselineCheck2 0.02% oracle oracle [.] kxsSsaUpdateAllssa 0.02% oracle oracle [.] qksceGetParam 0.02% oracle oracle [.] xplMakeNode 0.02% oracle oracle [.] _intel_fast_memcmp 0.02% oracle oracle [.] kghalo 0.02% oracle oracle [.] kghgex 0.02% oracle oracle [.] kghupr_flg 0.02% oracle oracle [.] kksBindFrameListCheck 0.02% oracle [kernel.kallsyms] [k] hrtimer_peek_ahead_timers 0.02% oracle oracle [.] kghfre 0.02% oracle oracle [.] kksfbc 0.02% oracle oracle [.] kksmal 0.02% oracle oracle [.] kslfre 0.02% oracle oracle [.] ksmcat 0.02% oracle oracle [.] opiosq0 0.02% oracle oracle [.] qkaMarkQkn 0.02% oracle oracle [.] qkexrXformOpn

Profile without parsing

For reference, the profile for the same statement without the parsing (running exactly the same statement 10,000 time) is shown below

Oracle 12.1.0.2 Oracle 11.2.0.1

real 0m8.79s user 0m3.41s sys 0m7.25s

real 0m8.71s user 0m3.40s sys 0m7.37s

Samples: 8K of event 'cpu-clock', Event count (approx.): 2074500000 62.98% oracle_2679_o12 [vsyscall] [.] 0x000000000000014c 27.49% oracle_2679_o12 [kernel.kallsyms] [k] _spin_unlock_irqrestore 4.83% oracle_2679_o12 [kernel.kallsyms] [k] pcnet32_wio_read_csr 2.53% oracle_2679_o12 [kernel.kallsyms] [k] pcnet32_wio_write_csr 0.08% oracle_2679_o12 [kernel.kallsyms] [k] __do_softirq 0.08% oracle_2679_o12 [kernel.kallsyms] [k] finish_task_switch 0.07% oracle_2679_o12 oracle [.] __intel_ssse3_rep_memcpy 0.06% oracle_2679_o12 oracle [.] __intel_new_memset 0.05% oracle_2679_o12 [kernel.kallsyms] [k] tcp_packet 0.05% oracle_2679_o12 oracle [.] kcbgtcr 0.05% oracle_2679_o12 oracle [.] kksfbc 0.05% oracle_2679_o12 oracle [.] ksupucg 0.04% oracle_2679_o12 [vdso] [.] __vdso_clock_gettime 0.04% oracle_2679_o12 oracle [.] kghalo 0.04% oracle_2679_o12 oracle [.] kghfrf 0.04% oracle_2679_o12 oracle [.] kgscCacheCursor 0.04% oracle_2679_o12 oracle [.] opidsa 0.04% oracle_2679_o12 oracle [.] ttcpip 0.02% oracle_2679_o12 [kernel.kallsyms] [k] sock_update_classid 0.02% oracle_2679_o12 [kernel.kallsyms] [k] unmap_vmas 0.02% oracle_2679_o12 libpthread-2.12.so [.] __read_nocancel 0.02% oracle_2679_o12 oracle [.] kdstf11001010000100km 0.02% oracle_2679_o12 oracle [.] kdsttgr 0.02% oracle_2679_o12 oracle [.] kghfre 0.02% oracle_2679_o12 oracle [.] kghfrempty 0.02% oracle_2679_o12 oracle [.] kghprmalo 0.02% oracle_2679_o12 oracle [.] kksMapCursor

Samples: 10K of event 'cpu-clock', Event count (approx.): 2620500000 62.60% oracle [vsyscall] [.] 0x000000000000014c 27.86% oracle [kernel.kallsyms] [k] _spin_unlock_irqrestore 5.19% oracle [kernel.kallsyms] [k] pcnet32_wio_read_csr 2.89% oracle [kernel.kallsyms] [k] pcnet32_wio_write_csr 0.08% oracle [kernel.kallsyms] [k] __do_softirq 0.06% oracle [kernel.kallsyms] [k] finish_task_switch 0.06% oracle oracle [.] kcbgtcr 0.04% oracle oracle [.] kpoal8 0.03% oracle oracle [.] kslwt_update_stats_int 0.03% oracle oracle [.] ksupucg 0.03% oracle oracle [.] kxsGetRuntimeLock 0.03% oracle oracle [.] qksbgGetVal 0.02% oracle [kernel.kallsyms] [k] __audit_syscall_exit 0.02% oracle [kernel.kallsyms] [k] local_bh_enable 0.02% oracle [kernel.kallsyms] [k] sock_common_recvmsg 0.02% oracle [kernel.kallsyms] [k] system_call_after_swapgs 0.02% oracle [vsyscall] [.] 0x000000000000014e 0.02% oracle oracle [.] kcf_afn_to_fob 0.02% oracle oracle [.] kghfrempty 0.02% oracle oracle [.] kghualloc 0.02% oracle oracle [.] kghupr_flg 0.02% oracle oracle [.] kksSessionCache 0.02% oracle oracle [.] kpofcr 0.02% oracle oracle [.] kpuhhalp 0.02% oracle oracle [.] nsbasic_brc 0.02% oracle oracle [.] opiodr 0.01% oracle [kernel.kallsyms] [k] __alloc_skb

Oracle 12.1.0.2	Oracle 11.2.0.1
real 0m8.79s user 0m3.41s sys 0m7.25s	real 0m8.71s user 0m3.40s sys 0m7.37s
Samples: 8K of event 'cpu-clock', Event count (approx.): 2074500000 62.98% oracle_2679_o12 [vsyscall] [.] 0x000000000000014c 27.49% oracle_2679_o12 [kernel.kallsyms] [k] _spin_unlock_irqrestore 4.83% oracle_2679_o12 [kernel.kallsyms] [k] pcnet32_wio_read_csr 2.53% oracle_2679_o12 [kernel.kallsyms] [k] pcnet32_wio_write_csr 0.08% oracle_2679_o12 [kernel.kallsyms] [k] __do_softirq 0.08% oracle_2679_o12 [kernel.kallsyms] [k] finish_task_switch 0.07% oracle_2679_o12 oracle [.] __intel_ssse3_rep_memcpy 0.06% oracle_2679_o12 oracle [.] __intel_new_memset 0.05% oracle_2679_o12 [kernel.kallsyms] [k] tcp_packet 0.05% oracle_2679_o12 oracle [.] kcbgtcr 0.05% oracle_2679_o12 oracle [.] kksfbc 0.05% oracle_2679_o12 oracle [.] ksupucg 0.04% oracle_2679_o12 [vdso] [.] __vdso_clock_gettime 0.04% oracle_2679_o12 oracle [.] kghalo 0.04% oracle_2679_o12 oracle [.] kghfrf 0.04% oracle_2679_o12 oracle [.] kgscCacheCursor 0.04% oracle_2679_o12 oracle [.] opidsa 0.04% oracle_2679_o12 oracle [.] ttcpip 0.02% oracle_2679_o12 [kernel.kallsyms] [k] sock_update_classid 0.02% oracle_2679_o12 [kernel.kallsyms] [k] unmap_vmas 0.02% oracle_2679_o12 libpthread-2.12.so [.] __read_nocancel 0.02% oracle_2679_o12 oracle [.] kdstf11001010000100km 0.02% oracle_2679_o12 oracle [.] kdsttgr 0.02% oracle_2679_o12 oracle [.] kghfre 0.02% oracle_2679_o12 oracle [.] kghfrempty 0.02% oracle_2679_o12 oracle [.] kghprmalo 0.02% oracle_2679_o12 oracle [.] kksMapCursor	Samples: 10K of event 'cpu-clock', Event count (approx.): 2620500000 62.60% oracle [vsyscall] [.] 0x000000000000014c 27.86% oracle [kernel.kallsyms] [k] _spin_unlock_irqrestore 5.19% oracle [kernel.kallsyms] [k] pcnet32_wio_read_csr 2.89% oracle [kernel.kallsyms] [k] pcnet32_wio_write_csr 0.08% oracle [kernel.kallsyms] [k] __do_softirq 0.06% oracle [kernel.kallsyms] [k] finish_task_switch 0.06% oracle oracle [.] kcbgtcr 0.04% oracle oracle [.] kpoal8 0.03% oracle oracle [.] kslwt_update_stats_int 0.03% oracle oracle [.] ksupucg 0.03% oracle oracle [.] kxsGetRuntimeLock 0.03% oracle oracle [.] qksbgGetVal 0.02% oracle [kernel.kallsyms] [k] __audit_syscall_exit 0.02% oracle [kernel.kallsyms] [k] local_bh_enable 0.02% oracle [kernel.kallsyms] [k] sock_common_recvmsg 0.02% oracle [kernel.kallsyms] [k] system_call_after_swapgs 0.02% oracle [vsyscall] [.] 0x000000000000014e 0.02% oracle oracle [.] kcf_afn_to_fob 0.02% oracle oracle [.] kghfrempty 0.02% oracle oracle [.] kghualloc 0.02% oracle oracle [.] kghupr_flg 0.02% oracle oracle [.] kksSessionCache 0.02% oracle oracle [.] kpofcr 0.02% oracle oracle [.] kpuhhalp 0.02% oracle oracle [.] nsbasic_brc 0.02% oracle oracle [.] opiodr 0.01% oracle [kernel.kallsyms] [k] __alloc_skb

Other Comments

Curiously, in the 10053 trace (version 12.1.0.2), all three queires had the same plan hashes, but the outline data for the two ANSI queries had three extra lines relative to the one "Old Oracle" query.