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);
  }
}

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?)