IBM on troubleshooting Java applications

In a previous entry entitled "What's calling System.gc()?" Ian talked about how to find out what code is calling System.gc() using method trace and the jstacktrace or javadump options.

For users of "IBM Monitoring and Diagnostic Tools for Java - HealthCenter" (Health Center) there's a much simpler mechanism, which I'll cover below.

Detecting the (over) use of System.gc() using Health Center

Health Center provides live monitoring and analysis of a number of areas of a running JVM and application, including Garbage collection (GC). Part of the GC analysis determines if calls to System.gc() are being made, and the rate at which those calls are occurring. If the rate is high, Health Center will flag up a warning or an error in the Status panel: In this case Health Center has highlighted a warning that calls to System.gc() are accounting for 15% of the GC cycles.
 

If your worried about any calls to System.gc(), clicking on the "Garbage Collection" link will give you a more detailed view of GC, including a count of the number of calls to System.gc() (forced GCs), the number of allocation failures (non-forced GCs) and the total number of GC cycles.

Determining what is calling System.gc()

If you want to know what code is making the calls to System.gc(), the "Profiling" link contains the information. Clicking on the link opens the following panel:

This gives a breakdown of the various methods that are being called in the application. If you then filter on "System.gc()", and click on the "Invocation paths" tab in the bottom window, you see the call stack for the calls to System.gc():

In this case, there is only one method calling System.gc(), which is StoreData.run(). If there were multiple methods calling System.gc() then there would be an expandable tree under the System.gc() call, and the percentage against each displayed method would show the rate at which each method is responsible for calling System.gc(). In the case above there is only one caller, it is therefore responsible for 100% of the calls to System.gc().

In the previous entry, I covered how to use the -Xdump option to generate additional information when an exception is thrown. In this entry I promised to show how to use a system dump to get more information about a java.net.ConnectException. Below is a worked example of how to do just that!

Generating the exception

In case you want to try this yourself, below is a simple testcase that will generate a java.net.ConnectException (assuming you don't have anything listening to port 100 on your local machine!):

    public void createSocketException(){
    		try {
    			InetAddress address = InetAddress.getLocalHost();
    			Socket theSocket = new Socket(address, 100);
    		} catch (UnknownHostException e) {
    			e.printStackTrace();
    		} catch (IOException e) {
    			e.printStackTrace();
    		}
    	}

    java.net.ConnectException: Connection refused: connect
	at java.net.PlainSocketImpl.socketConnect(Native Method)
	at java.net.PlainSocketImpl.doConnect(PlainSocketImpl.java:352)
	at java.net.PlainSocketImpl.connectToAddress(PlainSocketImpl.java:214)
	at java.net.PlainSocketImpl.connect(PlainSocketImpl.java:201)
	at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:377)
	at java.net.Socket.connect(Socket.java:530)
	at java.net.Socket.connect(Socket.java:480)
	at java.net.Socket.(Socket.java:377)
	at java.net.Socket.(Socket.java:220)

Generating the system dump

As we discussed in the previous entry, the exception can be used as a trigger point for creating a system dump using the following -Xdump option on the command line:

    -Xdump:system:events=throw,range=1..1,filter=java/net/ConnectException

    JVMDUMP006I Processing dump event "throw", detail "java/net/ConnectException" - please wait.
    JVMDUMP032I JVM requested System dump using 'C:\work\tools\Eclipse\workspace\tests\core.20091101.222014.3756.0001.dmp' in response to an event
    JVMDUMP010I System dump written to C:\work\tools\Eclipse\workspace\tests\core.20091101.222014.3756.0001.dmp
    JVMDUMP013I Processed dump event "throw", detail "java/net/ConnectException".
    java.net.ConnectException: Connection refused: connect
    	at java.net.PlainSocketImpl.socketConnect(Native Method)
    	at java.net.PlainSocketImpl.doConnect(PlainSocketImpl.java:352)
    	at java.net.PlainSocketImpl.connectToAddress(PlainSocketImpl.java:214)
    	at java.net.PlainSocketImpl.connect(PlainSocketImpl.java:201)
    	at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:377)
    	at java.net.Socket.connect(Socket.java:530)
    	at java.net.Socket.connect(Socket.java:480)
    	at java.net.Socket.(Socket.java:377)
    	at java.net.Socket.(Socket.java:220)

