Re: Native compiled code *much* slower??
- From: Steve Baldwin <stbaldwin@xxxxxxxxxxxxxxxx>
- To: Jared Still <jkstill@xxxxxxxxx>
- Date: Fri, 25 Dec 2009 07:51:12 +1100
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> @sb4
SQL> alter session set plsql_code_type = interpreted;
Session altered.
SQL> alter package msc$log_p compile package;
Package altered.
SQL> @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> @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> @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@xxxxxxxxxxxxxxxx> 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@xxxxxxxxx> wrote:
>> On Wed, Dec 23, 2009 at 11:48 AM, Steve Baldwin <stbaldwin@xxxxxxxxxxxxxxxx>
>> 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
>>
>
--
//www.freelists.org/webpage/oracle-l
Other related posts:
