Recently I have been working on performance in the API layer and discovered a nice bug in our JSON parsing usage that is worth blogging on.

Background

Our usage of Jackson to handle JSON manipulation boils-down to moving data from an internal JSON documents to JSON document of the API response.
Most of the data is represented by primitive data types like String and Integer but some are wrapped in custom POJO objects like "Id" that wraps id string to provide more consistence programming model. Enums, by-the-way, have the same issue, as they are also Java objects under the hood, though Enums require additional overhead of parsing string to Enum value.
To read the JSON value as POJO object we use ObjectMapper.treeToValue method that accepts the TreeNode and the Java Class of the POJO type to convert the value to. For the conversation to work we annotate one of the POJO type constructors with @JsonCreator so ObjectMapper will know which constructor to use to convert the string value into a typed object.
 

Finding the issue

After seeing performance issue in one of the APIs (using Zipkin) I ran the relevant API in a tight loop and collected profiling data using YourKit Java profiler.
As can be seen in figure 1 and 2 ObjectMapper.treeToValue method contribution to the performance issue is clear.
 

Figure 1: the hot path directing straight to ObjectMapper.treeToValue method.
 

Figure 2: Overall ObjectMapper.treeToValue is the most expensive method by far.
 
Digging into the usage of ObjectMapper.treeToValue method, as can be seen in YourKit Call Tree (figure 1), we discovered that we have a proxy class with an ObjectMapper instance field (figure 3). Therefor for each new instance of ModelAuditorInvocationHandler a new instance of ObjectMapper is created.
 

private static  class ModelAuditorInvocationHandler implements InvocationHandler {      
    private final ObjectMapper objectMapper =  new ObjectMapper();      
...

Figure 3: Class with ObjectMapper instance fields.
 
It raised my suspicion as everywhere else we use ObjectMapper as a static field so only a single instance is created.
After making a little tester (simplified version can be found below) I discovered that the using instance vs. static ObjectMapper field result in approximately x20 performance difference, that is the instance field usage is 20 times slower than static field!
Changing the ObjectMapper to static and re-running the test confirmed the issue, performance was significantly improved and the most expensive method became Proxy.newProxyInstance.
 
I can speculate that ObjectMapper uses reflection to create the POJO type from the string value, at least to find the constructor annotated with @JsonCreator. To improve performance ObjectMapper keeps some kind of caching per instance so creating a new instance each time requires ObjectMapper to do the expensive work each time.
 

Conclusion

• Use single instance of ObjectMapper in your code.
• Make sure you check the performance of any code that uses reflection, directly or indirectly.
• YourKit is an excellent and easy to use Java profiler.
• Zipkin is great for finding application wise performance issues.

Sample test code

See the effect of using static vs. not static ObjectMapper instance in Wrapper class.
When ObjectMapper instance is not static the overhead of getting MyString is ~500% while if it is static there is no overhead at all.
Although in this simple tester we see "only" x5 difference I believe it is effected by the complexity of the code as I saw x20 – x25 difference in real code.
 

public class Main {      

    public static void main(String[] args)  throws Exception {      

        ObjectMapper objectMapper = new  ObjectMapper();      
        ObjectNode node = (ObjectNode)  objectMapper.readTree("{"string":"hello  world"}");      

        long start1 = System.nanoTime();      
        for (int i = 0; i < 10000; i++) {      
            Wrapper wrapper = new  Wrapper(node);      
            wrapper.getString();      
        }      
        long time1 = System.nanoTime() -  start1;      

        long start2 = System.nanoTime();      
        for (int i = 0; i < 10000; i++) {      
            Wrapper wrapper = new  Wrapper(node);      
            wrapper.getMyString();      
        }      
        long time2 = System.nanoTime() -  start2;      

        System.out.println("Overhead:  " + time2 / (double) time1);      
    }      

    public static class Wrapper {      

        private /*static*/ final ObjectMapper  objectMapper = new ObjectMapper();      

        private final ObjectNode node;      

        private Wrapper(ObjectNode node) {      
            this.node = node;      
        }      

        public String getString() throws  JsonProcessingException {      
            return  objectMapper.treeToValue(node.get("string"), String.class);      
        }      

        public MyString getMyString() throws  JsonProcessingException {      
            return  objectMapper.treeToValue(node.get("string"), MyString.class);      
        }      
    }      

    public static class MyString {      

        private final String string;      

        @JsonCreator      
        public MyString(String string) {      
            this.string = string;      
        }      
    }      
}