6.5.  Use the Performance Monitoring Infrastructure (PMI) metrics and poll MBeans for performance data.


Request Metrics

Request metrics (RM) is a tool that enables you to track individual transactions, recording the processing time in each of the major WebSphere Application Server components.

Compared to Application Server's Performance Monitoring Infrastructure (PMI), RM does not provide statistical estimates for system resources usage, yet it can illustrate a detailed end-to-end flow of the transaction, usually dependent on the requested data sent to WebSphere Application Server applications.

Typically, different components of the enterprise application might be hosted across several nodes in a distributed system. For example, the servlets might be hosted on one node, while the enterprise beans on which these servlets depend might be hosted on an entirely different node. When a request comes to a process, the process might send the request to one or more downstream processes, as shown in the following figure:

Figure 6.26. Request flow

Request flow

Trace records might be generated for each process with associated elapsed times for that process. These trace records might be correlated together to build a complete picture of the request flow through the distributed system.

You can view the process response time that is monitored by request metrics through the Application Response Measurement (ARM) interface and System Out log files. When a request is sent to the application server, request metrics captures response times for the initiating request and any related downstream invocations. Request metrics are instrumented in the following components as the request, for example, transaction, travels through the web server, Proxy Server and the application server:

Select the components that you want to instrument. For example, if you want instrumentation data only for the web container and the JMS API, select this data in the administrative console and the detailed instrumentation data is generated only for the components that you select. The edge transactions are traced for the other components that are not specified for instrumentation.

When filtering is enabled, only requests that match the filter generate request metrics data, create log records, or call the ARM interfaces. You can add work into a running system specifically to generate trace information to evaluate the performance of specific types of requests in the context of normal load, ignoring requests from other sources that might affect the system. If the request matches any filter with a trace level greater than None, trace records are generated for that request.

Configuring Request Metrics

WAS RM instrumentation behavior is controlled through the Integrated Solutions Console (ISC) on a dedicated Request Metrics page. To start using RM, some generic configuration is required. In some cases, additional RM filtering functionality may be useful.

To configure RM in the WAS runtime, you need to open the Process Server ISC in your Web browser and perform the following steps:

  1. In the navigation tree, expand Monitoring and Tuning:

    Figure 6.27. 

  2. Click Request metrics.

  3. Enable RM by checking the Prepare Servers for Request metrics collection checkbox.

    Figure 6.28. 

  4. Specify Components to be instrumented by selecting an option from:

    1. None: RM instrumentation is disabled.

    2. All: RM data will be collected for all components listed under the "Custom" list (see below).

    3. Custom: Specify a set of components for which RM instrumentation will be enabled. You can select any combination from the provided list: AsyncBeans, EJB, JCA, JDBC, JMS, JNDI, portlet, SIB, servlet, servlet filter, and Web services.

    Figure 6.29. 

  5. In the "Trace level" drop down combo box, select from the list how much information to gather:

    1. None: No data at all (RM instrumentation is disabled).

    2. Hops: Collecting information on process boundaries only.

    3. Performance_debug: At the "Hops" level, plus one additional (first) level of the intra-process servlet and Enterprise JavaBeans (EJB) call.

    4. Debug: Detailed information with response times for all intra-process calls.

    Figure 6.30. 

  6. In the "Request Metrics Destination" section, check where the RM data will be sent to:

    1. Standard Logs: RM records will be written to the SystemOut.log file.

      As your RM records will be written into the WAS standard logs (SystemOut.log file), you need to check the current configuration of the JVM logs for your WAS to ensure none of your measurement data will be lost. This might be the case if you rely on the default settings of "Log File Rotation" based on the "File Size" with 1 MB value and 1 historical log file. The recommended changes for SystemOut.log are as follows:

      • The Log File RotationFile Size checkbox is set (no change here), Maximum Size is set to 5 MB.

      • For the Maximum Number of Historical Log Files, change from 1 to 10.

      You can set these values via ISC, for example, in the following path: Troubleshooting > Logs and trace > Logging and Tracing > your_server_name> > JVM Logs

      Figure 6.31. 

    2. Application Response Measurement (ARM) agent: RM will use an underlying ARM infrastructure via specified ARM agent calls. By choosing that option, you need to specify two additional parameters:

      • Agent Type: Select between ARM40 and TIVOLI_ARM.

      • ARM transaction factory implementation class name (value needed only if the ARM40 option above is selected): Enter the name of the ARM transaction factory implementation class that is present in the ARM library.

      Note: Before enabling ARM, you need to install an ARM agent and configure it to the appropriate classpath and path, following the instructions of the ARM provider.

    Figure 6.32. 

  7. Confirm your configuration by clicking the "Apply" button.

    Save the changes and restart the server.

    test317:~ # cd /opt/IBM/WebSphere/AppServer/profiles/AppSrv01/bin
    test317:/opt/IBM/WebSphere/AppServer/profiles/AppSrv01/bin # ./stopServer.sh server1
    ADMU0116I: Tool information is being logged in file
    ADMU0128I: Starting tool with the AppSrv01 profile
    ADMU3100I: Reading configuration for server: server1
    ADMU3201I: Server stop request issued. Waiting for stop status.
    ADMU4000I: Server server1 stop completed.
    test317:/opt/IBM/WebSphere/AppServer/profiles/AppSrv01/bin # ./startServer.sh server1
    ADMU0116I: Tool information is being logged in file
    ADMU0128I: Starting tool with the AppSrv01 profile
    ADMU3100I: Reading configuration for server: server1
    ADMU3200I: Server launched. Waiting for initialization status.
    ADMU3000I: Server server1 open for e-business; process id is 64187
    test317:/opt/IBM/WebSphere/AppServer/profiles/AppSrv01/bin #

