Performance regression with 2.17.x

[plokhotnyuk]

Both 2.17.0 and 2.17.0-rc1 are affected when small messages (less than 100 bytes) are parsed or serialized in multiple threads using the same object mapper instance.

The problem exists when parsing bigger messages but the performance difference is smaller.

All libraries that use the latest version of jackson library under the hood are affected: json4s, play-json, weePickle, etc.

Here are results of benchmarks that parse and serialize 62-byte and 1185-byte messages (ADTReading/ADTWriting and ArrayOfEnumADTsReading/ArrayOfEnumADTsWriting accordingly) on Intel(R) Core(TM) i7-11700 @ 2.50GHz (max 4.90 GHz) with DDR4-3200 using 16 threads:

2.16.2

[info] Benchmark                                           (size)   Mode  Cnt          Score         Error  Units
[info] ADTReading.borer                                       N/A  thrpt   10    6794141.947 ±   28943.355  ops/s
[info] ADTReading.circe                                       N/A  thrpt   10    5733802.213 ±   20142.997  ops/s
[info] ADTReading.circeJsoniter                               N/A  thrpt   10    6033807.062 ±   39206.180  ops/s
[info] ADTReading.jacksonScala                                N/A  thrpt   10    8600750.285 ±   29585.508  ops/s
[info] ADTReading.json4sJackson                               N/A  thrpt   10    1986617.545 ±   11937.239  ops/s
[info] ADTReading.json4sNative                                N/A  thrpt   10     728301.651 ±    3179.717  ops/s
[info] ADTReading.jsoniterScala                               N/A  thrpt   10   31056253.119 ±  162615.821  ops/s
[info] ADTReading.playJson                                    N/A  thrpt   10    2854140.465 ±   12044.125  ops/s
[info] ADTReading.playJsonJsoniter                            N/A  thrpt   10    5930774.513 ±   12228.253  ops/s
[info] ADTReading.smithy4sJson                                N/A  thrpt   10    8047920.054 ±   57498.071  ops/s
[info] ADTReading.sprayJson                                   N/A  thrpt   10    7559747.663 ±   37500.787  ops/s
[info] ADTReading.uPickle                                     N/A  thrpt   10   10820366.906 ±   38588.185  ops/s
[info] ADTReading.weePickle                                   N/A  thrpt   10    8520949.161 ±   38999.046  ops/s
[info] ADTReading.zioJson                                     N/A  thrpt   10    6516965.272 ±   30056.348  ops/s
[info] ADTWriting.borer                                       N/A  thrpt   10   12725701.358 ±   64383.508  ops/s
[info] ADTWriting.circe                                       N/A  thrpt   10    5702372.141 ±  123333.038  ops/s
[info] ADTWriting.circeJsoniter                               N/A  thrpt   10    6136183.702 ±   31911.935  ops/s
[info] ADTWriting.jacksonScala                                N/A  thrpt   10   20213415.218 ±  154415.084  ops/s
[info] ADTWriting.json4sJackson                               N/A  thrpt   10    1970762.580 ±    5888.709  ops/s
[info] ADTWriting.json4sNative                                N/A  thrpt   10    2129475.567 ±   10664.320  ops/s
[info] ADTWriting.jsoniterScala                               N/A  thrpt   10   86348750.403 ± 3923732.627  ops/s
[info] ADTWriting.jsoniterScalaPrealloc                       N/A  thrpt   10  126135815.779 ±  753875.520  ops/s
[info] ADTWriting.playJson                                    N/A  thrpt   10    7066647.975 ±   38110.136  ops/s
[info] ADTWriting.playJsonJsoniter                            N/A  thrpt   10   10034627.023 ±   45579.652  ops/s
[info] ADTWriting.smithy4sJson                                N/A  thrpt   10   19544469.284 ±  206715.422  ops/s
[info] ADTWriting.sprayJson                                   N/A  thrpt   10    8817363.222 ±   29355.150  ops/s
[info] ADTWriting.uPickle                                     N/A  thrpt   10   12346407.504 ±   41903.003  ops/s
[info] ADTWriting.weePickle                                   N/A  thrpt   10   15216077.687 ±   71823.446  ops/s
[info] ADTWriting.zioJson                                     N/A  thrpt   10    6696186.925 ±   37137.477  ops/s
[info] ArrayOfEnumADTsReading.borer                           128  thrpt   10    1485188.033 ±   11824.058  ops/s
[info] ArrayOfEnumADTsReading.circe                           128  thrpt   10    1060544.252 ±    5714.295  ops/s
[info] ArrayOfEnumADTsReading.circeJsoniter                   128  thrpt   10    1078942.307 ±    2906.939  ops/s
[info] ArrayOfEnumADTsReading.jacksonScala                    128  thrpt   10    1399993.550 ±    5345.969  ops/s
[info] ArrayOfEnumADTsReading.json4sJackson                   128  thrpt   10     386204.100 ±    1860.096  ops/s
[info] ArrayOfEnumADTsReading.json4sNative                    128  thrpt   10     312858.047 ±    3125.767  ops/s
[info] ArrayOfEnumADTsReading.jsoniterScala                   128  thrpt   10    4289813.648 ±   15066.858  ops/s
[info] ArrayOfEnumADTsReading.playJson                        128  thrpt   10     478973.090 ±    2376.637  ops/s
[info] ArrayOfEnumADTsReading.playJsonJsoniter                128  thrpt   10     515684.604 ±    1902.051  ops/s
[info] ArrayOfEnumADTsReading.sprayJson                       128  thrpt   10     755587.471 ±    4383.413  ops/s
[info] ArrayOfEnumADTsReading.uPickle                         128  thrpt   10    1242681.165 ±    2746.319  ops/s
[info] ArrayOfEnumADTsReading.weePickle                       128  thrpt   10    1169063.048 ±    4494.799  ops/s
[info] ArrayOfEnumADTsReading.zioJson                         128  thrpt   10     563521.111 ±    1445.949  ops/s
[info] ArrayOfEnumADTsWriting.borer                           128  thrpt   10    2054275.748 ±    9991.515  ops/s
[info] ArrayOfEnumADTsWriting.circe                           128  thrpt   10    1241981.451 ±  112432.709  ops/s
[info] ArrayOfEnumADTsWriting.circeJsoniter                   128  thrpt   10    2522632.787 ±   16045.668  ops/s
[info] ArrayOfEnumADTsWriting.jacksonScala                    128  thrpt   10    3174526.420 ±   17247.360  ops/s
[info] ArrayOfEnumADTsWriting.json4sJackson                   128  thrpt   10    1069988.662 ±    5451.828  ops/s
[info] ArrayOfEnumADTsWriting.json4sNative                    128  thrpt   10     387662.462 ±    1569.061  ops/s
[info] ArrayOfEnumADTsWriting.jsoniterScala                   128  thrpt   10   13584173.183 ±   65176.029  ops/s
[info] ArrayOfEnumADTsWriting.jsoniterScalaPrealloc           128  thrpt   10   15338486.834 ±   73143.637  ops/s
[info] ArrayOfEnumADTsWriting.playJson                        128  thrpt   10    2497807.549 ±   15178.768  ops/s
[info] ArrayOfEnumADTsWriting.playJsonJsoniter                128  thrpt   10    3063237.303 ±   25286.111  ops/s
[info] ArrayOfEnumADTsWriting.sprayJson                       128  thrpt   10    1816238.727 ±    8867.954  ops/s
[info] ArrayOfEnumADTsWriting.uPickle                         128  thrpt   10    1595086.586 ±    8474.119  ops/s
[info] ArrayOfEnumADTsWriting.weePickle                       128  thrpt   10    2396877.337 ±    8272.100  ops/s
[info] ArrayOfEnumADTsWriting.zioJson                         128  thrpt   10    2754854.478 ±   10817.622  ops/s

