Re: Native compiled code *much* slower??

From: Steve Baldwin <stbaldwin_at_multiservice.com>
Date: Fri, 25 Dec 2009 07:51:12 +1100
Message-ID: <d282b3ab0912241251o728aee5avfae336b7ca9e4b4_at_mail.gmail.com>

I apologise if my tone gave the indication I was unwilling to put up my code. This is the first time I have tried using native compilation of PL/SQL code and my reading of the Oracle doc's (maybe I missed something) didn't uncover any "don't compile native if your code has any of the following constructs ....", so I didn't think it mattered.

Here is the code :

CREATE OR REPLACE PACKAGE
--

• Module : msc$log_p
• Author : Steve Baldwin
• Created : 03-Jan-2006
• Purpose : Provide Error Context Logging
  --
  
• Version : $Revision: 26 $
• Changed By : $Author: stbaldwin $
• Checked In : $Date: 2009-11-16 09:23:37 +1100 (Mon, 16 Nov 2009) $
  --
  msc$log_p AS
  --
  PROCEDURE enable_logging(iMax_History IN PLS_INTEGER := NULL); PROCEDURE disable_logging; -- PROCEDURE clear_all_context; PROCEDURE clear_context; PROCEDURE set_context( iKey IN VARCHAR2, iValue IN VARCHAR2, iClear_Before IN BOOLEAN := TRUE); PROCEDURE set_context_kvp( iKey_Value_1 IN VARCHAR2, iKey_Value_2 IN VARCHAR2 := NULL, iKey_Value_3 IN VARCHAR2 := NULL, iKey_Value_4 IN VARCHAR2 := NULL, iKey_Value_5 IN VARCHAR2 := NULL, iKey_Value_6 IN VARCHAR2 := NULL, iKey_Value_7 IN VARCHAR2 := NULL, iKey_Value_8 IN VARCHAR2 := NULL, iKey_Value_9 IN VARCHAR2 := NULL, iKey_Value_10 IN VARCHAR2 := NULL, iClear_Before IN BOOLEAN := TRUE);
  --
  END msc$log_p; /

CREATE OR REPLACE PACKAGE BODY
--

• Module : msc$log_p
• Author : Steve Baldwin
• Created : 03-Jan-2006
• Purpose : Provide Error Context Logging
  --
  
• Version : $Revision: 26 $
• Changed By : $Author: stbaldwin $
• Checked In : $Date: 2009-11-16 09:23:37 +1100 (Mon, 16 Nov 2009) $
  --
  msc$log_p AS
  --
  k_dflt_max_history CONSTANT PLS_INTEGER := 100; k_max_history CONSTANT PLS_INTEGER := 1000; -- SUBTYPE stKey IS VARCHAR2(80); SUBTYPE stSource IS db_error_stack_context.context_at%TYPE; -- TYPE tContext IS RECORD ( name_orig db_error_stack_context.context_name%TYPE, source stSource, value db_error_stack_context.context_value%TYPE ); TYPE thContext IS TABLE OF tContext INDEX BY stKey; TYPE tahContext IS TABLE OF thContext INDEX BY BINARY_INTEGER; TYPE taContext IS TABLE OF tContext INDEX BY BINARY_INTEGER; -- k_user_prefix CONSTANT VARCHAR2(31) := USER || '.'; -- gMax_History PLS_INTEGER; gContext tahContext; gHistory taContext; gLevel PLS_INTEGER; gTOS stSource; gEnabled BOOLEAN := FALSE; gError_ID PLS_INTEGER; gError_Depth PLS_INTEGER; -- PROCEDURE get_stack (oTOS OUT VARCHAR2);
  --
  PROCEDURE enable_logging(iMax_History IN PLS_INTEGER := NULL) AS BEGIN gEnabled := TRUE; clear_all_context; gError_ID := NULL; gError_Depth := NULL; gMax_History := LEAST(NVL(iMax_History, k_dflt_max_history), k_max_history); END enable_logging;
  --
  PROCEDURE disable_logging AS BEGIN gEnabled := FALSE; END disable_logging;
  --
  FUNCTION is_enabled RETURN BOOLEAN AS BEGIN RETURN gEnabled; END is_enabled;
  --
  PROCEDURE get_stack (oTOS OUT VARCHAR2) AS
  --
  l_callstack VARCHAR2(4096) := dbms_utility.format_call_stack; l_tos VARCHAR2(256); l_tos_length PLS_INTEGER; l_linenum PLS_INTEGER; l_p1 PLS_INTEGER; l_p2 PLS_INTEGER; l_p3 PLS_INTEGER; l_type VARCHAR2(30); l_me stKey; l_name stKey; l_idx PLS_INTEGER;
  --
  BEGIN
  --
  
