Jackson 1.9.7 tracing

gistfile1.txt

In particular, note from the log above that the first parse of an instance of TestObject is slow, but further invocations are very fast. HOWEVER, the next invocation of another class (TestObject2) is ALSO very slow (followed by subsequent fast ones).

Here is the full .trace file:
http://apetresc.s3.amazonaws.com/jacksontrace2.trace

Here are various screenshots of the trace inspector:
http://apetresc.s3.amazonaws.com/trace-BasicClassIntrospector.collectProperties.png
http://apetresc.s3.amazonaws.com/trace-BeanDeserializerFactory.createBeanDeserializer.png
http://apetresc.s3.amazonaws.com/trace-DeserializationConfig.introspect.png
http://apetresc.s3.amazonaws.com/trace-JacksonAnnotationInspector.isHandled.png
http://apetresc.s3.amazonaws.com/trace-POJOPropertiesCollector._addMethods.png
http://apetresc.s3.amazonaws.com/trace-POJOPropertiesCollector.collect.png

In particular, check out JacksonAnnotationInspector.isHandled. This guy makes multiple calls to Class.getAnnotation() and each invocation takes ~4ms on Android. Added all together, we're spending 74ms of our total 540ms in this method alone.

jacksontrace2.log

08-09 14:13:40.410: I/dalvikvm(2717): TRACE STARTED: '/sdcard/jacksontrace2.trace' 8192KB
08-09 14:13:40.790: D/JsonTest(2717): at 335ms: read object TestObject <a b c d e 1 2 3>
08-09 14:13:40.810: D/JsonTest(2717): at 353ms: read object TestObject <a b c d e 1 2 3>
08-09 14:13:40.840: D/JsonTest(2717): at 384ms: read object TestObject <a b c d e 1 2 3>
08-09 14:13:40.850: D/dalvikvm(2717): GC_CONCURRENT freed 328K, 50% free 2830K/5639K, external 0K/0K, paused 4ms+4ms
08-09 14:13:41.050: D/JsonTest(2717): at 590ms: read object TestObject2 <a b c d e 1 2 3>
08-09 14:13:41.060: D/JsonTest(2717): at 601ms: read object TestObject2 <a b c d e 1 2 3>
08-09 14:13:41.070: D/JsonTest(2717): at 611ms: read object TestObject2 <a b c d e 1 2 3>
08-09 14:13:41.070: D/dalvikvm(2717): +++ active profiler count now 0
08-09 14:13:41.340: I/dalvikvm(2717): TRACE STOPPED: writing 82798 records

MainActivity.java

package com.example.jsontest;

import java.io.IOException;

import org.codehaus.jackson.JsonParseException;
import org.codehaus.jackson.map.JsonMappingException;
import org.codehaus.jackson.map.ObjectMapper;

import android.app.Activity;
import android.os.Bundle;
import android.os.Debug;
import android.util.Log;

public class MainActivity extends Activity {

  private static final String TEST_OBJECT = "{\"s1\" : \"a\", \"s2\" : \"b\", \"s3\" : \"c\", \"s4\" : \"d\", \"s5\" : \"e\", \"i1\" : 1, \"i2\" : 2, \"i3\" : 3}";
  private static final String TAG = "JsonTest";

  private static void log(long startTime, String message) {
    Log.d(TAG, "at " + (System.currentTimeMillis() - startTime) + "ms: " + message);
  }
  
  @Override
  public void onCreate(Bundle savedInstanceState) {
    super.onCreate(savedInstanceState);

    try {
      TestObject o = new TestObject();
      ObjectMapper m = new ObjectMapper();

      Debug.startMethodTracing("jacksontrace2");

      final long start = System.currentTimeMillis();
      
      testRead(start, m, TestObject.class);
      testRead(start, m, TestObject.class);
      testRead(start, m, TestObject.class);

      testRead(start, m, TestObject2.class);
      testRead(start, m, TestObject2.class);
      testRead(start, m, TestObject2.class);
      
      Debug.stopMethodTracing();
      
    } catch (Exception e) {
      e.printStackTrace();
    }

    setContentView(R.layout.activity_main);
  }



