DBMS_PROFILER showing TOTAL_TIME as 0 in some scenarios

Question

I have the following anonymous block that calls DBMS_PROFILER:

set serveroutput on;
DECLARE
    l_result  BINARY_INTEGER;
    P_PARTY_NAME        varchar2(100)   := NULL;
    P_COUNTRY           varchar2(100)   := 'DE';
    P_SET_OF_BOOKS_ID   NUMBER          := 185;
    --P_SET_OF_BOOKS_ID     NUMBER          := 475;
    P_AS_OF_DATE        DATE            := '07-JUL-2020';
    
BEGIN

    dbms_output.put_line('current run time is '|| SYSDATE);

   l_result := DBMS_PROFILER.start_profiler(run_comment => 'xxz5a_test_original: ' || SYSDATE);
  
   xxz5a_test_original( P_PARTY_NAME        => P_PARTY_NAME
                    ,   P_COUNTRY           => P_COUNTRY
                    ,   P_SET_OF_BOOKS_ID   => P_SET_OF_BOOKS_ID
                    ,   P_AS_OF_DATE        => P_AS_OF_DATE);
           
  l_result := DBMS_PROFILER.stop_profiler;
  
END;
/

If i use P_SET_OF_BOOKS_ID as 475, it works fine:

SET LINESIZE 200
SET TRIMOUT ON

COLUMN runid FORMAT 99999
COLUMN run_comment FORMAT A50
COLUMN run_total_time FORMAT 999999
SELECT runid,
       run_date,
       run_comment,
       NUMTODSINTERVAL( run_total_time / 1000000000, 'SECOND' ) "Time" 
FROM   plsql_profiler_runs
ORDER BY runid;

 RUNID RUN_DATE    RUN_COMMENT                                        Time               
------ ----------- -------------------------------------------------- -------------------
     6 07-JUL-2020 xxz5a_test_original: 07-JUL-2020                   +00 00:00:21.030000
     

I can see the breakdown properly:

COLUMN runid FORMAT 99999
COLUMN unit_number FORMAT 99999
COLUMN unit_type FORMAT A20
COLUMN unit_owner FORMAT A20

SELECT u.runid,
       u.unit_number,
       u.unit_type,
       u.unit_owner,
       u.unit_name,
       d.line#,
       d.total_occur,
       d.total_time,
       d.min_time,
       d.max_time
FROM   plsql_profiler_units u
       JOIN plsql_profiler_data d ON u.runid = d.runid AND u.unit_number = d.unit_number
WHERE  u.runid = 6
ORDER BY u.unit_number, d.line#;    
         
 RUNID UNIT_NUMBER UNIT_TYPE                        UNIT_OWNER                       UNIT_NAME                             LINE# TOTAL_OCCUR TOTAL_TIME   MIN_TIME   MAX_TIME
------ ----------- -------------------------------- -------------------------------- -------------------------------- ---------- ----------- ---------- ---------- ----------
     6           1 ANONYMOUS BLOCK                  <anonymous>                      <anonymous>                               1           0          0          0          0
     6           1 ANONYMOUS BLOCK                  <anonymous>                      <anonymous>                               3           0          0          0          0
     6           1 ANONYMOUS BLOCK                  <anonymous>                      <anonymous>                               4           0          0          0          0
     6           1 ANONYMOUS BLOCK                  <anonymous>                      <anonymous>                               6           0          0          0          0
     6           1 ANONYMOUS BLOCK                  <anonymous>                      <anonymous>                               7           0          0          0          0
     6           1 ANONYMOUS BLOCK                  <anonymous>                      <anonymous>                              11           0          0          0          0
     6           1 ANONYMOUS BLOCK                  <anonymous>                      <anonymous>                              13           0          0          0          0
     6           1 ANONYMOUS BLOCK                  <anonymous>                      <anonymous>                              15           1 2.1030E+10 2.1030E+10 2.1030E+10
     6           1 ANONYMOUS BLOCK                  <anonymous>                      <anonymous>                              20           0          0          0          0
     6           1 ANONYMOUS BLOCK                  <anonymous>                      <anonymous>                              22           0          0          0          0

10 rows selected. 
         
         

