The Server Labs Blog Rotating Header Image

Performance & Tuning

Human readable JVM GC timestamps

When we are diagnosing problems in a Java (EE or otherwise) application, is often a good idea to check how garbage collection is performing. One of the basic and most unobtrusive actions is to enable garbage collection logging.

As you may know, if we add the following arguments to the java start command…

-Xloggc:<file_name> –XX:+PrintGCDetails -XX:+PrintGCDateStamps

… the JVM will start writing garbage collection messages to the file we set with the parameter -Xlogcc. The messages should be something like:


2010-04-22T18:12:27.796+0200: 22.317: [GC 59030K->52906K(97244K), 0.0019061 secs]
2010-04-22T18:12:27.828+0200: 22.348: [GC 59114K->52749K(97244K), 0.0021595 secs]
2010-04-22T18:12:27.859+0200: 22.380: [GC 58957K->53335K(97244K), 0.0022615 secs]
2010-04-22T18:12:27.890+0200: 22.409: [GC 59543K->53385K(97244K), 0.0024157 secs]

The bold part is simply the date and time when reported garbage collection event starts.

Unfortunately -XX:+PrintGCDateStamps is available only for Java 6 Update 4 and later JVMs. So, if we are unlucky and our application is running on older JVMs we are forced to use…

-Xloggc:<file> –XX:+PrintGCDetails

… and the messages will be like:


22.317: [GC 59030K->52906K(97244K), 0.0019061 secs]
22.348: [GC 59114K->52749K(97244K), 0.0021595 secs]
22.380: [GC 58957K->53335K(97244K), 0.0022615 secs]
22.409: [GC 59543K->53385K(97244K), 0.0024157 secs]

Now, the bold numbers (also present in previous format) are the seconds elapsed from JVM start time.

Mmm… way harder to correlate GC events with information from other log files in this case :/

Wouldn’t it be easier to process the gc log file and calculate date and time from seconds elapsed? It seems so, but seconds elapsed from… when? Or, putting it in other words, where do we extract the JVM startup date and time from?

In order to be as unobtrusive as possible, we should try to calculate the start date and time from the same GC log file. That brings us to the file attributes. We have different options:

Unix Windows
Access time Access time
Change time Creation time
Modify time Modify time

We discard access time (for obvious reasons) and change time and creation time as they are not available in both platforms, so we are left with modification time, which represents the time when the file was last modified.

In Windows, modification time is maintained when the file is copied elsewhere, but in Unix we should use the -p flag to preserve timestamp attributes if we want to copy the GC log file prior to our processing.

The last modification time of the GC log file should match the last timestamp recorded for a GC event in the log file. Well… for the purists, it should match exactly the last elapsed time plus the execution time (both in bold) as each log line is written piece by piece as it executes.


22.409: [GC 59543K->53385K(97244K), 0.0024157 secs]

In our approach, we discard the execution time as we don’t need accurate precision to have a rough idea of what time each garbage collection event occurred. Nevertheless, keep in mind that GC execution time could sometimes be as long as several seconds in large heaps.

When we experienced this situation in a client recently, we needed to quickly develop a simple and portable script, so we used Python for the task. You already knew we don’t do just Java, didn’t you? 😛

#!/usr/bin/env python

import sys, os, datetime

# true if string is a positive float
def validSeconds(str_sec):
    try:
        return 0 < float(str_sec)
    except ValueError:
        return False
                
# show usage                
if len(sys.argv) < 2:
    print "Usage: %s " % (sys.argv[0])
    sys.exit(1)
    
file_str = sys.argv[1]
lastmod_date = datetime.datetime.fromtimestamp(os.path.getmtime(file_str))

file = open(file_str, 'r')
lines = file.readlines()
file.close()

# get last elapsed time
for line in reversed(lines):
    parts = line.split(':')
    if validSeconds(parts[0]):
        break

# calculate start time
start_date = lastmod_date - datetime.timedelta(seconds=float(parts[0]))
  
# print file prepending human readable time where appropiate  
for line in lines:
    parts = line.split(':')
    if not validSeconds(parts[0]):
        print line.rstrip()
        continue
    line_date = start_date + datetime.timedelta(seconds=float(parts[0]))
    print "%s: %s" % (line_date.isoformat(), line.rstrip())

The script output can be redirected to another file, where we’ll have