  private <T> void testRead(long startTime, ObjectMapper m, Class<T> _class) throws JsonParseException, JsonMappingException, IOException {
    
    T o = m.readValue(TEST_OBJECT, _class);
    log(startTime, "read object " + o.toString());
  }

}

TestObject.java

package com.example.jsontest;

import org.codehaus.jackson.annotate.JsonAutoDetect;

@JsonAutoDetect
public class TestObject {

  private String s1;
  private String s2;
  private String s3;
  private String s4;
  private String s5;
  
  private int i1;
  private int i2;
  private int i3;
  
  public String getS1() {
    return s1;
  }
  public void setS1(String s1) {
    this.s1 = s1;
  }
  public String getS2() {
    return s2;
  }
  public void setS2(String s2) {
    this.s2 = s2;
  }
  public String getS3() {
    return s3;
  }
  public void setS3(String s3) {
    this.s3 = s3;
  }
  public String getS4() {
    return s4;
  }
  public void setS4(String s4) {
    this.s4 = s4;
  }
  public String getS5() {
    return s5;
  }
  public void setS5(String s5) {
    this.s5 = s5;
  }
  public int getI1() {
    return i1;
  }
  public void setI1(int i1) {
    this.i1 = i1;
  }
  public int getI2() {
    return i2;
  }
  public void setI2(int i2) {
    this.i2 = i2;
  }
  public int getI3() {
    return i3;
  }
  public void setI3(int i3) {
    this.i3 = i3;
  }
  
  public String toString() {
    return String.format("%s <%s %s %s %s %s %d %d %d>", this.getClass().getSimpleName(), s1, s2, s3, s4, s5, i1, i2, i3);
  }
}

TestObject2.java

package com.example.jsontest;

import org.codehaus.jackson.annotate.JsonAutoDetect;

@JsonAutoDetect
public class TestObject2 {

  private String s1;
  private String s2;
  private String s3;
  private String s4;
  private String s5;
  
  private int i1;
  private int i2;
  private int i3;
  
  public String getS1() {
    return s1;
  }
  public void setS1(String s1) {
    this.s1 = s1;
  }
  public String getS2() {
    return s2;
  }
  public void setS2(String s2) {
    this.s2 = s2;
  }
  public String getS3() {
    return s3;
  }
  public void setS3(String s3) {
    this.s3 = s3;
  }
  public String getS4() {
    return s4;
  }
  public void setS4(String s4) {
    this.s4 = s4;
  }
  public String getS5() {
    return s5;
  }
  public void setS5(String s5) {
    this.s5 = s5;
  }
  public int getI1() {
    return i1;
  }
  public void setI1(int i1) {
    this.i1 = i1;
  }
  public int getI2() {
    return i2;
  }
  public void setI2(int i2) {
    this.i2 = i2;
  }
  public int getI3() {
    return i3;
  }
  public void setI3(int i3) {
    this.i3 = i3;
  }
  
  public String toString() {
    return String.format("%s <%s %s %s %s %s %d %d %d>", this.getClass().getSimpleName(), s1, s2, s3, s4, s5, i1, i2, i3);
  }
}

