Paul Dissected – Part 3 – Profiling & Optimization

The Java server part of PaulPredicts is running regular background jobs which import big XML files with new data. After the initial development we realized, that these jobs are very slow but could not pinpoint the exact reason. As developers we often get into this situation. Being bound by time-constraints we also don’t want to invest too much of it by optimizing the wrong code. This blog post shows our approach of finding the responsible bottlenecks.

The Tools

When installing the HANA Cloud tools we see an interesting option: SAP JVM Profiler. Let’s give it a try.

We also need the SAP JVM. This can be found on the tools page as well, under the “Additional Software” tab. Install it and set it as the default Java execution environment.

Ready For Action

Now we are all set. Start your application and then select “Run/Start Profiling” in Eclipse. It will allow you to connect to your running instance.

As soon as this is done it will start recording. If we start our long-running process now we can see very nicely where all the time goes into. Looking at the hierarchical method view we find out that the extractPlayerStat() method seems to make a lot of XML parsing.

When we look at the method, that is quite true. The method will receive a node and, using a helper function, will do another XPath call relative from that node for every attribute.

private PlayerStat extractPlayerStat(Node node, Team team) {
        String extId = XmlUtilsExt.getXPathResultValue(node, "../@player_id");
        String position = XmlUtilsExt.getXPathResultValue(node, "../@position");
        String jerseyNumber = XmlUtilsExt.getXPathResultValue(node, "../@shirtNumber");
        String firstName = XmlUtilsExt.getXPathResultValue(node, "../@first_name");
        String lastName = XmlUtilsExt.getXPathResultValue(node, "../@last_name");
        String nickName = XmlUtilsExt.getXPathResultValue(node, "../@known_name");
        String key = XmlUtilsExt.getXPathResultValue(node, "@name");
        String value = XmlUtilsExt.getXPathResultValue(node, ".");
.....

This can easily be optimized by reading the attribute from the node directly instead of using the expansive XPath call. Our rewritten method looks like this now:

private PlayerStat extractPlayerStat(Node node, Team team) {
        String extId = getAttribute(node.getParentNode().getAttributes(), "player_id");
        String position = getAttribute(node.getParentNode().getAttributes(), "position");
        String jerseyNumber = getAttribute(node.getParentNode().getAttributes(), "shirtNumber");
        String firstName = getAttribute(node.getParentNode().getAttributes(), "first_name");
        String lastName = getAttribute(node.getParentNode().getAttributes(), "last_name");
        String nickName = getAttribute(node.getParentNode().getAttributes(), "known_name");
        String key = getAttribute(node.getAttributes(), "name");
        String value = node.getTextContent();
.....
private String getAttribute(NamedNodeMap attributes, String name) {
    Node value = attributes.getNamedItem(name);
    return (value == null) ? null : value.getTextContent();
}

Finally we do another profiling session and voila, with this small change we already saved 12 minutes (from 15 to 3) in the import activity.

Using this technique we can concentrate on the next hot-spots now.