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 2BREAK 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#;
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
…
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;
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
…
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
/
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;
@go-faster.co.uk on BlueSky
Posts
