Open yigit opened 3 years ago
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.
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 https://github.com/tschuchortdev/kotlin-compile-testing/issues/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.
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.
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)
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 https://github.com/yigit/kotlin-compile-testing/commit/4640ee79db15edf34ab3378e6f0dc29d064271e0
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.
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)
oh also all tests passed when i moved to that class loader though i'm not sure how well that path is tested.
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.
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).
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
so adding some more code in room to prevent KCT from resolving all classpath also has some minor improvements:
javac: avg: 128.78703703703704 median: 107 runCnt: 108 total: 13909
kapt: avg: 813.0925925925926 median: 1055 runCnt: 108 total: 87814
ksp: avg: 2440.435185185185 median: 2432 runCnt: 108 total: 263567
btw here is a profile in KCT after the caching changes. profile.svg.tar.gz
Pretty much all time is spent in kotlin compilation so i don't think we will be able to do much here unless we figure out how to run kotlin compiler more efficiently. Maybe there are ways to reuse project model etc.
Btw, KSP tests, which run similar, run a lot faster. Though they possibly just analyze without really compiling so it might be apples to oranges.
some more info:
Looks like this is what gradle does for build.kts files: https://github.com/gradle/gradle/blob/5532c5883dc21a34a809802d967c69ee3ea7d112/subprojects/kotlin-dsl/src/main/kotlin/org/gradle/kotlin/dsl/support/KotlinCompiler.kt#L379-L388
It does require some more lifecycle management but seems to help in Room when I set that env property via gradle task. A noticeable difference is that Gradle is not going through the CLI compiler path hence implementing it in KCT might require more core changes. Once I get some time, I'll try to run my profiler w/ that flag in KCT, see if it helps and if so, try to figure out how we can even use it. Also, if we end up using core environment APIs directly, we might as well use create for test method like KSP.
hmm a simple test to enable it didn't help.
report for manySources
TestConfiguration(processorType=KAPT, useCachedCompilerEnv=true) (806ms) : AnalysisResult(avg=806ms, median=800ms, sampleSize=24, min=751ms, max=1.00s)
TestConfiguration(processorType=KAPT, useCachedCompilerEnv=false) (822ms) : AnalysisResult(avg=822ms, median=812ms, sampleSize=24, min=752ms, max=952ms)
report for emptyKotlinFile
TestConfiguration(processorType=KAPT, useCachedCompilerEnv=true) (44.8ms) : AnalysisResult(avg=44.8ms, median=43.1ms, sampleSize=24, min=39.6ms, max=64.7ms)
TestConfiguration(processorType=KAPT, useCachedCompilerEnv=false) (48.4ms) : AnalysisResult(avg=48.4ms, median=44.4ms, sampleSize=24, min=38.6ms, max=71.1ms)
report for emptyKotlinFile_withInheritedClasspath
TestConfiguration(processorType=KAPT, useCachedCompilerEnv=true) (118ms) : AnalysisResult(avg=118ms, median=116ms, sampleSize=24, min=101ms, max=146ms)
TestConfiguration(processorType=KAPT, useCachedCompilerEnv=false) (124ms) : AnalysisResult(avg=124ms, median=122ms, sampleSize=24, min=104ms, max=160ms)
report for manySources_inheritClasspath
TestConfiguration(processorType=KAPT, useCachedCompilerEnv=true) (1.13s) : AnalysisResult(avg=1.13s, median=1.12s, sampleSize=24, min=1.04s, max=1.29s)
TestConfiguration(processorType=KAPT, useCachedCompilerEnv=false) (1.13s) : AnalysisResult(avg=1.13s, median=1.12s, sampleSize=24, min=1.03s, max=1.42s)
Are you sure that this env variable has any effect when we are using the embedded compiler like this? Maybe we should ask someone on the compiler team if they have any ideas how to get some cheap speed-ups.
actually i might've found something. I was trying to replicate K2JvmCompiler to see if creating it for tests will have an impact (no it didn't).
Then I started adding more logs inside KCT and discovered that java compilation actually takes longer than kotlin compilation. It is no surprise this affects room more as most of our tests are with java sources.
Appearantly, we do create a process for java compilation which might be why it is slower.
Any particular reason for that? I'll try to switch it to use an in process java compiler and measure the overall effect.
This is what i'm thinking of using: https://cs.android.com/androidx/platform/frameworks/support/+/androidx-main:room/compiler/src/test/kotlin/androidx/room/testing/test_util.kt;l=330?q=test_util.kt
btw here is that logging code: https://github.com/yigit/kotlin-compile-testing/commit/eb58fd729f9995e396cc97c9be4ff22ae24d36e7
hmm actually we do use a process only if java home is set but since it has a default, it would (almost?) always be set unless we fail to find jdk home from current classpath. https://github.com/tschuchortdev/kotlin-compile-testing/blob/master/core/src/main/kotlin/com/tschuchort/compiletesting/Utils.kt#L14
here are some measurements w/ an additional flag to use the in process java compiler:
report for manySources
TestConfiguration(processorType=KAPT, useInProcessJavac=true) (259ms) : AnalysisResult(avg=259ms, median=265ms, sampleSize=24, min=213ms, max=287ms)
TestConfiguration(processorType=KAPT, useInProcessJavac=false) (935ms) : AnalysisResult(avg=935ms, median=945ms, sampleSize=24, min=848ms, max=1.01s)
report for emptyKotlinFile
TestConfiguration(processorType=KAPT, useInProcessJavac=false) (149ms) : AnalysisResult(avg=149ms, median=141ms, sampleSize=24, min=131ms, max=176ms)
TestConfiguration(processorType=KAPT, useInProcessJavac=true) (154ms) : AnalysisResult(avg=154ms, median=153ms, sampleSize=24, min=130ms, max=195ms)
report for emptyKotlinFile_withInheritedClasspath
TestConfiguration(processorType=KAPT, useInProcessJavac=false) (302ms) : AnalysisResult(avg=302ms, median=302ms, sampleSize=24, min=266ms, max=345ms)
TestConfiguration(processorType=KAPT, useInProcessJavac=true) (304ms) : AnalysisResult(avg=304ms, median=301ms, sampleSize=24, min=261ms, max=395ms)
report for manySources_inheritClasspath
TestConfiguration(processorType=KAPT, useInProcessJavac=true) (462ms) : AnalysisResult(avg=462ms, median=454ms, sampleSize=24, min=404ms, max=539ms)
TestConfiguration(processorType=KAPT, useInProcessJavac=false) (1.31s) : AnalysisResult(avg=1.31s, median=1.29s, sampleSize=24, min=1.22s, max=1.47s)
So when java files are involved, this has a huge impact.
Here is a recommendation:
KotlinCompilation#compileJava
be based on whether jdkHome was set by the user or not. (instead of checking it is null)Alternatively, we could just introduce another parameter for in process compilation.
@tschuchortdev any preferences?
ok it fails with Fatal Error: Unable to find package java.lang in classpath or bootclasspath
because we set --system none
.
In the original CL, there is a test that exercise this path:
https://github.com/tschuchortdev/kotlin-compile-testing/commit/3d2b49c2abe8292f0e815a15d37c72e8dd4885e3#diff-7fb94e186b90e892149ed14df8015ef1b938f18dfb81947c498f50351c74eaf5R119
So it seems very intentional though idk if anyone relies on this behavior. Compiling java w/o boothclasspath seems weird, was there a particular use case for that?
That test also intentionally sets jdkHome to null so maybe it makes sense and the right solution is to literally check jdkHome == my_process_jdk_home
run via in process javac and also don't erase boothclasspath unless jdkHome is set to null.
So it seems very intentional though idk if anyone relies on this behavior. Compiling java w/o boothclasspath seems weird, was there a particular use case for that?
I don't remember exactly why I did it that way (probably should've documented it better) but I think it was mostly to be consistent with the behaviour of kotlinc when jdkHome
is set to null
.
It says in the doc comment of jdkHome
:
* If null, no JDK will be used with kotlinc (option -no-jdk)
* and the system java compiler will be used with empty bootclasspath
* (on JDK8) or --system none (on JDK9+). This can be useful if all
* the JDK classes you need are already on the (inherited) classpath.
My guess is that nobody uses this feature but since there was a -no-jdk
option for kotlinc I wanted to include it.
hmm actually we do use a process only if java home is set but since it has a default, it would (almost?) always be set unless we fail to find jdk home from current classpath.
Starting javac in another process when jdkHome
is set was necessary to enable people to write tests for a different JDK than is used for running the host process. Perhaps it's possible to do that in-process by using a custom classloader that is completely disjoint but it's probably not straight forward. The interaction with jdkHome
default parameter here is unfortunate and I think your PR #116 is a good compromise/solution.
BTW does Room have any tests that have only Java sources and no reliance on the Kotlin compiler? If I'm not mistaken, the K2JVMCompiler
will always be executed right now, since my assumption was that people who have only Java sources would use the original Google compile testing library. If you have many tests that don't need Kotlin, this could be another area where we can save a lot of time.
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)
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.