Investigating Unfamiliar PL/SQL with the Hierarchical Profiler

The PL/SQL profiler can tell you how much time you spend where in your PL/SQL code (see my presentation Performance Tuning with the PL/SQL Performance Profilers).  Therefore it also tells you which code blocks were executed, and in which test run.  If you are debugging code with which you are unfamiliar, this can provide insight into where to focus attention and determine what is going on.

Example Problem

I was looking at a third-party application that uses the database job scheduler to run multiple concurrent batch jobs.  I needed to work out why they were not balancing properly between the database instances.  This application has its own scheduler package.  It is driven by metadata to define the jobs to be submitted.  This package then calls the delivered DBMS_SCHEDULER package.  However, this third-party package is quite complicated, there are lots of similar calls, and it is difficult to work out what was executed by just reading the code.

I ran the application having enabled the hierarchical profiler, DBMS_HPROF.  I was able to query the profiler tables to find the calls to DBMS_SCHEDULER that were executed.

Querying the Profiler Tables

Each time DBMSHP is run, the data is tagged with a separate run ID, so if I do different tests I can easily separate them.  However, in this example, I have run only one test.

SELECT * 
FROM   dbmshp_runs
ORDER BY runid;

 Run
  ID RUN_TIMESTAMP                  TOTAL_ELAPSED_TIME RUN_COMMENT                                          TRACE_ID
---- ------------------------------ ------------------ -------------------------------------------------- ----------
   3 28-MAR-23 19.23.20.891595000             78254498                                                             2

Usually, I am interested in improving performance, so I look for the code that took the most time and profile the code blocks by elapsed time.  However, this time, I have sorted them by module and line number so I can see which code blocks were executed.

BREAK ON OWNER ON TYPE ON module skip 1
SELECT fi.symbolid, fi.owner, fi.type, fi.module, fi.function, fi.line#, fi.namespace, fi.calls, fi.function_elapsed_time, fi.sql_id
FROM   dbmshp_function_info fi
WHERE  fi.runid = 3
ORDER BY fi.owner, fi.module, fi.line#;

The profile includes the application code and also the Oracle packages owned by SYS Function

 Symbol                                                                                                        Line Name             Elapsed
     ID OWNER              TYPE            MODULE                    FUNCTION                                     # Space   CALLS       Time SQL_ID
------- ------------------ --------------- ------------------------- ---------------------------------------- ----- ----- ------- ---------- -------------
      8 XXXXX_CUST         PACKAGE BODY    CUST_PARALLEL_JOBS        ISJOBSRUNNING                                6 PLSQL      38        708
      9                                                              ISJOBSRUNNING.C_RUNNING_JOBS_CNT            12 PLSQL      38        266
    137                                                              __static_sql_exec_line13                    13 SQL        38       9681 2y7y7t8bf4ykw
    133                                                              __sql_fetch_line23                          23 SQL        38    2026632 2y7y7t8bf4ykw
      6                                                              GETJOBSSTATUS                               42 PLSQL       7        150
      7                                                              GETJOBSSTATUS.C_JOB_STATUS                  48 PLSQL       7         59
    138                                                              __static_sql_exec_line49                    49 SQL         7        565 d5g73bnmxjuqd
    134                                                              __sql_fetch_line59                          59 SQL         7        238 d5g73bnmxjuqd
      3                                                              CUST_SIMULATE_SURRENDER                    105 PLSQL       1       1232
      5                                                              CUST_SIMULATE_SURRENDER.C_JOB_GROUPS       110 PLSQL       1         16
    135                                                              __static_sql_exec_line111                  111 SQL         1        159 1xrrajz8mgbhs
      4                                                              CUST_SIMULATE_SURRENDER.C_CFG              119 PLSQL       1         12
    136                                                              __static_sql_exec_line120                  120 SQL         1         90 9ytv0rhjjp3mr
    131                                                              __sql_fetch_line160                        160 SQL         1        118 1xrrajz8mgbhs
    132                                                              __sql_fetch_line165                        165 SQL         1        135 9ytv0rhjjp3mr