Hmmh. That part on 'isHandled()' is interesting, since it is sort of unnecessary check in any case (only used to prune away unneeded annotations.

One question: any chance you could try out Jackson 2.0? I think calls to isHandled() are actually removed, since that allows custom handlers to see custom annotations (not just "jackson annotations"); and this means there is no need for isHandled().

Sorry, my last comment didn't format property.

I ran a nearly identical test with Jackson 2.0.5.
Again, the first deserialization for each type (TestObject, TestObject2)
takes ~200ms, and subsequent ones take ~5ms.

Here is a condensed version of the profiling data:

* DeserializerCache._createDeserializer - 264 ms
    * 51.1% in DeserializationConfig.introspect - 135ms
        * 70% in POJOPropertiesCollector.collect() - 92ms
            * 55% in POJOPropertiesCollector._addMethods() - 51 ms
                * 45% in AnnotatedClass.memberMethods() - 23 ms
                    * 30% in AnnotatedMethodMap.add() - 7 ms
                    * 19.4% in AnnotatedClass._constructMethod() - 4 ms
                    * 16% in Class.getDeclaredMethods() - 3 ms
                    * 15% in AnnotatedClass._isIncludableMemberMethod - 3 ms
                    * 15% in AnnotatedMethodMap.find() - 3 ms
                * 27% in POJOPropertiesCollector._addGetterMethod() - 14 ms
                * 20% in POJOPropertiesCollector._addSetterMethod() - 10 ms
            * 23.2% in POJOPropertiesCollector._addFields() - 21 ms
                * 39% in AnnotatedClass.fields() - 8ms
                * 19% in JacksonAnnotationIntrospector.findDeserialization() - 4 ms
                * 19% in POJOPropertiesCollector._property() - 4 ms
        * 29.1% in BasicClassIntrospector.constructPropertyCollector() - 38 ms
            * 73% in VisibilityChecker$Std.with() - 43 ms
            * 27% in AnnotatedClass.getAnnotation() - 15 ms
    * 46.2% in BeanDeserializerFactory.createBeanDeserializer - 122 ms
        * 69% in BeanDeserializerFactory.addBeanProps() - 79 ms
            * 50 % in BeanDeserializerFactory.constructSettableProperty() - 39 ms
            * 28 % in BeanDeserializerFactory.filterBeanProps() - 22 ms
        * 23% in BasicDeserializerFactory.findValueInstantiator() - 27 ms
            * 73% in VisibilityChecker$Std.with() - 43 ms
            * 27% in AnnotatedClass.getAnnotation() - 15 ms

Here is the log output:


08-09 17:37:16.850: I/dalvikvm(4144): TRACE STARTED: '/sdcard/jackson2.0.5trace.trace' 8192KB
08-09 17:37:17.110: D/JsonTest(4144): at 214ms: jackson 2.0.5 read object TestObject <a b c d e 1 2 3>
08-09 17:37:17.120: D/JsonTest(4144): at 225ms: jackson 2.0.5 read object TestObject <a b c d e 1 2 3>
08-09 17:37:17.130: D/JsonTest(4144): at 236ms: jackson 2.0.5 read object TestObject <a b c d e 1 2 3>
08-09 17:37:17.300: D/dalvikvm(4144): GC_CONCURRENT freed 315K, 50% free 2852K/5639K, external 0K/0K, paused 5ms+4ms
08-09 17:37:17.360: D/JsonTest(4144): at 471ms: jackson 2.0.5 read object TestObject2 <a b c d e 1 2 3>
08-09 17:37:17.370: D/JsonTest(4144): at 481ms: jackson 2.0.5 read object TestObject2 <a b c d e 1 2 3>
08-09 17:37:17.390: D/JsonTest(4144): at 492ms: jackson 2.0.5 read object TestObject2 <a b c d e 1 2 3>
08-09 17:37:17.390: D/dalvikvm(4144): +++ active profiler count now 0
08-09 17:37:17.440: D/dalvikvm(3880): GC_FOR_MALLOC freed 5K, 33% free 9682K/14279K, external 131K/1429K, paused 1166ms
08-09 17:37:17.560: D/dalvikvm(3880): GC_FOR_MALLOC freed 2K, 32% free 9714K/14279K, external 131K/1429K, paused 98ms
08-09 17:37:17.560: I/dalvikvm-heap(3880): Grow heap (frag case) to 12.089MB for 65552-byte allocation
08-09 17:37:17.650: I/dalvikvm(4144): TRACE STOPPED: writing 64840 records

I wonder if Dalvik might not be caching member (Method, Field, Ctor) information: regular J2SE JDK does, so further calls are basically free. If so, maybe Jackson could be improved to try to retain that info.
Although some entries look highly suspicious (as either profiling artifacts, or things not JIT'ed, to degree Dalvik even does that); specifically, things like VisibilityChecker$Std.with() or 'constructSettableProperty()`.

Any chance these could be further broken down? Or are these the leaf methods? I don't see methods from 'java.lang.Class' etc -- maybe profiler just hides standard classes by default?

Thanks again for the replies, @cowtowncoder!

According to another team member (@tavianator), he knows for a fact that Dalvik does NOT cache the member information returned by Class.getFields()/Class.getMethods().

Here are two variations on the experiment that may prove to be illuminating:
1) If we get rid of @JsonAutoDetect on TestObject and replace it with @JsonProperty(value) on each field, getter, and setter, it actually INCREASES the time for the first parse to about 450 ms (up from 200).
2) If we use ObjectMapper() to parse to JsonNode instead of our custom type, it REDUCES the time by an order of magnitude (to about 30-40 ms)

As for breaking down that stack trace even further, it starts getting unwieldy very fast. The .trace files linked above (and the one at this link for the Jackson 2.0 experiment: http://apetresc.s3.amazonaws.com/jackson2.0.5trace.trace) contain the whole tree (which makes it almost 1MB long). It can be viewed as a plaintext file, but it's probably easier to use the traceview utility included with the Android SDK. Plus, that giant graphviz image I tweeted earlier does actually contain most of the information in the trace file, including the "leaf nodes" you're asking about :)

Cheers!

One more note: @JsonAutoDetect itself is actually redundant, and should be possible to remove (it just says "use defaults" which... are used by default).

No surprise on JsonNode, since it does not invoke (much of) Bean/POJO introspection.

But the non-caching of Reflection info might prove helpful; just not sure at what level -- whether it'd be more at "cache AnnotatedClass instances" or somewhere lower. At lower level would be safer (since class defs do not change in that way), but more intrusive. At higher level there may be issues when resolving annotations on class hierarchies, where interpretation of the whole may differ depending on level; and testing of all (or even representative) variations becomes impractical.

Also: interesting note on @JsonProperty, mostly because addition or removal of annotation instances should not (it seems) matter that much -- all annotations of all fields, methods, are resolved anyway. That is, amount of processing increases but not drastically, considering that all the same getters/setters, and properties inferred for them, are still produced.

So my initial guess would be that what is costly is actual materialization of objects that represent annotations; or, possibly, loading of annotation definitions.

Thanks for having a look, @cowtowncoder!

I did another test to see what performance I get doing some basic introspection myself.

private <T> void testRead(Class<T> _class) {

  ArrayList<String> strings = new ArrayList<String>();

  final long startAnnotations = System.currentTimeMillis();
  Annotation[] annotations = _class.getAnnotations();
  for (Annotation a : annotations) {
    strings.add("<annotation: " + a.annotationType().getSimpleName() + ">");
  }
  log(startAnnotations, "read annotations for " + _class.getSimpleName());

  final long startMethods = System.currentTimeMillis();
  Method[] methods = _class.getMethods();
  for (Method m : methods) {
    strings.add("<method: " + m.getName() + " annotations: " +  m.getAnnotations().toString() +  " modifiers: " + m.getModifiers()  + ">");
  }
  log(startMethods, "read methods for " + _class.getSimpleName());

  final long startFields = System.currentTimeMillis();
  Field[] fields = _class.getFields();
  for (Field f : fields) {
    strings.add("<field: " + f.getName() + " annotations: " +  f.getAnnotations().toString() + " modifiers: " + f.getModifiers() +  ">");
  }
  log(startFields, "read fields for " + _class.getSimpleName());

  Log.d(TAG, "Introspection results: " + strings);
}

Called this on my TestObject class which has 8 private fields, 8 public getter methods and 8 public setter methods, and no annotations.
And the results are:

08-10 14:21:28.050: D/JsonTest(9346): took 1ms for: read annotations for TestObject
08-10 14:21:28.100: D/JsonTest(9346): took 44ms for: read methods for TestObject
08-10 14:21:28.100: D/JsonTest(9346): took 1ms for: read fields for TestObject

And this is only getting public methods/fields, since I'm using getAnnotations()getMethods()/getFields().

Given that my simple introspection example already takes nearly 50ms - which is pretty horrible - and it doesn't even read private fields, I worry there may not be that much room for improvement in Jackson. :-/

Ok. Very interesting... wonder what exactly is the deal with slow method access. It seems to stand out.

And yes, it also unfortunately suggests there might not be all that much that can be done: Reflection must be used to get hold of methods, no matter how they are indicated to be used (annotations, explicit, whatever).

Oh. One more thing: Jackson calls "getDeclaredMethods()", which might be bit faster, as it only gets methods that class directly declares. "getMethods()" will do more work, going through inheritance chain. Of course, Jackson will also do that, just explicitly (this is needed to weave in mix-ins), but at least that kind of explains why it's more expensive than "getFields()" (which are only from same class I think?)