Example: Investigating high CPU consumption by a routine
You can use routine monitoring to investigate why a routine is consuming a higher than expected amount of CPU resources.
Scenario
In this example, the database administrator
(DBA) is investigating the performance of a critical stored procedure
called TEST.PROC1. The TOTAL_ROUTINE_CPU_TIME monitor element that
is returned by the MON_GET_ROUTINE table function shows that the stored
procedure is using a higher than expected amount of CPU resources.
The DBA previously configured the database to track statement information
by routine, using the MON_RTN_EXECLIST database configuration parameter.
The DBA issues the following query to sum the CPU usage for each statement
that is executed by the routine across all members:
WITH TOTAL_STMT_CPU (EXEC_ID, TOTAL_CPU, NUM_ROUTINES, MIN_MEMBER) AS
(SELECT
EXECUTABLE_ID,
SUM(TOTAL_CPU_TIME),
MAX(NUM_ROUTINES),
MIN(MEMBER)
FROM
TABLE(MON_GET_ROUTINE_EXEC_LIST('P', 'TEST', NULL, 'PROC1', -2)) AS T
GROUP BY
EXECUTABLE_ID
),
TOTAL_RTN_CPU (TOTAL_RTN_CPU) AS
(SELECT
SUM(TOTAL_CPU_TIME)
FROM
TABLE(MON_GET_ROUTINE('P', 'TEST', NULL, 'PROC1', -2)) AS R
)
SELECT
B.EXEC_ID,
100*B.TOTAL_CPU / A.TOTAL_RTN_CPU AS PERCENT_CPU,
B.NUM_ROUTINES,
C.STMT_TEXT
FROM
TOTAL_RTN_CPU AS A,
TOTAL_STMT_CPU AS B,
TABLE(MON_GET_PKG_CACHE_STMT(NULL, NULL, NULL, -2)) AS C
WHERE
B.EXEC_ID = C.EXECUTABLE_ID AND
B.MIN_MEMBER = C.MEMBER AND
A.TOTAL_RTN_CPU<>0
ORDER BY
TOTAL_CPU DESC
The result lists the statements executed
by the stored procedure ranked by percentage CPU consumption relative
to the total CPU used by the routine.EXEC_ID PERCENT_CPU NUM_ROUTINES STMT_TEXT
------------------------------------------------------------------- ------------ -------------- --------------------------------------------
x'0100000000000000560100000000000002000000010020120801142628005514' 10 0 WITH GET_UPDATE_LIST (COL1, COL2STATS) AS AF
x'0100000000000000560100000000000002000000010020120801142628005514' 1 0 insert into T1 values(3,'d','d','d')
x'0100000000000000560100000000000001000000010020120801142628005514' 0 1 call SYSIBMSUBROUTINE.P1_66613_1157394573()
3 record(s) selected.
The CPU usage reported for
each statement by the MON_GET_ROUTINE_EXEC_LIST table function does
not include CPU consumed by any child statements. The report that
is generated by MON_GET_ROUTINE_EXEC_LIST shows only the percentage
of CPU consumed by statements invoked directly by the routine. The
DBA can continue the investigation in the following ways:
- If a direct child statement is using most of the CPU, the MON_GET_ROUTINE_EXEC_LIST
report identifies that candidate and the DBA can investigate that
statement. For example, drilling down on the statement that has high
CPU usage using the MON_GET_PKG_CACHE_STMT table function to list
the full set of metrics for all executions of the statement:
SELECT * FROM TABLE(MON_GET_PKG_CACHE_STMT (NULL, '<high_cpu_consuming_exec_id>', NULL, -2)) AS T
- If the output shows that none of the statements that are executed
directly by the routine are using a high amount of CPU, the DBA can
examine the num_routines monitor element that
is listed for each executed statement.
- If num_routines is 0 (zero) for each executed statement, then the high CPU consumption is due to processing in the routine itself.
- If num_routines is
not zero, then the DBA can use the MON_GET_SECTION_ROUTINE table function
to determine the routines that the statement invoked and investigate
if those routines might be contributing to the overall CPU consumption
of TEST.PROC1. For example:
The returned result is:SELECT ROUTINESCHEMA, ROUTINEMODULENAME, ROUTINENAME, SPECIFICNAME FROM TABLE(MON_GET_SECTION_ROUTINE('<exec_id>')) AS T
The DBA can investigate these routines for high CPU consumption, but must keep in mind that the routines might have been called from different contexts other than TEST.PROC1. This means that the metrics returned from MON_GET_SECTION_ROUTINE for these routines might be larger than the metrics for TEST.PROC1.ROUTINESCHEMA ROUTINEMODULENAME ROUTINENAME SPECIFICNAME ----------------- ------------------ --------------------------- ------------- DRICARD - PROC1 PROC1 SYSIBMSUBROUTINE - PROC1_66613_101877843 - 2 record(s) selected