However, when i use P_SET_OF_BOOKS_ID as 185, it runs for 4-5 mins and completes without any issue:

SET LINESIZE 200
SET TRIMOUT ON

COLUMN runid FORMAT 99999
COLUMN run_comment FORMAT A50
COLUMN run_total_time FORMAT 999999
SELECT runid,
       run_date,
       run_comment,
       NUMTODSINTERVAL( run_total_time / 1000000000, 'SECOND' ) "Time" 
FROM   plsql_profiler_runs
ORDER BY runid;



 RUNID RUN_DATE    RUN_COMMENT                                        Time               
------ ----------- -------------------------------------------------- -------------------
     7 07-JUL-2020 xxz5a_test_original: 07-JUL-2020                   +00 00:04:15.889999

but when i check the detailed report, it doesn't show any breakdown:

SELECT u.runid,
       u.unit_number,
       u.unit_type,
       u.unit_owner,
       u.unit_name,
       d.line#,
       d.total_occur,
       d.total_time,
       d.min_time,
       d.max_time
FROM   plsql_profiler_units u
       JOIN plsql_profiler_data d ON u.runid = d.runid AND u.unit_number = d.unit_number
WHERE  u.runid = 7
ORDER BY u.unit_number, d.line#;     


 RUNID UNIT_NUMBER UNIT_TYPE                        UNIT_OWNER                       UNIT_NAME                             LINE# TOTAL_OCCUR TOTAL_TIME   MIN_TIME   MAX_TIME
------ ----------- -------------------------------- -------------------------------- -------------------------------- ---------- ----------- ---------- ---------- ----------
     7           1 ANONYMOUS BLOCK                  <anonymous>                      <anonymous>                               1           0          0          0          0
     7           1 ANONYMOUS BLOCK                  <anonymous>                      <anonymous>                               3           0          0          0          0
     7           1 ANONYMOUS BLOCK                  <anonymous>                      <anonymous>                               4           0          0          0          0
     7           1 ANONYMOUS BLOCK                  <anonymous>                      <anonymous>                               5           0          0          0          0
     7           1 ANONYMOUS BLOCK                  <anonymous>                      <anonymous>                               7           0          0          0          0
     7           1 ANONYMOUS BLOCK                  <anonymous>                      <anonymous>                              11           0          0          0          0
     7           1 ANONYMOUS BLOCK                  <anonymous>                      <anonymous>                              13           0          0          0          0
     7           1 ANONYMOUS BLOCK                  <anonymous>                      <anonymous>                              15           0          0          0          0
     7           1 ANONYMOUS BLOCK                  <anonymous>                      <anonymous>                              20           0          0          0          0
     7           1 ANONYMOUS BLOCK                  <anonymous>                      <anonymous>                              22           0          0          0          0

10 rows selected. 

At first, i think it had something to do with the procedure xxz5a_test_original. This procedure is a very long procedure that consumed a lot of memory depending on the valuye of P_SET_OF_BOOKS_ID. However, i've tried to put an Exception in the Procedure but nothing comes up:

create or replace procedure xxz5a_test_original
(
    P_PARTY_NAME        varchar2
,   P_COUNTRY           varchar2
,   P_SET_OF_BOOKS_ID   NUMBER
,   P_AS_OF_DATE        DATE
)
as
begin

    << some long query here>>
 
EXCEPTION
    WHEN OTHERS THEN
        dbms_output.put_line('Error in xxz5a_test_original'|| SQLERRM);
end xxz5a_test_original;            

Any idea why the TOTAL_OCCUR, TOTAL_TIME, MIN_TIME and MAX_TIME aren't showing the breakdowns?

Answer 1

In order for dbms_profiler to write data, PLSQL code needs to be compiled in interpreted, not in the (better performing) default native mode. Before compilation of the profiled code, execute:

alter session set plsql_code_type=interpreted;

To analyze the profiler data, easiest is to use blitz report DBA DBMS Profiler Data.

Answer 2

I'd suggest to analyze it using dbms_hprof to see if all the time is spent on internal objects. dbms_hprof traces on lower level than dbms_profiler. If it will not help, please show strace or systemtap traces of you process, may be even with flamegraph. I'll try to check it