Running "jextract"

In order for a number of the Java troubleshooting tools supplied by IBM to act on a system dump, it must first be post-processed using a utility called "jextract" that ships with the IBM Java JREs in the jre/bin directory. The jextract utility needs to be run using the JRE that created the system dump, as it creates a metadata file that describes the Java structures in the system dump, and them produces a zip file of the resulting data. This zip file can then be loaded into the tools.

The jextract utility is running using "jextract ", and gives the following output:

    C:\work\tools\Eclipse\workspace\tests>"c:\Program Files\IBM\Java60\jre\bin\jextract.exe" core.20091101.222014.3756.0001.dmp
    Loading dump file...
    Read memory image from core.20091101.222014.3756.0001.dmp
    VM set to 00098088
    Dumping JExtract file to core.20091101.222014.3756.0001.dmp.xml
    <!-- extracting gpf state -->
    <!-- 20ms -->
    <!-- extracting host network data -->
    <!-- 22ms -->
    <!-- extracting classes -->
    ........................<!-- 986ms -->
    <!-- extracting classloaders -->
    <!-- 1050ms -->
    <!-- extracting monitors -->
    <!-- 1185ms -->
    <!-- extracting threads -->
    <!-- 1208ms -->
    <!-- extracting trace buffers -->
    <!-- 1210ms -->
    <!-- extracting roots -->
    ..<!-- 1220ms -->
    <!-- extracting objects -->
    <!-- 1358ms -->
    Finished writing jextract XML file in 1364ms
    Creating archive file: core.20091101.222014.3756.0001.dmp.zip
    Adding "core.20091101.222014.3756.0001.dmp"
    Adding "core.20091101.222014.3756.0001.dmp.xml"
    Adding "C:\Program Files\IBM\Java60\jre\bin\J9HOOKABLE24.dll"
    Adding "C:\Program Files\IBM\Java60\jre\bin\dbghelp.dll"
    Adding "C:\Program Files\IBM\Java60\jre\bin\hyprtshim24.dll"
    Adding "C:\Program Files\IBM\Java60\jre\bin\hythr.dll"
    Adding "C:\Program Files\IBM\Java60\jre\bin\iverel24.dll"
    Adding "C:\Program Files\IBM\Java60\jre\bin\j9bcv24.dll"
    Adding "C:\Program Files\IBM\Java60\jre\bin\j9dmp24.dll"
    Adding "C:\Program Files\IBM\Java60\jre\bin\j9dyn24.dll"
    Adding "C:\Program Files\IBM\Java60\jre\bin\j9gc24.dll"
    Adding "C:\Program Files\IBM\Java60\jre\bin\j9jit24.dll"
    Adding "C:\Program Files\IBM\Java60\jre\bin\j9jvmti24.dll"
    Adding "C:\Program Files\IBM\Java60\jre\bin\j9prt24.dll"
    Adding "C:\Program Files\IBM\Java60\jre\bin\j9thr24.dll"
    Adding "C:\Program Files\IBM\Java60\jre\bin\j9trc24.dll"
    Adding "C:\Program Files\IBM\Java60\jre\bin\j9ute24.dll"
    Adding "C:\Program Files\IBM\Java60\jre\bin\j9vm24.dll"
    Adding "C:\Program Files\IBM\Java60\jre\bin\j9vm\jvm.dll"
    Adding "C:\Program Files\IBM\Java60\jre\bin\j9vrb24.dll"
    Adding "C:\Program Files\IBM\Java60\jre\bin\j9zlib24.dll"
    Adding "C:\Program Files\IBM\Java60\jre\bin\java.dll"
    Adding "C:\Program Files\IBM\Java60\jre\bin\javaw.exe"
    Adding "C:\Program Files\IBM\Java60\jre\bin\jclscar_24.dll"
    Adding "C:\Program Files\IBM\Java60\jre\bin\jsig.dll"
    Adding "C:\Program Files\IBM\Java60\jre\bin\msvcr71.dll"
    Adding "C:\Program Files\IBM\Java60\jre\bin\net.dll"
    Adding "C:\Program Files\IBM\Java60\jre\bin\nio.dll"
    Adding "C:\Program Files\IBM\Java60\jre\bin\vmi.dll"
    Adding "C:\Program Files\IBM\Java60\jre\bin\zip.dll"
    Adding "C:\WINDOWS\system32\advapi32.dll"
    Adding "C:\WINDOWS\system32\dnsapi.dll"
    Adding "C:\WINDOWS\system32\gdi32.dll"
    Adding "C:\WINDOWS\system32\hnetcfg.dll"
    Adding "C:\WINDOWS\system32\imm32.dll"
    Adding "C:\WINDOWS\system32\iphlpapi.dll"
    Adding "C:\WINDOWS\system32\kernel32.dll"
    Adding "C:\WINDOWS\system32\msvcrt.dll"
    Adding "C:\WINDOWS\system32\mswsock.dll"
    Adding "C:\WINDOWS\system32\ntdll.dll"
    Adding "C:\WINDOWS\system32\powrprof.dll"
    Adding "C:\WINDOWS\system32\rasadhlp.dll"
    Adding "C:\WINDOWS\system32\rpcrt4.dll"
    Adding "C:\WINDOWS\system32\secur32.dll"
    Adding "C:\WINDOWS\system32\setupapi.dll"
    Adding "C:\WINDOWS\system32\user32.dll"
    Adding "C:\WINDOWS\system32\userenv.dll"
    Adding "C:\WINDOWS\system32\winrnr.dll"
    Adding "C:\WINDOWS\system32\wldap32.dll"
    Adding "C:\WINDOWS\system32\ws2_32.dll"
    Adding "C:\WINDOWS\system32\ws2help.dll"
    Adding "C:\WINDOWS\system32\wshbth.dll"
    Adding "C:\WINDOWS\system32\wshtcpip.dll"
    Adding "c:\Program Files\IBM\Java60\jre\lib\TraceFormat.dat"
    Adding "c:\Program Files\IBM\Java60\jre\lib\J9TraceFormat.dat"
    jextract complete.

