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:
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:
the web server plug-in which is only available when using the web server port.
the Proxy Server, instrumented as servlet and web services requests.
the web container, including servlet and servlet filters.
the Enterprise JavaBeans (EJB) container.
Java DataBase Connectivity (JDBC) calls.
Java EE Connector Architecture (JCA).
Web services, both on the server and the client side.
the Java Message Service (JMS) engine.
Service Integration Bus (SIB).
Portlet container, including the portlet requests.
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:
In the navigation tree, expand Monitoring and Tuning:
Click Request metrics.
Enable RM by checking the Prepare Servers for Request metrics collection checkbox.
Specify Components to be instrumented by selecting an option from:
None: RM instrumentation is disabled.
All: RM data will be collected for all components listed under the "Custom" list (see below).
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.
In the "Trace level" drop down combo box, select from the list how much information to gather:
None: No data at all (RM instrumentation is disabled).
Hops: Collecting information on process boundaries only.
Performance_debug: At the "Hops" level, plus one additional (first) level of the intra-process servlet and Enterprise JavaBeans (EJB) call.
Debug: Detailed information with response times for all intra-process calls.
In the "Request Metrics Destination" section, check where the RM data will be sent to:
Standard Logs: RM records will be written to the
As your RM records will be written into the WAS standard logs (
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 Rotation – File 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
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
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
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.
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 /opt/IBM/WebSphere/AppServer/profiles/AppSrv01/logs/server1/stopServer.log 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 /opt/IBM/WebSphere/AppServer/profiles/AppSrv01/logs/server1/startServer.log 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.
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:
The amount of RM data gathered during test measurement.
The current configuration of the JVM logs for your server.
The size of the
SystemOut.log file just before the test measurement.
Another issue is that your RM records are just one type of entry, as there are other types being written to
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:
Every RM record in the
SystemOut_*.log file is distinguished by the
string. It searches an input file for lines containing a match to a specified pattern. This is a fundamental
functionality of the
The output of the
grep command is simply lines matching a given pattern, so it can be easily
redirected to another file.
grep command can search in one or more input files. When there are matches in many input
grep adds a unique string at the beginning of a matching line as a
so you can identify a source file of that line directly.
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=192.168.87.128,time=1376162968376,pid=64187,reqid=1,event=1 - current:ver=1,ip=192.168.87.128,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=192.168.87.128,time=1376162968376,pid=64187,reqid=1,event=1 - current:ver=1,ip=192.168.87.128,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=192.168.87.128,time=1376162968376,pid=64187,reqid=1,event=1 - current:ver=1,ip=192.168.87.128,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=192.168.87.128,time=1376162968376,pid=64187,reqid=1,event=1 - current:ver=1,ip=192.168.87.128,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=192.168.87.128,time=1376162968376,pid=64187,reqid=1,event=1 - current:ver=1,ip=192.168.87.128,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.