23 November 2011

Explanation for Slow Performance of VARCHAR2 Overloading?

Valentin Nikotin, a PL/SQL Challenge player, recently brought to my attention some unexpectedly slow performance when executing from within a query an overloaded function that accepts a VARCHAR2 argument, compared to a NUMBER argument. I have been able to reproduce this (see below). I thought I'd see if any readers of this blog had an idea as to what might be the cause.

We both ran this code on an 11.2 instance.
CREATE OR REPLACE PACKAGE pkg_test
AS
   FUNCTION fv (i VARCHAR2)
      RETURN NUMBER;

   FUNCTION fn (i NUMBER)
      RETURN NUMBER;
END;
/

CREATE OR REPLACE PACKAGE BODY pkg_test
AS
   FUNCTION fv (i VARCHAR2)
      RETURN NUMBER
   IS
   BEGIN
      RETURN 1;
   END;

   FUNCTION fn (i NUMBER)
      RETURN NUMBER
   IS
   BEGIN
      RETURN 1;
   END;
END;
/

CREATE OR REPLACE FUNCTION fv (i VARCHAR2)
   RETURN NUMBER
IS
BEGIN
   RETURN 1;
END;
/

CREATE OR REPLACE FUNCTION fn (i NUMBER)
   RETURN NUMBER
IS
BEGIN
   RETURN 1;
END;
/

/* No difference in PL/SQL 

"VC2 overloading" completed in: 2.5 seconds
"Number overloading" completed in: 2.52 seconds
"Schema-level VC2" completed in: 2.48 seconds
"Schema-level Number" completed in: 2.49 seconds

*/

DECLARE
   l             NUMBER;
   last_timing   NUMBER := NULL;

   PROCEDURE start_timer
   IS
   BEGIN
      last_timing := DBMS_UTILITY.get_cpu_time;
   END;

   PROCEDURE show_elapsed_time (message_in IN VARCHAR2 := NULL)
   IS
   BEGIN
      DBMS_OUTPUT.put_line (
            '"'
         || message_in
         || '" completed in: '
         || (DBMS_UTILITY.get_cpu_time - last_timing) / 100
         || ' seconds');
   END;
BEGIN
   start_timer;

   FOR indx IN 1 .. 10000000
   LOOP
      l := pkg_test.fv (NULL);
   END LOOP;

   show_elapsed_time ('VC2 overloading');
   --
   start_timer;

   FOR indx IN 1 .. 10000000
   LOOP
      l := pkg_test.fn (NULL);
   END LOOP;

   show_elapsed_time ('Number overloading');
   --
   start_timer;

   FOR indx IN 1 .. 10000000
   LOOP
      l := fv (NULL);
   END LOOP;

   show_elapsed_time ('Schema-level VC2');
   --
   start_timer;

   FOR indx IN 1 .. 10000000
   LOOP
      l := fv (NULL);
   END LOOP;

   show_elapsed_time ('Schema-level Number');
END;
/

/* Noticeable difference in SQL 

MAX(PKG_TEST.FV(NULL))
----------------------
                     1
1 row selected.
Elapsed: 00:00:07.93

MAX(FV(NULL))
-------------
            1
1 row selected.
Elapsed: 00:00:05.03

MAX(PKG_TEST.FN(NULL))
----------------------
                     1
1 row selected.
Elapsed: 00:00:04.45

MAX(FN(NULL))
-------------
            1
1 row selected.
Elapsed: 00:00:05.45

*/

SET TIMING ON

CREATE TABLE driver_table
AS
       SELECT LEVEL id
         FROM DUAL
   CONNECT BY LEVEL < 1000000
/

SELECT MAX (pkg_test.fv (NULL)) FROM driver_table
/

SELECT MAX (fv (NULL)) FROM driver_table
/

SELECT MAX (pkg_test.fn (NULL)) FROM driver_table
/

SELECT MAX (fn (NULL)) FROM driver_table
/

DROP driver_table
/

DROP package pkg_test
/

DROP FUNCTION fn
/

DROP FUNCTION fv
/