Analyzing the system dump to get more information using Memory Analyzer

Now that we have the data, need to be able to extract the useful information relating to our exception out of it. For this we use "IBM Monitoring and Diagnostic Tools for Java - Memory Analyzer" (Memory Analyzer). Memory Analyzer is primarily a tool for analyzing and resolving Java heap memory leaks, but it is also a Java object browser and has knowledge of the executing Java threads and what Java objects they are using. It's this thread and object knowledge that allows us to find out more about the exception.

Once you've installed Memory Analyzer and started it in ISA, you can load the jextracted system dump using the "File" -> "Open Heap Dump..." option and selecting the jextract output. This will then load the system dump, produce an Overview report of the memory being used on the Java heap, and open a "Getting Started" dialog box. You can select "Cancel" in the dialog box as the reports it offers you are all related to memory footprint leak analysis, which we're not doing on this occasion.

The capability we do want from Memory Analyzer, is the "Threads Stacks" option which lists the Java thread stacks and the objects those threads reference. The option is found under "Open Query Browser" -> "Java Basics" -> "Thread Stacks" as shown in the diagram below. The "Open Query Browser" option is the icon that looks like a hard drive and a cog:

This then gives the list of threads and the objects associated with each method in the stack trace of the threads.

By expanding the current thread and the method frames in the thread its possible to look at the objects associated with those methods. In the case of a java.net.ConnectException, the most interesting method is java.net.Socket.connect(). By expanding this method frame, a "" reference to a "java.net.Socket" object "@0xd036c0" in memory is shown. This is the socket connection we were trying to make.

When you select the Socket object, the fields in the object are show in the "Attributes" panel on the bottom left hand side:

This doesn't give us too much useful information because the real implementation of the Socket is in the "impl" field, so we need to look at the object referenced from there. This can be done by either expanding the Socket object and selecting the "impl java.net.SocksSocketImpl @ 0xd036c0" line in the main panel, or by right clicking on the "impl" field i the Attributes panel and selecting "Go Into". This now gives you the fields for the SocksSocketImpl in the Attributes panel:

Giving you access to the "address" and "port" fields. In this case the port is "100", but the address field points to a java.net.Inet4Address object, so we need to look at the fields in that object too:

Which shows us that the hostName is set to "baileyt60p", which is the hostname of my laptop (the localhost).

