First call to `ArraysKt.contains` is slow

Question

Consider this:

import kotlin.system.measureTimeMillis

fun main() {
  // Uncomment, and make it >=2 elements will make [timeInMillis] 0.
  // Changing [setOf] to [arrayOf] doesn't help.
  // setOf(1, 2)

  val timeInMillis = measureTimeMillis {
    3 in arrayOf(4)
  }
  println("$timeInMillis ms")
}

I believe 3 in arrayOf(4) is equivalent to the ArraysKt.contains(new Integer[]{4}, 3); Java code.

For some reason, on linux in the JVM, timeInMillis can take up to 30ms. I was led to this when benchmarking the equivalent on Android, where on a Pixel 2 device, it can take up to 90 ms. These numbers seem to be quite large considering the workload.

My guess is that there's some sort of lazy initialization going on in Kotlin stdlib which causes this. How do I find out more about what's going on?

user_5133585 · Answer

My guess is that there's some sort of lazy initialization going on in Kotlin stdlib which causes this.

There is indeed lazy initialisation, and this is not about Kotlin, but the JVM. This is the way the JVM loads classes. You can use the -verbose:class JVM option to find out which classes are initialised.

println("Measure Start!")
val timeInMillis = measureNanoTime {
    3 in arrayOf(4)
}
println("Measure End!")
println("$timeInMillis ns")

Running this on my macOS machine with IntelliJ with -verbose:class prints (showing relevant parts of the output only):

