Skip to Main Content
  • Questions
  • How to trace PL/SQL procedure for tuning

Breadcrumb

Question and Answer

Chris Saxon

Thanks for the question, oracle.

Asked: March 06, 2018 - 7:25 am UTC

Last updated: March 14, 2019 - 8:39 am UTC

Version: 12.1.0

Viewed 10K+ times! This question is

You Asked

Hi tom,

There is an procedure which is running very long/ taking time So, how can i trace that procedure to check where is the issue.

like - tkprod or trace session

and Chris said...

You can use SQL trace to capture execution stats for a procedure. But this only gathers SQL execution details.

If you want to know details of the PL/SQL execution, you can use the hierarchical profiler.

create or replace function f ( p int ) 
  return number as
begin
  return sqrt (p);
end f;
/

create or replace procedure p  as
  val number;
begin
  for i in 1 .. 10000 loop
    val := val + f ( i );
  end loop;
  
  dbms_output.put_line ( val );
  
end p;
/

var run number;

begin
  dbms_hprof.start_profiling (
    location => 'PLSHPROF_DIR',
    filename => 'profile.txt');
   
  p();

  dbms_hprof.stop_profiling;

  :run := DBMS_HPROF.analyze (
     location    => 'PLSHPROF_DIR',
     filename    => 'profile.txt',
     run_comment => 'PL/SQL profile'
  );

end;
/

select rpad(' ', (level-1)*2, ' ') || a.name as name,
       a.subtree_elapsed_time,
       a.function_elapsed_time,
       a.calls
from   (select fi.symbolid,
               pci.parentsymid,
               rtrim(fi.owner || '.' || fi.module || '.' || nullif(fi.function,fi.module), '.') as name,
               nvl(pci.subtree_elapsed_time, fi.subtree_elapsed_time) as subtree_elapsed_time,
               nvl(pci.function_elapsed_time, fi.function_elapsed_time) as function_elapsed_time,
               nvl(pci.calls, fi.calls) as calls
        from   dbmshp_function_info fi
        left join dbmshp_parent_child_info pci 
        on     fi.runid = pci.runid and fi.symbolid = pci.childsymid
        where  fi.runid = :run
        and    fi.module != 'DBMS_HPROF') a
connect by a.parentsymid = prior a.symbolid
start with a.parentsymid is null;

NAME                           SUBTREE_ELAPSED_TIME   FUNCTION_ELAPSED_TIME   CALLS   
CHRIS.P                                         29880                   12981       1 
  CHRIS.F                                       16832                   16832   10000 
  SYS.DBMS_OUTPUT.PUT_LINE                         67                       4       1 
    SYS.DBMS_OUTPUT.NEW_LINE                        2                       2       1 
    SYS.DBMS_OUTPUT.PUT                            61                      61       1


HT to Tim Hall for the query above. You can read more from him about how to configure the profiler at:

https://oracle-base.com/articles/11g/plsql-hierarchical-profiler-11gr1

Or run it in SQL Developer. Barry McGillin has instructions on this at:

https://barrymcgillin.blogspot.co.uk/2012/04/using-hierarchical-profiler-in-sql.html

Rating

  (2 ratings)

Is this answer out of date? If it is, please let us know via a Comment

Comments

How to profile a non-interactive scheduler job ?

Ankit V, March 13, 2019 - 1:29 pm UTC

Hi Tom,

Above response is very useful. I was able to successfully find contentious SQL in my long running stored procedure using DBMS_HPROF.

But I wonder how can we profile a scheduled job which is running a procedure.

In my case, I am looking to profile a scheduler job running every night at 23:00 hrs and takes approx 8-9 hrs to finish.

Oracle version is 11.2
Environment : Production

1) Can I use DBMS_HPROF in this case somehow?
2) If not, what other options do I have ? (since its production, they are not allowing me to enable trace)

Thanks
Chris Saxon
March 13, 2019 - 1:39 pm UTC

I'm not aware of a way to enable this for procedures running in other sessions.

You could update the job to call dbms_hprof around the current procedure. Or skip the scheduler job one night and manually run it with the profiler.


logon/logoff triggers

Mikhail Velikikh, March 13, 2019 - 8:27 pm UTC

A logon trigger can come in handy here. You can test any conditions in it and call DBMS_HPROF selectively.
Just call dbms_hprof.stop_profiling in a logoff trigger as well.
SQL> conn system/oracle@localhost/pdb
Connected.
SQL>
SQL> create or replace package hprof_helper_pkg
  2  is
  3    function fb_need_profile return boolean;
  4    procedure p_profile_if_needed;
  5    procedure p_stop_profiling;
  6  end;
  7  /

Package created.

