Optimize speed
Closed this issue · 41 comments
The Scala test runner is functional right now, but it is quite slow. In fact, it is so slow that the test runner times out before being able to return the results. We should speedup the test runner to not have it timeout.
Some possibly useful references:
(cc @exercism/scala)
If you run sbt package it will package everything in a jar, which will be put under target/scala-2.12, that should avoid the steps of compiling and sbt warming up if used as executable
@MeerKatDev Would you be able to PR that? Erik is off for the next 10 days and it would be nice to get Scala in the beta with a working test runner! :)
@MeerKatDev It should be a question of using sbt package instead of sbt compile (I assume) in the Dockerfile (see https://github.com/exercism/scala-test-runner/blob/main/Dockerfile#L8), and then probably changing how the application is run in the bin/run.sh file (see https://github.com/exercism/scala-test-runner/blob/main/bin/run.sh#L57).
If you have Docker installed, you can verify that everything still works by running ./bin/run-tests-in-docker.sh. If there are no error messages, all is good (CI will verify this too).
Even with #14 merged, the testing still times out :(
@ErikSchierboom I left a comment in the PR about it
Commented
I don't understand, run-tests takes few seconds in the first cases. What's running so slow?
That's what we're trying to find out :)
I mean, which command do you run? What exact operation? Until I cannot see on my local what's taking so long I cannot help :)
There is of course a difference between running tests locally and on a remote machine that probably has less resources. Also, run-tests is running things locally, not in the Docker container so that is a huge difference. Do you have Docker installed?
I have, and docker is taking quite some time, but that's due to the building process, only that takes 50+ seconds
That should only be the first time. If you want to time a individual test run, you can run: ./bin/run-in-docker.sh example-partial-fail "$PWD/tests/example-partial-fail" "$PWD/tests/example-partial-fail"
but docker is running sbt assembly, why?
EDIT: Also, I get this:
example-partial-fail: testing...
Error: Unable to access jarfile target/scala-2.12/testRunner-assembly-0.1.0-SNAPSHOT.jar
example-partial-fail: done
and I assemblied it just before
but docker is running sbt assembly, why?
Yeah, it runs sbt assembly once when creating the Docker image. Afterwards, each time a Docker container is created from the image, that image already contains the compiled test runner.
EDIT: Also, I get this:
That means there must be local changes to the bin/run.sh file, as the casing of testRunner should be TestRunner, which is in the latest commit: https://github.com/exercism/scala-test-runner/blob/main/bin/run.sh#L57
I modified it because I had already the jar compiled, so I changed the casing for it to be found. I think there is some issue with the searched directory, at least on my local.
Also, I changed the Scala version because of this:
[error]
[error] java.io.IOError: java.lang.RuntimeException: /packages cannot be represented as URI
[error] at java.base/jdk.internal.jrtfs.JrtPath.toUri(JrtPath.java:176)
[error] at scala.tools.nsc.classpath.JrtClassPath.asURLs(DirectoryClassPath.scala:213)
[error] at scala.tools.nsc.classpath.AggregateClassPath.$anonfun$asURLs$1(AggregateClassPath.scala:64)
[error] at scala.collection.TraversableLike.$anonfun$flatMap$1(TraversableLike.scala:244)
[error] at scala.collection.Iterator.foreach(Iterator.scala:941)
[error] at scala.collection.Iterator.foreach$(Iterator.scala:941)
[error] at scala.collection.AbstractIterator.foreach(Iterator.scala:1429)
...
which apparently is a version-related issue, so I'm using scala-2.13 in local.
More in general, I think the execution velocity is dependent on one of these factors:
- it times out at some point, that means there is some file not found or some part that couldn't be executed
- the
sbtbuilding phase for the uploaded code, the one that has to be put under test. For one, it can help using the last Scala version, as there are improvements to the compiler in every version
The jar takes max 2 seconds on my local to execute, it cannot take much more on any other machine. So I think the culprit is either one of the above or a mix of the two.
Just for the sake of clarity: The issue at hand here is the time here, after running the command you gave me above, that:
when I run it:
=> exporting to image 0.0s
=> => exporting layers 0.0s
=> => writing image sha256:222687946d7b692f02d8f57f1af98e6d76611178b672aebce88ff482b7e9a330 0.0s
=> => naming to docker.io/exercism/test-runner 0.0s
Use 'docker scan' to run Snyk tests against images to find vulnerabilities and learn how to fix them
example-partial-fail: testing...
example-partial-fail: done
the time it takes between testing... and done is excessive. Is that correct?
That is correct. I'm fairly sure that the line that is being slow is running sbt test on the student's solution, now that we use the precompiled jar.
can you see the runtime of the tests in the logs? In the part where it says this:
[info] Run completed in 287 milliseconds.
[info] Total number of tests run: 7
[info] Suites: completed 1, aborted 0
above, per each test we can see the time it takes to run adding this to the build.sbt file:
testOptions in Test += Tests.Argument(scalaTest, "-oD")
@MeerKatDev I would have to add that to the exercise's build.sbt file, which are in the scala repo. I could temporarily add the line though as a test from within the test runner. That said, I don't think it is actually the running of the tests that is slow, but the compiling of the test suite. But I don't have hard data. Maybe we should add more logging, so see the timing of all individual steps including the compilation?
I could temporarily add the line though as a test from within the test runner.
that was what I was aiming at, yes. Add logging and timing wherever you can and run it in the production environment, to see what's taking so long.
Do you know how to output more verbose logging with compile steps etc?
About general information, as they wrote here, this is the maximum we can achieve. For timing, that has to be done manually from the scala code itself, or with the arguments I wrote above for the tests
I've run the partial fail test with an additional .jvmopts file that contains the following line: -Dsbt.task.timings=true. This produces the following output:
example-partial-fail: testing...
[info] welcome to sbt 1.4.5 (Oracle Corporation Java 1.8.0_232)
[info] loading project definition from /solution/project
[info] Total time: 2771 ms
[info] solution-build / update : 1272 ms
[info] solution-build / Compile / compileIncremental : 899 ms
[info] solution-build / dependencyPositions : 179 ms
[info] solution-build / Compile / scalacOptions : 87 ms
[info] solution-build / csrProject : 84 ms
[info] solution-build / Compile / previousCompile : 56 ms
[info] solution-build / Runtime / unmanagedClasspath : 51 ms
[info] solution-build / Compile / unmanagedResources / allInputPathsAndAttributes: 48 ms
[info] solution-build / Compile / compile / compilerReporter : 48 ms
[info] solution-build / scalaCompilerBridgeScope / csrConfiguration : 47 ms
[info] solution-build / csrConfiguration : 46 ms
[info] solution-build / projectDescriptors : 43 ms
[info] solution-build / csrFallbackDependencies : 28 ms
[info] solution-build / scalaInstance : 28 ms
[info] solution-build / Compile / unmanagedJars : 28 ms
[info] streams-manager : 27 ms
[info] solution-build / ivyModule : 27 ms
[info] solution-build / csrInterProjectDependencies : 27 ms
[info] solution-build / Runtime / exportedProducts : 26 ms
[info] solution-build / Compile / unmanagedSources / allInputPathsAndAttributes : 25 ms
[info] solution-build / Compile / exportedProducts : 22 ms
[info] solution-build / Compile / copyResources : 21 ms
[info] solution-build / csrRecursiveResolvers : 18 ms
[info] ThisBuild / reusableStamper : 18 ms
[info] solution-build / Compile / discoveredSbtPlugins : 17 ms
[info] solution-build / Compile / managedClasspath : 17 ms
[info] solution-build / Runtime / unmanagedJars : 16 ms
[info] solution-build / Compile / unmanagedClasspath : 16 ms
[info] solution-build / csrResolvers : 15 ms
[info] solution-build / Runtime / managedClasspath : 14 ms
[info] solution-build / moduleSettings : 12 ms
[info] solution-build / Compile / incOptions : 10 ms
[info] solution-build / Compile / compileIncSetup : 9 ms
[info] solution-build / Compile / earlyOutputPing : 9 ms
[info] solution-build / projectResolver : 8 ms
[info] solution-build / Compile / compile / compileOptions : 8 ms
[info] solution-build / ivySbt : 8 ms
[info] solution-build / projectDependencies : 7 ms
[info] solution-build / Compile / compile / bspReporter : 7 ms
[info] Global / incOptions : 7 ms
[info] solution-build / Compile / externalHooks : 7 ms
[info] solution-build / Compile / unmanagedResources / inputFileStamps : 7 ms
[info] solution-build / ivyConfiguration : 6 ms
[info] solution-build / dependencyResolution : 6 ms
[info] Global / csrLogger : 6 ms
[info] solution-build / Compile / dependencyVirtualClasspath : 5 ms
[info] solution-build / scalaCompilerBridgeScope / dependencyResolution : 5 ms
[info] solution-build / allCredentials : 4 ms
[info] solution-build / Compile / internalDependencyClasspath : 4 ms
[info] solution-build / Runtime / internalDependencyClasspath : 3 ms
[info] solution-build / otherResolvers : 3 ms
[info] solution-build / csrExtraProjects : 3 ms
[info] Global / compilers : 3 ms
[info] solution-build / Compile / dependencyClasspath : 3 ms
[info] solution-build / allDependencies : 3 ms
[info] state : 2 ms
[info] solution-build / transitiveUpdate : 2 ms
[info] solution-build / Compile / managedSources : 2 ms
[info] ThisBuild / sourcePositionMappers : 2 ms
[info] executionRoots : 1 ms
[info] solution-build / scalaCompilerBridgeScope / csrResolvers : 1 ms
[info] solution-build / Compile / externalDependencyClasspath : 1 ms
[info] solution-build / Compile / compile : 1 ms
[info] solution-build / Compile / compileOutputs : 1 ms
[info] solution-build / Runtime / externalDependencyClasspath : 1 ms
[info] solution-build / Compile / classpathConfiguration : 1 ms
[info] solution-build / Compile / managedResources : 1 ms
[info] solution-build / Compile / discoveredMainClasses : 1 ms
[info] solution-build / bootResolvers : 1 ms
[info] solution-build / Compile / classpathEntryDefinesClassVF : 1 ms
[info] solution-build / Runtime / fullClasspath : 1 ms
[info] solution-build / Compile / unmanagedSources : 1 ms
[info] loading settings for project solution from build.sbt ...
[info] set current project to solution (in build file:/solution/)
[info] Defining offline
[info] The new value will be used by updateConfiguration
[info] Reapplying settings...
[info] set current project to solution (in build file:/solution/)
[info] compiling 1 Scala source to /solution/target/scala-2.12/classes ...
[info] done compiling
[info] compiling 1 Scala source to /solution/target/scala-2.12/test-classes ...
[info] done compiling
[info] ExamplePartialFailTest:
[info] - year not divisible by 4: common year
[info] - year divisible by 4, not divisible by 100: leap year
[info] - year divisible by 100, not divisible by 400: common year
[info] - year divisible by 400: leap year *** FAILED ***
[info] false was not true (ExamplePartialFailTest.scala:22)
[info] Run completed in 778 milliseconds.
[info] Total number of tests run: 4
[info] Suites: completed 1, aborted 0
[info] Tests: succeeded 3, failed 1, canceled 0, ignored 0, pending 0
[info] *** 1 TEST FAILED ***
[error] Failed tests:
[error] ExamplePartialFailTest
[info] Total time: 14261 ms
[info] solution / Compile / compileIncremental : 6943 ms
[info] solution / Test / compileIncremental : 3900 ms
[info] solution / update : 792 ms
[info] solution / Compile / compile : 689 ms
[info] ExamplePartialFailTest : 583 ms
[info] solution / Test / executeTests : 528 ms
[info] solution / dependencyPositions : 290 ms
[info] solution / Test / loadedTestFrameworks : 282 ms
[info] solution / Test / unmanagedSources / allInputPathsAndAttributes : 71 ms
[info] solution / Test / copyResources : 70 ms
[info] solution / Test / test / testListeners : 69 ms
[info] solution / Compile / copyResources : 60 ms
[info] solution / Compile / unmanagedJars : 52 ms
[info] solution / Test / unmanagedJars : 52 ms
[info] solution / Test / definedTests : 47 ms
[info] solution / scalaCompilerBridgeScope / csrConfiguration : 45 ms
[info] solution / Test / dependencyClasspathFiles / outputFileStamps : 42 ms
[info] solution / Test / managedClasspath : 42 ms
[info] solution / testListeners : 35 ms
[info] solution / Test / unmanagedResources / allInputPathsAndAttributes : 34 ms
[info] solution / Compile / dependencyClasspath : 20 ms
[info] solution / Test / test : 19 ms
[info] solution / Test / testLoader : 18 ms
[info] solution / Runtime / unmanagedJars : 18 ms
[info] solution / csrConfiguration : 18 ms
[info] solution / Test / compile : 16 ms
[info] solution / Test / forkOptions : 11 ms
[info] streams-manager : 9 ms
[info] solution / Test / internalDependencyClasspath : 8 ms
[info] solution / scalaInstance : 7 ms
[info] solution / csrProject : 4 ms
[info] solution / Compile / scalacOptions : 3 ms
[info] solution / Test / unmanagedClasspath : 3 ms
[info] solution / Test / scalacOptions : 3 ms
[info] solution / ivySbt : 3 ms
[info] solution / Compile / unmanagedSources / allInputPathsAndAttributes : 3 ms
[info] solution / Test / exportedProducts : 2 ms
[info] solution / Test / dependencyClasspath : 2 ms
[info] solution / Test / unmanagedResources / inputFileStamps : 2 ms
[info] solution / Compile / exportedProducts : 2 ms
[info] solution / Test / unmanagedSources / inputFileStamps : 2 ms
[info] solution / Runtime / exportedProducts : 2 ms
[info] solution / ivyConfiguration : 2 ms
[info] solution / projectDescriptors : 1 ms
[info] solution / Compile / managedClasspath : 1 ms
[info] solution / Test / test / testOptions : 1 ms
[info] solution / Compile / internalDependencyClasspath : 1 ms
[info] solution / Test / externalDependencyClasspath : 1 ms
[info] solution / Compile / compile / compilerReporter : 1 ms
[info] solution / Compile / unmanagedClasspath : 1 ms
[info] solution / Test / compileSplit : 1 ms
[info] solution / csrRecursiveResolvers : 1 ms
[info] solution / Test / compile / compilerReporter : 1 ms
[info] solution / Test / incOptions : 1 ms
[info] solution / Compile / unmanagedResources / allInputPathsAndAttributes: 1 ms
[info] Global / csrLogger : 1 ms
[info] state : 1 ms
[info] solution / dependencyResolution : 1 ms
[info] solution / csrInterProjectDependencies : 1 ms
[error] (Test / test) sbt.TestsFailedException: Tests unsuccessful
[error] Total time: 14 s, completed Apr 28, 2021 4:29:43 PM
example-partial-fail: done
real 0m35.404s
user 0m0.332s
sys 0m0.403s
If I'm reading this correctly, just compiling the source and the tests ends up taking 10 seconds!
[info] solution / Compile / compileIncremental : 6943 ms
[info] solution / Test / compileIncremental : 3900 ms
The actual running of the tests is fast enough:
[info] solution / Test / executeTests : 528 ms
I see. Good effort! Have you tried to tune jvm parameters to give, for example, the maximum amount of memory the machine can offer? here a good example. I'd say maybe look in the Java test runner for this, but maybe they don't use sbt.
What can also speed up, it's first entering in the sbt console, and then running all the commands from there inside, i.e. instead of running sbt sth, sbt sth2, sbt sth3, write sbt, sth, sth2, sth3
Have you tried to tune jvm parameters to give, for example, the maximum amount of memory the machine can offer? here a good example.
I haven't tried that, as I know nothing about the JVM. But I'll look at the example.
I'd say maybe look in the Java test runner for this, but maybe they don't use sbt.
sbt is Scala-specific unfortunately
What can also speed up, it's first entering in the sbt console, and then running all the commands from there inside, i.e. instead of running sbt sth, sbt sth2, sbt sth3, write sbt, sth, sth2, sth3
Yeah I read about that, but I don't think it's possible for us to do that as we only have a single sbt command that is being executed.
@MeerKatDev I've tried the settings suggested in the example, but to no avail. The compile times are virtually identical. We'll have to try something else.
the trouble is that in some systems the jvm doesn't respond to those parameters for some reason. Also, the settings in that example might be too high, so it won't take them. Try with 512M, 1G, and so on. It also depends on the JVM used.
sbt is Scala-specific unfortunately
Sbt can be used to run Java too :)
I found this article, if you're in the mood for some profiling
Sbt can be used to run Java too :)
Really? I've never seen that being used, but that's fascinating!
I'll look at the other article.
The profiling is too much for me. I also don't really want to dive into the JVM tweaking, so I'd rather someone experienced in tuning Scala/SBT/JVM looks into that. It will take too much time for me.
Indeed. While someone like that will appear, I could try and look into it in the next days, which machine are you running this in? Can you give me some specs like OS, memory, cpu, and so on?
Good question. I'll defer to @iHiD for the exact specs. One thing to consider is that by default, the Docker container runs with 3GB of memory (which you can simulate by passing -m 3GB to the docker run command).
Erm, the specs will vary, so I wouldn't want to commit to anything. I think Erik's benchmarks are all him just running locally. In production it's a pretty heavy machine - it should be as good as any laptop/PC we have in production, but as Erik says it's resource limited to 3GB currently.
@ErikSchierboom can you test something?
- Comment out this line https://github.com/exercism/scala-test-runner/blob/main/bin/run.sh#L57
- Replace
testwithversionin this line: https://github.com/exercism/scala-test-runner/blob/main/bin/run.sh#L47
What could be happening here is that the price you are paying to load sbt is too high. So the idea would be to check what happens if we basically run the test runner and do nothing other than starting sbt. Would it still be too slow and time out?
I experimented a bit locally and that seems to be the case. Wdyt?
@jcranky I've retested things a bit, and it looks like the test runner is actually a bit faster now. No idea why. I'm tempted to at least temporarily enable the test runner and see how it fares on our production infrastructure.
That said, it is still quite slow. Here are the timings:
Running sbt version
real 0m3.335s
user 0m15.682s
sys 0m1.262sRunning sbt test
real 0m6.692s
user 0m29.615s
sys 0m2.230sRunning the jar
real 0m0.245s
user 0m0.259s
sys 0m0.157sWe can see that sbt is taking about 3 seconds to run just sbt version, which to me sounds incredibly slow. Any thoughts on how to improve this?
running commands like sbt command loads every time sbt and then executes the command. Those 3 seconds are actually sbt loading. All commands, for speed, should be ran like
% sbt
....
sbt> version
<version>
Also, there is this: https://github.com/scalacenter/bloop but I never used it. It could be tested in place of sbt.
@MeerKatDev That works great locally, but I don't see how that would work in Docker. We're already running sbt assembly when building the Docker image (see https://github.com/exercism/scala-test-runner/blob/main/Dockerfile#L8), so I would have expected sbt to have done its initial loading at that point, which would mean it should be faster afterwards, right?
so I would have expected sbt to have done its initial loading at that point, which would mean it should be faster afterwards
Unfortunately I don't think sbt does that. That was the point I was trying to make: you are paying the sbt loading time price, all the time, and that is painful - quite a waste, actually 😄. sbt was not meant to be used like that.
The real fix here is probably to completely take sbt out of the picture. I have some ideas and will try to find some time to experiment a bit 😸
Ah okay, I didn't know! Looking forward to any different options to use.
@ErikSchierboom a question: the tests for the exercises are generated with the build.sbt file included in them? Where is that file generated? I was looking at https://github.com/exercism/scala and couldn't find it.
They're part of each exercise: https://github.com/exercism/scala/tree/main/exercises/practice/allergies