Whilst this is a simple case: we only need to discover the hostname and port, its easy to see how the ability to investigate the objects associated with the thread generating the exception allows you to get much more information about the exception causes, and hopefully make it easier to resolve the issue.

Debugging the cause of Java exceptions is a common activity for Java developers, however this is not always easy to do as the exception messages are often generic. A good example of this is the java.net.ConnectException. When trying to make a socket connection to a host that is not accepting connections, you get the following message:

    java.net.ConnectException: Connection refused: connect
    	at java.net.PlainSocketImpl.socketConnect(Native Method)
    	at java.net.PlainSocketImpl.doConnect(PlainSocketImpl.java:352)
    	at java.net.PlainSocketImpl.connectToAddress(PlainSocketImpl.java:214)
    	at java.net.PlainSocketImpl.connect(PlainSocketImpl.java:201)
    	at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:377)
    	at java.net.Socket.connect(Socket.java:530)
    	at java.net.Socket.connect(Socket.java:480)
    	at java.net.Socket.(Socket.java:377)
    	at java.net.Socket.(Socket.java:220)

Getting more information when the exception is generated
The Java Runtimes from IBM provide (in Java 5.0 and 6.0) a mechanism for triggering additional data generation on various events using the -Xdump option. On these events its possble to generate several different dump types which can provide some insight as to the cause of the exception.

What additional data can be generated?
The -Xdump options allow you to generate a number of different dump types when the trigger event occurs, however the following are most likely to be of use for debugging exceptions:

Which trigger events are available?
Available events include the "throw" and "catch" of exceptions, as well as when exceptions are left "uncaught". This means that its possible to set up a dump trigger to generate more data when the java.net.ConnectException is produced.

It is usually best to use the the "throw" event rather than "catch" or "uncaught" as the catch and uncaught events occur after the stack has been unwound/rolled back, which means that the stack trace represents the point at which the catch block in the code is hit rather than the point the exception is generated. As this is after the initial generation of the exception, objects may have been released and threads may have moved on.

Putting it all together
In order to set up the generation of a system dump on a ConnectException, you can use the following added to the command line:

    -Xdump:system:events=throw,range=1..1,filter=java/net/ConnectException

Also note that there is a "range" set to "1..1". This means that only a single dump will be generated. As exceptions can be and often are re-thrown several times, this is required to prevent multiple dumps being generated.

To achieve the same thing but produce a javacore.txt file, you just need to change the "system" value to "java":

    -Xdump:java:events=throw,range=1..1,filter=java/net/ConnectException

Analysing the new data
Now that you can generate extra data for the exception, the next step is use that data to find our more information about the cause of the exception and to hopefully solve the problem it's reporting.

In the next entry I'll go through how to use a system dump from a java.net.ConnectException to find our what hostname and port was being used.

The replay of the WebSphere Online Support Virtual Community webcast on "IBM Monitoring and Diagnostic Tools for Java - Health Center" presented by Holly Cummins and Helen Beeken is now available.

You can download the replay by going to the following link:  http://www.websphere.org/websphere/jsp/vwugmtg.jsp
and clicking on the "Nov 9 2009" link under "WebSphere Online Support Virtual Community"

In IBM Java support, a large number of the problems we help customers with present themselves as poor application performance. Often, when we dig into the problem it turns out to be related to unexpected garbage collection behaviour, and quite often, related to an application's use of the System.gc() API.

In this entry I'll discuss the System.gc() API, and why IBM support recommend that you don't use it. I'll talk about how you can find out where in your application is calling System.gc() and also how to detect whether third-party code you're using calls it.

About System.gc()
System.gc() is a Java API provided by the system class libraries. An important point to note, which you can read about in the Sun javadoc is that calling System.gc() is a hint to the garbage collector to run - it's under no obligation to actually do so. IBM has some further information and advice on this point. You may be interested to know that IBM provide a command-line option to disable System.gc() entirely. To get the behaviour, add -Xdisableexplicitgc to your command-line (the equivalent Sun option is -XX:+DisableExplicitGC). However, completely disabling System.gc() may have unintended consequences, because some System.gc() calls are useful and necessary (those which are used to generate seeds for crypto operations, or to free up resources associated with NIO buffers, for example).