2.17.x

[info] Benchmark                                           (size)   Mode  Cnt          Score         Error  Units
[info] ADTReading.borer                                       N/A  thrpt   10    6808060.010 ±   24121.820  ops/s
[info] ADTReading.circe                                       N/A  thrpt   10    5504991.218 ±   28924.908  ops/s
[info] ADTReading.circeJsoniter                               N/A  thrpt   10    5965473.392 ±   24541.654  ops/s
[info] ADTReading.jacksonScala                                N/A  thrpt   10    3880829.241 ±   14779.470  ops/s
[info] ADTReading.json4sJackson                               N/A  thrpt   10    1684115.890 ±   17922.496  ops/s
[info] ADTReading.json4sNative                                N/A  thrpt   10     781783.122 ±    9209.704  ops/s
[info] ADTReading.jsoniterScala                               N/A  thrpt   10   28193676.278 ±  170866.780  ops/s
[info] ADTReading.playJson                                    N/A  thrpt   10    1861673.096 ±   32396.971  ops/s
[info] ADTReading.playJsonJsoniter                            N/A  thrpt   10    5936651.174 ±   28715.564  ops/s
[info] ADTReading.smithy4sJson                                N/A  thrpt   10    8183263.456 ±   78205.821  ops/s
[info] ADTReading.sprayJson                                   N/A  thrpt   10    7725596.379 ±   25148.636  ops/s
[info] ADTReading.uPickle                                     N/A  thrpt   10   10532982.352 ±   34026.274  ops/s
[info] ADTReading.weePickle                                   N/A  thrpt   10    3662160.317 ±   10805.963  ops/s
[info] ADTReading.zioJson                                     N/A  thrpt   10    6552279.264 ±   26565.487  ops/s
[info] ADTWriting.borer                                       N/A  thrpt   10   14804007.272 ±   66986.481  ops/s
[info] ADTWriting.circe                                       N/A  thrpt   10    5555829.627 ±   33717.558  ops/s
[info] ADTWriting.circeJsoniter                               N/A  thrpt   10    6289535.722 ±   24806.934  ops/s
[info] ADTWriting.jacksonScala                                N/A  thrpt   10    3815278.282 ±   44918.845  ops/s
[info] ADTWriting.json4sJackson                               N/A  thrpt   10       6895.294 ±    4815.743  ops/s
[info] ADTWriting.json4sNative                                N/A  thrpt   10    2123757.624 ±   10590.700  ops/s
[info] ADTWriting.jsoniterScala                               N/A  thrpt   10   82359727.429 ± 3453467.534  ops/s
[info] ADTWriting.jsoniterScalaPrealloc                       N/A  thrpt   10  134212123.633 ± 1162472.156  ops/s
[info] ADTWriting.playJson                                    N/A  thrpt   10     586570.259 ± 1309910.167  ops/s
[info] ADTWriting.playJsonJsoniter                            N/A  thrpt   10    9828872.088 ±   63874.635  ops/s
[info] ADTWriting.smithy4sJson                                N/A  thrpt   10   28487361.435 ±  130873.054  ops/s
[info] ADTWriting.sprayJson                                   N/A  thrpt   10   12135052.269 ±   49628.928  ops/s
[info] ADTWriting.uPickle                                     N/A  thrpt   10   10269863.568 ±   68308.485  ops/s
[info] ADTWriting.weePickle                                   N/A  thrpt   10    3263834.084 ±    8549.350  ops/s
[info] ADTWriting.zioJson                                     N/A  thrpt   10    6440516.792 ±   20713.803  ops/s
[info] ArrayOfEnumADTsReading.borer                           128  thrpt   10    1267431.783 ±    6201.075  ops/s
[info] ArrayOfEnumADTsReading.circe                           128  thrpt   10    1061247.664 ±    7164.785  ops/s
[info] ArrayOfEnumADTsReading.circeJsoniter                   128  thrpt   10    1079132.139 ±    5715.793  ops/s
[info] ArrayOfEnumADTsReading.jacksonScala                    128  thrpt   10    1396218.772 ±    6514.442  ops/s
[info] ArrayOfEnumADTsReading.json4sJackson                   128  thrpt   10     384574.257 ±    2804.130  ops/s
[info] ArrayOfEnumADTsReading.json4sNative                    128  thrpt   10     314105.580 ±    2377.774  ops/s
[info] ArrayOfEnumADTsReading.jsoniterScala                   128  thrpt   10    4304162.519 ±   14939.710  ops/s
[info] ArrayOfEnumADTsReading.playJson                        128  thrpt   10     394406.502 ±    1457.237  ops/s
[info] ArrayOfEnumADTsReading.playJsonJsoniter                128  thrpt   10     667298.395 ±    2485.742  ops/s
[info] ArrayOfEnumADTsReading.sprayJson                       128  thrpt   10     764851.351 ±    4757.110  ops/s
[info] ArrayOfEnumADTsReading.uPickle                         128  thrpt   10    1249665.477 ±    7025.275  ops/s
[info] ArrayOfEnumADTsReading.weePickle                       128  thrpt   10    1127465.787 ±    7466.347  ops/s
[info] ArrayOfEnumADTsReading.zioJson                         128  thrpt   10     563303.187 ±    2571.587  ops/s
[info] ArrayOfEnumADTsWriting.borer                           128  thrpt   10    2058803.540 ±   12165.516  ops/s
[info] ArrayOfEnumADTsWriting.circe                           128  thrpt   10    2011009.990 ±   12085.455  ops/s
[info] ArrayOfEnumADTsWriting.circeJsoniter                   128  thrpt   10    2667427.734 ±   13161.756  ops/s
[info] ArrayOfEnumADTsWriting.jacksonScala                    128  thrpt   10    2969747.276 ±   13888.207  ops/s
[info] ArrayOfEnumADTsWriting.json4sJackson                   128  thrpt   10     970464.315 ±    6924.823  ops/s
[info] ArrayOfEnumADTsWriting.json4sNative                    128  thrpt   10     388122.507 ±    1894.329  ops/s
[info] ArrayOfEnumADTsWriting.jsoniterScala                   128  thrpt   10   13694337.067 ±   54600.403  ops/s
[info] ArrayOfEnumADTsWriting.jsoniterScalaPrealloc           128  thrpt   10   15482028.886 ±   63118.277  ops/s
[info] ArrayOfEnumADTsWriting.playJson                        128  thrpt   10    2181855.381 ±   11481.359  ops/s
[info] ArrayOfEnumADTsWriting.playJsonJsoniter                128  thrpt   10    3063457.946 ±   22866.313  ops/s
[info] ArrayOfEnumADTsWriting.sprayJson                       128  thrpt   10    1822167.265 ±   11824.459  ops/s
[info] ArrayOfEnumADTsWriting.uPickle                         128  thrpt   10    2018705.050 ±   10173.067  ops/s
[info] ArrayOfEnumADTsWriting.weePickle                       128  thrpt   10    2164800.857 ±   22721.277  ops/s
[info] ArrayOfEnumADTsWriting.zioJson                         128  thrpt   10    2720774.650 ±   12951.514  ops/s