Measure Start!
[0.132s][info][class,load] java.net.SocketAddress source: jrt:/java.base
[0.132s][info][class,load] java.net.InetSocketAddress source: jrt:/java.base
[0.132s][info][class,load] java.net.InetAddress source: shared objects file
[0.133s][info][class,load] jdk.internal.access.JavaNetInetAddressAccess source: shared objects file
[0.133s][info][class,load] java.net.InetAddress$1 source: shared objects file
[0.133s][info][class,load] java.net.InetAddress$InetAddressHolder source: shared objects file
[0.133s][info][class,load] java.util.SortedSet source: shared objects file
[0.133s][info][class,load] java.util.NavigableSet source: shared objects file
[0.133s][info][class,load] java.util.concurrent.ConcurrentSkipListSet source: shared objects file
[0.134s][info][class,load] java.util.SortedMap source: shared objects file
[0.134s][info][class,load] java.util.NavigableMap source: shared objects file
[0.134s][info][class,load] java.util.concurrent.ConcurrentNavigableMap source: shared objects file
[0.134s][info][class,load] java.util.concurrent.ConcurrentSkipListMap source: shared objects file
[0.134s][info][class,load] java.util.concurrent.ConcurrentSkipListMap$Index source: shared objects file
[0.134s][info][class,load] java.util.concurrent.atomic.Striped64 source: shared objects file
[0.134s][info][class,load] java.util.concurrent.atomic.LongAdder source: shared objects file
[0.134s][info][class,load] java.util.concurrent.ConcurrentSkipListMap$Node source: shared objects file
[0.134s][info][class,load] java.net.InetAddressImplFactory source: shared objects file
[0.134s][info][class,load] java.net.InetAddressImpl source: shared objects file
[0.134s][info][class,load] java.net.Inet6AddressImpl source: shared objects file
[0.134s][info][class,load] java.lang.Class$1 source: shared objects file
[0.135s][info][class,load] java.net.InetAddress$NameService source: shared objects file
[0.135s][info][class,load] java.net.InetAddress$PlatformNameService source: shared objects file
[0.135s][info][class,load] java.net.Inet4Address source: shared objects file
[0.135s][info][class,load] java.net.InetSocketAddress$InetSocketAddressHolder source: jrt:/java.base
[0.135s][info][class,load] java.net.SocketOptions source: jrt:/java.base
[0.135s][info][class,load] java.net.SocketImpl source: jrt:/java.base
[0.136s][info][class,load] java.net.SocketImpl$$Lambda$14/0x0000000800b69840 source: java.net.SocketImpl
[0.136s][info][class,load] sun.net.NetProperties source: jrt:/java.base
[0.136s][info][class,load] sun.net.NetProperties$1 source: jrt:/java.base
[0.136s][info][class,load] java.util.Properties$LineReader source: shared objects file
[0.137s][info][class,load] sun.net.PlatformSocketImpl source: jrt:/java.base
[0.138s][info][class,load] sun.nio.ch.NioSocketImpl source: jrt:/java.base
[0.138s][info][class,load] sun.nio.ch.NativeDispatcher source: jrt:/java.base
[0.138s][info][class,load] sun.nio.ch.SocketDispatcher source: jrt:/java.base
[0.138s][info][class,load] sun.nio.ch.IOUtil source: jrt:/java.base
[0.140s][info][class,load] java.util.concurrent.locks.AbstractQueuedSynchronizer source: shared objects file
[0.140s][info][class,load] java.util.concurrent.locks.ReentrantLock$Sync source: shared objects file
[0.140s][info][class,load] java.util.concurrent.locks.ReentrantLock$NonfairSync source: shared objects file
[0.140s][info][class,load] java.net.SocksConsts source: jrt:/java.base
[0.140s][info][class,load] java.net.DelegatingSocketImpl source: jrt:/java.base
[0.140s][info][class,load] java.net.SocksSocketImpl source: jrt:/java.base
[0.140s][info][class,load] sun.nio.ch.Net source: jrt:/java.base
[0.140s][info][class,load] java.net.ProtocolFamily source: jrt:/java.base
[0.140s][info][class,load] sun.nio.ch.Net$1 source: jrt:/java.base
[0.141s][info][class,load] sun.net.ext.ExtendedSocketOptions source: jrt:/java.base
[0.141s][info][class,load] jdk.net.ExtendedSocketOptions source: jrt:/jdk.net
[0.141s][info][class,load] java.net.SocketOption source: jrt:/java.base
[0.141s][info][class,load] jdk.net.ExtendedSocketOptions$ExtSocketOption source: jrt:/jdk.net
[0.141s][info][class,load] jdk.net.SocketFlow source: jrt:/jdk.net
[0.141s][info][class,load] jdk.net.ExtendedSocketOptions$PlatformSocketOptions source: jrt:/jdk.net
[0.141s][info][class,load] jdk.net.ExtendedSocketOptions$PlatformSocketOptions$1 source: jrt:/jdk.net
[0.141s][info][class,load] jdk.net.MacOSXSocketOptions source: jrt:/jdk.net
[0.143s][info][class,load] kotlin.collections.ArraysKt__ArraysJVMKt source: file:/Applications/IntelliJ%20IDEA%20CE.app/Contents/plugins/Kotlin/kotlinc/lib/kotlin-stdlib.jar
[0.143s][info][class,load] kotlin.collections.ArraysKt__ArraysKt source: file:/Applications/IntelliJ%20IDEA%20CE.app/Contents/plugins/Kotlin/kotlinc/lib/kotlin-stdlib.jar
[0.143s][info][class,load] kotlin.collections.ArraysKt___ArraysJvmKt source: file:/Applications/IntelliJ%20IDEA%20CE.app/Contents/plugins/Kotlin/kotlinc/lib/kotlin-stdlib.jar
[0.143s][info][class,load] kotlin.collections.ArraysKt___ArraysKt source: file:/Applications/IntelliJ%20IDEA%20CE.app/Contents/plugins/Kotlin/kotlinc/lib/kotlin-stdlib.jar
[0.143s][info][class,load] kotlin.collections.ArraysKt source: file:/Applications/IntelliJ%20IDEA%20CE.app/Contents/plugins/Kotlin/kotlinc/lib/kotlin-stdlib.jar
[0.143s][info][class,load] jdk.net.ExtendedSocketOptions$1 source: jrt:/jdk.net
[0.144s][info][class,load] java.net.Inet6Address source: shared objects file
[0.145s][info][class,load] java.net.Inet6Address$Inet6AddressHolder source: shared objects file
[0.151s][info][class,load] kotlin.jvm.internal.Intrinsics source: file:/Applications/IntelliJ%20IDEA%20CE.app/Contents/plugins/Kotlin/kotlinc/lib/kotlin-stdlib.jar
[0.151s][info][class,load] kotlin.KotlinNullPointerException source: file:/Applications/IntelliJ%20IDEA%20CE.app/Contents/plugins/Kotlin/kotlinc/lib/kotlin-stdlib.jar
[0.152s][info][class,load] kotlin.UninitializedPropertyAccessException source: file:/Applications/IntelliJ%20IDEA%20CE.app/Contents/plugins/Kotlin/kotlinc/lib/kotlin-stdlib.jar
[0.152s][info][class,load] java.lang.AssertionError source: jrt:/java.base
[0.152s][info][class,load] java.lang.IllegalStateException source: jrt:/java.base
[0.152s][info][class,load] java.lang.UnsupportedOperationException source: jrt:/java.base
[0.152s][info][class,load] java.net.StandardProtocolFamily source: jrt:/java.base
Measure End!
20704379 ns