Using -verbose:gc
The best way to detect whether System.gc() is being called is to examine the output you get by enabling -verbose:gc. Setting -verbose:gc causes the garbage collector to write a log summarising its activity to stderr. You can read more about IBM's -verbose:gc output in the IBM Java Diagnostics Guide. If you're interested in parsing and plotting the output from -verbose:gc then a great tool to use is IBM's Garbage Collection and Memory Visualizer (GCMV).

Here's an example section from some -verbose:gc output, showing the sort of output produced when System.gc() is called by the Java application.

    <sys id="1" timestamp="Jul 08 16:26:53 2009" intervalms="0.000">
      <time exclusiveaccessms="0.026" />
      <tenured freebytes="635784" totalbytes="26214400" percent="2" />
      <gc type="global" id="5" totalid="5" intervalms="1584.443">
        <classunloading classloaders="0" classes="0" timevmquiescems="0.000" timetakenms="0.045" />
        <timesms mark="2.321" sweep="0.361" compact="0.000" total="2.799" />
        <tenured freebytes="25800240" totalbytes="26214400" percent="98" />
      </gc>
      <tenured freebytes="25800240" totalbytes="26214400" percent="98" />
      <time totalms="2.845" />
    </sys>

Finding the culprits
So, how do you find out where in a large application called System.gc()? Well, obviously you could search your codebase. But what if you are using third-party code which you don't have the source code to? Here is where features built-in to IBM's JVMs can help you. There are two main ways to work out where System.gc() is coming from.

Triggering a javacore
The IBM JVM has a "trace engine" built in, which can be used to track Java methods and trigger different actions when certain method(s) execute. One of the actions is to trigger a javacore - a text file showing information about the JVM, including thread stacks. Here's how you would tell the JVM to write a javacore every time System.gc is called:

    -Xtrace:trigger=method{java/lang/System.gc,javadump}

    public class SystemGCTest {

	    public static void main(String[] args) {
	    	    one();
	    }

	    public static void one() {
		    two();
	    }

	    public static void two() {
		    System.gc();
	    }
    }

    JVMDUMP034I User requested Java dump using 'C:\javacore.20091105.162252.8048.0001.txt' through -Xtrace:trigger
    JVMDUMP010I Java dump written to C:\javacore.20091105.162252.8048.0001.txt

    3XMTHREADINFO      "main" TID:0x41C31300, j9thread_t:0x003A54C4, state:R, prio=5
    3XMTHREADINFO1            (native thread ID:0xC4C, native priority:0x5, native policy:UNKNOWN)
    4XESTACKTRACE          at java/lang/System.gc(System.java:284)
    4XESTACKTRACE          at SystemGCTest.two(SystemGCTest.java:12)
    4XESTACKTRACE          at SystemGCTest.one(SystemGCTest.java:8)
    4XESTACKTRACE          at SystemGCTest.main(SystemGCTest.java:4)

Seeing it on the console
Sometimes, taking a javacore file might be too heavyweight though. Maybe you'd just like to see the stacktrace on the console output? Try this option:

    -Xtrace:print=mt,methods={java/lang/System.gc},trigger=method{java/lang/System.gc,jstacktrace}

    16:29:53.234*0x41c31300              mt.3        > java/lang/System.gc()V Bytecode static method
    16:29:53.234 0x41c31300              mt.19       - Static method arguments: ()
    16:29:53.234 0x41c31300       j9trc_aux.0        - jstacktrace:
    16:29:53.234 0x41c31300       j9trc_aux.1        - [1] java.lang.System.gc (System.java:284)
    16:29:53.234 0x41c31300       j9trc_aux.1        - [2] SystemGCTest.two (SystemGCTest.java:12)
    16:29:53.234 0x41c31300       j9trc_aux.1        - [3] SystemGCTest.one (SystemGCTest.java:8)
    16:29:53.234 0x41c31300       j9trc_aux.1        - [4] SystemGCTest.main (SystemGCTest.java:4)
    16:29:53.234 0x41c31300              mt.9        < java/lang/System.gc()V Bytecode static method

Conclusion
I've shown two different ways that you can use the trace facilities that are built-in to the IBM JVM to work out where stray calls to System.gc() are originating from. Of course, you could also use these options to trace any other Java method that you are interested in. If you'd like more information, a good reference is the trigger trace documentation in the IBM Java Diagnostics Guide.

