search

scalameta / metals

Scala language server with rich IDE features 🚀
https://scalameta.org/metals/
Apache License 2.0
2.08k stars 327 forks source link

'Run with debugging' takes a lot of time to start the debug session #6544

Closed roshith-i closed 2 months ago

roshith-i commented 3 months ago

Bug Description:

Whenever I start a debug session (Run with debugging), it is taking more than a minute to start the server and to execute the code. As you can see in the screenshot attached below, the time to load all the sources and classes is around a 1 minute. Though I am working on a large project, I do not understand why it is taking exactly 1 minute every single time to load the classes. I remember this behavior didn't exist before version Metals v1.30.0, back then the debug session used to start up pretty quickly (around 10-15 seconds if I'm not wrong). And I am not quite sure if there's something wrong on my Mac that's causing this issue.

Screenshot 2024-06-27 at 10 32 35

I am not quite sure on the replication steps because I doubt if the issue happens only for me.

Expected behaviour:

The debug session could start within few seconds and not 1 minute every single time.

Operating system: Mac OS X

Java version: 17

Editor/extension: Visual Studio Code v1.90.1

Metals version: 1.3.2+13-0206537d-SNAPSHOT

Workspace information:

tgodzik commented 3 months ago

Thanks for reporting! Are you maybe able to provide a reproduction or is it an issue only a bigger internal projecT?

@adpi2 would anything in https://github.com/scalacenter/scala-debug-adapter/releases/tag/v4.0.0 cause it?

tgodzik commented 3 months ago

Och and does it work better if you run without debugging?

roshith-i commented 3 months ago

Yes, Run without debugging starts almost instantly without any delay. And regarding the reproduction, I don't know any other way to reproduce this. I tried to run the same project on my Windows laptop as well and it happens the same way as this.

roshith-i commented 3 months ago

Update: I tried to debug another sample scala project and it's taking the same time as well, around 1 min.

tgodzik commented 3 months ago

Update: I tried to debug another sample scala project and it's taking the same time as well, around 1 min.

Och cool! Which example is that?

roshith-i commented 3 months ago

Just a simple 'hello world' kind of scala project with Scala version 2.12.18 and Java 17.

tgodzik commented 3 months ago

That's unexpected, I need to check windows then. Do you have any antivirus or anything that could cause it?

roshith-i commented 3 months ago

It's not just on Windows. My primary work device is a Mac. I just tested out the same case on Windows machine as well. And nope, I don't use any Antivirus on my Windows machine.

adpi2 commented 3 months ago

@adpi2 would anything in https://github.com/scalacenter/scala-debug-adapter/releases/tag/v4.0.0 cause it?

This was added in 4.0.0, and it only affects Mac and Windows:

https://github.com/scalacenter/scala-debug-adapter/blob/65d11ac11267fcb7bbfba047fbd9e98d0176b18d/modules/core/src/main/scala/ch/epfl/scala/debugadapter/internal/ClassEntryLookUp.scala#L360-L384

tgodzik commented 3 months ago

Huh, do you think this can be problematic? I will check my windows machine

tgodzik commented 3 months ago

It doesn't seem to cause any issues on my Windows machine actually and this should actually be cached, no?

roshith-i commented 3 months ago

Windows is not my primary work device. I just tested it there as well to compare. I didn't understand the term 'cached', can you explain it please?

This was the example I tested:

image image

It just has a simple print statement. And this is the only scala file in the entire project. It still took me around 55 seconds to load the sources & classes.

tgodzik commented 3 months ago

Not sure if I am right and @adpi2 would confirm, but do we cache the indexing? It would probably be good to do actually if not.

Weirdly enough on my machine in a simple I get for https://github.com/scala/scala3.g8 :

