Seeing where time is spent across the system

You can use the time-spent monitor elements to get a view of where time is being spent in the system. Time spent monitor elements can be used to report on specific units of work, service subclasses, workloads or connections.

About this task

Once you retrieve the various monitor elements that report where time is being spent in the system, you can view them in several ways. At the most basic level, you can view the reported values as a list. You might want to use the values to create ratios, for example the ratio of lock wait time to total request time. Or you could use the values retrieved to create charts to help you visualize time spent monitor elements relative to another.

Notes:

The values shown in the output for queries are for illustrative purposes only, and should not be construed as representative of what you might see in your own system.
This task shows you how to retrieve specific time-spent monitor elements. You can also use new formatting functions introduced in version 9.7 Fix Pack 1 to retrieve time spent monitor elements that meet specific criteria, such as those with non-zero values, those within a certain range of values that you specify, or the top n monitor element (for example, the top five wait times). Example 4 illustrates how these functions work.

Procedure

First, determine what time-spent elements you are interested in.
For example, you might want to look at total wait time as compared to the total request time for all connections in your system.

Formulate an SQL query that uses one of the monitoring table functions that retrieve the elements you are interested in.

In this case, you can retrieve the total_request_time and the total_wait_time monitor elements for a connection using the MON_GET_CONNECTION table function:

SELECT APPLICATION_HANDLE,
       TOTAL_WAIT_TIME, 
       TOTAL_RQST_TIME 
FROM TABLE(MON_GET_CONNECTION(NULL,NULL))

The preceding query will return the following output (times are reported in milliseconds):

APPLICATION_HANDLE   TOTAL_WAIT_TIME      TOTAL_RQST_TIME
-------------------- -------------------- --------------------
                  39                  179                  269
                  78                    0                    0
                  51                  207                  316
                  77                    0                   21
                  50                 1014                 1408
                  40                  109                  351
                  79                   89                  167

  7 record(s) selected.

In this case, there are 7 application connections; you could use the results from the second and third columns to determine the percentage of time spent waiting for each application.
For example, for application 50, compared to the total request time, the wait time spent by that application is (1014 ÷ 1408) × 100 ≈ 72%.

Example

Example 1: Determining the average across all connections of the time spent waiting relative to overall request time.

This example is similar to the preceding one, except that the calculation of the average percentage wait time is done within the SQL:

WITH PCTWAIT AS (
     SELECT SUM(TOTAL_WAIT_TIME)AS WAIT_TIME, 
            SUM(TOTAL_RQST_TIME)AS RQST_TIME 
     FROM TABLE(MON_GET_CONNECTION(NULL,NULL)) AS METRICS)
     SELECT WAIT_TIME,
            RQST_TIME,
     CASE WHEN RQST_TIME > 0 
     THEN DEC((FLOAT(WAIT_TIME))/FLOAT(RQST_TIME) * 100,5,2) 
     ELSE NULL END AS WAIT_PCT FROM PCTWAIT

The results of running the preceding query would look something like this:

WAIT_TIME            RQST_TIME            WAIT_PCT
-------------------- -------------------- --------
                1515                 2439    62.11

  1 record(s) selected.

Example 2: Comparing total wait time against selected component processing times for a specific service subclass

This example shows how you can compare time spent in specific types of component processing with the time spent waiting:

SELECT SUM(TOTAL_WAIT_TIME) AS WAIT,
       SUM(TOTAL_COMPILE_PROC_TIME) AS COMPILE,
       SUM(TOTAL_IMPLICIT_COMPILE_PROC_TIME) AS IMP_COMPILE,
       SUM(TOTAL_SECTION_PROC_TIME) AS SECTION,
       SUM(TOTAL_COMMIT_PROC_TIME) AS COMMIT,
       SUM(TOTAL_REORG_PROC_TIME) AS REORG,
       SUM(TOTAL_RUNSTATS_PROC_TIME) AS RUNSTATS,
       SUM(TOTAL_ROLLBACK_PROC_TIME) AS ROLLBACK,
       SUM(TOTAL_LOAD_PROC_TIME) AS LOAD
 FROM TABLE(MON_GET_SERVICE_SUBCLASS( 'SYSDEFAULTUSERCLASS','SYSDEFAULTSUBCLASS',NULL))

The results of the preceding query would look something like this (the output rows from the query have been split for presentation purposes):


