Open DavyLandman opened 2 years ago
Some details of interest:
INFO: detected |lib://rascal-lsp| at |jar+file:///home/davy/.vscode/extensions/usethesource.rascalmpl-0.4.0/assets/jars/rascal-lsp.jar!/|
INFO: detected |lib://rascal| at |jar+file:///home/davy/.vscode/extensions/usethesource.rascalmpl-0.4.0/assets/jars/rascal.jar!/|
INFO: detected |lib://typepal| at |jar+file:///home/davy/.m2/repository/org/rascalmpl/typepal/0.7.8/typepal-0.7.8.jar!/|
INFO: detected |lib://rascal| at |jar+file:///home/davy/.m2/repository/org/rascalmpl/rascal/0.24.2/rascal-0.24.2.jar!/|
INFO: detected |lib://rascal-core| at |jar+file:///home/davy/.m2/repository/org/rascalmpl/rascal-core/0.7.8/rascal-core-0.7.8.jar!/|
INFO: detected |lib://rascal-lsp| at |jar+file:///home/davy/.m2/repository/org/rascalmpl/rascal-lsp/2.4.0/rascal-lsp-2.4.0.jar!/|
INFO: detected |lib://rascal-lsp| at |jar+file:///home/davy/.vscode/extensions/usethesource.rascalmpl-0.4.0/assets/jars/rascal-lsp.jar!/|
INFO: detected |lib://rascal| at |jar+file:///home/davy/.vscode/extensions/usethesource.rascalmpl-0.4.0/assets/jars/rascal.jar!/|
INFO: detected |lib://typepal| at |jar+file:///home/davy/.m2/repository/org/rascalmpl/typepal/0.7.8/typepal-0.7.8.jar!/|
INFO: detected |lib://rascal| at |jar+file:///home/davy/.m2/repository/org/rascalmpl/rascal/0.24.2/rascal-0.24.2.jar!/|
INFO: detected |lib://rascal-core| at |jar+file:///home/davy/.m2/repository/org/rascalmpl/rascal-core/0.7.8/rascal-core-0.7.8.jar!/|
INFO: detected |lib://rascal-lsp| at |jar+file:///home/davy/.m2/repository/org/rascalmpl/rascal-lsp/2.4.0/rascal-lsp-2.4.0.jar!/|
INFO: resolved |lib://rascal-lsp| at |jar+file:///home/davy/.m2/repository/org/rascalmpl/rascal-lsp/2.4.0/rascal-lsp-2.4.0.jar!/|
Rascal Version: 0.24.6
Rascal-lsp Version: 2.4.0
pathConfig(
javaCompilerPath=[
|file:///home/davy/.vscode/extensions/usethesource.rascalmpl-0.4.0/assets/jars/rascal-lsp.jar|,
|file:///home/davy/.vscode/extensions/usethesource.rascalmpl-0.4.0/assets/jars/rascal.jar|,
|file:///home/davy/.m2/repository/org/rascalmpl/typepal/0.7.8/typepal-0.7.8.jar|,
|file:///home/davy/.m2/repository/org/tukaani/xz/1.9/xz-1.9.jar|,
|file:///home/davy/.m2/repository/org/checkerframework/checker-qual/3.18.0/checker-qual-3.18.0.jar|,
|file:///home/davy/.m2/repository/org/rascalmpl/rascal/0.24.2/rascal-0.24.2.jar|,
|file:///home/davy/.m2/repository/org/apache/commons/commons-compress/1.21/commons-compress-1.21.jar|,
|file:///home/davy/.m2/repository/com/google/errorprone/error_prone_annotations/2.5.1/error_prone_annotations-2.5.1.jar|,
|file:///home/davy/.m2/repository/org/hamcrest/hamcrest-core/1.3/hamcrest-core-1.3.jar|,
|file:///home/davy/.m2/repository/org/junit/jupiter/junit-jupiter-api/5.6.2/junit-jupiter-api-5.6.2.jar|,
|file:///home/davy/.m2/repository/io/usethesource/capsule/0.7.0/capsule-0.7.0.jar|,
|file:///home/davy/.m2/repository/junit/junit/4.13.1/junit-4.13.1.jar|,
|file:///home/davy/.m2/repository/org/rascalmpl/rascal-core/0.7.8/rascal-core-0.7.8.jar|,
|file:///home/davy/.m2/repository/org/rascalmpl/rascal-lsp/2.4.0/rascal-lsp-2.4.0.jar|,
|file:///home/davy/.m2/repository/org/opentest4j/opentest4j/1.2.0/opentest4j-1.2.0.jar|,
|file:///home/davy/.m2/repository/io/usethesource/vallang/0.14.2/vallang-0.14.2.jar|,
|file:///home/davy/.m2/repository/com/github/ben-manes/caffeine/caffeine/2.9.2/caffeine-2.9.2.jar|,
|file:///home/davy/.m2/repository/org/apiguardian/apiguardian-api/1.1.0/apiguardian-api-1.1.0.jar|,
|file:///home/davy/.m2/repository/org/junit/platform/junit-platform-commons/1.6.2/junit-platform-commons-1.6.2.jar|,
|file:///home/davy/.m2/repository/com/github/luben/zstd-jni/1.5.0-4/zstd-jni-1.5.0-4.jar|
],
bin=|target://slow-vscode|,
classloaders=[
|lib://rascal-lsp|,
|target://slow-vscode|,
|system:///|,
|file:///home/davy/.m2/repository/org/rascalmpl/typepal/0.7.8/typepal-0.7.8.jar|,
|file:///home/davy/.m2/repository/org/tukaani/xz/1.9/xz-1.9.jar|,
|file:///home/davy/.m2/repository/org/checkerframework/checker-qual/3.18.0/checker-qual-3.18.0.jar|,
|file:///home/davy/.m2/repository/org/rascalmpl/rascal/0.24.2/rascal-0.24.2.jar|,
|file:///home/davy/.m2/repository/org/apache/commons/commons-compress/1.21/commons-compress-1.21.jar|,
|file:///home/davy/.m2/repository/com/google/errorprone/error_prone_annotations/2.5.1/error_prone_annotations-2.5.1.jar|,
|file:///home/davy/.m2/repository/org/hamcrest/hamcrest-core/1.3/hamcrest-core-1.3.jar|,
|file:///home/davy/.m2/repository/org/junit/jupiter/junit-jupiter-api/5.6.2/junit-jupiter-api-5.6.2.jar|,
|file:///home/davy/.m2/repository/io/usethesource/capsule/0.7.0/capsule-0.7.0.jar|,
|file:///home/davy/.m2/repository/junit/junit/4.13.1/junit-4.13.1.jar|,
|file:///home/davy/.m2/repository/org/rascalmpl/rascal-core/0.7.8/rascal-core-0.7.8.jar|,
|file:///home/davy/.m2/repository/org/rascalmpl/rascal-lsp/2.4.0/rascal-lsp-2.4.0.jar|,
|file:///home/davy/.m2/repository/org/opentest4j/opentest4j/1.2.0/opentest4j-1.2.0.jar|,
|file:///home/davy/.m2/repository/io/usethesource/vallang/0.14.2/vallang-0.14.2.jar|,
|file:///home/davy/.m2/repository/com/github/ben-manes/caffeine/caffeine/2.9.2/caffeine-2.9.2.jar|,
|file:///home/davy/.m2/repository/org/apiguardian/apiguardian-api/1.1.0/apiguardian-api-1.1.0.jar|,
|file:///home/davy/.m2/repository/org/junit/platform/junit-platform-commons/1.6.2/junit-platform-commons-1.6.2.jar|,
|file:///home/davy/.m2/repository/com/github/luben/zstd-jni/1.5.0-4/zstd-jni-1.5.0-4.jar|
],
libs=[|lib://rascal|],
srcs=[
|lib://rascal-lsp|,
|file:///mnt/c/Users/Davy/swat.engineering/temp/slow-vscode/src|,
|jar+file:///home/davy/.m2/repository/org/rascalmpl/typepal/0.7.8/typepal-0.7.8.jar!/src|,
|jar+file:///home/davy/.m2/repository/org/tukaani/xz/1.9/xz-1.9.jar!/src|,
|jar+file:///home/davy/.m2/repository/org/checkerframework/checker-qual/3.18.0/checker-qual-3.18.0.jar!/src|,
|jar+file:///home/davy/.m2/repository/org/rascalmpl/rascal/0.24.2/rascal-0.24.2.jar!/src/org/rascalmpl/library|,
|jar+file:///home/davy/.m2/repository/org/apache/commons/commons-compress/1.21/commons-compress-1.21.jar!/src|,
|jar+file:///home/davy/.m2/repository/com/google/errorprone/error_prone_annotations/2.5.1/error_prone_annotations-2.5.1.jar!/src|,
|jar+file:///home/davy/.m2/repository/org/hamcrest/hamcrest-core/1.3/hamcrest-core-1.3.jar!/src|,
|jar+file:///home/davy/.m2/repository/org/junit/jupiter/junit-jupiter-api/5.6.2/junit-jupiter-api-5.6.2.jar!/src|,
|jar+file:///home/davy/.m2/repository/io/usethesource/capsule/0.7.0/capsule-0.7.0.jar!/src|,
|jar+file:///home/davy/.m2/repository/junit/junit/4.13.1/junit-4.13.1.jar!/src|,
|jar+file:///home/davy/.m2/repository/org/rascalmpl/rascal-core/0.7.8/rascal-core-0.7.8.jar!/src/org/rascalmpl/core/library|,
|jar+file:///home/davy/.m2/repository/org/rascalmpl/rascal-lsp/2.4.0/rascal-lsp-2.4.0.jar!/src/main/rascal|,
|jar+file:///home/davy/.m2/repository/org/opentest4j/opentest4j/1.2.0/opentest4j-1.2.0.jar!/src|,
|jar+file:///home/davy/.m2/repository/io/usethesource/vallang/0.14.2/vallang-0.14.2.jar!/src|,
|jar+file:///home/davy/.m2/repository/com/github/ben-manes/caffeine/caffeine/2.9.2/caffeine-2.9.2.jar!/src|,
|jar+file:///home/davy/.m2/repository/org/apiguardian/apiguardian-api/1.1.0/apiguardian-api-1.1.0.jar!/src|,
|jar+file:///home/davy/.m2/repository/org/junit/platform/junit-platform-commons/1.6.2/junit-platform-commons-1.6.2.jar!/src|,
|jar+file:///home/davy/.m2/repository/com/github/luben/zstd-jni/1.5.0-4/zstd-jni-1.5.0-4.jar!/src|
],
courses=[])INFO: resolved |lib://rascal| at |jar+file:///home/davy/.m2/repository/org/rascalmpl/rascal/0.24.2/rascal-0.24.2.jar!/|
rascal>import Hello;
ok
rascal>main()
Hi world
ok
I think I have some regrets about this code:
try (BufferedReader processOutputReader = new BufferedReader(new InputStreamReader(process.getInputStream()))) {
process.waitFor();
return processOutputReader.lines()
.filter(line -> !line.startsWith(
in PathConfig.java, rascal project, line 615 in getPomXmlCompilerClasspath
Because while we are not reading from stdout, what is the guarantee that the process terminates and when?
It could be that the OS holds on to the mvn
process until its output has been processed, and in that case this try-block will only terminate after a time-out that kills the process.
printing the mvn dependency:build-classpath
output takes exactly 3 seconds on my machine, while executing the same code from within PathConfig takes 15 seconds.
I've just done some rough profiling, at least on windows, we also loose half of the time in the installNecessaryMavenPlugins
function.
also, I think we might be looking at the slow start of maven. as the reported "total time" does not include time spend in starting maven:
❯ time mvn dependency:build-classpath
[INFO] Scanning for projects...
[INFO]
[INFO] ---------------------< org.rascalmpl:slow-vscode >----------------------
[INFO] Building slow-vscode 0.0.1-SNAPSHOT
[INFO] --------------------------------[ jar ]---------------------------------
[INFO]
[INFO] --- maven-dependency-plugin:2.8:build-classpath (default-cli) @ slow-vscode ---
[INFO] Dependencies classpath:
C:\Users\Davy\.m2\repository\org\rascalmpl\rascal-lsp\2.4.0\rascal-lsp-2.4.0.jar;C:\Users\Davy\.m2\repository\org\rascalmpl\rascal\0.24.2\rascal-0.24.2.jar;C:\Users\Davy\.m2\repository\org\rascalmpl\rascal-core\0.7.8\rascal-core-0.7.8.jar;C:\Users\Davy\.m2\repository\org\junit\jupiter\junit-jupiter-api\5.6.2\junit-jupiter-api-5.6.2.jar;C:\Users\Davy\.m2\repository\org\apiguardian\apiguardian-api\1.1.0\apiguardian-api-1.1.0.jar;C:\Users\Davy\.m2\repository\org\opentest4j\opentest4j\1.2.0\opentest4j-1.2.0.jar;C:\Users\Davy\.m2\repository\org\junit\platform\junit-platform-commons\1.6.2\junit-platform-commons-1.6.2.jar;C:\Users\Davy\.m2\repository\io\usethesource\vallang\0.14.2\vallang-0.14.2.jar;C:\Users\Davy\.m2\repository\io\usethesource\capsule\0.7.0\capsule-0.7.0.jar;C:\Users\Davy\.m2\repository\org\apache\commons\commons-compress\1.21\commons-compress-1.21.jar;C:\Users\Davy\.m2\repository\org\tukaani\xz\1.9\xz-1.9.jar;C:\Users\Davy\.m2\repository\com\github\luben\zstd-jni\1.5.0-4\zstd-jni-1.5.0-4.jar;C:\Users\Davy\.m2\repository\com\github\ben-manes\caffeine\caffeine\2.9.2\caffeine-2.9.2.jar;C:\Users\Davy\.m2\repository\com\google\errorprone\error_prone_annotations\2.5.1\error_prone_annotations-2.5.1.jar;C:\Users\Davy\.m2\repository\org\checkerframework\checker-qual\3.18.0\checker-qual-3.18.0.jar;C:\Users\Davy\.m2\repository\org\rascalmpl\typepal\0.7.8\typepal-0.7.8.jar;C:\Users\Davy\.m2\repository\junit\junit\4.13.1\junit-4.13.1.jar;C:\Users\Davy\.m2\repository\org\hamcrest\hamcrest-core\1.3\hamcrest-core-1.3.jar
[INFO] ------------------------------------------------------------------------
[INFO] BUILD SUCCESS
[INFO] ------------------------------------------------------------------------
[INFO] Total time: 2.044 s
[INFO] Finished at: 2022-10-03T15:50:21+02:00
[INFO] ------------------------------------------------------------------------
mvn dependency:build-classpath 0.12s user 0.37s system 9% cpu 5.168 total
so, 2s reported, but 5s actual.
Similarly for the dependency get install of the plugin:
❯ time mvn dependency:get -DgroupId=org.apache.maven.plugins -DartifactId=maven-dependency-plugin -Dversion=2.8
[INFO] Scanning for projects...
[INFO]
[INFO] ---------------------< org.rascalmpl:slow-vscode >----------------------
[INFO] Building slow-vscode 0.0.1-SNAPSHOT
[INFO] --------------------------------[ jar ]---------------------------------
[INFO]
[INFO] --- maven-dependency-plugin:2.8:get (default-cli) @ slow-vscode ---
[INFO] Resolving org.apache.maven.plugins:maven-dependency-plugin:jar:2.8 with transitive dependencies
[INFO] ------------------------------------------------------------------------
[INFO] BUILD SUCCESS
[INFO] ------------------------------------------------------------------------
[INFO] Total time: 3.208 s
[INFO] Finished at: 2022-10-03T15:53:42+02:00
[INFO] ------------------------------------------------------------------------
mvn dependency:get -DgroupId=org.apache.maven.plugins -Dversion=2.8 0.18s user 0.26s system 6% cpu 6.391 total
that takes 6.3s to complete.
so on my machine, that's 11s for a single run of those two commands, and we are running them quite often. (before the REPL starts we also run it, since vscode asks for a project config)
installNecessaryMavenPlugins
is interesting since that is not an "offline" one. Perhaps checking if they are installed first, would be faster..
I've interesting results here:
This is running mvn dependency:get -DgroupId=org.apache.maven.plugins -DartifactId=maven-dependency-plugin -Dversion=2.8
which is what installNecessaryMavenPlugins
does (and nothing else).
real 0m1.978s
user 0m6.716s
sys 0m0.377s
So you see the prompt returns within 2 seconds, but CPU time spent is almost 7 seconds. This is probably due to using multiple cores.
If I run this with or without --offline
the results remain the same, given that I've already installed the maven-dependency-plugin version 2.8 in my .m2
repository and all of its required dependencies. Of course if I remove those plugins then it is slower, but that is not the common use case that we are optimizing.
Aren't we just looking at the infamous cold starts of JVM processes? So starting maven takes time?
I've snipped away one of the maven calls here: https://github.com/usethesource/rascal/pull/1661
Also on my machine, counting with my hands, it takes longer than 2s.
I've put a timer next to it.
In the bottom you see a timer running, it takes roughly 7 seconds to finish. (This effect might be more pronounced on windows)
Solution directions:
-Drascal.local.repository
? Not a happy camper...Alternatives wanted!
Could we try and encapsulate the maven-dependency-plugin specifically? So that we do not need all of maven to work, but just that plugin?
I've tried that for the JUnit plugin. I can load all the objects but I can not populate all the injected data. The core platform is what reads the pom and then populates the data model that is injected to the parameters of all the plugins. It's well designed but its also a tight knot.
@DavyLandman mentioned maven-embedder and way back when in 2018 this was not an option. But maybe now it is. It could also make other integrations with maven easy when we need them (for example for a component listing and installation UX in the repl).
I've been stumbling through one issue after the other, but I think we're bitten by the dependency injection of maven.
https://stackoverflow.com/questions/43264732/maven-embedded-3-3-9-is-it-possible
Here a discussion is roughly saying: this won't work with shaded jars and other kinds of bundled jars. And that is what we are doing with rascal.
okay, that pull request (https://github.com/usethesource/rascal/pull/1661 ) contains the work to call maven inside of rascal, without starting a new jvm. on windows it reduces the call to build the path from 14s to less than 2s.
@jurgenvinju: can you get it to work together with our maven shading, as it currently fails when it's inside of a big jar.
I'll try :-) but not very soon. There's a backlog.
Describe the bug
The REPL takes 40s+ to show up in the terminal view, and then another 40s+ to be available for the user.
To Reproduce
Here is a project config:
slow-vscode.zip
src/Hello.rsc
It takes 40s before any UI action is happening, so a user is confused that nothing is happening.
Then the terminal starts up and takes a long while before it's ready for use.
Expected behavior
Fast opening of the terminal, fast loading of the repl.
Stack traces
No errors in developer tools or rascal output window.
REPL window:
Desktop (please complete the following information):