StackTraceRequest is very slow after version 4.0.2

[crt-31]

Processing StackTraceRequest has become orders of magnitude slower since version 4.0.2, almost to a point where debugging is unusable. We are using Metals/Bloop, and everytime we debug break, the StackTraceRequest is sent and can take 5 to 10 seconds to process.

The regression seems to be caused by the new feature to add presentation hint for each method in the callstack.

The culprit seems to be in JdiExtensions.isLazyGetter which calls jdi.Method.argumentTypes(). jdi.Method.argumentTypes() seems to be an expensive function as it queries the host for all the fields. Doing this on every method in callstack is slowing things down.

scala-debug-adapter/modules/core/src/main/scala/ch/epfl/scala/debugadapter/internal/stacktrace/JdiExtensions.scala

Lines 45 to 49 in b2800f0

	def isLazyGetter: Boolean =
	method.argumentTypes.asScala.toSeq match {
	case Seq(argType) => lazyTypes.contains(argType.name)
	case _ => false
	}

I don't have any great solutions to fix this, other than finding a way to not have to call isLazyGetter all the time, or maybe a config option to turn off presentationHint? Just ideas.

[adpi2]

Thanks for the report!

I will need more information to address this issue:

• Does it happen on Scala 2.12, 2.13 or 3? Have you tried other Scala versions?
• What JVM do you use? Does it happen on other JVMs?
• Have you tried the latest version of the Scala Debug Adapter?
• Why do you think isLazyGetter is the culprit?

[crt-31]

• Issue happens on scala 2.13.14 and 2.13.10... Haven't tried any other versions
• Using Correto 17.0.11 & Hotspot 17.0.6.10
• Confirmed issue happens on latest main of Scala Debug Adapter
• Used Flight Recorder to narrow down to the isLazyGetter function. The slowness went away when I commented that line out.

Investigating the code further, it made sense since method.argumentTypes() sends request to the host and waits for response... also the problem appears to be exasperated by presense of anonymous functions such as for comprehensions and lambdas.

Note, we are running a large application, I don't notice it in small applications.

[adpi2]

Thanks for the details! That's very helpful.

Note, we are running a large application, I don't notice it in small applications.

If you use VSCode, it only loads the top 10 frames and then you need to click to expand the entire stack. In other code editors, I don't know, maybe there is a similar feature that you can enable. But anyway I'll see if I can avoid this method.argumentTypes call.

[crt-31]

Thanks for addressing this. (Also, we are using VSCode & Metals)

[adpi2]

Also, we are using VSCode & Metals

Then it should only load 10 frames, which should not be slow. So I guess it becomes slow only when you expand the entire stack?

[crt-31]

I'm not expanding or even really touching the vs code stack frame ui.

[adpi2]

@crt-31 Could you show me a screenshot of stacktrace that is slow to load? I'd like to determine if there is a pattern that makes it slow.

[crt-31]

@adpi2: Here you go. Here is an example of a (redacted) callstack that is real slow and one that is fast.

SLOW CALLSTACK

FAST CALLSTACK

Also, I see that VS Code requests 20 requests at a time... but not relevant... still its still slow.

[crt-31]

@adpi2, just seeing if there is any progress on this issue.

[crt-31]

@adpi2, anything more to do to move toward a fix for this issue?

[adpi2]

I created a piece of code that generates a stack trace that is very similar to yours. But the problem is that it does not seem to be slow.

Here is my code:

//> using scala 2.13.14

object Test {
  def main(args: Array[String]): Unit = {
    println(System.getProperty("java.vendor"))
    println(System.getProperty("java.version"))
    m[Int](List(1, 2, 3))(_ > 0)
  }

  def m[T](xs: List[T])(filter: T => Boolean): Unit = {
    def local(x: String): Unit =
      println(x)
    
    for {
      x1 <- xs
      if filter(x1)
      x2 <- xs
      if filter(x2)
      x3 <- xs
      if filter(x3)
    } {
      local(s"$x1$x2$x3")
    }
  }
}

And here is the stack trace:

Test$.local$1(String): void
Test$.$anonfun$m$6(Object,Object,Object): void
Test$.$anonfun$m$6$adapted(Object,Object,Object): Object
Test$$$Lambda$9/0x00007f81700ad000.apply(Object): Object
IterableOnceOps.foreach(Function1): void
IterableOnceOps.foreach$(IterableOnceOps,Function1): void
AbstractIterable.foreach(Function1): void
IterableOps$WithFilter.foreach(Function1): void
Test$.$anonfun$m$4(List,Function1,Object,Object): void
Test$.$anonfun$m$4$adapted(List,Function1,Object,Object): Object
Test$$$Lambda$7/0x00007f81700af750.apply(Object): Object
IterableOnceOps.foreach(Function1): void
IterableOnceOps.foreach$(IterableOnceOps,Function1): void
AbstractIterable.foreach(Function1): void
IterableOps$WithFilter.foreach(Function1): void
Test$.$anonfun$m$2(List,Function1,Object): void
Test$.$anonfun$m$2$adapted(List,Function1,Object): Object
Test$$$Lambda$5/0x00007f81700aa3e0.apply(Object): Object (Unknown Source:-1)
IterableOnceOps.foreach(Function1): void
IterableOnceOps.foreach$(IterableOnceOps,Function1): void

However it becomes slow if I add a lot of generators in the for loops, like a thousand of generators. It takes about 6 seconds to load the 5000 frames. But in my case loading the top 20 frames is always fast.

When I profile it, I can see that skipOver is taking most of the CPU time, but inside skipOver it is getScalaSig that is slow (88%) and not isLazyGetter (2%).

I will try something to speed up isLazyGetter but I will need you to check that it actually fixes the issue.

[adpi2]

Also I am curious, what's your OS?

[adpi2]

I pushed #849, hopefully it is going to be much faster now.