How to use IBM Java -Xtrace

If Java method A calls Java method B, then you can determine the relative performance by timing both method calls. A sampling profiler such as IBM Java Health Center cannot do this deterministically, and a tracing profiler such as IBM Rational Agent Controller tends to take more time to configure and analyze, although essentially we will be using -Xtrace as a tracing profiler.

1. Determine the -Xtrace specification of methods A and B: http://pic.dhe.ibm.com/infocenter/java7sdk/v7r0/topic/com.ibm.java.lnx.70.doc/diag/tools/trace_options_method.html

2. Add the following generic JVM argument (http://www.ibm.com/support/docview.wss?uid=swg21417365), replacing 'METHODS' with the set of methods from #1 above:

"-Xtrace:none,output={methods%p_#.trc,100m,5},maximal=mt,methods={METHODS}"

For example:

"-Xtrace:none,output={methods%p_#.trc,100m,5},maximal=mt,methods={com/ibm/ws/webcontainer/channel/WCChannelLink.ready,com/ibm/ws/webcontainer/servlet/ServletWrapper.service,com/ibm/ws/wswebcontainer/stats/ServletPmiModule.decRequests,com/ibm/BaseServlet.service}"

Note: The entire argument should be double quoted. If a set of generic JVM arguments already exists, append this new argument to the end, but only double quote this argument, not the entire set of JVM arguments. For example, -Xgcpolicy:gencon "-Xtrace..."

3. Save, synchronize, and restart the JVM.

4. Reproduce the problem.

5. Gracefully stop the JVM.

6. Log files named methods${PID_NUMBER}.trc will be written to the current working directory of the JVM, which is normally the profile directory (i.e. where javacores go by default).

7. For each file, execute the following command:

${WebSphere}/java/bin/java com.ibm.jvm.TraceFormat methodsPID_NUMBER.trc methodsPID_NUMBER.trc.txt -indent

For example:

${WebSphere}/java/bin/java com.ibm.jvm.TraceFormat methods15110_0.trc methods15110_0.trc.txt -indent

8. Create a ZIP of the method trace files and formatting data files:

${WebSphere}/java/bin/jar cvf methodtrace.jar methods*trc* ${WebSphere}/java/jre/lib/J9TraceFormat.dat ${WebSphere}/java/jre/lib/TraceFormat.dat

9. Upload methodtrace.jar along with WAS and other logs.

If the following two conditions are true:

1. Method B is not called by anyone outside of method A.
2. For every single call of method A, there is exactly one call of method B.

Then, simply load the .trc files directly into IBM Monitoring and Diagnostic Tools for Java - Health Center (File > Load Data). This should automatically show the Method Trace view which aggregates the timings of each method. For example:

Count Total Time Max Time Mean Time Method Name
2 61050 ms 60008 ms 30525 ms com.ibm.ws.webcontainer.WebContainer.handleRequest...
2 61016 ms 60005 ms 30508 ms com.ibm.BaseServlet.service...

Confirm the prerequisite conditions above by ensuring that the "Count" numbers match.

In this case, we can conclude that method B (com.ibm.BaseServlet.service) is taking the majority of the time of the containing method A call (61016/61050 = 99.9%). This concludes that method A is not the cause of the delay and method B needs to be investigated further. If, on the other hand, there was a significant delta between method A and method B, then the activity of method A (excluding the activity of method B) is a candidate for the delay (depending on how much the difference is and the expectation for how much work it should be doing relative to method A).

If the two conditions are not true, then the trc.txt files must be analyzed to take into account the calling pattern. For example:

20:39:36.640863000 *0xcf9d5500 mt.0 Entry >com/ibm/ws/webcontainer/WebContainer.handleRequest(Lcom/ibm/websphere/servlet/request/IRequest;Lcom/ibm/websphere/servlet/response/IResponse;)V Bytecode method, This = 0xf48123b0
20:39:36.670827000 0xcf9d5500 mt.0 Entry >com/ibm/BaseServlet.service(Ljavax/servlet/http/HttpServletRequest;Ljavax/servlet/http/HttpServletResponse;)V Bytecode method, This = 0xf13a71b0
20:39:37.681781000 0xcf9d5500 mt.6 Exit <com/ibm/BaseServlet.service(Ljavax/servlet/http/HttpServletRequest;Ljavax/servlet/http/HttpServletResponse;)V Bytecode method
20:39:37.682997000 0xcf9d5500 mt.6 Exit <com/ibm/ws/webcontainer/WebContainer.handleRequest(Lcom/ibm/websphere/servlet/request/IRequest;Lcom/ibm/websphere/servlet/response/IResponse;)V Bytecode method
20:39:40.052976000 0xcf9d5500 mt.0 Entry >com/ibm/ws/webcontainer/WebContainer.handleRequest(Lcom/ibm/websphere/servlet/request/IRequest;Lcom/ibm/websphere/servlet/response/IResponse;)V Bytecode method, This = 0xf48123b0
20:39:40.054371000 0xcf9d5500 mt.0 Entry >com/ibm/BaseServlet.service(Ljavax/servlet/http/HttpServletRequest;Ljavax/servlet/http/HttpServletResponse;)V Bytecode method, This = 0xf13a71b0
20:40:40.059800000 0xcf9d5500 mt.6 Exit <com/ibm/BaseServlet.service(Ljavax/servlet/http/HttpServletRequest;Ljavax/servlet/http/HttpServletResponse;)V Bytecode method
20:40:40.060307000 0xcf9d5500 mt.6 Exit <com/ibm/ws/webcontainer/WebContainer.handleRequest(Lcom/ibm/websphere/servlet/request/IRequest;Lcom/ibm/websphere/servlet/response/IResponse;)V Bytecode method

We can see the same data as above, which is that there are two calls to method A (lines 1 and 5) and two calls to method B (lines 2 and 6). The second column is the thread identifier.

"Note: When tracing to a file, buffers for each thread are written when the buffer is full or when the JVM terminates. If a thread has been inactive for a period of time before JVM termination, what seems to be 'old' trace data is written to the file. When formatted, it then seems that trace data is missing from the other threads, but this is an unavoidable side-effect of the buffer-per-thread design. This effect becomes especially noticeable when you use the generation facility, and format individual earlier generations."