• Get rid of headings
  --
  l_callstack := SUBSTR(l_callstack, INSTR(l_callstack, CHR(10) || '0x') + 1); -- l_idx := 0; LOOP --
  • Get the relevant parts of this stack entry -- l_tos := SUBSTR(l_callstack, 1, INSTR(l_callstack, CHR(10)) - 1); l_tos_length := LENGTH(l_tos); l_p1 := INSTR(l_tos, ' '); l_p2 := regexp_instr(l_tos, '\S', l_p1); l_p3 := INSTR(l_tos, ' ', l_p2); l_linenum := TO_NUMBER(SUBSTR(l_tos, l_p2, l_p3 - l_p2)); l_p1 := regexp_instr(l_tos, '\S', l_p3); l_tos := UPPER(SUBSTR(l_tos, l_p1)); l_p1 := 1; -- Type following l_p2 := 1; -- Name following IF INSTR(l_tos, 'ANONYMOUS') = 1 THEN l_type := 'Anonymous Block'; l_p2 := 0; ELSIF INSTR(l_tos, 'PACKAGE BODY ') = 1 THEN l_type := 'Package Body'; ELSIF INSTR(l_tos, 'PACKAGE ') = 1 THEN l_type := 'Package'; ELSIF INSTR(l_tos, 'PROC') = 1 THEN l_type := 'Procedure'; ELSIF INSTR(l_tos, 'FUNC') = 1 THEN l_type := 'Function'; ELSE -- Trigger l_type := 'Trigger'; l_p1 := 0; END IF; IF l_p1 = 1 THEN l_tos := SUBSTR(l_tos, LENGTH(l_type) + 2); END IF; IF l_p2 = 1 THEN IF INSTR(l_tos, k_user_prefix) = 1 THEN l_tos := SUBSTR(l_tos, INSTR(l_tos, '.') + 1); END IF; l_name := ' ' || l_tos; ELSE l_name := NULL; END IF; IF l_idx = 0 THEN --
    • If this is the first time through, save who I am -- l_me := l_name; ELSIF NVL(l_name, '~') != l_me THEN --
    • If this is not the first time through, and the Name is not
    • Me, we've found the 'real' Caller. -- oTOS := l_type || l_name || '(' || l_linenum || ')'; --
    • Level = Number of NL's left in the CallStack + 1 -- gLevel := LENGTH(l_callstack) - LENGTH(TRANSLATE(l_callstack, 'x' || CHR(10), 'x')); EXIT; END IF; l_idx := l_idx + 1; l_callstack := SUBSTR(l_callstack, l_tos_length + 2); END LOOP; END get_stack;
      --
      PROCEDURE clear_all_context AS BEGIN IF gEnabled THEN gContext.DELETE; gHistory.DELETE; END IF; END clear_all_context;
      --
      PROCEDURE clear_context AS BEGIN IF gEnabled THEN get_stack(gTOS); gContext.DELETE(gLevel); END IF; END clear_context;
      --
      PROCEDURE set_context( iKey IN VARCHAR2, iValue IN VARCHAR2, iClear_Before IN BOOLEAN := TRUE) AS
      --
      l_key stKey := UPPER(iKey); l_idx PLS_INTEGER := NVL(gHistory.LAST, 0) + 1;
      --
      BEGIN IF gEnabled THEN IF iClear_Before THEN clear_context; END IF; gContext(gLevel)(l_key).name_orig := iKey; gContext(gLevel)(l_key).source := gTOS; gContext(gLevel)(l_key).value := SUBSTR(iValue, 1, 4000); --
  • Add to history -- IF gMax_History > 0 THEN IF l_idx > gMax_History THEN gHistory.DELETE(l_idx - gMax_History); END IF; gHistory(l_idx).name_orig := iKey; gHistory(l_idx).source := gTOS; gHistory(l_idx).value := SUBSTR(iValue, 1, 4000); END IF; END IF; END set_context;
    --
    PROCEDURE set_context_kvp( iKey_Value_1 IN VARCHAR2, iKey_Value_2 IN VARCHAR2 := NULL, iKey_Value_3 IN VARCHAR2 := NULL, iKey_Value_4 IN VARCHAR2 := NULL, iKey_Value_5 IN VARCHAR2 := NULL, iKey_Value_6 IN VARCHAR2 := NULL, iKey_Value_7 IN VARCHAR2 := NULL, iKey_Value_8 IN VARCHAR2 := NULL, iKey_Value_9 IN VARCHAR2 := NULL, iKey_Value_10 IN VARCHAR2 := NULL, iClear_Before IN BOOLEAN := TRUE) AS
    --
    l_clear_before BOOLEAN := iClear_Before; -- PROCEDURE split(i_key_value IN VARCHAR2) AS -- l_delim_pos PLS_INTEGER; -- BEGIN IF i_key_value IS NOT NULL THEN l_delim_pos := INSTR(i_key_value, '='); IF l_delim_pos > 0 THEN set_context( SUBSTR(i_key_value, 1, l_delim_pos - 1), SUBSTR(i_key_value, l_delim_pos + 1), l_clear_before); l_clear_before := FALSE; END IF; END IF; END split;
    --
    BEGIN IF gEnabled THEN split(iKey_Value_1); split(iKey_Value_2); split(iKey_Value_3); split(iKey_Value_4); split(iKey_Value_5); split(iKey_Value_6); split(iKey_Value_7); split(iKey_Value_8); split(iKey_Value_9); split(iKey_Value_10); END IF; END set_context_kvp;
    --
    END msc$log_p; /