WAIT                 COMPILE              IMP_COMPILE          SECTION              COMMIT               
-------------------- -------------------- -------------------- -------------------- -------------------- 
                 611                 1931                    0                  395                   15 
                                                                                                                                                                                 
REORG                RUNSTATS             ROLLBACK             LOAD                                      
-------------------- -------------------- -------------------- --------------------                      
                   0                  432                   18                    0                      
                                                                                                         
                                                                                                         
  1 record(s) selected.

The numbers reported could be used to construct a pie chart to show the relative time spent waiting as compared to time spent in different stages of processing (component times of 0 are not included):

Pie chart, showing wait and processing times relative to one another.

Example 3: View the ratio of total time spent as compared to processing time in different components

This example shows you how you can get an overview of the time spent doing work in different stages of processing (components), relative to the total time spent in that component. The following query computes the ratio (expressed as a percentage) of the time spent in actual processing as compared to the total elapsed time spent in a specific component.

WITH PCTPROC AS (
     SELECT SUM(TOTAL_SECTION_TIME) AS SECT_TIME, SUM(TOTAL_SECTION_PROC_TIME) AS SECT_PROC_TIME, 
            SUM(TOTAL_COMPILE_TIME) AS COMP_TIME, SUM(TOTAL_COMPILE_PROC_TIME) AS COMP_PROC_TIME,
            SUM(TOTAL_IMPLICIT_COMPILE_TIME) AS IMP_C_TIME, SUM(TOTAL_IMPLICIT_COMPILE_PROC_TIME) AS IMP_C_PROC_TIME,
            SUM(TOTAL_COMMIT_TIME) AS COMMIT_TIME, SUM(TOTAL_COMMIT_PROC_TIME) AS COMMIT_PROC_TIME,
            SUM(TOTAL_ROLLBACK_TIME) AS ROLLBACK_TIME, SUM(TOTAL_ROLLBACK_PROC_TIME) AS ROLLBACK_PROC_TIME,
            SUM(TOTAL_RUNSTATS_TIME) AS RUNSTATS_TIME, SUM(TOTAL_RUNSTATS_PROC_TIME)AS RUNSTATS_PROC_TIME,
            SUM(TOTAL_REORG_TIME) AS REORG_TIME, SUM(TOTAL_REORG_PROC_TIME) AS REORG_PROC_TIME,
            SUM(TOTAL_LOAD_TIME) AS LOAD_TIME, SUM(TOTAL_LOAD_PROC_TIME) AS LOAD_PROC_TIME
     FROM TABLE(MON_GET_CONNECTION(NULL, -2)) AS METRICS)
     SELECT CASE WHEN SECT_TIME > 0 
                 THEN DEC((FLOAT(SECT_PROC_TIME) / FLOAT(SECT_TIME)) * 100,5,1) 
                 ELSE NULL END AS SECT_PROC_PCT,
            CASE WHEN COMP_TIME > 0 
                 THEN DEC((FLOAT(COMP_PROC_TIME) / FLOAT(COMP_TIME)) * 100,5,1) 
                 ELSE NULL END AS COMPILE_PROC_PCT,
            CASE WHEN IMP_C_TIME > 0 
                 THEN DEC((FLOAT(IMP_C_PROC_TIME) / FLOAT(IMP_C_TIME)) * 100,5,1) 
                 ELSE NULL END AS IMPL_COMPILE_PROC_PCT,
              CASE WHEN ROLLBACK_TIME > 0 
                 THEN DEC((FLOAT(ROLLBACK_PROC_TIME) / FLOAT(ROLLBACK_TIME)) * 100,5,1) 
                 ELSE NULL END AS ROLLBACK_PROC_PCT,
              CASE WHEN COMMIT_TIME > 0 
                 THEN DEC((FLOAT(COMMIT_PROC_TIME) / FLOAT(COMMIT_TIME)) * 100,5,1) 
                 ELSE NULL END AS COMMIT_PROC_PCT,
              CASE WHEN RUNSTATS_TIME > 0 
                 THEN DEC((FLOAT(RUNSTATS_PROC_TIME) / FLOAT(RUNSTATS_TIME)) * 100,5,1) 
                 ELSE NULL END AS RUNSTATS_PROC_PCT,
            CASE WHEN REORG_TIME > 0 
                 THEN DEC((FLOAT(REORG_PROC_TIME) / FLOAT(REORG_TIME)) * 100,5,1) 
                 ELSE NULL END AS REORG_PROC_PCT,
            CASE WHEN LOAD_TIME > 0 
                 THEN DEC((FLOAT(LOAD_PROC_TIME) / FLOAT(LOAD_TIME)) * 100,5,1) 
                 ELSE NULL END AS LOAD_PROC_PCT
       FROM PCTPROC

