compilation performance

[yigit]

We've started running more tests of Room with KCT (each test is run w/ java compile testing, KCT/KAPT, KCT/ KSP) and saw a significant slow down in our tests.

Creating this issue to track that work to see if there are places where we can improve in the library.

I started profiling them and seems like most time is spent in KAPT. In fact, KSP path is almost equal to Java compile testing path whereas KAPT runs are ~5x slower.
Sample run for the same test:

And for whatever reasons, commonJvmArgs is taking a long time in KAPT's stubs and apt task but not in KSP. (specifically, parseCommandlineArguments)

When commonArguments is invoked for KAPT:

When commonArguments is invoked for KSP:

I've not yet debugged what is going on there.

Another penalty is the classgraph / jar searches.
Right now, each KotlinCompilation instances re-acquires the class graph and find jars but they could be cached since they won't change per process.

As a result, it dominates the time spent in tests. I'm taking a small test sample so this might also be already cached in ClassGraph side so it might be an amortized cost but in my small test sample, it spend 30% much time as running actual tests (where compilation happens)

org/gradle/api/internal/tasks/testing/junit/JUnitTestClassExecutor.runTestClass
[30] 28.43% 1,181 self: 0.00% 0 org/junit/runners/ParentRunner.run
vs

[4] 8.81% 366 self: 0.00% 0 nonapi/io/github/classgraph/concurrency/WorkQueue$1.call

Below are two profile outputs (html and interactive svg). FYI they are from different runs of the same task.
There is a lot of overhead from gradle there since i'm not running many tests in the batch so please don't pay attention on total time ratios.

profile.html.tar.gz
profile.svg.tar.gz

I'll try to share more and hopefully come up with some solutions.

[yigit]

the first KSP KAPT graph is wrong, KAPT just gets the penalty for being the first one to run. I'll try to collect more data in room for this when we run full test suite in different orders.

[yigit]

So I did some manual tracing for test runners (just record the time) and here are the results from running our processing abstraction tests:

first kapt then ksp

kapt: avg: 780.0287769784172 median: 613 runCnt: 139 total: 108424
ksp: avg: 1185.1317829457364 median: 626 runCnt: 129 total: 152882
javac: avg: 52.735849056603776 median: 47 runCnt: 53 total: 2795

first ksp then kapt

ksp: avg: 1486.7906976744187 median: 783 runCnt: 129 total: 191796
kapt: avg: 969.9712230215828 median: 780 runCnt: 139 total: 134826
javac: avg: 56.62264150943396 median: 53 runCnt: 53 total: 3001

Btw, KSP is higher here because it runs kotlin compilation twice in most cases (due to #72) But i don't know what the number would be (definitely not half) if we properly integrated it.

I do expect kotlin compilation to be slower but ~15x more than javac feels like we can find some places to improve.
I'll try to isolate this out of room and see if it still reproduces. Specifically, I'm also suspecting that test ends up running w/ a large classpath, causing some of those methods to take too much time (again, it only matters if it is not cached).
Other than that, maybe there is a way to reuse some of kotlin compilation module setup.

[tschuchortdev]

Caching the jar dependencies and classpath scanning is an obvious low hanging fruit and could be done in a simple way without many changes if we don't need to give the user control about caching (I don't think that ClassGraph caches anything by default). Finding the resources path can also be cached, though I doubt that it will make much of a difference. Beyond that, there are many places where directories are enumerated to gather input files; we can avoid this to some degree by keeping lists of generated files where possible. In the Result class, all the properties can be made lazy.

Can you compare the runtime when using host classpath with cached classpath scanning? I'm interested to see if that makes any difference.

Caching anything internal of the compiler would require significant changes because we can no longer use the K2JVMCompiler interface and is of course a bit dangerous, given that we want tests to be independent and ideally parallelizable.

And for whatever reasons, commonJvmArgs is taking a long time in KAPT's stubs and apt task but not in KSP. (specifically, parseCommandlineArguments)

That's weird and definitely requires some further investigation.