2010-04-22T18:12:27.796375: 22.317: [GC 59030K->52906K(97244K), 0.0019061 secs]
2010-04-22T18:12:27.828375: 22.348: [GC 59114K->52749K(97244K), 0.0021595 secs]
2010-04-22T18:12:27.859375: 22.380: [GC 58957K->53335K(97244K), 0.0022615 secs]
2010-04-22T18:12:27.890375: 22.409: [GC 59543K->53385K(97244K), 0.0024157 secs]

You may note the date format is not 100% the same as the one with -XX:+PrintGCDateStamps argument, but it should be enough to get an idea of when each GC event happened (Timezone management in Python is way out of the scope of this blog entry).

This has been my first blog entry for The Server Labs and I hope some of you find it useful. Of course, all comments, suggestions and feedback are very welcome.

Performance Tests with Jmeter, Maven and Hudson

Continuing with the series of blog posts regarding testing, automation and continuous integration, this time I will talk about how to integrate performance tests, in this case using Jmeter, with Maven and the Hudson continuous integration system. Jmeter is one of the main tools we use in our projects to create relevant performance tests, and automation and integration in our CI systems is essential. We also use SoapUI and Grinder depending on the platform, but we will cover those in future posts.

To integrate Jmeter and Maven, you must use the Maven Jmeter plugin, the first version of which is officially hosted here. There are are several posts discussing the use of this plugin that I have used as reference, particularly this one from James Lorenzen.

An updated version of this original plugin was released in google code by Ronald Alleva. It adds support for the latest version of Jmeter (2.3.2) and contains some additional enhacements such as parameterisation support. I decided to use this version to get this extra funcionality.

To make this post as simple and easy to follow as possible, my idea was to test Jmeter tests automation and integration against an application web running in an embeded Jetty container.

My objectives were:

  • Be able to run my Jmeter tests in a specific maven phase.
  • Create the relevant Jmeter test results html reports and publish them during the maven site phase.
  • Integrate Jmeter execution and reporting with Hudson, via the Hudson Jmeter plugin available here.

This post is a combination of James and Ron’s posts, adding solutions to problems I discovered while creating and executing my tests and showing the integration with Hudson.

Ronald describes pretty well here the different steps required in order to make the plugin work. I will not include these steps but rather comment on them.

  • Download the support jars and the maven Jmeter plugin and install them.
  • Add the dependency to your maven project. In our case, we want to execute our Jmeter tests when we start the embedded jetty container. We usually start/stop Jetty as part of the pre-integration and post-integration maven phases. We just need to add the Jmeter plugin execution to the integration-test phase (I have also included the jetty part below):

   
       env-dev-jetty
	
	   true
	
	
	   
		
			org.apache.jmeter
			maven-jmeter-plugin
			1.0
			
				
					jmeter-tests
					integration-test
					
						jmeter
					
				
			
			
				
					${project.build.directory}/jmeter-reports
				
				
					   localhost
			       	  	   9080
       	  	  	  	
			
		
		
			org.mortbay.jetty
			maven-jetty-plugin
			6.1.12rc1
			
				
					${basedir}/target/${project.build.finalName}/${project.parent.name}-webapp-${project.version}.war
				
				
					${project.parent.name}-webapp
				
				
					
					   9080
					   60000
				        
				
				
					
						
						   pmtool.application.environment
						
						dev
					
				
				9966
				foo
				true
				0
			
			
				
					start-jetty
					pre-integration-test
					
						run-war
					
				
				
					stop-jetty
					post-integration-test
					
						stop
					
				
			
		
	
   


In a real scenario where, as part of your project cycle, the application is deployed to a development or pre-production environment, we could use the verify phase to execute the performance tests.

  • Also, in case you want to generate html reports for publication on the project site generated by Maven, execute the XSLT transformation from xml to html provided by Jmeter using the xml-maven-plugin:

   org.codehaus.mojo
   xml-maven-plugin
   1.0-beta-2
   
      
         pre-site
         
             transform
         
         
    
    
         
             
                  ${project.build.directory}/jmeter-reports
                  src/test/resources/jmeter-results-detail-report_21.xsl
                  ${project.build.directory}/site/jmeter-results
                  
                      
                         html
                      
                  
             
         
    

  • Create some Jmeter tests. I created 2 Jmeter tests, PerfTest1 and PerfTest2, which are parametized so different hostnames and ports can be specified for the tests. The maven profile “env-dev-jetty” (which is the default used) defines the Jmeter parameters for Jetty in the “jmeterUserProperties” section. We have a separate profile to run Jmeter against against the application deployed in a weblogic container.
  • Copy the jmeter.properties file to the “/src/test/jmeter” folder in your project and modify the properties to fit your needs. For example, I had to modify some “jmeter.save.saveservice” parameters to enable additional output and also some “log_level” to see a bit more of detail in the jmeter.log file.
  • Execute mvn to run the tests.