Note the timestamps.

A lot of classes got loaded while you are doing 3 in arrayOf(4), because this is the first time you are using those classes. Note specifically that kotlin.collections.ArraysKt is loaded.

What if you do this first?

println("Calling setOf")
println(setOf(1, 2))

The output becomes:

Calling setOf
[0.126s][info][class,load] jdk.internal.access.JavaNetInetAddressAccess source: shared objects file
[0.126s][info][class,load] java.net.InetAddress$1 source: shared objects file
[0.126s][info][class,load] java.net.InetAddress$InetAddressHolder source: shared objects file
[0.126s][info][class,load] java.util.SortedSet source: shared objects file
[0.126s][info][class,load] java.util.NavigableSet source: shared objects file
[0.126s][info][class,load] java.util.concurrent.ConcurrentSkipListSet source: shared objects file
[0.126s][info][class,load] java.util.SortedMap source: shared objects file
[0.126s][info][class,load] java.util.NavigableMap source: shared objects file
[0.126s][info][class,load] java.util.concurrent.ConcurrentNavigableMap source: shared objects file
[0.126s][info][class,load] java.util.concurrent.ConcurrentSkipListMap source: shared objects file
[0.126s][info][class,load] java.util.concurrent.ConcurrentSkipListMap$Index source: shared objects file
[0.126s][info][class,load] java.util.concurrent.atomic.Striped64 source: shared objects file
[0.126s][info][class,load] java.util.concurrent.atomic.LongAdder source: shared objects file
[0.126s][info][class,load] java.util.concurrent.ConcurrentSkipListMap$Node source: shared objects file
[0.126s][info][class,load] java.net.InetAddressImplFactory source: shared objects file
[0.127s][info][class,load] java.net.InetAddressImpl source: shared objects file
[0.127s][info][class,load] java.net.Inet6AddressImpl source: shared objects file
[0.127s][info][class,load] kotlin.collections.SetsKt__SetsJVMKt source: file:/Applications/IntelliJ%20IDEA%20CE.app/Contents/plugins/Kotlin/kotlinc/lib/kotlin-stdlib.jar
[0.127s][info][class,load] kotlin.collections.SetsKt__SetsKt source: file:/Applications/IntelliJ%20IDEA%20CE.app/Contents/plugins/Kotlin/kotlinc/lib/kotlin-stdlib.jar
[0.127s][info][class,load] java.lang.Class$1 source: shared objects file
[0.127s][info][class,load] kotlin.collections.SetsKt___SetsKt source: file:/Applications/IntelliJ%20IDEA%20CE.app/Contents/plugins/Kotlin/kotlinc/lib/kotlin-stdlib.jar
[0.127s][info][class,load] kotlin.collections.SetsKt source: file:/Applications/IntelliJ%20IDEA%20CE.app/Contents/plugins/Kotlin/kotlinc/lib/kotlin-stdlib.jar
[0.127s][info][class,load] java.net.InetAddress$NameService source: shared objects file
[0.127s][info][class,load] java.net.InetAddress$PlatformNameService source: shared objects file
[0.127s][info][class,load] java.net.Inet4Address source: shared objects file
[0.127s][info][class,load] java.net.InetSocketAddress$InetSocketAddressHolder source: jrt:/java.base
[0.128s][info][class,load] java.net.SocketOptions source: jrt:/java.base
[0.128s][info][class,load] java.net.SocketImpl source: jrt:/java.base
[0.128s][info][class,load] kotlin.jvm.internal.Intrinsics source: file:/Applications/IntelliJ%20IDEA%20CE.app/Contents/plugins/Kotlin/kotlinc/lib/kotlin-stdlib.jar
[0.128s][info][class,load] java.net.SocketImpl$$Lambda$14/0x0000000800b6a040 source: java.net.SocketImpl
[0.128s][info][class,load] kotlin.KotlinNullPointerException source: file:/Applications/IntelliJ%20IDEA%20CE.app/Contents/plugins/Kotlin/kotlinc/lib/kotlin-stdlib.jar
[0.129s][info][class,load] sun.net.NetProperties source: jrt:/java.base
[0.129s][info][class,load] sun.net.NetProperties$1 source: jrt:/java.base
[0.129s][info][class,load] java.util.Properties$LineReader source: shared objects file
[0.129s][info][class,load] kotlin.UninitializedPropertyAccessException source: file:/Applications/IntelliJ%20IDEA%20CE.app/Contents/plugins/Kotlin/kotlinc/lib/kotlin-stdlib.jar
[0.129s][info][class,load] java.lang.AssertionError source: jrt:/java.base
[0.129s][info][class,load] java.lang.IllegalStateException source: jrt:/java.base
[0.129s][info][class,load] java.lang.UnsupportedOperationException source: jrt:/java.base
[0.130s][info][class,load] sun.net.PlatformSocketImpl source: jrt:/java.base
[0.130s][info][class,load] sun.nio.ch.NioSocketImpl source: jrt:/java.base
[0.130s][info][class,load] sun.nio.ch.NativeDispatcher source: jrt:/java.base
[0.130s][info][class,load] sun.nio.ch.SocketDispatcher source: jrt:/java.base
[0.130s][info][class,load] sun.nio.ch.IOUtil source: jrt:/java.base
[0.132s][info][class,load] java.util.concurrent.locks.AbstractQueuedSynchronizer source: shared objects file
[0.132s][info][class,load] java.util.concurrent.locks.ReentrantLock$Sync source: shared objects file
[0.132s][info][class,load] java.util.concurrent.locks.ReentrantLock$NonfairSync source: shared objects file
[0.132s][info][class,load] java.net.SocksConsts source: jrt:/java.base
[0.132s][info][class,load] java.net.DelegatingSocketImpl source: jrt:/java.base
[0.132s][info][class,load] java.net.SocksSocketImpl source: jrt:/java.base
[0.133s][info][class,load] sun.nio.ch.Net source: jrt:/java.base
[0.133s][info][class,load] java.net.ProtocolFamily source: jrt:/java.base
[0.133s][info][class,load] sun.nio.ch.Net$1 source: jrt:/java.base
[0.133s][info][class,load] sun.net.ext.ExtendedSocketOptions source: jrt:/java.base
[0.133s][info][class,load] jdk.net.ExtendedSocketOptions source: jrt:/jdk.net
[0.133s][info][class,load] java.net.SocketOption source: jrt:/java.base
[0.133s][info][class,load] jdk.net.ExtendedSocketOptions$ExtSocketOption source: jrt:/jdk.net
[0.133s][info][class,load] jdk.net.SocketFlow source: jrt:/jdk.net
[0.133s][info][class,load] jdk.net.ExtendedSocketOptions$PlatformSocketOptions source: jrt:/jdk.net
[0.133s][info][class,load] jdk.net.ExtendedSocketOptions$PlatformSocketOptions$1 source: jrt:/jdk.net
[0.133s][info][class,load] jdk.net.MacOSXSocketOptions source: jrt:/jdk.net
[0.135s][info][class,load] jdk.net.ExtendedSocketOptions$1 source: jrt:/jdk.net
[0.136s][info][class,load] java.net.Inet6Address source: shared objects file
[0.136s][info][class,load] java.net.Inet6Address$Inet6AddressHolder source: shared objects file
[0.139s][info][class,load] kotlin.collections.ArraysKt__ArraysJVMKt source: file:/Applications/IntelliJ%20IDEA%20CE.app/Contents/plugins/Kotlin/kotlinc/lib/kotlin-stdlib.jar
[0.139s][info][class,load] kotlin.collections.ArraysKt__ArraysKt source: file:/Applications/IntelliJ%20IDEA%20CE.app/Contents/plugins/Kotlin/kotlinc/lib/kotlin-stdlib.jar
[0.139s][info][class,load] kotlin.collections.ArraysKt___ArraysJvmKt source: file:/Applications/IntelliJ%20IDEA%20CE.app/Contents/plugins/Kotlin/kotlinc/lib/kotlin-stdlib.jar
[0.139s][info][class,load] kotlin.collections.ArraysKt___ArraysKt source: file:/Applications/IntelliJ%20IDEA%20CE.app/Contents/plugins/Kotlin/kotlinc/lib/kotlin-stdlib.jar
[0.139s][info][class,load] kotlin.collections.ArraysKt source: file:/Applications/IntelliJ%20IDEA%20CE.app/Contents/plugins/Kotlin/kotlinc/lib/kotlin-stdlib.jar
[0.143s][info][class,load] java.net.StandardProtocolFamily source: jrt:/java.base
[0.146s][info][class,load] sun.nio.ch.NioSocketImpl$$Lambda$15/0x0000000800b6a440 source: sun.nio.ch.NioSocketImpl
[0.146s][info][class,load] java.net.SocksSocketImpl$3 source: jrt:/java.base
[0.146s][info][class,load] java.net.ProxySelector source: jrt:/java.base
[0.146s][info][class,load] sun.net.spi.DefaultProxySelector source: jrt:/java.base
[0.146s][info][class,load] java.net.Proxy source: jrt:/java.base
[0.147s][info][class,load] java.net.Proxy$Type source: jrt:/java.base
[0.147s][info][class,load] sun.net.spi.DefaultProxySelector$1 source: jrt:/java.base
[0.147s][info][class,load] sun.net.spi.DefaultProxySelector$NonProxyInfo source: jrt:/java.base
[0.147s][info][class,load] sun.net.spi.DefaultProxySelector$3 source: jrt:/java.base
[0.147s][info][class,load] sun.net.NetHooks source: jrt:/java.base
[0.147s][info][class,load] sun.net.NetHooks$Provider source: jrt:/java.base
[0.147s][info][class,load] sun.net.sdp.SdpProvider source: jrt:/java.base
[0.148s][info][class,load] sun.nio.ch.NativeThread source: jrt:/java.base
[0.150s][info][class,load] kotlin.collections.MapsKt__MapWithDefaultKt source: file:/Applications/IntelliJ%20IDEA%20CE.app/Contents/plugins/Kotlin/kotlinc/lib/kotlin-stdlib.jar
[0.150s][info][class,load] kotlin.collections.MapsKt__MapsJVMKt source: file:/Applications/IntelliJ%20IDEA%20CE.app/Contents/plugins/Kotlin/kotlinc/lib/kotlin-stdlib.jar
[0.150s][info][class,load] kotlin.collections.MapsKt__MapsKt source: file:/Applications/IntelliJ%20IDEA%20CE.app/Contents/plugins/Kotlin/kotlinc/lib/kotlin-stdlib.jar
[0.150s][info][class,load] kotlin.collections.MapsKt___MapsKt source: file:/Applications/IntelliJ%20IDEA%20CE.app/Contents/plugins/Kotlin/kotlinc/lib/kotlin-stdlib.jar
[0.150s][info][class,load] kotlin.collections.MapsKt source: file:/Applications/IntelliJ%20IDEA%20CE.app/Contents/plugins/Kotlin/kotlinc/lib/kotlin-stdlib.jar
[0.150s][info][class,load] java.util.LinkedHashMap$LinkedKeySet source: jrt:/java.base
[0.151s][info][class,load] java.util.LinkedHashMap$LinkedHashIterator source: shared objects file
[0.151s][info][class,load] java.util.LinkedHashMap$LinkedKeyIterator source: jrt:/java.base
[1, 2]
Measure Start!
Measure End!
19515 ns

