Saturday, March 9, 2013

Monitor OS pauses with jHiccup when benchmarking Java App

Benchmarking java code implies to be sure that the underlying platform does not impact the performance of the JVM in any way. Hopefully, there is a tool that monitors pauses and stalls that may occur at platform level: jHiccup from Azul.



As explained on the Azul's site, jHiccup captures the aggregate effects of the Java Virtual Machine (JVM), operating system, hypervisor (if used) and hardware on application stalls and response time.

This tool records platform pause/stall into log files that you can import into a MS Excel file:


Next you can plot platform "hiccup" and percentiles as illustrated below:


chart from MS Excel

This chart shows that during a 25 seconds benchmark, 99% of the latencies collected are lesser than 300 milliseconds, with a peak of half a second ! Such values indicate that we are not in the case of a dedicated/quiet system, and there must be some background activities (actually, i ran this benchmark during a Windows 7 user session with mail, browser and other usual softwares).

As you can guess, such a tool is really useful to check:
  • that your JVM is running on a dedicated or quiet system
  • that application response time behavior are not influenced by the platform
Running jHiccup is quite simple, use the provided script to launch your JVM on Unix environment (e.g jHiccup /usr/bin/java <Java args> -jar UsefulProgram.jar -a -b -c ) or as an instrumentation agent in other cases (e.g -javaagent:D:\apps\jHiccup.1.2.2\bin\jHiccup.jar="-d 0 -i 1000 -l hiccuplog -c c.hiccuplog") and you are done !


Thursday, March 7, 2013

Continuous Performance and JUnit with ContiPerf

If you want to introduce some continuous performance into your Java project, you should definitively check the ContiPerf library : that tool transforms your unit tests into performance tests simply by adding few annotations !

For instance, suppose your need to do some XML serialization with JAXB as illustrated below and therefore you have to test the UserSerializer class.


The corresponding code for the UserSerializer class is:
package org.javabenchmark;

import java.io.File;
import javax.xml.bind.JAXBContext;
import javax.xml.bind.JAXBException;
import javax.xml.bind.Marshaller;

public class UserSerializer {

    public void serializeUserToXmlFile(User user, File file) throws JAXBException {

        JAXBContext jaxbContext = JAXBContext.newInstance(User.class);
        Marshaller jaxbMarshaller = jaxbContext.createMarshaller();
        jaxbMarshaller.marshal(user, file);
    }
}
and the corresponding code for the UserSerializer test would be:
package org.javabenchmark;

import java.io.File;
import java.util.UUID;
import javax.xml.bind.JAXBException;
import org.junit.Test;
import static org.fest.assertions.api.Assertions.*;

public class UserSerializerTest {
    
    @Test
    public void shouldSerializeRandomUser() throws JAXBException {
        
        // given a random user
        String id = UUID.randomUUID().toString();
        String firstName = "Julien";
        String lastName = "Paoletti";
        
        User randomUser = new User();
        randomUser.setId(id);
        randomUser.setFirstName(firstName);
        randomUser.setLastName(lastName);
        
        // when serializing it to a random XML file
        File xmlFile = new File("target/" + id + ".xml");
        xmlFile.deleteOnExit();
        
        UserSerializer serializer = new UserSerializer();
        serializer.serializeUserToXmlFile(randomUser, xmlFile);
        
        // then the file contains the corresponding XML
        String validXmlContent = ""
                + ""+ firstName + ""
                + ""+ lastName + ""
                + "";
        assertThat(xmlFile).hasContent(validXmlContent);
    }
}

The test passes,  it is now time to transform this unit test into a performance one in 2 steps:
  1. add a JUnit rule from ContiPerf
  2. add a ContiPerf annotation to configure the execution of the performance test

public class UserSerializerTest {

    @Rule
    public ContiPerfRule i = new ContiPerfRule();
    
    @Test
    @PerfTest(invocations = 200, threads = 2)
    public void shouldSerializeRandomUser() throws JAXBException {

        // ...
    }
}
As you can see, the test will be exectuted 200 times by 2 threads. On my computer (Ubuntu VM 5Go 4 CPU), running the test produces the following output:

org.javabenchmark.UserSerializerTest.shouldSerializeRandomUser
samples: 200
max:     140
average: 6.79
median:  4

You would think that a simple XML serialization could be faster (almost 7 ms on average). To get some clue, let's profile the performance test with VisualVM :


Ouch, 95% of the execution time is taken by the JAXBContext method newInstance(). How to improve this ? A quick search on the internet shows that the JAXBContext is actually thread-safe, so it is not necessary to instantiate it each time.

The previous code can be improved:
public class UserSerializer {
    
    private static JAXBContext jaxbContext;
    
    static {
        try {
            jaxbContext = JAXBContext.newInstance(User.class);
        } catch (JAXBException ex) {
            // handles exception
            // ...
        }
    }

    public void serializeUserToXmlFile(User user, File file) throws JAXBException {
        Marshaller jaxbMarshaller = jaxbContext.createMarshaller();
        jaxbMarshaller.marshal(user, file);
    }
}

Now, running the test again produces the output:

org.javabenchmark.UserSerializerTest.shouldSerializeRandomUser
samples: 200
max:     133
average: 1.4
median:  0


It is much better and then we can add performance checks to our test. To achieve this, ContiPerf provides the @Required annotation:
  • @Required(throughput = 20) : Requires to have at least 20 test executions per second 
  • @Required(average = 50): Requires an average execution time of not more than 50 milliseconds
  • @Required(median = 45): Requires that 50% of all executions do not take longer than 45 milliseconds
  • @Required(max = 2000): Requires that no invocation takes more than 2000 milliseconds (2 seconds)
  • @Required(totalTime = 5000): Requires that the sum of all execution times is not more than 5000 milliseconds (5 seconds)
  • @Required(percentile90 = 3000): Requires that 90% of all executions do not take longer than 3000 milliseconds
  • @Required(percentile95 = 5000): Requires that 95% of all executions do not take longer than 5000 milliseconds
  • @Required(percentile99 = 10000): Requires that 99% of all executions do not take longer than 10000 milliseconds
  • @Required(percentiles = "66:200,96:500"): Requires that 66% of all executions do not take longer than 200 milliseconds and 96% of all executions do not take longer than 500 milliseconds