mvn integration-test

Up to this point everything was ok apart from the fact that when running in maven, the Jmeter tests where hanging just after finishing correctly. After some investigation, I found that the reason was the exit logic implemented in the maven Jmeter plugin. The plugin exits when the number of threads drops to the number just before the Jmeter start call. This works in most cases, but when you are also running an embedded Jetty server, the threads spawned to service the requests triggered by the Jmeter tests are counted as well, causing the wait. The plugin eventually exits when all these connection threads are closed after timing out.

The solution was to change the exit logic, monitoring the jmeter.log file as described here, instead of monitoring the number of threads. This should work in most cases.

  • Integrate into Hudson, the continuous integration that we use. For that I installed the Jmeter Hudson plugin and configured it as shown below:
Hudson Jmeter Plugin Configuration

Hudson Jmeter Plugin Configuration

  • In order to keep the Jmeter detailed performance test results, I configured Hudson to archive the relevant reports as build artifacts.
  • The Hudson and Maven Jmeter plugins have different naming convention for the report files. The maven Jmeter plugin generates the report filename with a date which is not compatible with the static file name required by the Hudson Jmeter Plugin. Solution: I modified the maven plugin source code to generate a results file without the date in it (e.g. from PerfTest1-090413.xml to PerfTest1-result.xml). There is no disadvantage as Hudson will store the results for each build as an artifact, keeping a log.
  • The Hudson plugin doesn’t really support collecting information about multiple Jmeter Tests at this moment. The way to go would be to group different performance tests into a single Jmeter file and create separate Hudson jobs for them.
  • After all this setup has been done, you can execute some builds and the check that the Jmeter execution graphs works as they should. I created an example, containing errors and different response times to make it pretty. The graphs show the trend for only one of the Jmeter tests.
Hudson Jmeter Test Execution Trend

Hudson Jmeter Test Execution Trend

  • Note the section “Last Successful Artifacts” that contains the html reports created during the maven site creation and archived for future reference. An example of this detail report is:
Jmeter Detailed report as Hudson Artifact

Jmeter Detailed report as Hudson Artifact

JBoss Remoting + JBoss Serialization kills JavaRMI and Spring Remoting

We have found recently this powerful libray provided by JBoss.

The performance we have gain in terms of speed is that JBossRemoting + JBossSerlization is 8.72 times faster than JavaRMI + JavaSerialization (JDK 6 update 11)

In our real scenario, basically we are sending a list of around 100000 user defined objects from clients to servers. This data It is around 15MB.each message call

The clustered architecture we have deployed is not relevant to mention; but what I want to point; it is how easy has been to move from Java RMI to JBoss Remoting.  Just one line of code and you have your server and client applications running.


//server side code
//where this is the target object
TransporterServer.createTransporterServer("socket://"+ yourhostname+": port/?serializationtype=jboss", this, serverName);

//client side code
//where remoteServerClass.class is just the remote server interface like RMI
remoteServer = (T) TransporterClient.createTransporterClient("socket://"+remoteHostname+":remotePort/?serializationtype=jboss" , remoteServerClass.class);

Once you get the remote reference to the remote object, you can invoke methods on the object running in the remote Java virtual machine. The same way you do it for your RMI solution.

The purpose of JBoss Remoting is to provide a single API for most network based invocations and related service that uses pluggable transports and data marshallers. The JBoss Remoting API provides the ability for making synchronous and asynchronous remote calls, push and pull callbacks, and automatic discovery of remoting servers. The intention is to allow for the addition of different transports to fit different needs, yet still maintain the same API for making the remote invocations and only requiring configuration changes, not code changes, to fit these different needs
JBoss Remoting

JBoss provides nice features such Pluggable transports, Callbacks and many other, so you do not have to re-invent the wheel.

Although we are using version 2.5, and we are waiting for the forthcoming 3.0, there is complete performance test report where you can compare JBoss implementation against Java and Spring Remoting.

JBoss Performance Benchmark