(Test script)
set timing on
declare

    procedure p1 (i_p1 in number, i_p2 in varchar2);
    procedure p2 (i_p1 in number, i_p2 in varchar2);
    procedure p3 (i_p1 in number, i_p2 in varchar2);

    --
    procedure p1 (i_p1 in number, i_p2 in varchar2) as     begin

        msc$log_p.set_context_kvp('i_p1=' || i_p1, 'i_p2=' || i_p2);
        p2(i_p1, i_p2);

    end;
    --
    procedure p2 (i_p1 in number, i_p2 in varchar2) as     begin

        msc$log_p.set_context_kvp('i_p1=' || i_p1, 'i_p2=' || i_p2);
        p3(i_p1, i_p2);

    end;
    --
    procedure p3 (i_p1 in number, i_p2 in varchar2) as     begin

        msc$log_p.set_context_kvp('i_p1=' || i_p1, 'i_p2=' || i_p2);     end;
    --
begin

    msc$log_p.enable_logging(10);
    for i in 1 .. 1000 loop

        p1(100, 'parm : ' || 100);
    end loop;
    msc$log_p.disable_logging;
end;
/

(Compile interpreted)
alter session set plsql_code_type = interpreted; alter package msc$log_p compile package;

(Compile native)
alter session set plsql_code_type = native; alter package msc$log_p compile package;

Sample execution on our environment ...

SQL> _at_sb4
SQL> alter session set plsql_code_type = interpreted;

Session altered.

SQL> alter package msc$log_p compile package;

Package altered.