Steps to reproduce:

1. Download binaries of async-profiler and unpack them into /opt/async-profiler
2. git clone https://github.com/plokhotnyuk/jsoniter-scala
3. cd jsoniter-scala
4. sbt -java-home /usr/lib/jvm/jdk-21 jsoniter-scala-benchmarkJVM/clean 'jsoniter-scala-benchmarkJVM/jmh:run -prof "async:dir=target/async-reports;interval=1000000;output=flamegraph;libPath=/opt/async-profiler/lib/libasyncProfiler.so" -jvmArgsAppend "-XX:+UnlockDiagnosticVMOptions -XX:+DebugNonSafepoints" --p size=128 -t 16 -wi 10 -i 10 ADT'

The issue exists when tested on other JVMs (GraalVM Community, Oracle GraalVM) and with other garbage collectors (G1GC, ZGC)

Here are flame-graphs of async-profiler reports for ADTWriting.jacksonScala benchmark:

2.16.2

2.17.0

For json4s and play-json libraries performance could dynamically slowing down in about 1000x times:

[info] # Warmup Iteration   1: 498097.603 ops/s
[info] # Warmup Iteration   2: 1396602.529 ops/s
[info] # Warmup Iteration   3: 1390047.351 ops/s
[info] # Warmup Iteration   4: 1397460.036 ops/s
[info] # Warmup Iteration   5: 548693.538 ops/s
[info] # Warmup Iteration   6: 467155.766 ops/s
[info] # Warmup Iteration   7: 308437.551 ops/s
[info] # Warmup Iteration   8: 299814.921 ops/s
[info] # Warmup Iteration   9: 120140.861 ops/s
[info] # Warmup Iteration  10: 16015.216 ops/s
[info] Iteration   1: 6210.625 ops/s
[info] Iteration   2: 3199.072 ops/s
[info] Iteration   3: 9214.890 ops/s
[info] Iteration   4: 6565.308 ops/s
[info] Iteration   5: 1545.670 ops/s
[info] Iteration   6: 9597.542 ops/s
[info] Iteration   7: 6781.583 ops/s
[info] Iteration   8: 12569.237 ops/s
[info] Iteration   9: 5324.412 ops/s
[info] Iteration  10: 7944.598 ops/s