As you can see, now all that class loading is done before you start measuring. Specifically, kotlin.collections.ArraysKt also got loaded here (at 0.139s).

If you call arrayOf rather than setOf first, however, it won't work as effectively, because arrayOf is inline. The Kotlin compiler directly translates arrayOf(1, 2) to new Integer[] { 1, 2 }, which doesn't use anything in ArraysKt, so it doesn't cause ArraysKt to be loaded.

If you call setOf with one element, a similar thing happens. The single parameter setOf calls java.util.Collections.singleton, so it doesn't use anything in ArraysKt either :(

You can also experiment with the JVM option -XX:+PrintCompilation. It shows you when each method is being JIT compiled. The time required to JIT compile methods could also be a reason why calling in the first time is slow.

See also: Why does the JVM require warmup?

user_3277386 · Answer

The implementation of measureTimeMillis uses the System.currentTimeMillis() system function, which is usually no precise enough for use cases as yours. You need a more precise measurement to measure such short-lived processes. For this, use measureNanoTime.

As other users have noted, the Just in time compiler of the JVM usually takes a bit of time to make Classes available at runtime. If you run your code twice, and only measure the second run, you should get much better results.

import kotlin.system.measureNanoTime

fun main() {
  val init: Boolean = 3 in arrayOf(4)
  val timeInNanos = measureNanoTime {
    3 in arrayOf(4)
  }
  println("$timeInNanos ns")
}