Now you can turn to the tool you have chosen for sending input requests to the tested WAS application and start providing it with the prepared request. Wait for a response and repeat that action at least twice again to have some statistical sample for your test case.

Figure 6.33. 

Extracting Request Metrics data from SystemOut log files

Your RM records will be collected not only in the most current SystemOut.log file, but they may be spread throughout other historical SystemOut_*.log files. The reasons for that may be as follows:

Another issue is that your RM records are just one type of entry, as there are other types being written to the SystemOut.log file. Hence, to focus on analyzing the collected RM records only, you will need to extract those RM entries from the log files.

You can use the Unix-like search tool called grep (offered in many flavors for the Windows systems as well) to pre-process your SystemOut_*.log files to extract the required RM record entries. That tool is chosen for the following reasons:

For example, to prepare a new data file RMrecords.txt that contains only RM record entries extracted from your SystemOut_*.log files, the following command typed in the WAS logs directory is required:

test317:/opt/IBM/WebSphere/AppServer/profiles/AppSrv01/logs/server1 # ls -al
total 1932
drwxr-xr-x 4 root root    4096 Aug 10 15:29 .
drwxr-xr-x 7 root root    4096 Jul  6 10:05 ..
-rw-r--r-- 1 root root   51072 Jul  1 10:14 SystemErr.log
-rw-r--r-- 1 root root  478754 Aug 10 15:38 SystemOut.log
-rw-r--r-- 1 root root 1046393 Jul  1 11:29 SystemOut_13.07.01_11.29.54.log
drwxr-xr-x 4 root root    4096 Jul  6 16:33 logdata
-rw-r--r-- 1 root root    5780 Aug 10 15:29 native_stderr.log
-rw-r--r-- 1 root root   43007 Aug 10 15:29 native_stdout.log
-rw-r--r-- 1 root root       5 Aug 10 15:29 server1.pid
-rw-r--r-- 1 root root   44110 Aug 10 15:29 startServer.log
-rw-r--r-- 1 root root   32942 Aug 10 15:25 stopServer.log
-rw-r--r-- 1 root root  223442 Aug 10 15:38 trace.log
drwxr-xr-x 3 root root    4096 Jul  6 16:33 tracedata

test317:/opt/IBM/WebSphere/AppServer/profiles/AppSrv01/logs/server1 # grep "PMRM0003I" SystemOut*.log > RMrecords.txt

The sample content of the RMrecords.txt file with the RM record entries extracted from multiple SystemOut_*.log files is presented below:

test317:/opt/IBM/WebSphere/AppServer/profiles/AppSrv01/logs/server1 # cat RMrecords.txt
SystemOut.log:[8/10/13 15:38:50:516 EDT] 00000022 PmiRmArmWrapp I   PMRM0003I:  parent:ver=1,ip=,time=1376162968376,pid=64187,reqid=1,event=1 - current:ver=1,ip=,time=1376162968376,pid=64187,reqid=2,event=1 type=JDBC detail=javax.resource.spi.ManagedConnectionFactory.createConnectionFactory(ConnectionManager) elapsed=88
SystemOut.log:[8/10/13 15:38:54:101 EDT] 00000022 PmiRmArmWrapp I   PMRM0003I:  parent:ver=1,ip=,time=1376162968376,pid=64187,reqid=1,event=1 - current:ver=1,ip=,time=1376162968376,pid=64187,reqid=3,event=1 type=JDBC detail=javax.resource.spi.ManagedConnectionFactory.createManagedConnection(Subject, ConnectionRequestInfo) elapsed=3493
SystemOut.log:[8/10/13 15:38:54:108 EDT] 00000022 PmiRmArmWrapp I   PMRM0003I:  parent:ver=1,ip=,time=1376162968376,pid=64187,reqid=1,event=1 - current:ver=1,ip=,time=1376162968376,pid=64187,reqid=4,event=1 type=JDBC detail=javax.resource.spi.ManagedConnectionFactory.matchManagedConnections(Set, Subject, ConnectionRequestInfo) elapsed=4
SystemOut.log:[8/10/13 15:38:54:134 EDT] 00000022 PmiRmArmWrapp I   PMRM0003I:  parent:ver=1,ip=,time=1376162968376,pid=64187,reqid=1,event=1 - current:ver=1,ip=,time=1376162968376,pid=64187,reqid=5,event=1 type=JDBC detail=javax.resource.spi.ManagedConnection.getConnection(Subject, ConnectionRequestInfo) elapsed=22
SystemOut.log:[8/10/13 15:38:54:145 EDT] 00000022 PmiRmArmWrapp I   PMRM0003I:  parent:ver=1,ip=,time=1376162968376,pid=64187,reqid=1,event=1 - current:ver=1,ip=,time=1376162968376,pid=64187,reqid=1,event=1 type=URI detail=/testdsweb/test.jsp elapsed=5498
test317:/opt/IBM/WebSphere/AppServer/profiles/AppSrv01/logs/server1 #

The created data file is a convenient text input to further process your RM measurement results.

Professional hosting         Free 'Oracle Certified Expert Web Services Developer 6' Guide     Free SCDJWS 5.0 Guide