7 comments:

  1. Well - first it looks to me like the last of your PL/SQL test calls fv(null) where it should have called fn(null)?

    (In principle I also object to the word "overloading" - you do not have two functions of the same name within the same package that the database needs to select solely based on input datatypes.)

    Anyway - I changed the PL/SQL test to do fn(null), and I also changed the order of execution to match the SQL test (to make it easier for me to compare ;-)

    (meant to have html pre tag here but I can't do that?)

    DECLARE
    l NUMBER;
    last_timing NUMBER := NULL;

    PROCEDURE start_timer
    IS
    BEGIN
    last_timing := DBMS_UTILITY.get_cpu_time;
    END;

    PROCEDURE show_elapsed_time (message_in IN VARCHAR2 := NULL)
    IS
    BEGIN
    DBMS_OUTPUT.put_line (
    '"'
    || message_in
    || '" completed in: '
    || (DBMS_UTILITY.get_cpu_time - last_timing) / 100
    || ' seconds');
    END;
    BEGIN
    start_timer;

    FOR indx IN 1 .. 10000000
    LOOP
    l := pkg_test.fv (NULL);
    END LOOP;

    show_elapsed_time ('pkg_test.fv');
    --
    start_timer;

    FOR indx IN 1 .. 10000000
    LOOP
    l := fv (NULL);
    END LOOP;

    show_elapsed_time ('fv');
    --
    start_timer;

    FOR indx IN 1 .. 10000000
    LOOP
    l := pkg_test.fn (NULL);
    END LOOP;

    show_elapsed_time ('pkg_test.fn');
    --
    start_timer;

    FOR indx IN 1 .. 10000000
    LOOP
    l := fn (NULL);
    END LOOP;

    show_elapsed_time ('fn');
    END;
    /

    (end of pre)

    Then I ran both tests on my test instance: Oracle Database 11g Enterprise Edition Release 11.1.0.7.0 - 64bit Production.

    For the PL/SQL test (second run - my first run I forgot to set serveroutput on):

    "pkg_test.fv" completed in: 6,13 seconds
    "fv" completed in: 6,67 seconds
    "pkg_test.fn" completed in: 6,03 seconds
    "fn" completed in: 6,81 seconds

    Not much difference whether it was varchar or number. Packaged function consistently a little faster than schema-level function. I guess that shows nicely packages staying in the shared pool once instantiated?

    (SQL test I continue in the next post...)

    ReplyDelete
  2. (...Continued post:)

    The SQL test I also ran twice:

    First run:

    SQL> SELECT MAX (pkg_test.fv (NULL)) FROM driver_table
    2 /

    MAX(PKG_TEST.FV(NULL))
    ----------------------
    1

    Elapsed: 00:00:07.98
    SQL>
    SQL> SELECT MAX (fv (NULL)) FROM driver_table
    2 /

    MAX(FV(NULL))
    -------------
    1

    Elapsed: 00:00:06.00
    SQL>
    SQL> SELECT MAX (pkg_test.fn (NULL)) FROM driver_table
    2 /

    MAX(PKG_TEST.FN(NULL))
    ----------------------
    1

    Elapsed: 00:00:04.46
    SQL>
    SQL> SELECT MAX (fn (NULL)) FROM driver_table
    2 /

    MAX(FN(NULL))
    -------------
    1

    Elapsed: 00:00:04.50


    Second run (with the driver table "warmed up"):

    SQL> SELECT MAX (pkg_test.fv (NULL)) FROM driver_table
    2 /

    MAX(PKG_TEST.FV(NULL))
    ----------------------
    1

    Elapsed: 00:00:06.76
    SQL>
    SQL> SELECT MAX (fv (NULL)) FROM driver_table
    2 /

    MAX(FV(NULL))
    -------------
    1

    Elapsed: 00:00:05.98
    SQL>
    SQL> SELECT MAX (pkg_test.fn (NULL)) FROM driver_table
    2 /

    MAX(PKG_TEST.FN(NULL))
    ----------------------
    1

    Elapsed: 00:00:04.34
    SQL>
    SQL> SELECT MAX (fn (NULL)) FROM driver_table
    2 /

    MAX(FN(NULL))
    -------------
    1

    Elapsed: 00:00:04.45


    For numbers same pattern - packaged function slightly faster than schema-level function.

    For varchar2s different - packaged function slower than schema-level function. That is the mysterious case?

    For both cases varchar2s are slower here than numbers. Perhaps that is the max() distorting the results?


    (Will continue in yet a third post...)

    ReplyDelete
  3. A test eliminating possible max() distortions:
    (Temoved explain plan from the output because of 4.096 character blogger limit.)


    SQL> SET AUTOTRACE TRACEONLY
    SQL>
    SQL> SELECT pkg_test.fv (NULL) FROM driver_table
    2 /

    999999 rows selected.

    Elapsed: 00:00:23.92

    Statistics
    ----------------------------------------------------------
    7 recursive calls
    0 db block gets
    68309 consistent gets
    0 physical reads
    0 redo size
    7062044 bytes sent via SQL*Net to client
    466914 bytes received via SQL*Net from client
    66668 SQL*Net roundtrips to/from client
    0 sorts (memory)
    0 sorts (disk)
    999999 rows processed

    SQL>
    SQL> SELECT fv (NULL) FROM driver_table
    2 /

    999999 rows selected.

    Elapsed: 00:00:22.60

    Statistics
    ----------------------------------------------------------
    7 recursive calls
    0 db block gets
    68309 consistent gets
    0 physical reads
    0 redo size
    7595560 bytes sent via SQL*Net to client
    466914 bytes received via SQL*Net from client
    66668 SQL*Net roundtrips to/from client
    0 sorts (memory)
    0 sorts (disk)
    999999 rows processed

    SQL>
    SQL> SELECT pkg_test.fn (NULL) FROM driver_table
    2 /

    999999 rows selected.

    Elapsed: 00:00:21.81

    Statistics
    ----------------------------------------------------------
    7 recursive calls
    0 db block gets
    68309 consistent gets
    0 physical reads
    0 redo size
    7595569 bytes sent via SQL*Net to client
    466914 bytes received via SQL*Net from client
    66668 SQL*Net roundtrips to/from client
    0 sorts (memory)
    0 sorts (disk)
    999999 rows processed

    SQL>
    SQL> SELECT fn (NULL) FROM driver_table
    2 /

    999999 rows selected.

    Elapsed: 00:00:21.17


    Statistics
    ----------------------------------------------------------
    7 recursive calls
    0 db block gets
    68309 consistent gets
    0 physical reads
    0 redo size
    7595560 bytes sent via SQL*Net to client
    466914 bytes received via SQL*Net from client
    66668 SQL*Net roundtrips to/from client
    0 sorts (memory)
    0 sorts (disk)
    999999 rows processed

    ---

    Timing results:
    pkg_test.fv - Elapsed: 00:00:23.92
    fv - Elapsed: 00:00:22.60
    pkg_test.fn - Elapsed: 00:00:21.81
    fn - Elapsed: 00:00:21.17

    And another interesting thing:

    pkg_test.fv:
    7062044 bytes sent via SQL*Net to client
    fv:
    7595560 bytes sent via SQL*Net to client

    ???

    Guess would have to do some more tracing... :-)
    Might be back with some new comment if I get the time to dig deeper...

    ReplyDelete
  4. I think this question is perfectly suited for Bryn.

    The only guess I can made is, that PL/SQL must somewhere allocate memory for the VARCHAR2 parameter and passes a pointer to it whereas the memory for the NUMER can directly be passed over the stack.

    ----------------------------------------------
    P.S.: by the way Steven, how was your visit with the PL/SQL development team at Oracle HQ? Anything you want (and can) share with us?

    ReplyDelete
  5. Hello All,

    I will also post my answer in several parts, because of the length problems.

    ( part 1 )

    I tried to reproduce your test in 11gR1 (11.1.0.7.0) and it was a little bit different:

    The PL/SQL results almost similar, with one slight difference:

    "VC2 overloading" completed in: 4.65 seconds
    "Number overloading" completed in: 3.81 seconds
    "Schema-level VC2" completed in: 4.64 seconds
    "Schema-level Number" completed in: 4.58 seconds

    But in SQL, I received similar times for the two FV functions, both of them much higher than the two FN functions:

    SQL>SELECT MAX (pkg_test.fv (NULL)) FROM driver_table
    2 /

    MAX(PKG_TEST.FV(NULL))
    ----------------------
    1

    1 row selected.

    Elapsed: 00:00:07.07

    SQL>SELECT MAX (fv (NULL)) FROM driver_table
    2 /

    MAX(FV(NULL))
    -------------
    1

    1 row selected.

    Elapsed: 00:00:07.00

    SQL>SELECT MAX (pkg_test.fn (NULL)) FROM driver_table
    2 /

    MAX(PKG_TEST.FN(NULL))
    ----------------------
    1

    1 row selected.

    Elapsed: 00:00:04.02

    SQL>SELECT MAX (fn (NULL)) FROM driver_table
    2 /

    MAX(FN(NULL))
    -------------
    1

    1 row selected.

    Elapsed: 00:00:04.03


    If I perform an explicit conversion of a NULL to a CHAR, then I receive the following:

    SQL>SELECT MAX (pkg_test.fv( TO_CHAR(NULL) )) FROM driver_table
    2 /

    MAX(PKG_TEST.FV(TO_CHAR(NULL)))
    -------------------------------
    1

    1 row selected.

    Elapsed: 00:00:04.04


    SQL>SELECT MAX (fv( TO_CHAR(NULL) )) FROM driver_table
    2 /

    MAX(FV(TO_CHAR(NULL)))
    ----------------------
    1

    1 row selected.

    Elapsed: 00:00:04.05


    SQL>SELECT MAX (pkg_test.fn( TO_CHAR(NULL) )) FROM driver_table
    2 /

    MAX(PKG_TEST.FN(TO_CHAR(NULL)))
    -------------------------------
    1

    1 row selected.

    Elapsed: 00:00:04.05


    SQL>SELECT MAX (fn( TO_CHAR(NULL) )) FROM driver_table
    2 /

    MAX(FN(TO_CHAR(NULL)))
    ----------------------
    1

    1 row selected.

    Elapsed: 00:00:04.00


    The results are SIMILAR, regardless of the fact that two of the functions expect NUMBER arguments !

    ReplyDelete
  6. ( continued )
    -- PART 2 --
    Repeating the same selects passing a NON-NULL argument:

    /* with number argument - one difference observed, the pkg_test.fn time is the lowest, the same as the NULL-s test in PL/SQL ! */

    SQL>SELECT MAX (pkg_test.fv (1)) FROM driver_table
    2 /

    MAX(PKG_TEST.FV(1))
    -------------------
    1

    1 row selected.

    Elapsed: 00:00:04.02

    SQL>SELECT MAX (fv (1)) FROM driver_table
    2 /

    MAX(FV(1))
    ----------
    1

    1 row selected.

    Elapsed: 00:00:04.00

    SQL>SELECT MAX (pkg_test.fn (1)) FROM driver_table
    2 /

    MAX(PKG_TEST.FN(1))
    -------------------
    1

    1 row selected.

    Elapsed: 00:00:03.06

    SQL>SELECT MAX (fn (1)) FROM driver_table
    2 /

    MAX(FN(1))
    ----------
    1

    1 row selected.

    Elapsed: 00:00:04.00


    /* with char argument - identical results */

    SQL>SELECT MAX (pkg_test.fv ('1')) FROM driver_table
    2 /

    MAX(PKG_TEST.FV('1'))
    ---------------------
    1

    1 row selected.

    Elapsed: 00:00:04.02

    SQL>SELECT MAX (fv ('1')) FROM driver_table
    2 /

    MAX(FV('1'))
    ------------
    1

    1 row selected.

    Elapsed: 00:00:04.00

    SQL>SELECT MAX (pkg_test.fn ('1')) FROM driver_table
    2 /

    MAX(PKG_TEST.FN('1'))
    ---------------------
    1

    1 row selected.

    Elapsed: 00:00:04.01

    SQL>SELECT MAX (fn ('1')) FROM driver_table
    2 /

    MAX(FN('1'))
    ------------
    1

    1 row selected.

    Elapsed: 00:00:04.02

    ( to be continued )

    ReplyDelete
  7. ( continued )
    -- PART 3 --

    In my opinion, the issue is related to the way in which SQL is treating (or implying)
    the datatype of "NULL".

    I remember that in older versions of Oracle, NULL used to be treated as having a CHAR datatype, so, for example, when creating a view containing a UNION of two SELECT-s, a NUMBER column in one of the union-ed selects was not "compatible" with a NULL in the other select, so I had to use an explicit TO_NUMBER(NULL) to make the UNION work.

    Though this restriction is not any more an issue for a UNION, however, internally, probably
    the "NULL" literal is still considered (at least by the SQL layer) as having its own "datatype", in spite of the fact that we use the same NULL for ALL the datatypes.


    Another thing, in one of the past quizzes
    ( I think the one in the last quarter about factoring out common statements from PL/SQL loops, that was ultimately cancelled due to palyers objections on the overall logic)
    there was some discussion regarding the speed of the implicit conversion of a CHAR to a NUMBER, versus the opposite and I remember that a difference was signalled by some players,
    there at the PL/SQL level.

    It looks like what happens in our case in this thread is that, when executing the functions
    in the PL/SQL code, the NULL-s are treated by the PL/SQL engine as somehow having "the same datatype".

    On the other hand, when calling the functions at the SQL layer, this layer seems to "favorize"
    the NUMBER datatype for the NULL-s, so it maybe performs an implicit conversion of the
    "NUMBER TYPE" NULL to a "VARCHAR2 TYPE" NULL expected by the two FV functions, and this probably explains the difference we see when simply passing a NULL literal.


    I don't know at all whether this is the case, probably a very interesting issue to be researched.

    But, in fact, why not submitting this question to Oracle and have their answer to it ?

    Thanks a lot & Best Regards,
    Iudith

    ReplyDelete