Well it has been a month since my last blog post, so I think it’s time to write something 🙂
Those context switches can be a real pain in the ass – there is a great article by Frits Hoogland about context switching from SQL to PL/SQL – you can read it here:
https://fritshoogland.wordpress.com/2016/01/23/plsql-context-switch/
You should also read a great blog post by Martin Widlake: Pragma UDF – Some Current Limitations
https://mwidlake.wordpress.com/2015/11/11/pragma-udf-some-current-limitations/
I also wrote a few words about reducing context switching with PRAGMA UDF:
https://blog.ora-600.pl/2015/10/29/oracle-12c-pragma-udf-the-truth/
To sum up – since there is no wait event for context switch, you can use for example perf, to verify if the function "plsql_run" has a lot of executions on your system, which can indicate that you have the context switching problem.
But this method can be used only to reveal problems with PL/SQL functions being called from SQL.
In a lots of cases there is a problem with developers not using BUlK COLLECT syntax. From Oracle 10g onwards, there is a performance feature in PL/SQL that transforms regular cursor loops to BULK COLLECTs.
Let’s check the fetch size of this optimization – the function responsible for fetching the row is called opifch2.
How do we know that? Well, one of my favourite examples of showing the context switching (or fetching) problem is comparing the execution times of those two anonymous blocks:
SQL> declare 2 x number; 3 begin 4 for i in 1..1000000 loop 5 select 1 into x from dual; 6 end loop; 7 end; 8 / PL/SQL procedure successfully completed. Elapsed: 00:00:20.08 SQL> ed Wrote file afiedt.buf 1 declare 2 x number; 3 begin 4 for i in 1..1000000 loop 5 x:=1; 6 end loop; 7* end; SQL> / PL/SQL procedure successfully completed. Elapsed: 00:00:00.01
With perf we can see the top function calls while executing the first anonymous block:
# Overhead Command Shared Object Symbol
# ........ ............... ................. ..................................
#
20.51% oracle_3902_orc [vdso] [.] 0x0000000000000bb0
3.28% oracle_3902_orc oracle [.] opiexe
2.46% oracle_3902_orc [kernel.kallsyms] [k] __audit_syscall_entry
2.21% oracle_3902_orc [kernel.kallsyms] [k] system_call_after_swapgs
1.83% oracle_3902_orc oracle [.] opifch2
The function opiexe is responsible for executing some stuff – in this example: the select statement for 1 000 000 times.
The opifch2 is the function which we will be examining, since this is the function responsible for fetching.
After some investigation, I’ve noticed that the number of rows fetched by this function is stored in RCX registry – let’s try to prove it 🙂
I will use a simple "bulk collect limit" syntax to change the number of rows being fetched. To display the RCX value I will use GDB with breakpoint at opifch2 function.
Preparing GDB session:
- get SPID info about your session:
SQL> get myspid
1 select spid
2 from v$session s, v$process p
3 where s.paddr=p.addr
4* and s.sid=sys_context('userenv','sid')
SQL> /
SPID
------------------------
5543
- start GDB and prepare a breakpoint:
[root@rico ~]# gdb -p 5543 (gdb) b opifch2 Breakpoint 1 at 0xcb0acb0 (gdb) command 1 Type commands for breakpoint(s) 1, one per line. End with a line saying just "end". >p/d $rcx >c >end (gdb) set pagination off (gdb) c Continuing.
Now we will execute anonymous PL/SQL block and check our RCX value for LIMIT 25, 59, 123
- LIMIT 25
PL/SQL block:
SQL> ; 1 declare 2 cursor c_sql is 3 select salary from employees; 4 type t_sql is table of c_sql%ROWTYPE index by pls_integer; 5 v_sql t_sql; 6 v_x number; 7 begin 8 open c_sql; 9 loop 10 fetch c_sql bulk collect into v_sql limit 25; 11 exit when c_sql%NOTFOUND; 12 for i in v_sql.first..v_sql.last loop 13 v_x:=v_x+v_sql(i).salary; 14 end loop; 15 end loop; 16 close c_sql; 17* end; SQL> /
GDB:
Breakpoint 1, 0x000000000cb0acb0 in opifch2 () $1 = 140159623635016 Breakpoint 1, 0x000000000cb0acb0 in opifch2 () $2 = 25 Breakpoint 1, 0x000000000cb0acb0 in opifch2 () $3 = 25 Breakpoint 1, 0x000000000cb0acb0 in opifch2 () $4 = 25 Breakpoint 1, 0x000000000cb0acb0 in opifch2 () $5 = 25 Breakpoint 1, 0x000000000cb0acb0 in opifch2 () $6 = 25
- LIMIT 59
PL/SQL block:
SQL> ed Wrote file afiedt.buf 1 declare 2 cursor c_sql is 3 select salary from employees; 4 type t_sql is table of c_sql%ROWTYPE index by pls_integer; 5 v_sql t_sql; 6 v_x number; 7 begin 8 open c_sql; 9 loop 10 fetch c_sql bulk collect into v_sql limit 59; 11 exit when c_sql%NOTFOUND; 12 for i in v_sql.first..v_sql.last loop 13 v_x:=v_x+v_sql(i).salary; 14 end loop; 15 end loop; 16 close c_sql; 17* end; SQL> / PL/SQL procedure successfully completed.
GDB:
Breakpoint 1, 0x000000000cb0acb0 in opifch2 () $7 = 59 Breakpoint 1, 0x000000000cb0acb0 in opifch2 () $8 = 59
- LIMIT 123
PL/SQL block:
SQL> ed Wrote file afiedt.buf 1 declare 2 cursor c_sql is 3 select salary from employees; 4 type t_sql is table of c_sql%ROWTYPE index by pls_integer; 5 v_sql t_sql; 6 v_x number; 7 begin 8 open c_sql; 9 loop 10 fetch c_sql bulk collect into v_sql limit 123; 11 exit when c_sql%NOTFOUND; 12 for i in v_sql.first..v_sql.last loop 13 v_x:=v_x+v_sql(i).salary; 14 end loop; 15 end loop; 16 close c_sql; 17* end; SQL> / PL/SQL procedure successfully completed.
GDB:
Breakpoint 1, 0x000000000cb0acb0 in opifch2 () $9 = 123
Great! So now we have proved, that the number of rows fetched by opifch2 is stored at RCX.
Now we can check how many rows are being fetched by standard cursor loop optimization:
PL/SQL block:
SQL> ; 1 declare 2 cursor c_sql is 3 select salary from employees; 4 type t_sql is table of c_sql%ROWTYPE index by pls_integer; 5 v_sql t_sql; 6 v_x number; 7 begin 8 for i in c_sql loop 9 v_x:=v_x+i.salary ; 10 end loop; 11* end; SQL> / PL/SQL procedure successfully completed.
GDB:
Breakpoint 1, 0x000000000cb0acb0 in opifch2 () $10 = 100 Breakpoint 1, 0x000000000cb0acb0 in opifch2 () $11 = 100
I made tests for different table sizes and each time it was exactly 100 rows – so this is fixed value and it doesn’t depend on statistics.
I think that main problem is, that you can’t figure it out based on regular wait events or statistics (or at least I don’t know any).
If you check active sessions with a lot of cursor loops being executed on big tables, you will see something like this:
Oracle 12c - orc 19:49:45 up: 6.4h, 1 ins, 2 sn, 1 us, 2.1G mt, 66.0% db ID %CPU LOAD %DCU AAS ASC ASI ASW AST IOPS %FR PGA UTPS UCPS SSRT %DBT 1 16 0 15 0.7 1 1 0 1 5 7 82M 0 2 41u 100 EVENT (RT) TOT WAITS TIME(s) AVG_MS PCT WAIT_CLASS DB CPU 7 100 direct path read 37 0 0 0 User I/O ID SID SPID USR PROG S PGA SQLID/BLOCKER OPN E/T STA STE EVENT/*LA W/T 1 48 5543 HR sqlp D 3.1M 6ucj0mtv5bf9b SEL 18s ACT CPU direct pa 3m Enter sql_id: 6ucj0mtv5bf9b PLAN_TABLE_OUTPUT ------------------------------------------------------------------------------ SQL_ID: 6ucj0mtv5bf9b, child number 0 -------------------------------------------------- SELECT AMOUNT_SOLD FROM SH.SALES2 Plan hash value: 497282378 ------------------------------------------------------------------------------ | Id | Operation | Name | Rows | Cost | Stale | ------------------------------------------------------------------------------ | 0 | SELECT STATEMENT | | | 13k | | | 1 | TABLE ACCESS FULL | SALES2 | 10M | 13k | YES | ------------------------------------------------------------------------------
Fortunately you can use operating system tools like perf – you should check out this amazing article by Luca Canali about Linux Perf Probes for Oracle Tracing: http://externaltable.blogspot.com/2016/02/linux-perf-probes-for-oracle-tracing.html
Based on Luca’s findings we can create a perf probe for opifch2 function and check out fetch size for all server processes on our operating system:
[root@rico ~]# perf probe -x /u01/app/oracle/product/12.1.0/dbhome_1/bin/oracle opifch2 fetchsize=%cx Added new event: probe_oracle:opifch2 (on 0xc70acb0 with fetchsize=%cx) You can now use it in all perf tools, such as: perf record -e probe_oracle:opifch2 -aR sleep 1 [root@rico ~]# perf record -e probe_oracle:opifch2 -aR ^C[ perf record: Woken up 149 times to write data ] [ perf record: Captured and wrote 37.395 MB perf.data (~1633825 samples) ] [root@rico ~]# perf script > opifch2.out
After recording events for some time we can process the output with a very simple AWK oneliner:
[root@rico ~]# awk '/oracle_/ {fsize=strtonum("0x"substr($NF,11));fsize_tab[$1 " was "fsize]++} END {for(fs in fsize_tab) {print "Fetchsize for " fs " (executed " fsize_tab[fs] " times)"}}' opifch2.out | sort -n -k7
Fetchsize for oracle_5857_orc was 2 (executed 1 times)
Fetchsize for oracle_5857_orc was 2147483647 (executed 1 times)
Fetchsize for oracle_5857_orc was 100 (executed 2 times)
Fetchsize for oracle_5857_orc was 140171241660488 (executed 2 times)
Fetchsize for oracle_5857_orc was 1 (executed 4 times)
Fetchsize for oracle_5857_orc was 227183808 (executed 4 times)
Fetchsize for oracle_5857_orc was 25 (executed 5 times)
Fetchsize for oracle_5755_orc was 2 (executed 22 times)
Fetchsize for oracle_5755_orc was 140058172228192 (executed 36 times)
Fetchsize for oracle_5543_orc was 100 (executed 441045 times)
The high number of executions for fetchsize 100 suggests that your system is using a lot of cursor loops with auto optimization – but without actual BULK COLLECT syntax.
Please notice, that this method can reveal also wrong fetch sizes from any other client – like JDBC or .NET.