[yigit]

I'm working on moving that profiling setup to my fork of KCT to reduce any overhead etc caused by the AndroidX infra. It could also make sense to use something like JMH, not sure yet.

I'll try to get some baseline numbers first. I think i was wrong on commonJvmArgs and it simply showed up high because it happened to be the first KCT run and i run very few tests (so it looked relatively looked high)

[yigit]

i started doing something very simple (and not really accurate) here:
https://github.com/yigit/kotlin-compile-testing/blob/profiling/profiling/src/test/kotlin/com/tschuchort/compiletesting/ProfilingTest.kt

just running the same thing 100 times w/ and w/o inherit classpath (and w/ or w/o host cache) AND also removing top & bottom 10% of results, it printed:

measurements:
emptyKotlinFile[KAPT-useCachedClasspath:false]
    AnalysisResult(avg=261ms, median=259ms, sampleSize=80, min=216ms, max=316ms)
emptyKotlinFile[KAPT-useCachedClasspath:true]
    AnalysisResult(avg=162ms, median=156ms, sampleSize=80, min=136ms, max=209ms)

emptyKotlinFile_withInheritedClasspath[KAPT-useCachedClasspath:false]
    AnalysisResult(avg=407ms, median=405ms, sampleSize=80, min=364ms, max=448ms)
emptyKotlinFile_withInheritedClasspath[KAPT-useCachedClasspath:true]
    AnalysisResult(avg=316ms, median=311ms, sampleSize=80, min=275ms, max=378ms)

emptyKotlinFile[KSP-useCachedClasspath:false]
    AnalysisResult(avg=175ms, median=163ms, sampleSize=80, min=140ms, max=221ms)
emptyKotlinFile[KSP-useCachedClasspath:true]
    AnalysisResult(avg=83.4ms, median=80.2ms, sampleSize=80, min=68.0ms, max=126ms)

emptyKotlinFile_withInheritedClasspath[KSP-useCachedClasspath:false]
    AnalysisResult(avg=221ms, median=216ms, sampleSize=80, min=191ms, max=263ms)
emptyKotlinFile_withInheritedClasspath[KSP-useCachedClasspath:true]
    AnalysisResult(avg=133ms, median=134ms, sampleSize=80, min=118ms, max=152ms)

my host cache thing is super simple just to try hence might be wrong / limited
yigit@4640ee7

But seems like it is helping.

Also, these absolute numbers are still significantly lower than what i'm observing in Room. I'll also try to add more test cases w/ java files, more kotlin files etc.

Last but not least, profiling this way is not really reliable so it would make sense to consider finding a proper library (damn I really miss android benchmarking library :) ) On the other hand, i'm kind of wishing that we'll spot something big (like the classpath thing, but bigger maybe) so it wouldn't matter too much to go to that depth :).

I'm mostly done for today but will try to pick this up later.

[yigit]