…
     54 XXXXX_SCHEDULER    PACKAGE BODY    SCHEDULER_ENGINE          __pkg_init                                   0 PLSQL       1          5
     55 XXXXX_SCHEDULER    PACKAGE SPEC    SCHEDULER_ENGINE          __pkg_init                                   0 PLSQL       1          5
     52 XXXXX_SCHEDULER    PACKAGE BODY    SCHEDULER_ENGINE          RUN_JOB                                    770 PLSQL       7        176
     53                                                              SET_JOB_ARGUMENT                          1317 PLSQL      21        202
    178                                                              __static_sql_exec_line1355                1355 SQL        21       4733 3h8uatusjv84c
…
    118 SYS                PACKAGE BODY    DBMS_SCHEDULER            CREATE_PROGRAM                              15 PLSQL       1         24
    121                                                              DROP_PROGRAM                                43 PLSQL       2         98
    119                                                              DEFINE_PROGRAM_ARGUMENT                    112 PLSQL       3        186
    122                                                              DROP_PROGRAM_ARGUMENT                      211 PLSQL       6        363
    117                                                              CREATE_JOB                                 432 PLSQL       7        428
    124                                                              RUN_JOB                                    546 PLSQL       7        239
    120                                                              DROP_JOB                                   696 PLSQL      14       7484
    123                                                              ENABLE                                    2992 PLSQL       1         87
    125                                                              SET_ATTRIBUTE                             3063 PLSQL      14        957
    126                                                              SET_ATTRIBUTE                             3157 PLSQL      14       2923
    127                                                              SET_ATTRIBUTE_NULL                        3274 PLSQL       7         42
    116                                                              CHECK_SYS_PRIVS                           3641 PLSQL      69     153470
…

The hierarchical profiler tracks which code blocks call which code blocks, so I can perform a hierarchical query starting where the parent is null.

SELECT symbolid, parentsymid,
       RPAD(' ', (level-1)*2, ' ') || a.name AS name, 
       a.line#, a.calls,
       a.subtree_elapsed_time, 
       a.function_elapsed_time       
FROM   (SELECT fi.symbolid,
               pci.parentsymid,
               RTRIM(fi.owner || '.' || fi.module || '.' || NULLIF(fi.function, fi.module), '.') AS name,
               fi.line#,
               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 = 3
        AND    NOT fi.module LIKE 'DBMS_HPROF%'
        ) a
CONNECT BY a.parentsymid = PRIOR a.symbolid
START WITH a.parentsymid IS NULL;

I can see that CUST_PARALLEL_JOBS.CUST_SIMULATE_SURRENDER calls XXXXX_SCHEDULER.SCHEDULER_ENGINE.RUN_JOB and that calls DBMS_SCHEDULER.RUN_JOB.

Symbol  Parent                                                                                                       Line            Elapsed    Elapsed
     ID  Sym ID NAME                                                                                                     #   CALLS       Time       Time
------- ------- ---------------------------------------------------------------------------------------------------- ----- ------- ---------- ----------
     18         XXXXX_CUST_ADDON.CUST_SCHED_SIMSURRENDERS                                                                1       1   78254334        570
      3      18   XXXXX_CUST.CUST_PARALLEL_JOBS.CUST_SIMULATE_SURRENDER                                                105       1   77139478       1232
      4       3     XXXXX_CUST.CUST_PARALLEL_JOBS.CUST_SIMULATE_SURRENDER.C_CFG                                        119       1        102         12
    136       4       XXXXX_CUST.CUST_PARALLEL_JOBS.__static_sql_exec_line120                                          120       1         90         90
…
     52       3     XXXXX_SCHEDULER.SCHEDULER_ENGINE.RUN_JOB                                                           770       7      58708        176
     56      52       XXXXX_SCHEDULER.SCHEDULER_UTILS.LOG_AUDIT_EVENT                                                  173       7         45         40
    115      56         SYS.DBMS_OUTPUT.PUT_LINE                                                                       109      41         43         43
     57      52       XXXXX_SCHEDULER.SCHEDULER_UTILS.SCHEMA_OWNER                                                     238       7         24         24
    124      52       SYS.DBMS_SCHEDULER.RUN_JOB                                                                       546       7      58463        239
    104     124         SYS.DBMS_ISCHED.CHECK_COMPAT                                                                  3509       7         11         11
    112     124         SYS.DBMS_ISCHED.RUN_JOB                                                                        242       7      44391      44391
…

