Tracing PL/SQL subprogram calls with parameters values [Dynamic tracing]

The purpose of this blog post is demonstrate again the power of Linux dynamic tracing/instrumentation tools.

In my last blog post Enhancing DBMS_OUTPUT using systemtap i showed how we can track  the parameter values passed to “dbms_output.put_line” routine using systemtap.That was a very simple example because we already know the type of the arguments passed (a simple VARCHAR2) and also because there is only ONE parameter.

Tracking PL/SQL routine calls arguments using dynamic tracing utility like perf or systemtap can become quite complex depending on many things like :

• Argument types
• Argument number
• Argument passed  By Value/By reference
• Subprograms type (nested/package/standalone subprogram)
• Optimization level (ex: inlining of call of procedure)

Time for the serious stuff  with dynamic tracing tool PERF ! 

TEST ENV : ORACLE 12.2.0.1/OEL 6/UEK 4.1

PL/SQL example program :

create or replace procedure test_string(n1 in out varchar2,n2 in out NOCOPY varchar2,n3 varchar2) as
begin
dbms_output.put_line(n1||n2||n3);
end;
/

create or replace procedure test_number(n1 number) as
begin
dbms_output.put_line(n1);
end;
/

create or replace procedure test_binary_integer(n1 BINARY_INTEGER) as
begin
dbms_output.put_line(n1);
end;
/

create or replace procedure test_date(n1 date) as
begin
dbms_output.put_line(to_char(n1,'dd/mm/yyyy'));
end;
/

create or replace procedure test_me as 
n date;
s1 varchar2(30);
s2 varchar2(30);
begin

s1:='aaaaaaaaaaaaaa';
s2:='bbbbbbbbbbb';

test_string(s1,s2,'ccccccccccc');

test_number(1000);

test_binary_integer(1000);

test_date(to_date('24/11/2017','dd/mm/yyyy'));

end;
/

 

Tracing routine call  “exec testme;” using “trace_plsql_func_args.sh”

This shell script based on linux perf was tested with arguments of the following types (varchar2,number,binary_interger,date) and does not trace nested subprogram.

All the subprograms are compiled using “PLSQL_Optimize_Level = 2”  in “INTERPRETED” mode.

This script will output the name of the current routine executed followed with it’s arguments which are displayed using there internal representation.So some conversion must be done to obtain the current value.

Number data type see :

• Internal representation of the NUMBER datatype
• How are Numbers Saved in Oracle?

Date data type see :

• Internal representation of the DATE datatype

 

trace_plsql_func_args.sh PID DELAY

Before executing “trace_plsql_func_args.sh” we must generate the file “plsql_obj.sed” which contain mapping between PL/SQL OBJECT_ID/SUBPROGRAM_ID and OBJECT_NAME/PROCEDURE_NAME by executing “plsql_obj.sql”.

Of course there is many rooms for improvement like automating data type conversion ( as we already know the data type of every argument which is stored in the data dictionary) but this is as usual only an overview of what can be done 😀

As already explained covering all possibility (ex :parameter of Composite type ) can be a very  tedious and difficult task but at least we can extract something  😀

All the research have been conducted using intel pin tools “debugtrace.so” for more information take look at my presentation memory-access-tracing-poug17

DOWNLOAD :

• trace_plsql_func_args.sh
• plsql_obj.sql

That’s it 😀