Performance regression in 2.2.3

[gianm]

Version 2.2.3 does untyped deserialization dramatically slower (about 150x in the benchmark I am using) than 2.2.2. I'm testing with a json object that has a few levels of nesting (maps within maps; some keys are lists too) with a loop that looks like this:

  def timeJacksonJava(reps: Int) = {
    var ret: Seq[AnyRef] = null
    val jm = new ObjectMapper
    for (i <- 0 until reps) {
      val xs = bytess map (jm.readValue(_, classOf[AnyRef]))
      if (ret == null) {
        ret = xs
      }
    }
    ret
  }

  def timeJacksonScala(reps: Int) = {
    var ret: Seq[AnyRef] = null
    val jm = new ObjectMapper()
    jm.registerModule(DefaultScalaModule)
    for (i <- 0 until reps) {
      val xs = bytess map (jm.readValue(_, classOf[AnyRef]))
      if (ret == null) {
        ret = xs
      }
    }
    ret
  }

bytess is a Seq[Array[Byte]] where each byte array is a json object on the order of a few kb. jackson-module-scala 2.2.2 runs roughly the same speed as jackson itself, but 2.2.3 is much slower.

[cowtowncoder]

Can you verify if 2.3.3 has the same issue?

[gianm]

Just tried it, looks like 2.3.3 is slow too.

[gianm]

Btw just to be totally clear-- timeJacksonJava runs about the same speed in 2.2.2, 2.2.3, & 2.3.3 (~170MB/s on my machine). timeJacksonScala runs at about 170MB/s as well on 2.2.2, but ~1MB/s on 2.2.3+

[brharrington]

I noticed a similar issue and the cause seems to be the changes for #89. In particular a profile of our application shows the time is being spent calling ctxt.findRootValueDeserializer. For my example, if I set DeserializationFeature.USE_JAVA_ARRAY_FOR_JSON_ARRAY the problem goes away because it bypasses these changes. I also confirmed the problem goes away for me if I build a jar with the changes to mapArray reverted, though a dataset with lots of objects would likely still have problems. A simple test case that illustrates the problem:

  val testJson = {
    val str = new StringBuilder
    str.append("{\"values\":[")
    (0 until 100000).foreach { i =>
      str.append(s"[${i.toDouble}],")
    }
    str.append(s"[${0.0}]")
    str.append("]}")
    str.toString
  }

  def main(args: Array[String]): Unit = {
    (0 until 10).foreach { i =>
      val s = System.nanoTime
      val m = deserialize[Map[String,AnyRef]](testJson)
      val e = System.nanoTime
      println(s"${m.size}, ${(e - s) / 1e6}ms")
    }
  }

If I run with DeserializationFeature.USE_JAVA_ARRAY_FOR_JSON_ARRAY enabled I get:

1, 530.666ms
1, 36.227ms
1, 19.585ms
1, 47.563ms
1, 17.945ms
1, 23.39ms
1, 19.716ms
1, 18.649ms
1, 22.985ms
1, 31.618ms

If I run it without that flag I get:

1, 27709.518ms
1, 26620.834ms
1, 23866.794ms
1, 23579.977ms
1, 23839.36ms
1, 23629.038ms
1, 23505.023ms
1, 23448.91ms
1, 23807.761ms
1, 23553.336ms

[deromka]

I also noticed significant performance degradation with the jackson scala module library starting from 2.2.3, here are my tests:

Recently I performed performance tests on one of our server side components and saw very significant impact on performance. After some investigations I have managed to isolate the culprit of the performance degradation, it is the Jackson library (for json parsing), here are the results:

In my tests I use some relatively big json string ~11KBytes.
The test performs deserialization from json to object 10000 times, repeats it 10 times and makes an average.

def measure(repeat : Int, times : Int) = {
    var start = 0L
    var end = 0L
    var diff = 0L
    var sum = 0L
    (1 to repeat).foreach { rep =>
      start = System.currentTimeMillis()
      (1 to times).par.foreach { i =>
        val hh = JsonLayer.JSON_MAPPER.readValue(householdString("hh" + i * rep), classOf[Household])
        //val st = JsonLayer.JSON_MAPPER.writeValueAsString(hh)
      }
      end = System.currentTimeMillis()
      diff = (end - start)
      sum += diff
      logger.debug("Round " + rep + " took " + diff + " millis")
    }
    sum
  }

  @Test
  def householdJsonPerformance() =
  {
    val repeat = 10
    val times = 10000
    var start = 0L
    var end = 0L
    var sum  = 0L
    var diff = 0L

    // warmup
    diff = measure(repeat, times)
    logger.debug("Round warm up took " + diff + " millis")

    Measure.time(this.logger, "performance household deserialize/serialize") {
          sum = measure(repeat, times)
      }
    logger.debug("Average per run " + (sum/repeat) + " millis")
  }