By the way, all these options apply to IBM Java 5.0 and later. If you're running an earlier version of IBM Java then the options are specified as system properties rather than through -Xtrace e.g.

    -Dibm.dg.trc.trigger=method(java/lang/System.gc,javadump)

Ian Partridge

The November 2009 edition of the WebSphere Support Authority column entitled "Know what your Web application is really doing" has been published on developerWorks.

The article covers the use of Health Center to understand what a web application that has been deployed on the WebSphere Application Server is doing, and shows a good example of doing this with the Plants by WebSphere sample application.

You can find the article here:
    http://www.ibm.com/developerworks/websphere/techjournal/0911_supauth/0911_supauth.html

On Monday 9th November 2009 at 10:00 AM EST (3:00 PM GMT) there will be a WebSphere Online Support Virtual Community presentation on "IBM Monitoring and Diagnostic Tools for Java - Health Center". The presentation will be given by Holly Cummins and Helen Beeken, who are members of the Java tooling team at IBM. Holly is the lead developer for HealthCenter and previously authored the GC and Memory Visualizer tool.

More details on the webcast are available from theWebSphere Online Support Virtual Community page:
     http://www.websphere.org/websphere/Site?page=ugdetail&groupId=125
and you can sign up for the webcase on the meeting page:
     https://www.websphere.org/check_user?type=meeting&meetid=1539

In the last entry we discussed how the TPROF utility that is part of the Performance Inspector package of tools can be used to carry out performance profiling where HealthCenter is not available. HealthCenter has a number of other capabilities, including: lock analysis, garbage collection monitoring, class loading and environment information. This leads to the question: "Are there any other tools I can use on earlier releases of Java where HealthCenter is unavailable?"

Lock analysis for Java 1.4.2: JLM
The answer is yes, at least for the case of lock analysis. The Performance Inspector package also provides a utility called Java Lock Monitor (JLM) which provides exactly the same data that you see in HealthCenter, although without the extra level of analysis that highlights potential or actual problems in locking data.
JLM is available for AIX, Linux, Windows and z/OS where the IBM JRE is being used and provides data on which locks, both Java object locks (synchronized objects and blocks) and system locks (JVM monitors and JNI requested raw monitors), are being used and how often those locks are contended: ie. are a bottleneck in the code execution.

Enabling Java Lock Monitor for a Java application
In order to track the lock usage of the Java VM and the Java application a JProf agent, supplied as part of the package from the Performance Inspector tools site, needs to be loaded into the Java process. This can be done as follows:
For Java 5.0 and earlier:

    java -Xrunjprof AppName

    java -agentlib:jprof AppName

Starting the Java process with the JProf agent causes the following information to be written out the console:

    >java -Xrunjprof -Xmx1024M BuyerSim

     Path and prefix for log files: .\log

     JPROF Version_9.6.1 (JVMPI)

     (OnDisk   : D:\ibmperf\bin\java\jprof.dll)

     (Built    : Wed Sep 16 12:13:46 Central Daylight Time 2009)

     (Source   : Wed Sep 16 12:00:00 Central Daylight Time 2009)

     (Platform : Windows-x86, OS=v5.1.2600-Service Pack 2, PerfUtil=v9.5.6, PERFDD=v9.5.5, CPUS=1, HT=0, MC=0, CpuSig=0x00000F07, Variable_TSC, Intel, Hostname=caragua)

     (JVM Info : IBM SOV)

     JPROF started at 20:46:17 on 2009/10/28

     JPROF options:

     Writing .\log-msg_4256

    HeapDump disabled, since EnableHeapDump not specified

    Server socket (1720) created for PID 4256. Listening on port 8888

Collecting lock data from the Java application
Once the Java application has been started with the JProf agent loaded, the rtdriver utility can then run which connects to the JProf socket on the local machine. This starts a command prompt process which can be used to control the data gathering in the Java process:

    D:\ibmperf\bin>rtdriver -l
    ** RTDriver for Windows-x86: v2.00.0, 02/05/2009 **

    ** RTDriver: 20:21:18 connecting to caragua (9.20.191.24) on port 8888 ... OK
    ** RTDriver: 20:21:18 piClient handshaking completed successfully by host on port 8888 **

    20:21:18 Enter command>

    20:21:18 Enter command> jlmstart
    ACCEPTED

    20:21:28 Enter command> jlmdump

     Writing .\log-jlm.1_5668
    ACCEPTED

    Writing .\log-jlm.1_5668

    20:23:53 Enter command> jlmstop
    ACCEPTED

