Beware of Hidden PLSQL to SQL Context Switches
Let's take a look at a query that was being run way too often and see why this was unnecessary.
Join the DZone community and get the full member experience.Join For Free
I recently stumbled upon a curious query on a customer's productive Oracle database:
SELECT USER FROM SYS.DUAL
Two things caught my attention:
- The query was executed many billions of times per month, accounting for about 0.3% of that system's load. That's 0.3% for something extremely silly!
- I don't think that customer would ever qualify the
SYS.DUAL, which hints at some system functionality
I found it in Oracle Enterprise Manager, but you could also find it using a query like this one:
SELECT sql_id, executions, elapsed_time, ratio_to_report(elapsed_time) over() p, sql_text FROM v$sql ORDER BY p DESC;
Why was this query being run so often? In Enterprise Manager, the query's statistics overview displayed that the query originated from a function called
STANDARD.USER (I don't know yet where I could find this information in the dictionary views, manually).
Naively, I had always thought that the
USER pseudo column or pseudo constant is some value from the context, but like many other functions, it's really just a function in that package.
What Does STANDARD.USER() do?
Now, I'm not 100% sure if that source code is something that I am allowed to reproduce from a legal perspective, this being Oracle and all. But if you run this query here, which I am freely allowing you to:
WITH s AS ( SELECT s.*, MIN(CASE WHEN upper(text) LIKE '%FUNCTION USER%' THEN line END ) OVER () s FROM all_source s WHERE owner = 'SYS' AND name = 'STANDARD' AND type = 'PACKAGE BODY' ) SELECT text FROM s WHERE line >= s AND line < s + 6;
Then you might be able to see something like this:
function USER return varchar2 is c varchar2(255); begin select user into c from sys.dual; return c; end;
This is just the result of some SQL query I've shown you. Any correspondence with actual source code is merely coincidental.
Let's assume this was the actual source code of the
STANDARD.USER() function. We can now clearly see that this very SQL query that I've observed before is being executed! Want to verify this?
In essence, I'm comparing the performances of 500000 executions of this loop:
FOR i IN 1 .. v_repeat LOOP v := USER; END LOOP;
With this one:
FOR i IN 1 .. v_repeat LOOP SELECT USER INTO v FROM dual; END LOOP;
And this one:
FOR i IN 1 .. v_repeat LOOP v := sys_context('USERENV', 'CURRENT_USER'); END LOOP;
The result of this benchmark is:
Run 1, Statement 1 : 2.40509 (avg : 2.43158) Run 1, Statement 2 : 2.13208 (avg : 2.11816) Run 1, Statement 3 : 1.01452 (avg : 1.02081) Run 2, Statement 1 : 2.41889 (avg : 2.43158) Run 2, Statement 2 : 2.09753 (avg : 2.11816) Run 2, Statement 3 : 1.00203 (avg : 1.02081) Run 3, Statement 1 : 2.45384 (avg : 2.43158) Run 3, Statement 2 : 2.09060 (avg : 2.11816) Run 3, Statement 3 : 1.02239 (avg : 1.02081) Run 4, Statement 1 : 2.39516 (avg : 2.43158) Run 4, Statement 2 : 2.14140 (avg : 2.11816) Run 4, Statement 3 : 1.06512 (avg : 1.02081) Run 5, Statement 1 : 2.48493 (avg : 2.43158) Run 5, Statement 2 : 2.12922 (avg : 2.11816) Run 5, Statement 3 : 1.00000 (avg : 1.02081)
How to read this benchmark result? These aren't actual times, which are not interesting, but relative times compared to the fastest run (run 5, statement 3 = 1). The explicit
SELECT USER FROM DUAL is about half as fast as the
SYS_CONTEXT call, and the
USER call is a bit slower, even.
When re-running this query:
SELECT sql_id, executions, ratio_to_report(elapsed_time) over() p, sql_text FROM v$sql ORDER BY p DESC;
We can see:
SQL_ID EXECUTIONS P SQL_TEXT 6r9s58qfu339c 1 0.26 DECLARE ... 1v717nvrhgbn9 2500000 0.14 SELECT USER FROM SYS.DUAL ...
So, this query has definitely been run way too many times, including the PL/SQL to SQL context switch that is involved.
I'm running this benchmark in Oracle 18.104.22.168.0 in Docker on a Windows machine. More close-to-the-metal and less virtualized setups might achieve more drastic results. See, e.g. Connor McDonald got a much better improvement from using
In this particular case, the
STANDARD.USER() reference was used very often in triggers to fill in audit columns of many tables. Very easy to fix. Just use
sys_context('USERENV', 'CURRENT_USER') instead.
Full Benchmark Logic
SET SERVEROUTPUT ON ALTER SYSTEM FLUSH SHARED_POOL; ALTER SYSTEM FLUSH BUFFER_CACHE; CREATE TABLE results ( run NUMBER(2), stmt NUMBER(2), elapsed NUMBER ); DECLARE v_ts TIMESTAMP WITH TIME ZONE; v_repeat CONSTANT NUMBER := 500000; v NUMBER; BEGIN -- Repeat the whole benchmark several times to -- avoid warmup penalty FOR r IN 1..5 LOOP v_ts := SYSTIMESTAMP; FOR i IN 1 .. v_repeat LOOP v := v + length(USER); END LOOP; INSERT INTO results VALUES (r, 1, SYSDATE + ((SYSTIMESTAMP - v_ts) * 86400) - SYSDATE); v_ts := SYSTIMESTAMP; FOR i IN 1 .. v_repeat LOOP SELECT v + length(USER) INTO v FROM dual; END LOOP; INSERT INTO results VALUES (r, 2, SYSDATE + ((SYSTIMESTAMP - v_ts) * 86400) - SYSDATE); v_ts := SYSTIMESTAMP; FOR i IN 1 .. v_repeat LOOP v := v + length(sys_context('USERENV', 'CURRENT_USER')); END LOOP; INSERT INTO results VALUES (r, 3, SYSDATE + ((SYSTIMESTAMP - v_ts) * 86400) - SYSDATE); END LOOP; FOR rec IN ( SELECT run, stmt, CAST(elapsed / MIN(elapsed) OVER() AS NUMBER(10, 5)) ratio, CAST(AVG(elapsed) OVER (PARTITION BY stmt) / MIN(elapsed) OVER() AS NUMBER(10, 5)) avg_ratio FROM results ORDER BY run, stmt ) LOOP dbms_output.put_line('Run ' || rec.run || ', Statement ' || rec.stmt || ' : ' || rec.ratio || ' (avg : ' || rec.avg_ratio || ')'); END LOOP; dbms_output.put_line(''); dbms_output.put_line('Copyright Data Geekery GmbH'); dbms_output.put_line('https://www.jooq.org/benchmark'); END; / DROP TABLE results;
Thanks for reading, and let me know of any questions or thoughts in the comments section.
Published at DZone with permission of Lukas Eder, DZone MVB. See the original article here.
Opinions expressed by DZone contributors are their own.