I was also checking what Google compile testing is doing.
It is a bit different that it uses an in memory file system but nevertheless, I ported their classpath function and that seems super fast (and they don't cache it either).

Here is the difference between two classpaths:

in system(google compile testing way), not in ClassGraph result:

/home/yboyar/src/yigit-kotlin-compile-testing/core/build/classes/java/main
/home/yboyar/src/yigit-kotlin-compile-testing/core/build/resources/main

in ClassGraph but not in system:

/home/yboyar/.gradle/wrapper/dists/gradle-6.3-bin/8tpu6egwsccjzp10c1jckl0rx/gradle-6.3/lib/gradle-core-api-6.3.jar
/home/yboyar/.gradle/wrapper/dists/gradle-6.3-bin/8tpu6egwsccjzp10c1jckl0rx/gradle-6.3/lib/gradle-worker-processes-6.3.jar
/home/yboyar/.gradle/wrapper/dists/gradle-6.3-bin/8tpu6egwsccjzp10c1jckl0rx/gradle-6.3/lib/gradle-core-6.3.jar
/home/yboyar/.gradle/wrapper/dists/gradle-6.3-bin/8tpu6egwsccjzp10c1jckl0rx/gradle-6.3/lib/gradle-logging-6.3.jar
/home/yboyar/.gradle/wrapper/dists/gradle-6.3-bin/8tpu6egwsccjzp10c1jckl0rx/gradle-6.3/lib/gradle-messaging-6.3.jar
/home/yboyar/.gradle/wrapper/dists/gradle-6.3-bin/8tpu6egwsccjzp10c1jckl0rx/gradle-6.3/lib/gradle-files-6.3.jar
/home/yboyar/.gradle/wrapper/dists/gradle-6.3-bin/8tpu6egwsccjzp10c1jckl0rx/gradle-6.3/lib/gradle-hashing-6.3.jar
/home/yboyar/.gradle/wrapper/dists/gradle-6.3-bin/8tpu6egwsccjzp10c1jckl0rx/gradle-6.3/lib/gradle-base-services-6.3.jar
/home/yboyar/.gradle/wrapper/dists/gradle-6.3-bin/8tpu6egwsccjzp10c1jckl0rx/gradle-6.3/lib/gradle-cli-6.3.jar
/home/yboyar/.gradle/wrapper/dists/gradle-6.3-bin/8tpu6egwsccjzp10c1jckl0rx/gradle-6.3/lib/gradle-native-6.3.jar
/home/yboyar/.gradle/wrapper/dists/gradle-6.3-bin/8tpu6egwsccjzp10c1jckl0rx/gradle-6.3/lib/plugins/gradle-testing-base-6.3.jar
/home/yboyar/.gradle/wrapper/dists/gradle-6.3-bin/8tpu6egwsccjzp10c1jckl0rx/gradle-6.3/lib/plugins/gradle-testing-jvm-6.3.jar
/home/yboyar/.gradle/wrapper/dists/gradle-6.3-bin/8tpu6egwsccjzp10c1jckl0rx/gradle-6.3/lib/plugins/gradle-testing-junit-platform-6.3.jar
/home/yboyar/.gradle/wrapper/dists/gradle-6.3-bin/8tpu6egwsccjzp10c1jckl0rx/gradle-6.3/lib/plugins/junit-platform-engine-1.3.1.jar
/home/yboyar/.gradle/wrapper/dists/gradle-6.3-bin/8tpu6egwsccjzp10c1jckl0rx/gradle-6.3/lib/plugins/junit-platform-launcher-1.3.1.jar
/home/yboyar/.gradle/wrapper/dists/gradle-6.3-bin/8tpu6egwsccjzp10c1jckl0rx/gradle-6.3/lib/plugins/junit-platform-commons-1.3.1.jar
/home/yboyar/.gradle/wrapper/dists/gradle-6.3-bin/8tpu6egwsccjzp10c1jckl0rx/gradle-6.3/lib/gradle-process-services-6.3.jar
/home/yboyar/.gradle/wrapper/dists/gradle-6.3-bin/8tpu6egwsccjzp10c1jckl0rx/gradle-6.3/lib/slf4j-api-1.7.28.jar
/home/yboyar/.gradle/wrapper/dists/gradle-6.3-bin/8tpu6egwsccjzp10c1jckl0rx/gradle-6.3/lib/jul-to-slf4j-1.7.28.jar
/home/yboyar/.gradle/wrapper/dists/gradle-6.3-bin/8tpu6egwsccjzp10c1jckl0rx/gradle-6.3/lib/native-platform-0.22-milestone-1.jar
/home/yboyar/.gradle/wrapper/dists/gradle-6.3-bin/8tpu6egwsccjzp10c1jckl0rx/gradle-6.3/lib/kryo-2.24.0.jar
/home/yboyar/.gradle/wrapper/dists/gradle-6.3-bin/8tpu6egwsccjzp10c1jckl0rx/gradle-6.3/lib/commons-lang-2.6.jar
/home/yboyar/.gradle/wrapper/dists/gradle-6.3-bin/8tpu6egwsccjzp10c1jckl0rx/gradle-6.3/lib/plugins/junit-4.12.jar

I'm not sure how correct it is to use classloader of KCT (might possibly miss ones coming from the app) but it gives the same speed benefits of caching:

{252ms: emptyKotlinFile_withInheritedClasspath[TestConfiguration(processorType=KAPT, enableClasspathCache=true, useGoogleCompileTestingClasspath=true)]
 AnalysisResult(avg=255ms, median=252ms, sampleSize=16, min=223ms, max=303ms)

{262ms: emptyKotlinFile_withInheritedClasspath[TestConfiguration(processorType=KAPT, enableClasspathCache=false, useGoogleCompileTestingClasspath=true)]
 AnalysisResult(avg=264ms, median=262ms, sampleSize=16, min=228ms, max=320ms)

{269ms: emptyKotlinFile_withInheritedClasspath[TestConfiguration(processorType=KAPT, enableClasspathCache=true, useGoogleCompileTestingClasspath=false)]
 AnalysisResult(avg=278ms, median=269ms, sampleSize=16, min=254ms, max=332ms)

{350ms: emptyKotlinFile_withInheritedClasspath[TestConfiguration(processorType=KAPT, enableClasspathCache=false, useGoogleCompileTestingClasspath=false)]
 AnalysisResult(avg=363ms, median=350ms, sampleSize=16, min=320ms, max=423ms)

This might also be simply because it is a 30% smaller (62 vs 41 entries)

[yigit]

oh also all tests passed when i moved to that class loader though i'm not sure how well that path is tested.

[tschuchortdev]

I'm not sure how correct it is to use classloader of KCT (might possibly miss ones coming from the app) but it gives the same speed benefits of caching

What do you mean by that? It should be the same one as far as I remember.

Besides referencing classes of the host project, the classpath scanning is also used to find jar dependencies (most notably the tools.jar). The idea is that the user can simply add a dependency for tools.jar to the host project with Gradle and it will be found automatically, so we should still be able to do that.

[yigit]

I'm not sure how correct it is to use classloader of KCT (might possibly miss ones coming from the app) but it gives the same speed benefits of caching

What do you mean by that? It should be the same one as far as I remember.

They are not equal but in my sample i'm using the classpath from the classloader of KotlinCompileTesting hence
it may not necessarily match. Classgraph seems to be grabbing all gradle jars along with it, not sure who would want that in tests but since this already works that way AND caching it has similar perf characteristics, probably not worth changing.

Also, I've tried adding caching to common classpaths we find (e.g. kotlin stdlib) but it does not really make a difference once the main classpath is cached (regardless, caching them in a helper object might be cleaner).

[yigit]

Some more interesting information from Room tests.
Apparently, the size of that classpath does have a relatively significant impact on how fast kotlin compilation runs.

I did a quick hack in room to
a) use KCT's classpath
b) use process classpath
c) use a filtered classpath that includes only room and androidx deps

Below are the results. These are not run under same circumstances so don't get attached to numbers too much but more or less, using a limited classpath shaves around 1-2 min over an 8 min test. (and once caching is in for classpath, that would mean another 50-60ms per run and we have ~ 400 compilations in this test)

a)

javac: avg: 126.87962962962963 median: 106 runCnt: 108 total: 13703
kapt: avg: 1240.4166666666667 median: 1529 runCnt: 108 total: 133965
ksp: avg: 3122.3888888888887 median: 3046 runCnt: 108 total: 337218

b)

javac: avg: 112.02777777777777 median: 100 runCnt: 108 total: 12099
kapt: avg: 1133.037037037037 median: 1472 runCnt: 108 total: 122368
ksp: avg: 3014.462962962963 median: 2936 runCnt: 108 total: 325562

c)

javac: avg: 127.21296296296296 median: 104 runCnt: 108 total: 13739
kapt: avg: 940.4074074074074 median: 1179 runCnt: 108 total: 101564
ksp: avg: 2631.6203703703704 median: 2587 runCnt: 108 total: 284215