The query produces the following output:

SECT_PROC_PCT COMPILE_PROC_PCT IMPL_COMPILE_PROC_PCT ROLLBACK_PROC_PCT COMMIT_PROC_PCT RUNSTATS_PROC_PCT REORG_PROC_PCT LOAD_PROC_PCT
------------- ---------------- --------------------- ----------------- --------------- ----------------- -------------- -------------
         57.6              0.1                     -              96.9            95.6               0.0           71.1          84.6
  1 record(s) selected.

A graphical representation of this data might look something like what is shown in Figure 1:

Stacked bar chart showing processing times plus other times, adding up to 100 percent for various components. — Figure 1. Component processing times as a percentage of overall time spent

Example 4: Ranking time-spent monitor elements

In the preceding examples, all monitor elements that are displayed are specified explicitly in the SQL for the query; each appears in its own column in the query results. However, there might be times when you do not know which time spent monitor elements you want to examine, such as if you want to see the top ten wait-time monitor elements, or only the non-zero time-spent monitor elements.

Several table functions enable you to display monitor elements in a row-oriented format, where each element appears in a row by itself. The table functions you can use to do this have names of the form MON_FORMAT_XML_* _BY_ROW. These functions extract metrics from XML documents returned by certain monitoring interfaces. (See Interfaces that return monitor data in XML documents for more information.)

The MON_FORMAT_XML_* _BY_ROW functions are useful when you do not know which elements you want to view. For example, you might want to see the top 10 wait-time monitor elements for the workload named CLPWORKLOAD. To collect this information, you can create a statistics event monitor called DBSTATS (event_wlstats logical data group). Assuming you set up this event monitor to write to a table, it records metrics in a column called DETAILS_XML in the table called WLSTATS_DBSTATS by default. Once the output table from the event monitor is populated with monitor data, you can construct a query that uses the MON_FORMAT_XML_WAIT_TIMES_BY_ROW function to extract the monitor elements you want to see:

SELECT SUBSTR(STATS.WORKLOAD_NAME,1,15) AS WORKLOAD_NAME,
       SUBSTR(METRICS.METRIC_NAME,1,30) AS METRIC_NAME, 
       SUM(METRICS.TOTAL_TIME_VALUE) AS TOTAL_TIME_VALUE
FROM   WLSTATS_DBSTATS AS STATS, 
       TABLE(MON_FORMAT_XML_WAIT_TIMES_BY_ROW(STATS.DETAILS_XML)) AS METRICS 
WHERE  WORKLOAD_NAME='CLPWORKLOAD' AND (PARENT_METRIC_NAME='TOTAL_WAIT_TIME')
GROUP  BY WORKLOAD_NAME,METRIC_NAME 
ORDER  BY TOTAL_TIME_VALUE DESC
FETCH FIRST 10 ROWS ONLY

Remember: Time spent monitor elements are organized into hierarchies. In this example, to avoid double-counting wait times, only the monitor elements that roll-up to total_wait_time are included (see the WHERE clause in the preceding SQL statement). Otherwise, total_wait_time itself would be included in the results, which includes several individual wait times.

The output that follows shows what the results of the preceding query might look like:

WORKLOAD_NAME   METRIC_NAME                    TOTAL_TIME_VALUE
--------------- ------------------------------ --------------------
CLPWORKLOAD     LOCK_WAIT_TIME                             15138541
CLPWORKLOAD     DIRECT_READ_TIME                            6116231
CLPWORKLOAD     POOL_READ_TIME                              6079458
CLPWORKLOAD     DIRECT_WRITE_TIME                            452627
CLPWORKLOAD     POOL_WRITE_TIME                              386208
CLPWORKLOAD     IPC_SEND_WAIT_TIME                           283172
CLPWORKLOAD     LOG_DISK_WAIT_TIME                           103888
CLPWORKLOAD     DIAGLOG_WRITE_WAIT_TIME                       78198
CLPWORKLOAD     IPC_RECV_WAIT_TIME                            15612
CLPWORKLOAD     TCPIP_SEND_WAIT_TIME                           3291

  10 record(s) selected.