Could be using of ThreadLocal for cashing of object mappers be an acceptable workaround for this issue?

Is any workaround where we can explicitly define initial size of underlying buffers to be suitable for using with other libraries like play-json and weePickle?

[pjfanning]

Thanks @plokhotnyuk

The switch away from ThreadLocal caching is the biggest change in 2.17. It can be switched back on via config.

Fyi @cowtowncoder

[plokhotnyuk]

It can be switched back on via config.

@pjfanning Is it .recyclerPool(JsonRecyclerPools.threadLocalPool()) call for the factory builder?

[cowtowncoder]

Interesting. My tests with jackson-benchmarks didn't show regression for rc1 (I think I did run tests) -- possibly since they do not collect output as byte[] (writeValueAsBytes()). This was with JDK 8 tho in case that matters.

[pjfanning]

It can be switched back on via config.

@pjfanning Is it .recyclerPool(JsonRecyclerPools.threadLocalPool()) call for the factory builder?

@plokhotnyuk I'm on a day trip so only have my phone. That looks right though.

@cowtowncoder would it be fair to say that users should try to create as few ObjectMappers as possible and reuse them as much as possible? With the new default recycler, having a single ObjectMapper shared across threads might be the best option for high throughput.

[cowtowncoder]

Yes, ObjectMappers should always be reused, regardless of other aspects: they (or rather, (de)serializer construction) are very heavy objects, and overhead of throwing them away negates any benefits of other caching, recycling.