Understanding the log-jlm report
The log-jlm report is breaks the locks down into two major sections:

• "System (Registered) Monitors"
• "Java (Inflated) Monitors"

      System (Registered) Monitors

       %MISS     GETS   NONREC     SLOW      REC    TIER2    TIER3 %UTIL AVER_HTM  MON-NAME

          11       26        9        1       17        0        0     7 83898563  Thread queue lock
           7    42468    42468     2941        0        0        0    24    63676  Heap lock
           0       18        9        0        9        0        0     7 83896461  Monitor Cache lock
           0       12       12        0        0        0        0     1  5241357  Sleep lock
           0        8        8        0        0        0        0     1  7858271  IO lock
           0        8        8        0        0        0        0     6 81832672  Intern String Table lock
           0        8        8        0        0        0        0     0     1618  JIT Code lock
           0        8        8        0        0        0        0     7 94381627  Free Class Loader Cache Entry lock
           0        8        8        0        0        0        0     6 81834000  System Heap lock
           0        8        8        0        0        0        0     7 94384774  Binclass lock
           0        8        8        0        0        0        0     7 94375454  JITC CHA lock
           0        8        8        0        0        0        0     7 94382865  JNI Pinning lock
           0        8        8        0        0        0        0     7 94384139  JNI Global Reference lock

The "Java (Inflated) Monitors" section lists all of the Java synchronised objects that have had some degree on contention between threads. If these has been no contention then the synchronised object will not be listed:

Java (Inflated) Monitors

 %MISS     GETS   NONREC     SLOW      REC    TIER2    TIER3 %UTIL AVER_HTM  MON-NAME

    99      854      170      169      684  3185149   109485     0  3358887  [21F70260] java/io/PrintStream@00463C40 (Object)
     0  1185233  1185233      284        0  6105043   126952     1      829  [21F995E0] BuyerSim$Cache@004B6E38 (Object)

The meaning of the columns is provided at the end of the report:

LEGEND:
                %MISS : 100 * SLOW / NONREC
                 GETS : Lock Entries
               NONREC : Non Recursive Gets
                 SLOW : Non Recursives that Block
                  REC : Recursive Gets
                TIER2 : SMP: Total try-enter spin loop cnt (middle for 3 tier)
                TIER3 : SMP: Total yield spin loop cnt (outer for 3 tier)
                %UTIL : 100 * Hold-Time / Total-Time
              AVER-HT : Hold-Time / NONREC

What to look for in the log-jlm report
The most important value to look at is the %MISS, which gives you an idea of how often a thread was blocked trying to get a lock because it was already owned by another thread. The higher this %MISS value, the more contention that has occurred on that lock.
Where there is a high %MISS value showing contention, the next value to look at is the AVER_HTM, which is the average time that the lock has been held by a thread. If this value is low then the contention is occurring because many threads are trying to take the same lock, and reducing the number of threads will likely improve the performance. If the value is high then the lock is being held for a long time because a lot of work is being done under the lock, and moving some of the work to outside of the lock will likely improve the performance.

More discussion on reducing lock contention is available in the Java Troubleshooting Guide section on resolving lock contention.

Differences between JLM and HealthCenter
There are very few differences between JLM and HealthCenter in terms of the data presented, as they both gather the data in the same way. HealthCenter however has the added level of helping you to interpret the data, and to alert you to locks which may be causing a performance bottleneck.

We discussed in previous entries on "Understanding the performance of your application on the IBM Java 5.0 and 6.0 JVMs" and "Using method profiling in Health Center to improve Java code performance" how the sample based method profiling in HealthCenter can be used to diagnose and fix performance problems in Java code in Java 5.0 and Java 6.0.
This leaves the question: What can I used to profile performance problems on earlier releases of Java where HealthCenter is unavailable?