Now I know which code to examine. This query outer joins the profiler data to the source code. NB. Any wrapped code will not be available in the ALL_SOURCE view. You might want to unwrap it, at least in a test environment (see Philipp Salisberg's PL/SQL Unwrapper for SQL Developer).

break on owner on name skip 1 on type
SELECT s.owner, s.type, s.name, h.function, s.line, 
       h.function_elapsed_time/1e6 function_elapsed_time, h.calls, s.text
FROM   all_source s
  LEFT OUTER JOIN dbmshp_function_info h
    ON s.owner = h.owner and s.name = h.module and s.type = h.type and s.line = h.line# and h.runid = 3
WHERE ((         s.owner = 'XXXXX_CUST'
             AND s.name = 'CUST_PARALLEL_JOBS'
             AND s.type = 'PACKAGE BODY'
             AND s.line between 100 and 300
       ) OR (    s.owner = 'XXXXX_SCHEDULER'
             AND s.name = 'SCHEDULER_ENGINE'
             AND s.type = 'PACKAGE BODY'
             AND s.line between 770 and 858
      ))
ORDER BY s.owner, s.name, s.type, s.line
/

Now, I can scan through the code and see how the code blocks were called.

                                                                                     Function
                                                                                      Elapsed
OWNER           TYPE         NAME                 FUNCTION                   LINE        Time   CALLS TEXT
--------------- ------------ -------------------- ------------------------- ----- ----------- ------- -------------------------------------------------------------------------------------------------------------
XXXXX_CUST      PACKAGE BODY CUST_PARALLEL_JOBS   CUST_SIMULATE_SURRENDER     105     .001232       1 PROCEDURE Cust_Simulate_Surrender (pi_bus_in IN SrvContext, pio_err  IN OUT SrvErr)
                                                                              106                     IS
…
                                                                              213                                     -- run current job when it is not started yet
                                                                              214                                     IF l_cfg_tbl(indx_job).allowed = 'Y' -- flag Y - to be started
                                                                              215                                     THEN
                                                                              216                                         -- run current job
                                                                              217                                         XXXXX_scheduler.scheduler_engine.Run_Job (l_cfg_tbl(indx_job).XXXXX_job_name);
                                                                              218                                         --XXXXX_scheduler.scheduler_engine.enable_Job (l_cfg_tbl(indx_job).XXXXX_job_name);
…
XXXXX_SCHEDULER PACKAGE BODY SCHEDULER_ENGINE     RUN_JOB                     770     .000176       7 PROCEDURE RUN_JOB( PI_JOB_NAME SCHEDULER_JOBS.JOB_NAME%TYPE )
…
                                                                              778                     IS
                                                                              779                     BEGIN
                                                                              780                         DBMS_SCHEDULER.RUN_JOB(
                                                                              781                             SCHEDULER_UTILS.SCHEMA_OWNER || '."' || PI_JOB_NAME || '"', USE_CURRENT_SESSION=>FALSE );
                                                                              782
                                                                              783
                                                                              784
                                                                              785                         SCHEDULER_UTILS.LOG_AUDIT_EVENT( 'RunJob', TRUE, PI_OBJECT_NAME => PI_JOB_NAME );
                                                                              786                     EXCEPTION
                                                                              787                       WHEN OTHERS THEN
…
                                                                              798                     END;
                                                                              799
                                                                              800
                                                                              801                     --dmk 29.3.2023 added
                                                                              802                     PROCEDURE ENABLE_JOB( PI_JOB_NAME SCHEDULER_JOBS.JOB_NAME%TYPE )
…
                                                                              810                     IS
                                                                              811                     BEGIN
                                                                              812                         DBMS_SCHEDULER.Enable(
                                                                              813                             SCHEDULER_UTILS.SCHEMA_OWNER || '."' || PI_JOB_NAME || '"');
                                                                              814
                                                                              815
                                                                              816
                                                                              817                         SCHEDULER_UTILS.LOG_AUDIT_EVENT( 'Enable_Job', TRUE, PI_OBJECT_NAME => PI_JOB_NAME );
                                                                              818                     EXCEPTION
                                                                              819                       WHEN OTHERS THEN
…
                                                                              830                     END;

By following the profiler data, I have found that DBMS_SCHEDULER.RUN_JOB was used.  I was then able to add an alternative procedure that calls DBMS_SCHEDULER.ENABLE and call that from the custom application code.