Jackson libraries version: 2.4.3

jackson-core-2.4.3.jar jackson-annotations-2.4.3.jar jackson-databind-2.4.3.jar

The only difference between the tests is following jar were updated each time:

jackson-module-scala_2.10-{version}.jar

The results of the test above with different versions of the jars:

2.2.2

 Round 1 took 2921 millis   
 Round 2 took 842 millis   
 Round 3 took 677 millis   
 Round 4 took 597 millis   
 Round 5 took 556 millis   
 Round 6 took 590 millis   
 Round 7 took 697 millis   
 Round 8 took 597 millis   
 Round 9 took 577 millis   
 Round 10 took 548 millis   
 Round warm up took 8602 millis   
 [ Executing performance household deserialize/serialize ...]   
 Round 1 took 474 millis   
 Round 2 took 458 millis   
 Round 3 took 465 millis   
 Round 4 took 493 millis   
 Round 5 took 519 millis   
 Round 6 took 445 millis   
 Round 7 took 446 millis   
 Round 8 took 485 millis   
 Round 9 took 485 millis   
 Round 10 took 456 millis   
 [ performance household deserialize/serialize took 4731 ms ]   
**Average per run 472 millis</strong>  millis**

2.2.3

Round 1 took 8228 millis</br>
Round 2 took 5428 millis</br>   
Round 3 took 3771 millis</br>   
Round 4 took 3798 millis</br>   
Round 5 took 3560 millis</br>   
Round 6 took 3558 millis</br>   
Round 7 took 3847 millis</br>   
Round 8 took 3709 millis</br>   
Round 9 took 3496 millis</br>   
Round 10 took 3836 millis</br>   
Round warm up took 43231 millis   </br>
[ Executing performance household deserialize/serialize ...]   </br>
Round 1 took 5355 millis   </br>
Round 2 took 6018 millis   </br>
Round 3 took 3962 millis   </br>
Round 4 took 3481 millis   </br>
Round 5 took 3821 millis   </br>
Round 6 took 3739 millis   </br>
Round 7 took 3545 millis   </br>
Round 8 took 3594 millis   </br>
Round 9 took 3615 millis   </br>
Round 10 took 3595 millis   </br>
[ performance household deserialize/serialize took 40726 ms ]   </br>
**Average per run 4072 millis**

2.3.3

Round 1 took 8631 millis   
Round 2 took 5342 millis   
Round 3 took 3617 millis   
Round 4 took 3578 millis   
Round 5 took 3633 millis   
Round 6 took 3740 millis   
Round 7 took 3541 millis   
Round 8 took 3833 millis   
Round 9 took 3678 millis   
Round 10 took 3596 millis   
Round warm up took 43189 millis   
[ Executing performance household deserialize/serialize ...]   
Round 1 took 3753 millis   
Round 2 took 3408 millis   
Round 3 took 4728 millis   
Round 4 took 4270 millis   
Round 5 took 3565 millis   
Round 6 took 3521 millis   
Round 7 took 3492 millis   
Round 8 took 3573 millis   
Round 9 took 3959 millis   
Round 10 took 4094 millis   
[ performance household deserialize/serialize took 38365 ms ]   
**Average per run 3836 millis**

2.4.3

 Round 1 took 8331 millis   
 Round 2 took 4903 millis   
 Round 3 took 3568 millis   
 Round 4 took 3545 millis   
 Round 5 took 3494 millis   
 Round 6 took 3597 millis   
 Round 7 took 3637 millis   
 Round 8 took 3629 millis   
 Round 9 took 3612 millis   
 Round 10 took 3550 millis   
 Round warm up took 41866 millis   
 [ Executing performance household deserialize/serialize ...]   
 Round 1 took 3611 millis   
 Round 2 took 3510 millis   
 Round 3 took 3508 millis   
 Round 4 took 3923 millis   
 Round 5 took 4848 millis   
 Round 6 took 4819 millis   
 Round 7 took 3960 millis   
 Round 8 took 3580 millis   
 Round 9 took 4092 millis   
 Round 10 took 4480 millis   
 [ performance household deserialize/serialize took 40332 ms ]   
**Average per run 4033 millis**

To summarize:

There is performance degradation in jackson scala module 2_10 libraries starting from 2.2.3 version (2.2.2 version works fine)

In my tests above version jackson-module-scala_2.10-2.2.2 work ~7.5 times faster that jackson-module-scala_2.10-2.2.3

When this bug will be fixed?

[nbauernfeind]

@deromka Can you re-run your test using the jar from 2.4.3 but with this module instead of the DefaultScalaModule:

new JacksonModule
     with IteratorModule
     with EnumerationModule
     with OptionModule
     with SeqModule
     with IterableModule
     with TupleModule
     with MapModule
     with SetModule
     with ScalaClassIntrospectorModule
     with UntypedObjectDeserializerModule {
  override def getModuleName = "DefaultScalaModule"
}

Version 2.2.3 added ScalaStdValueInstantiatorsModule which analyzes all methods/fields that are scala getter/setters.

[nbauernfeind]

@deromka Nevermind. I just did something similar to your test and that module is definitely not to blame.

[deromka]

No problem, I can run some additional tests

On Tue, Nov 11, 2014 at 5:28 PM, Nate Bauernfeind notifications@github.com
wrote:

@deromka https://github.com/deromka Nevermind. I just did something
similar to your test and that module is definitely not to blame.

—
Reply to this email directly or view it on GitHub
#148 (comment)
.

[cowtowncoder]

I would strongly recommend taking a profiler snapshot (with sampling). Given magnitude of deviation, it should be relatively easy what is taking time here.

[cowtowncoder]

Also: one other thing that may or may not be useful: this benchmark project:

https://github.com/FasterXML/jackson-benchmarks

is something I wrote for 2.4, and have used it for regular Java benchmarking, over most data formats Jackson supports. Perhaps it'd be possible to build a simplified version of problematic data type(s), and add a Scala test; so once we figure out and solve the current issue, we could perhaps guard against regression.

[deromka]

Hi,

I have done profiling on both versions - 2.2.2 and 2.4.3

2.2.2 screenshot

2.4.3 screenshot

So as it seen in the hotspots the reflection methods consumes about 50% cpu

java.lang.reflect.Method.getDeclaredAnnotations
java.lang.Class.getInterfaces
java.lang.Class.getDeclaredMethods
java.lang.Class.getDeclaredAnnotations
java.lang.Class.getDeclaredConstructors

These are called from

com.fasterxml.jackson.module.scala.deser.UntypedObjectDeserializer$$anonfun$deserializeAbstractType$1.appy

Please check that

On Tue, Nov 11, 2014 at 7:26 PM, Tatu Saloranta notifications@github.com
wrote:

Also: one other thing that may or may not be useful: this benchmark
project:

https://github.com/FasterXML/jackson-benchmarks

is something I wrote for 2.4, and have used it for regular Java
benchmarking, over most data formats Jackson supports. Perhaps it'd be
possible to build a simplified version of problematic data type(s), and add
a Scala test; so once we figure out and solve the current issue, we could
perhaps guard against regression.

—
Reply to this email directly or view it on GitHub
#148 (comment)
.

[cowtowncoder]

Thank you. I think that there are a few things in UntypedObjectDeserializer.scala that could be optimized (starting with per-deser-call construction of helper types); but the biggest thing probably is that it is not currently being cached.

Version 2.4.4 of jackson-databind may help here, actually, as the base implementation (UntypedObjectDeserializer.java) now implemented isCachable() to return true.
But it would probably make sense to override it on Scala sub-class as well, just in case.

If you can build Scala module locally, defining:

    @Override
    public boolean isCachable() { return true; }

(in suitable Scala version)

should help; so if it'd be easy enough to do, you may want to test to see if and how it would change performance.

[christophercurrie]

@cowtowncoder, with respect to per-deser-call construction of types, how immutable can I expect the results of DeserializationContext#getFactory and DeserializationContext#findRootValueDeserializer to be? Can I cache the results of these calls, do I need to cache them using the DeserializationContext as a key, or some other mechanism?

In general, I've been assuming that since DeserializationContext is passed in to mapArray and mapObject, that the value could be different every time, and thus I could get different results from those calls and can't cache them. If there's more caching I can do of those values, or a way that I could get them from the DeserizalizationConfig and not the DeserializationContext, I'm sure that would help performance here a lot.

[cowtowncoder]

@christophercurrie Good question. The answer should be considered static, and may be fully cached. This is related to ObjectMapper being "configure-fully-then-use", so that additional registrations or changes after first use are not guaranteed to have any effect.
Dynamic lookups are mostly needed for serializers, although same rule applies there. But type information may be incomplete (static declared type vs actual runtime type).

The main limitation is that deserializers themselves must be single-threaded, so most commonly deserializers resolve dependencies by implementing createContextual(...) method of ContextualDeserializer, and by constructing a new deserializer instance with new/changed deserializers.
The reason for doing it this way instead of trying to locate dependencies during construction (which is difficult for non-core deserializers due to other reasons as well) is that this gives access to annotations for the property, and class declaring property.

[christophercurrie]

Follow up question: can I rely upon ObjectMapper to synchronize access to my UntypedObjectDeserializer, or do I need to synchronize my caching logic?