In our case, we could check that the average does not exceed 2 ms and that 95% of all executions do not take longer that 1 ms:
public class UserSerializerTest {

    @Rule
    public ContiPerfRule i = new ContiPerfRule();

    @Test
    @PerfTest(invocations = 200, threads = 2)
    @Required(average = 2, percentile95 = 1)
    public void shouldSerializeRandomUser() throws JAXBException {
        // ...
    }
}

Conclusion
To enable continuous performance in your test:
  1. write a JUnit test that passes
  2. transform it into a performance one
  3. ensure that performance is fine
  4. add your performance requirements

Saturday, March 2, 2013

Write your own profiler with JEE6 interceptor

JEE6 interceptors are powerful components that interpose on method invocations and then provide an easy way to execute some given code just before and after method execution.

It is then trivial to build a basic profiler that would consist in starting a stopwatch before some method execution and stopping it just after the end. This can be easily done with a custom annotation to identify methods that are eligible to profiling and an interceptor to handle stopwatch.

The first step is to create the @Profiled annotation:
/**
 * The profiled annotation. Use it to mark methods that must be profiled.
 */
@Inherited
@InterceptorBinding
@Retention(RUNTIME)
@Target({METHOD, TYPE})
public @interface Profiled {
}

The next step is to write the interceptor that deals with methods that have the @Profiled annotation:
/**
 * An interceptor for profiling methods that have the
 * @Profiled annotation.
 */
@Profiled
@Interceptor
public class BasicProfiledMethodInterceptor {

    private static final Logger LOGGER = LoggerFactory.getLogger(BasicProfiledMethodInterceptor.class);

    /**
     * starts a stopwatch before a given method execution and stops it after the
     * method is proceeded. Then logs the elapsed time.
     *
     * @param context the invocation context.
     * @return the object produced by the method execution.
     * @throws Exception if an error occurs.
     */
    @AroundInvoke
    public Object profile(InvocationContext context) throws Exception {

        // starts the stopwatch
        final long startTime = System.currentTimeMillis();

        // executes the method that is profiled
        Object o = context.proceed();

        // stops the stopwatch and computes elapsed time
        final long elapsedTime = System.currentTimeMillis() - startTime;

        // logs method and time
        final String methodSignature = context.getMethod().toString();
        LOGGER.info("Profiled Method: {} in {} ms", methodSignature, elapsedTime);

        return o;
    }
}

Notice that logging is done with SLF4J and Logback in this example, but it is up to you to adapt the previous code to use your favorite logging library.

Now, to enable the interceptor, you must put a beans.xml file into the WEB-INF directory of your enterprise application (or META-INF directory with EJB modules or JAR), with the following content:
<?xml version="1.0" encoding="UTF-8"?>

    
        org.javabenchmark.BasicProfiledMethodInterceptor
    


Let's go now with a more sophisticated interceptor, that relies on Metrics (for monitoring) and Guava (for caching monitors) : the idea is to manage method dedicated Timers that are stored inside a cache. The key for retrieving a timer from the cache is the method signature (that also includes package and name of the class).

At the beginning, the cache is empty and when a method is profiled for the first time, a timer is instantiated and put in the cache by a cache loader.

The code of the new interceptor:
/**
 * An interceptor for profiling method executions. Starts a timer before method
 * execution and stops it after. Uses a cache for storing the different timers.
 */
@Profiled
@Interceptor
public class ProfiledMethodInterceptor {

    private static final Logger LOGGER = LoggerFactory.getLogger(ProfiledMethodInterceptor.class);
    /**
     * the cache for all timers. The key for an entry in the cache is the
     * signature of the method that is profiled. Max is 1000 timers.
     */
    private final LoadingCache<String, Timer> timersCache = CacheBuilder.newBuilder()
            .maximumSize(1000)
            .build(
            new CacheLoader<String, Timer>() {
                @Override
                public Timer load(String methodSignature) {
                    return Metrics.newTimer(ProfiledMethodInterceptor.class, methodSignature, TimeUnit.MILLISECONDS, TimeUnit.SECONDS);
                }
            });

    /**
     * gets the corresponding timer for the method being executed, starts it
     * before the execution and stops it after the method is proceeded.
     *
     * @param context the invocation context.
     * @return the object produced by the method execution.
     * @throws Exception if an error occurs.
     */
    @AroundInvoke
    public Object profile(InvocationContext context) throws Exception {

        // gets the corresponding timer
        String methodSignature = context.getMethod().toString();
        final Timer timer = timersCache.get(methodSignature);

        // starts it
        final TimerContext timerContext = timer.time();

        // executes the method that is profiled
        Object o = context.proceed();

        // stops the timer
        timerContext.stop();
        return o;
    }
}

With this interceptor you can now monitor several metrics like invocations per second, duration and percentiles directly via JMX, or by enabling  reporting in logs, CSV files or HTTP as explain there.

You need to update the beans.xml file to enable the new interceptor:
<?xml version="1.0" encoding="UTF-8"?>

    
        org.javabenchmark.ProfiledMethodInterceptor
    


Finally, the dependencies for Metrics and Guava:
        
        
            com.yammer.metrics
            metrics-core
            2.2.0
        
        
        
            com.google.guava
            guava
            13.0.1