Deserialisation performance regression (0.6.0 -> 0.8.0)

[keynmol]

Hey guys. Is there any log of deserialisation regressions between 0.6.0 and 0.8.0? I recently upgraded and noticed serious performance regression.

The file is 4.5M, basically a serialised Scala structure

case class ContextTokenStore(tokenLookup: Map[String, Int], idLookup: Map[Int, String], tokenTotalCounts: Map[Int, Int])

The hashcodes of both structures produced by different versions are exactly the same

Kryo is initialised as such:

val instantiator = (new ScalaKryoInstantiator).setReferences(false)
  val kryo: KryoPool = KryoPool.withByteArrayOutputStream(10, instantiator)
...
  def load[T](file: File): T = {
    val bytes = file.loadBytes
    val store: T = kryo.fromBytes(bytes).asInstanceOf[T]

    store
  }

The file size is the same if produced by both 0.6.0 and 0.8.0, but the loading from disk times vary significantly (basically loading 20 times, times in milliseconds):

0.6.0

[loading] took 562, and then 228, 179, 168, 117, 120, 138, 128, 125, 139, 130, 123, 137, 134, 120, 132, 141, 143, 144, 154

0.8.0

 [loading] took 3081, and then 1859, 1813, 1722, 1622, 1688, 1704, 1881, 2603, 2164, 2040, 1946, 2010, 2063, 2053, 2159, 2717, 2065, 2276, 2381

Any clue as to where to look?

[johnynek]

would be interesting to compare with 0.7 as well (which uses the same version of kryo as 0.6). The main things that have changed is that 0.8 is using a later version of kryo.

[keynmol]

Hi, it was a bit of a false alarm as this was caused by dependencies.

TL;DR

wrong version of minlog in the classpath led to every single deserialised object being logged on debug level.

The way @ianoc helped me spot it on gitter was after looking at the profiler:

Here's what happened

We had an exclusion rule:

libraryDependencies ~= { _.map(_.excludeAll(
      ExclusionRule("com.esotericsoftware", "minlog"), // <---- sic!
      ExclusionRule("commons-logging"),
      ExclusionRule("log4j", "log4j"),
      ExclusionRule("org.slf4j")
    )) },

and a merge strategy

      // com/esotericsoftware/kryo/kryo/2.21/kryo-2.21.jar
      // com/esotericsoftware/minlog/minlog/1.2-slf4j-jdanbrown-0/minlog-1.2-slf4j-jdanbrown-0.jar
      case PathList("com", "esotericsoftware", "minlog", xs @ _*) =>
        MergeStrategy.last

So in the dependencyTree of the branch with chill 0.8.0 there was only +-com.esotericsoftware.minlog:minlog:1.2-slf4j-jdanbrown-0, but the old branch without regressions (chill 0.6.0) had

[info]   | +-com.esotericsoftware.minlog:minlog:1.2
[info]   +-com.esotericsoftware.minlog:minlog:1.2
[info]   +-com.esotericsoftware.minlog:minlog:1.2-slf4j-jdanbrown-0 (evicted by: 1.2)
[info]   | | +-com.esotericsoftware.minlog:minlog:1.2
[info]   |     +-com.esotericsoftware.minlog:minlog:1.2
[info]   | |   +-com.esotericsoftware.minlog:minlog:1.2
[info]   | | | +-com.esotericsoftware.minlog:minlog:1.2
[info]   | |     +-com.esotericsoftware.minlog:minlog:1.2
[info]   | | | | +-com.esotericsoftware.minlog:minlog:1.2
[info]   | | |     +-com.esotericsoftware.minlog:minlog:1.2

So I guess the lesson here is kicking out com.esotericsoftware.minlog:minlog:1.2-slf4j-jdanbrown-0 leads to this silent regression because it logs every object it deserialises.

I'm sure I'm the only one who could possibly get bitten by this :) Unless there's any action here, I will close it.

[johnynek]

Thanks for running this down and reporting back.

…

On Tue, May 9, 2017 at 23:14 Anton Sviridov ***@***.***> wrote: Hi, it was a bit of a false alarm as this was caused by dependencies. TL;DR wrong version of minlog in the classpath led to every single deserialised object being logged on debug level. The way @ianoc <https://github.com/ianoc> helped me spot it on gitter <https://gitter.im/twitter/chill?at=5911ee830a783b6c0a7e8ea5> was after looking at the profiler: [image: screenshot 2017-05-09 17 29 08] <https://cloud.githubusercontent.com/assets/1052965/25891402/da4ec166-3568-11e7-98d7-8c4199cc7715.png> Here's what happened We had an exclusion rule: libraryDependencies ~= { _.map(_.excludeAll( ExclusionRule("com.esotericsoftware", "minlog"), // <---- sic! ExclusionRule("commons-logging"), ExclusionRule("log4j", "log4j"), ExclusionRule("org.slf4j") )) }, and a merge strategy // com/esotericsoftware/kryo/kryo/2.21/kryo-2.21.jar // com/esotericsoftware/minlog/minlog/1.2-slf4j-jdanbrown-0/minlog-1.2-slf4j-jdanbrown-0.jar case PathList("com", "esotericsoftware", "minlog", xs @ _*) => MergeStrategy.last So in the dependencyTree of the branch with chill *0.8.0* there was only +-com.esotericsoftware.minlog:minlog:1.2-slf4j-jdanbrown-0, but the old branch without regressions (chill *0.6.0*) had [info] | +-com.esotericsoftware.minlog:minlog:1.2 [info] +-com.esotericsoftware.minlog:minlog:1.2 [info] +-com.esotericsoftware.minlog:minlog:1.2-slf4j-jdanbrown-0 (evicted by: 1.2) [info] | | +-com.esotericsoftware.minlog:minlog:1.2 [info] | +-com.esotericsoftware.minlog:minlog:1.2 [info] | | +-com.esotericsoftware.minlog:minlog:1.2 [info] | | | +-com.esotericsoftware.minlog:minlog:1.2 [info] | | +-com.esotericsoftware.minlog:minlog:1.2 [info] | | | | +-com.esotericsoftware.minlog:minlog:1.2 [info] | | | +-com.esotericsoftware.minlog:minlog:1.2 So I guess the lesson here is kicking out com.esotericsoftware.minlog:minlog:1.2-slf4j-jdanbrown-0 leads to this silent regression because it logs every object it deserialises. I'm sure I'm the only one who could possibly get bitten by this :) Unless there's any action here, I will close it. — You are receiving this because you commented. Reply to this email directly, view it on GitHub <#291 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/AAEJduj4hv8y4OsrLGX0666bjICjF6oNks5r4X_xgaJpZM4NVUKV> .