SQL> _at_sb2
SQL> set timing on
SQL> declare
  2      procedure p1 (i_p1 in number, i_p2 in varchar2);
  3      procedure p2 (i_p1 in number, i_p2 in varchar2);
  4      procedure p3 (i_p1 in number, i_p2 in varchar2);
  5      --
  6      procedure p1 (i_p1 in number, i_p2 in varchar2) as
  7      begin
  8          msc$log_p.set_context_kvp('i_p1=' || i_p1, 'i_p2=' || i_p2);
  9          p2(i_p1, i_p2);
 10      end;
 11      --
 12      procedure p2 (i_p1 in number, i_p2 in varchar2) as
 13      begin
 14          msc$log_p.set_context_kvp('i_p1=' || i_p1, 'i_p2=' || i_p2);
 15          p3(i_p1, i_p2);
 16      end;
 17      --
 18      procedure p3 (i_p1 in number, i_p2 in varchar2) as
 19      begin
 20          msc$log_p.set_context_kvp('i_p1=' || i_p1, 'i_p2=' || i_p2);
 21      end;
 22      --
 23  begin
 24      msc$log_p.enable_logging(10);
 25      for i in 1 .. 1000 loop
 26          p1(100, 'parm : ' || 100);
 27      end loop;
 28      msc$log_p.disable_logging;

 29 end;
 30 /

PL/SQL procedure successfully completed.

Elapsed: 00:00:00.24
SQL> _at_sb3
SQL> alter session set plsql_code_type = native;

Session altered.

Elapsed: 00:00:00.00
SQL> alter package msc$log_p compile package;

Package altered.

Elapsed: 00:00:00.09

SQL> _at_sb2
SQL> set timing on
SQL> declare
  2      procedure p1 (i_p1 in number, i_p2 in varchar2);
  3      procedure p2 (i_p1 in number, i_p2 in varchar2);
  4      procedure p3 (i_p1 in number, i_p2 in varchar2);
  5      --
  6      procedure p1 (i_p1 in number, i_p2 in varchar2) as
  7      begin
  8          msc$log_p.set_context_kvp('i_p1=' || i_p1, 'i_p2=' || i_p2);
  9          p2(i_p1, i_p2);
 10      end;
 11      --
 12      procedure p2 (i_p1 in number, i_p2 in varchar2) as
 13      begin
 14          msc$log_p.set_context_kvp('i_p1=' || i_p1, 'i_p2=' || i_p2);
 15          p3(i_p1, i_p2);
 16      end;
 17      --
 18      procedure p3 (i_p1 in number, i_p2 in varchar2) as
 19      begin
 20          msc$log_p.set_context_kvp('i_p1=' || i_p1, 'i_p2=' || i_p2);
 21      end;
 22      --
 23  begin
 24      msc$log_p.enable_logging(10);
 25      for i in 1 .. 1000 loop
 26          p1(100, 'parm : ' || 100);
 27      end loop;
 28      msc$log_p.disable_logging;

 29 end;
 30 /

PL/SQL procedure successfully completed.

Elapsed: 00:00:37.17

Thanks again for the help.

Steve

On Fri, Dec 25, 2009 at 7:20 AM, Steve Baldwin <stbaldwin_at_multiservice.com> wrote:

> Does this list allow attachments to messages or do I need to inline the code?
>
> On Fri, Dec 25, 2009 at 6:35 AM, Jared Still <jkstill_at_gmail.com> wrote:
>> On Wed, Dec 23, 2009 at 11:48 AM, Steve Baldwin <stbaldwin_at_multiservice.com>
>> wrote:
>>>
>>> Has anyone found native compiled PL/SQL code to be much slower than
>>> interpreted?  Is this perhaps indicative that we have a setting
>>> screwed up somewhere?
>>>
>>
>> Please provide a reproducible test case with code.
>> Jared Still
>> Certifiable Oracle DBA and Part Time Perl Evangelist
>> Oracle Blog: http://jkstill.blogspot.com
>> Home Page: http://jaredstill.com
>>
>

--

http://www.freelists.org/webpage/oracle-l Received on Thu Dec 24 2009 - 14:51:12 CST