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

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