Example: Investigating high CPU consumption by a routine

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:

    SELECT 
       ROUTINESCHEMA, ROUTINEMODULENAME, ROUTINENAME, SPECIFICNAME  
       FROM TABLE(MON_GET_SECTION_ROUTINE('<exec_id>')) AS T 

    The returned result is:

    ROUTINESCHEMA     ROUTINEMODULENAME  ROUTINENAME                 SPECIFICNAME 
    ----------------- ------------------ --------------------------- -------------
    DRICARD           -                  PROC1                       PROC1        
    SYSIBMSUBROUTINE  -                  PROC1_66613_101877843       -            
    
      2 record(s) selected

    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.