On Kotlin-play: https://play.kotlinlang.org/?_gl=1sbvwfn_gaMTMwNjUxNzc1My4xNjIwMTEyMDY5_ga_J6T75801PF*MTYyOTEwMDQzMy4yOC4xLjE2MjkxMDExMTUuMA..&_ga=2.877105.1220867763.1629100434-1306517753.1620112069#eyJ2ZXJzaW9uIjoiMS41LjIxIiwicGxhdGZvcm0iOiJqYXZhIiwiYXJncyI6IiIsIm5vbmVNYXJrZXJzIjp0cnVlLCJ0aGVtZSI6ImlkZWEiLCJjb2RlIjoiaW1wb3J0IGtvdGxpbi5zeXN0ZW0ubWVhc3VyZU5hbm9UaW1lXG5cbmZ1biBtYWluKCkge1xuICB2YWwgaW5pdDogQm9vbGVhbiA9IDMgaW4gYXJyYXlPZig0KVxuICB2YWwgdGltZUluTmFub3MgPSBtZWFzdXJlTmFub1RpbWUge1xuICAgIDMgaW4gYXJyYXlPZig0KVxuICB9XG4gIHByaW50bG4oXCIkdGltZUluTmFub3MgbnNcIilcbn0ifQ==

3503 ns are about 1/300000 th of a second.

For a more reliable benchmark, measure the total tile multiple runs take, and divide by the number. An average will probably be more telling anyway.

First call to `ArraysKt.contains` is slow

2 Answers