And for safety, reusing ObjectReaders and ObjectWriters (constructed via ObjectMapper) is recommended: their creation is very cheap as well (as instances created by same ObjectMapper still share (de)serializer caching, reuse, in thread-safe manner).

Having said that, it sounds like here reuse is done as expected so wasteful non-reuse would not be an issue.

[cowtowncoder]

FWTW, json4s and play-json case is most worrying: it almost suggests like buffer recycling might be growing without bound? As if something was able to "return" buffers to recyclers, but not to actually recycle such buffer instances. Otherwise lack of recycling in itself should not cause increasingly bad performance.

[cowtowncoder]

And one more thing: I will be off for about a week so may not be able to follow up quickly here -- but I am very interested in learning what exactly might be going on to cause this problem, and how to resolve it.

[pjfanning]

FWTW, json4s and play-json case is most worrying: it almost suggests like buffer recycling might be growing without bound? As if something was able to "return" buffers to recyclers, but not to actually recycle such buffer instances. Otherwise lack of recycling in itself should not cause increasingly bad performance.

I haven't looked at the play-json/json4s code but one possibility is that they create ObjectMappers and use them once and throw them away. They possibly don't use a JsonFactory instance to create the ObjectMappers. So every ObjectMapper could have its own JsonFactory and every JsonFactory has its own BufferRecycler instance - and this ends up hardly seeing any reuse of arrays.

With the old ThreadLocal buffer-recycler the cache is not specific to a JsonFactory instance - so you can get away with not trying to reuse the specific buffer-recycler instance.

[cowtowncoder]

Yes but that wouldnt explain gradually worsening behavior… itd just be overall no-recycling case. I guess itd be possible to try with no op recycler and compare numbers.

…

On Wed, Mar 13, 2024 at 12:09 PM PJ Fanning ***@***.***> wrote: FWTW, json4s and play-json case is most worrying: it almost suggests like buffer recycling might be growing without bound? As if something was able to "return" buffers to recyclers, but not to actually recycle such buffer instances. Otherwise lack of recycling in itself should not cause increasingly bad performance. I haven't looked at the play-json/json4s code but one possibility is that they create ObjectMappers and use them once and throw them away. They possibly don't use a JsonFactory instance to create the ObjectMappers. So every ObjectMapper could have its own JsonFactory and every JsonFactory has its own BufferRecycler instance - and this ends up hardly seeing any reuse of arrays. With the old ThreadLocal buffer-recycler the cache is not specific to a JsonFactory instance - so you can get away with not trying to reuse the specific buffer-recycler instance. — Reply to this email directly, view it on GitHub <#672 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AAANOGKHLYHL6SIVG7EDTQLYYCP43AVCNFSM6AAAAABEUFKLHGVHI2DSMVQWIX3LMV43OSLTON2WKQ3PNVWWK3TUHMYTSOJVGQZTGMRQHA> . You are receiving this because you were mentioned.Message ID: ***@***.***>