2024.06.28 16:26:13 INFO  Starting debug proxy for [hello]
2024.06.28 16:26:13 INFO  Loaded expression compiler in 462 milliseconds
2024.06.28 16:26:14 INFO  C:\Users\tomas\AppData\Local\Coursier\cache\v1\https\repo1.maven.org\maven2\ch\epfl\scala\scala-debug-decoder_3\4.1.1\scala-debug-decoder_3-4.1.1.jar
2024.06.28 16:26:14 INFO  C:\Users\tomas\AppData\Local\Coursier\cache\v1\https\repo1.maven.org\maven2\org\scala-lang\scala3-library_3\3.5.0-RC1\scala3-library_3-3.5.0-RC1.jar
2024.06.28 16:26:14 INFO  C:\Users\tomas\AppData\Local\Coursier\cache\v1\https\repo1.maven.org\maven2\ch\epfl\scala\tasty-query_3\1.3.0\tasty-query_3-1.3.0.jar
2024.06.28 16:26:14 INFO  C:\Users\tomas\AppData\Local\Coursier\cache\v1\https\repo1.maven.org\maven2\org\ow2\asm\asm\9.7\asm-9.7.jar
2024.06.28 16:26:14 INFO  C:\Users\tomas\AppData\Local\Coursier\cache\v1\https\repo1.maven.org\maven2\org\ow2\asm\asm-util\9.7\asm-util-9.7.jar
2024.06.28 16:26:14 INFO  C:\Users\tomas\AppData\Local\Coursier\cache\v1\https\repo1.maven.org\maven2\org\scala-lang\scala-library\2.13.12\scala-library-2.13.12.jar
2024.06.28 16:26:14 INFO  C:\Users\tomas\AppData\Local\Coursier\cache\v1\https\repo1.maven.org\maven2\org\ow2\asm\asm-tree\9.7\asm-tree-9.7.jar
2024.06.28 16:26:14 INFO  C:\Users\tomas\AppData\Local\Coursier\cache\v1\https\repo1.maven.org\maven2\org\ow2\asm\asm-analysis\9.7\asm-analysis-9.7.jar
2024.06.28 16:26:14 INFO  Loaded step filter in 651 milliseconds
2024.06.28 16:26:16 INFO  Loaded all sources and classes in 1 second
2024.06.28 16:26:16 INFO  Initialized Scala 3 decoder in 499 milliseconds
2024.06.28 16:26:16 INFO  Trying to attach to remote debuggee VM 127.0.0.1:64495 .
2024.06.28 16:26:16 INFO  Attaching to debuggee VM succeeded.
2024.06.28 16:26:17 INFO  Canceling debug proxy for [hello]
2024.06.28 16:26:16 INFO  Closing debug server tcp://0.0.0.0:64492
2024.06.28 16:26:19 INFO  Deduplicating compilation of root from bsp client 'Metals 1.3.2' (since 26.405s)
2024.06.28 16:26:19 INFO  tracing is disabled for protocol dap-server, to enable tracing of incoming and outgoing JSON messages create an empty file at C:\Users\tomas\Documents\work\scala3-example\.metals\dap-server.trace.json or C:\Users\tomas\AppData\Local\scalameta\metals\cache\dap-server.trace.json
2024.06.28 16:26:19 INFO  tracing is disabled for protocol dap-client, to enable tracing of incoming and outgoing JSON messages create an empty file at C:\Users\tomas\Documents\work\scala3-example\.metals\dap-client.trace.json or C:\Users\tomas\AppData\Local\scalameta\metals\cache\dap-client.trace.json
2024.06.28 16:26:19 INFO  Starting debug proxy for [hello]
2024.06.28 16:26:19 INFO  Loaded expression compiler in 0 milliseconds
2024.06.28 16:26:19 INFO  Loaded step filter in 0 milliseconds
2024.06.28 16:26:19 INFO  Loaded all sources and classes in 644 milliseconds
2024.06.28 16:26:19 INFO  Initialized Scala 3 decoder in 180 milliseconds
2024.06.28 16:26:19 INFO  Trying to attach to remote debuggee VM 127.0.0.1:64504 .
2024.06.28 16:26:19 INFO  Attaching to debuggee VM succeeded.
2024.06.28 16:26:20 INFO  Canceling debug proxy for [hello]
2024.06.28 16:26:20 INFO  Closing debug server tcp://0.0.0.0:64502

so I it looks like it's related to your code specifically somehow.

Btw. I see that you wrote that you use Scala 2.12.18 and it seems the debugger is loading Scala 3? Maybe it's a misconfiguration somewhere? Could you attach the full logs just in case?

roshith-i commented 3 months ago

Sorry for not mentioning, I have added the same dependencies which I had in my Internal project to this test project as well. I had removed most of them and tested again. I see that the sources were loaded in 7 seconds. So, it's dependent on the number of dependencies that we use?

image

And also the entire logs has been attached below : metals.log

I doubt why Scala 3 decoder is being used. Metals Doctor shows the version as 2.12.18. I hope the logs help to find the root cause.

tgodzik commented 3 months ago

Sorry for not mentioning, I have added the same dependencies which I had in my Internal project to this test project as well. I had removed most of them and tested again. I see that the sources were loaded in 7 seconds. So, it's dependent on the number of dependencies that we use?

It would be influenced by it if we have a problem somewhere. Are those internal dependencies or are you able to provide them?

The logs look fine, though maybe it's an issue with JDK 8? Do you have the same issues when using a newer JDK?

roshith-i commented 3 months ago

No, I have removed the internal dependencies. Here is the dependencies list: dependencies.txt

The issues is the same with the newer JDK as well.

tgodzik commented 3 months ago

Looks like it takes around 18 seconds for me, so definitely this triggered by the dependencies and looks like each time do reindex everything.

@adpi2 do you think we could do some kind of caching? Or should we provide some indexes in Metals once again? We do save everything into a database so it should be fine.

adpi2 commented 3 months ago

Yes, for dependencies it would totally make sense to cache their index.

If I get the exact dependency that makes it slow, I can try to optimize it as well.

roshith-i commented 3 months ago

I think it's not because of a specific dependency in particular. As the number of dependencies increases, the time to load the classes and sources is getting increased.

tgodzik commented 2 months ago

It look like we should just cache everything, this might be a main reason for people that encounter slowness here. No matter how optimized the indexing we will at some point find something that makes it slow or reach an amount of deps that does it

adpi2 commented 2 months ago

It look like we should just cache everything, this might be a main reason for people that encounter slowness here. No matter how optimized the indexing we will at some point find something that makes it slow or reach an amount of deps that does it

Sure, but there is clearly a regression here, and we should also fix it if possible.

crt-31 commented 2 months ago

Hopefully https://github.com/scalacenter/scala-debug-adapter/pull/727 fixes this.

I was running into the same issue, initializing the debugger became super slow... it went from 12s to 75s. Issue started happening in scala-debug-adapter 4.0.0. I decided to look into it, and found what I think the culprit is... just a slightly inefficient function. So I went ahead and submitted a PR to fix it.

It look like we should just cache everything, this might be a main reason for people that encounter slowness here. No matter how optimized the indexing we will at some point find something that makes it slow or reach an amount of deps that does it

My 2 cents: Caching might not buy much for this particular issue... 12 seconds isn't really that much on my large project. (Also, its currently bloop doing the debugger initialization). The bigger win would be if bloop can speed up its incremental compile, as that can take like 30-45 seconds on our large codebase when starting the debugger.