SQL> create or replace package body hprof_helper_pkg
  2  is
  3    g_hprof_enabled boolean;
  4    function fb_need_profile return boolean
  5    is
  6    begin
  7      return
  8        sys_context('userenv', 'scheduler_job') = 'Y'
  9        and sys_context('userenv', 'session_user') = 'TEST';
 10    end fb_need_profile;
 11    procedure p_profile_if_needed
 12    is
 13    begin
 14      if fb_need_profile()
 15      then
 16        dbms_hprof.start_profiling (
 17          location => 'PLSHPROF_DIR',
 18          filename => 'profile.txt');
 19        g_hprof_enabled := true;
 20      end if;
 21    end p_profile_if_needed;
 22    procedure p_stop_profiling
 23    is
 24    begin
 25      if g_hprof_enabled
 26      then
 27        dbms_hprof.stop_profiling();
 28      end if;
 29    end p_stop_profiling;
 30  end;
 31  /

Package body created.

SQL>
SQL> create or replace trigger hprof_on
  2  after logon on database
  3  declare
  4  begin
  5    hprof_helper_pkg.p_profile_if_needed();
  6  end;
  7  /

Trigger created.

SQL>
SQL> create or replace trigger hprof_off
  2  before logoff on database
  3  declare
  4  begin
  5    hprof_helper_pkg.p_stop_profiling();
  6  end;
  7  /

Trigger created.

SQL>
SQL> drop user test cascade;

User dropped.

SQL>
SQL> grant connect, create job, create procedure to test identified by test;

Grant succeeded.

SQL>
SQL> conn test/test@localhost/pdb
Connected.
SQL>
SQL> create or replace function f ( p int )
  2    return number as
  3  begin
  4    return sqrt (p);
  5  end f;
  6  /

Function created.

SQL>
SQL> create or replace procedure p  as
  2    val number;
  3  begin
  4    for i in 1 .. 10000 loop
  5      val := val + f ( i );
  6    end loop;
  7
  8    dbms_output.put_line ( val );
  9
 10  end p;
 11  /

Procedure created.

SQL>
SQL> exec dbms_scheduler.create_job( -
>   job_name => 'SCJ_MONITOR', -
>   job_type => 'PLSQL_BLOCK', -
>   job_action => 'p;', -
>   enabled => true, -
>   auto_drop => true, -
>   comments => 'Calling DBMS_HPROF in logon/logoff triggers')

PL/SQL procedure successfully completed.

SQL>
SQL> conn system/oracle@localhost/pdb
Connected.
SQL> !ls -ltr /tmp
total 10876
drwxr-xr-x. 2 oracle oinstall        6 Feb 23 20:16 hsperfdata_oracle
-rw-r-----. 1 oracle oinstall 10493952 Mar 14 01:00 my_test.dbf
-rw-r--r--. 1 oracle oinstall   640920 Mar 14 02:24 profile.txt

SQL> @analyze
SQL> set echo on
SQL> var run number
SQL>
SQL> exec :run := DBMS_HPROF.analyze ( -
>      location  => 'PLSHPROF_DIR', -
>      filename  => 'profile.txt', -
>      run_comment => 'PL/SQL profile')

PL/SQL procedure successfully completed.

SQL>
SQL> select rpad(' ', (level-1)*2, ' ') || a.name as name,
  2         a.subtree_elapsed_time,
  3         a.function_elapsed_time,
  4         a.calls
  5  from   (select fi.symbolid,
  6                 pci.parentsymid,
  7                 rtrim(fi.owner || '.' || fi.module || '.' || nullif(fi.function,fi.module), '.') as name,
  8                 nvl(pci.subtree_elapsed_time, fi.subtree_elapsed_time) as subtree_elapsed_time,
  9                 nvl(pci.function_elapsed_time, fi.function_elapsed_time) as function_elapsed_time,
 10                 nvl(pci.calls, fi.calls) as calls
 11          from   dbmshp_function_info fi
 12          left join dbmshp_parent_child_info pci
 13          on     fi.runid = pci.runid and fi.symbolid = pci.childsymid
 14          where  fi.runid = :run
 15          and    fi.module != 'DBMS_HPROF') a
 16  connect by a.parentsymid = prior a.symbolid
 17  start with a.parentsymid = 1;

NAME                           SUBTREE_ELAPSED_TIME FUNCTION_ELAPSED_TIME      CALLS
------------------------------ -------------------- --------------------- ----------
SYS.DBMS_OUTPUT.ENABLE                            1                     1          1
SYSTEM.HPROF_HELPER_PKG.P_STOP                    6                     6          1
_PROFILING

TEST.P                                         5750                  1877          1
  SYS.DBMS_OUTPUT.PUT_LINE                       50                     1          1
    SYS.DBMS_OUTPUT.NEW_LINE                      0                     0          1
    SYS.DBMS_OUTPUT.PUT                          49                    49          1
  TEST.F                                       3823                  3823      10000

7 rows selected.


Chris Saxon
March 14, 2019 - 8:39 am UTC

Neat, thanks for sharing.

More to Explore

PL/SQL demos

Check out more PL/SQL tutorials on our LiveSQL tool.

PL/SQL docs

PL/SQL reference manual from the Oracle documentation library