Once you have defined the statistics you want to collect in the BMC_DEBUG_STATS_GROUP table, you can apply them to procedures by adding entries to the BMC_DEBUG_PARAMETER table.
To collect statistics for each individual invocation of a procedure, you use the CALL STATS GROUP parameter to assign the appropriate STATS_GROUP. Here is an example :-
SQL> INSERT INTO bmc_debug_stats_group (stats_group,stat_id,stat_name,delta,min_call_stat_value)
VALUES (4,14,'logical reads','Y',null);
1 row created.
SQL> INSERT INTO bmc_debug_stats_group (stats_group,stat_id,stat_name,delta,min_call_stat_value)
VALUES (4,5001,'elapsed time (in seconds)','Y',null);
1 row created.
SQL> commit;
Commit complete.
SQL> SELECT stats_group,stat_id,stat_name,delta,min_call_stat_value FROM bmc_debug_stats_group
WHERE stats_group = 4;
STATS_GROUP STAT_ID STAT_NAME D MIN_CALL_STAT_VALUE
----------- ---------- ------------------------------ - -------------------
4 14 logical reads Y
4 5001 elapsed time (in seconds) Y
So we have defined STATS_GROUP 4 containing two statistics which we want to record. We then apply that group as the CALL STATS GROUP for the procedure we want to monitor :-
SQL> INSERT INTO bmc_debug_parameter (param_name, param_value, inherit, package_name, procedure_name)
VALUES ('CALL STATS GROUP',4,'N','PROCEDURE','CALL_STATS_TEST');
1 row created.
SQL> commit;
Commit complete.
Now we can create and run the procedure CALL_STATS_TEST :-
SQL> CREATE OR REPLACE PROCEDURE call_stats_test (in_order_id IN NUMBER) IS
ct NUMBER;
BEGIN
bmc_debug.begincall('PROCEDURE','CALL_STATS_TEST');
SELECT count(*) INTO ct FROM all_objects;
bmc_debug.endcall('PROCEDURE','CALL_STATS_TEST');
EXCEPTION
WHEN OTHERS THEN
bmc_error.error_handle();
RAISE;
END call_stats_test;
/
Procedure created.
SQL> exec call_stats_test(174);
PL/SQL procedure successfully completed.
When the statistics are recorded, they are stored in the BMC_DEBUG_CALL_STATS table, so if we examine the table we see :-
SQL> SELECT call_date,sid,package_name,procedure_name,stat_name,stat_value FROM bmc_debug_call_stats
WHERE procedure_name = 'CALL_STATS_TEST';
CALL_DATE SID PACKAGE_NAME PROCEDURE_NAME STAT_NAME STAT_VALUE
------------------------------ ------- -------------------- -------------------- ------------------------------ ----------
09-NOV-14 08.44.17.529001 29 PROCEDURE CALL_STATS_TEST logical reads 14277
09-NOV-14 08.44.17.529001 29 PROCEDURE CALL_STATS_TEST elapsed time (in seconds) 0.22
So when the CALL_STATS_TEST procedure ran :-
It called BEGINCALL, which looked at the BMC_DEBUG_PARAMETER table to find the CALL STATS GROUP it should run with.
It was allocated group 4 due to the parameter table entry we added, so BEGINCALL collected the initial values of the statistics named in group 4.
The procedure body ran (containing the single SELECT statement)
ENDCALL collected the statistics again, calculated the delta values and stored them in the BMC_DEBUG_CALL_STATS table.
Once you have deployed your instrumented code into your production environment, you can change which statistics are recorded for which procedures simply by changing the contents of the BMC_DEBUG_PARAMETER and BMC_DEBUG_STATS_GROUP tables, without the need for any code changes or redeployment.
Encapsulating parameters in CALL_INFO
As we have previously seen in BEGINCALL and ENDCALL it is advisable to pass the details of a procedures parameters to BEGINCALL as CALL_INFO. We've seen one use of this in the section on The Generic Exception Handler where the error trace for an unhandled exception includes the procedures parameters from the CALL_INFO value.
Another reason for setting CALL_INFO is that the value is stored in the BMC_DEBUG_CALL_STATS table for any statistics recorded for an individual call. This is particularly useful when you define a MIN_CALL_STAT_VALUE to conditionally record a statistic which is above a set threshold, as the CALL_INFO value will hold the parameters which were passed into the procedure to cause the high statistic value.
Here is a modified version of the above procedure, which passes a string encapsulating the parameters as the 3rd argument to BEGINCALL :-
SQL> CREATE OR REPLACE PROCEDURE call_stats_test (in_order_id IN NUMBER) IS
ct NUMBER;
BEGIN
bmc_debug.begincall('PROCEDURE','CALL_STATS_TEST','order_id='||in_order_id);
SELECT count(*) INTO ct FROM all_objects;
bmc_debug.endcall('PROCEDURE','CALL_STATS_TEST');
EXCEPTION
WHEN OTHERS THEN
bmc_error.error_handle();
RAISE;
END call_stats_test;
/
Procedure created.
SQL> DELETE FROM bmc_debug_call_stats;
2 rows deleted.
SQL> COMMIT;
Commit complete.
SQL> exec call_stats_test(174);
PL/SQL procedure successfully completed.
So we delete the old rows from the BMC_DEBUG_CALL_STATS table, and run the new procedure. If we query the table, we see :-
SQL> SELECT call_date,sid,package_name,procedure_name,stat_name,stat_value,call_info FROM bmc_debug_call_stats
WHERE procedure_name = 'CALL_STATS_TEST' and CALL_INFO IS NOT NULL;
CALL_DATE SID PACKAGE_NAME PROCEDURE_NAME STAT_NAME STAT_VALUE CALL_INFO
------- ------- -------------------- -------------------- ------------------------- ---------- -------------------------------
09-NOV-14 29 PROCEDURE CALL_STATS_TEST logical reads 14277 order_id=174
09-NOV-14 29 PROCEDURE CALL_STATS_TEST elapsed time (in seconds) 0.22 order_id=174
So the parameters passed in to the procedure are recorded along with the statistics.
Intermediate Call Stats
The statistics which are recorded via CALL STATS GROUP represent the entire execution of a procedure, from the execution of BEGINCALL to the execution of ENDCALL.
It is also possible to record statistics at intermediate points during the execution of a procedure, if that procedure takes a long time to execute or uses a lot of resources and a more detailed breakdown of statistics for its execution is required.
Code which allows recording of intermediate call stats contains calls to BMC_DEBUG.RECORD_CALL_STATS. Here is an example :-
SQL> INSERT INTO bmc_debug_parameter (param_name, param_value, inherit, package_name, procedure_name)
VALUES ('CALL STATS GROUP',4,'N','PROCEDURE','INTERMEDIATE_TEST');
1 row created.
SQL> commit;
Commit complete.
SQL> CREATE OR REPLACE PROCEDURE intermediate_test IS
ct NUMBER;
BEGIN
bmc_debug.begincall('PROCEDURE','INTERMEDIATE_TEST');
-- Do something which takes a few seconds
select count(*) INTO ct FROM user_source,user_objects;
-- Record intermediate call stats at this point
bmc_debug.record_call_stats ('HALFWAY');
-- Do something else which takes a few seconds
select count(*) INTO ct FROM user_objects,user_objects;
bmc_debug.endcall('PROCEDURE','INTERMEDIATE_TEST');
END intermediate_test;
/
Procedure created.
SQL> exec intermediate_test;
PL/SQL procedure successfully completed.
If we look at the rows written to the BMC_DEBUG_CALL_STATS table for this procedure, including the columns BEGIN_STEP and END_STEP :-
SQL> SELECT call_date,sid,procedure_name,stat_name,stat_value,begin_step,end_step FROM bmc_debug_call_stats
WHERE procedure_name = 'INTERMEDIATE_TEST';
CALL_DATE SID PROCEDURE_NAME STAT_NAME STAT_VALUE BEGIN_STEP END_STEP
------------------------------ ---------- ---------------------- -------------------------- ---------- ---------- --------
14-NOV-2014 06.35.59.385929 143 INTERMEDIATE_TEST elapsed time (in seconds) .02 BEGIN HALFWAY
14-NOV-2014 06.35.59.385929 143 INTERMEDIATE_TEST elapsed time (in seconds) .01 HALFWAY END
14-NOV-2014 06.35.59.385929 143 INTERMEDIATE_TEST elapsed time (in seconds) .03 BEGIN END
14-NOV-2014 06.35.59.385929 143 INTERMEDIATE_TEST logical reads 3288 BEGIN HALFWAY
14-NOV-2014 06.35.59.385929 143 INTERMEDIATE_TEST logical reads 2452 HALFWAY END
14-NOV-2014 06.35.59.385929 143 INTERMEDIATE_TEST logical reads 5740 BEGIN END
So the procedure runs with CALL STATS GROUP 4 to record two statistics, and also includes a call to BMC_DEBUG.RECORD_CALL_STATS which records an intermediate stats point called 'HALFWAY'. The result of this is that the are 3 rows in BMC_DEBUG_CALL_STATS are recorded for each statistic, the values being between BEGINCALL and the HALFWAY mark, between HALFWAY and ENDCALL, and the total values between BEGINCALL and ENDCALL. Those ranges are shown in the BEGIN_STEP and END_STEP columns.