Sample based profiling for Java 1.4.2: TPROF
One option for sample based profiling at Java 1.4.2 is Time Profiler (TPROF) which is part of the Performance Inspector package of tools available from sourceforge.net.
TPROF is a system profiling tool available for AIX, Linux, Windows and z/OS that records what process, thread and code is executing on CPU(s) using time based sampling. This provides information on what C language functions are executing and occupying CPU time, and with the addition of an agent into the Java process will provide information on what Java language methods are executing.

Enabling Java method sampling in TPROF
In order to track the Java methods being executed in addition to the C functions a TPROF agent, supplied as part of the package from the Performance Inspector tools site, needs to be loaded into the Java process. This can be done as follows:
For Java 5.0 and earlier:

    java -Xrunjprof:tprof,fnm=D:\ibmperf\bin\log,pidx AppName

    java -agentlib:jprof=tprof,fnm=D:\ibmperf\bin\log,pidx AppName

Running TPROF to sample the Java application
Once the Java application has been started with the TPROF agent loaded, you need to start the TPROF data gathering process, which will begin sampling the data from the system. The most simple mode for running tprof is using:

    run.tprof

    \****\*
    \****\*
    ***** Press ENTER when ready to begin tracing or Ctrl-C to quit ...

    \****\*
    \****\*
    ***** Tracing. Press ENTER when ready to stop ...

TPROF in trace only mode using the "-t" flag, which produces just the trace file which has be post processed later using run.tprof with the "-p" option. The start and stop of the data gathering can also be set automatically using the "-s" flag which sets a delay time to start profiling and the the "-r" option to specify the time to gather data for:

    run.tprof -t s10 -r 60

    run.tprof -p

More information on running TPROF is available from the Performance Inspector website.

Interpreting the tprof.out report
The TPROF report is broken down into sections. The section that is the closest equivalent to that provided by HealthCenter is the Process Module Symbol section, which shows the highest used Java methods or C functions on a per process basis.
Looking up the Java process, you get the following kind of output:

    ================================
        )) Process_Module_Symbol
       ================================
    
       LAB    TKS   %%%     NAMES
    
       PID   5028 85.26    java.exe_138c
        MOD   2374 40.26     JITCODE
         SYM    489  8.29      java/util/regex/Pattern.compile()V_1c237b0
         SYM    370  6.27      java/util/regex/Pattern.atom()Ljava/util/regex/Pattern$Node; _1c274ec
         SYM    179  3.04      java/util/regex/Pattern.sequence(Ljava/util/regex/Pattern$Node; )Ljava/util/regex/Pattern$Node;_1c24758
         SYM    144  2.44      java/util/regex/Pattern.closure(Ljava/util/regex/Pattern$Node; )Ljava/util/regex/Pattern$Node;_1c17d3c
         SYM    135  2.29      java/io/BufferedReader.readLine(Z)Ljava/lang/String; _1c284bc
         SYM    113  1.92      java/util/regex/Pattern$Curly.match0(Ljava/util/regex/Matcher;IILjava/lang/CharSequence;)Z_1c291dc
         SYM     97  1.64      java/util/regex/Pattern.newSlice([IIZ)Ljava/util/regex/Pattern$Node; _1c1953c
         SYM     91  1.54      java/util/regex/Pattern.matcher(Ljava/lang/CharSequence; )Ljava/util/regex/Matcher;_1c2e19c
         SYM     87  1.48      java/util/regex/Matcher.(Ljava/util/regex/Pattern;Ljava/lang/CharSequence; )V_1c22e28
         SYM     63  1.07      sun/io/ByteToCharSingleByte.convert([BII[CII)I_1c219d4
         SYM     57  0.97      java/util/regex/Pattern$Ctype.match(Ljava/util/regex/Matcher;ILjava/lang/CharSequence; )Z_1c19ebc
         SYM     53  0.90      java/util/regex/Matcher.match(II)Z_1c1df90
         SYM     52  0.88      java/io/BufferedReader.readLine(Z)Ljava/lang/String;_1c30e30

Differences between TPROF and HealthCenter
HealthCenter has a number of advantages for Java method profiling over TPROF:

• HealthCenter provides a live view, whereas TPROF only provides snapshots from a given sample period
• HealthCenter has an Invocation Paths view, which shows the call relationships between methods (which method is calling which method)