Metals: High CPU loading in scala/scala

Created on 19 Apr 2020 · 15Comments · Source: scalameta/metals

Describe the bug
Opening some (all?) files from scala/scala leads to hight CPU loading (up to 100%) for long periods (at least takes more than 2 minutes).

To Reproduce
Steps to reproduce the behavior:

Clone https://github.com/scala/scala and open src/compiler/scala/tools/nsc/Global.scala or src/compiler/scala/tools/nsc/SubComponent.scala
Check the CPU loading / notice the noise from the cooling system

Installation:

Operating system: Linux
Editor: Visual Studio Code
Metals version: v0.8.4

Additional context
Not sure if it's close to problem but probably this might be related to super/implementation references finding.
jstack dosn't show anything suspicious except thread with trace that contain scala.meta.internal.implementation.SuperMethodProvider / scala.meta.internal.implementation.ImplementationProvider

Stacktrace sample


"pool-1-thread-34" #67 prio=5 os_prio=0 cpu=83225,05ms elapsed=132,72s tid=0x00007f400c032800 nid=0x5bd2 runnable  [0x00007f3fb2bf7000]
   java.lang.Thread.State: RUNNABLE
    at sun.nio.fs.UnixNativeDispatcher.realpath0([email protected]/Native Method)
    at sun.nio.fs.UnixNativeDispatcher.realpath([email protected]/UnixNativeDispatcher.java:262)
    at sun.nio.fs.UnixPath.toRealPath([email protected]/UnixPath.java:857)
    at scala.meta.internal.metals.MetalsEnrichments$XtensionAbsolutePathBuffers.dealias(MetalsEnrichments.scala:328)
    at scala.meta.internal.metals.MetalsEnrichments$XtensionString.toAbsolutePath(MetalsEnrichments.scala:419)
    at scala.meta.internal.metals.MetalsEnrichments$XtensionScalacOptions.$anonfun$targetroot$2(MetalsEnrichments.scala:510)
    at scala.meta.internal.metals.MetalsEnrichments$XtensionScalacOptions$$Lambda$583/0x00000008404a2440.apply(Unknown Source)
    at scala.Option.getOrElse(Option.scala:189)
    at scala.meta.internal.metals.MetalsEnrichments$XtensionScalacOptions.targetroot(MetalsEnrichments.scala:510)
    at scala.meta.internal.metals.FileSystemSemanticdbs.$anonfun$semanticdbTargetroot$2(FileSystemSemanticdbs.scala:53)
    at scala.meta.internal.metals.FileSystemSemanticdbs$$Lambda$1740/0x0000000840803840.apply(Unknown Source)
    at scala.Option.map(Option.scala:230)
    at scala.meta.internal.metals.FileSystemSemanticdbs.$anonfun$semanticdbTargetroot$1(FileSystemSemanticdbs.scala:52)
    at scala.meta.internal.metals.FileSystemSemanticdbs$$Lambda$1738/0x0000000840804840.apply(Unknown Source)
    at scala.Option.flatMap(Option.scala:271)
    at scala.meta.internal.metals.FileSystemSemanticdbs.semanticdbTargetroot(FileSystemSemanticdbs.scala:51)
    at scala.meta.internal.metals.FileSystemSemanticdbs.textDocument(FileSystemSemanticdbs.scala:25)
    at scala.meta.internal.metals.AggregateSemanticdbs.loop$1(AggregateSemanticdbs.scala:28)
    at scala.meta.internal.metals.AggregateSemanticdbs.textDocument(AggregateSemanticdbs.scala:34)
    at scala.meta.internal.implementation.ImplementationProvider.findSemanticdb(ImplementationProvider.scala:332)
    at scala.meta.internal.implementation.ImplementationProvider.$anonfun$findSemanticDbForSymbol$1(ImplementationProvider.scala:385)
    at scala.meta.internal.implementation.ImplementationProvider$$Lambda$1926/0x0000000840883040.apply(Unknown Source)
    at scala.Option.flatMap(Option.scala:271)
    at scala.meta.internal.implementation.ImplementationProvider.findSemanticDbForSymbol(ImplementationProvider.scala:384)
    at scala.meta.internal.implementation.ImplementationProvider.findSymbolInformation(ImplementationProvider.scala:366)
    at scala.meta.internal.implementation.ImplementationProvider.$anonfun$defaultSymbolSearch$3(ImplementationProvider.scala:101)
    at scala.meta.internal.implementation.ImplementationProvider$$Lambda$1909/0x000000084086f440.apply(Unknown Source)
    at scala.Option.orElse(Option.scala:447)
    at scala.meta.internal.implementation.ImplementationProvider.$anonfun$defaultSymbolSearch$1(ImplementationProvider.scala:101)
    at scala.meta.internal.implementation.ImplementationProvider$$Lambda$1880/0x0000000840855840.apply(Unknown Source)
    at scala.meta.internal.implementation.SuperMethodProvider$.$anonfun$findSuperForMethodOrFieldChecked$6(SuperMethodProvider.scala:213)
    at scala.meta.internal.implementation.SuperMethodProvider$$$Lambda$2010/0x00000008408e4040.apply(Unknown Source)
    at scala.collection.TraversableLike.$anonfun$flatMap$1(TraversableLike.scala:280)
    at scala.collection.TraversableLike$$Lambda$330/0x00000008403ae840.apply(Unknown Source)
    at scala.collection.Iterator.foreach(Iterator.scala:943)
    at scala.collection.Iterator.foreach$(Iterator.scala:943)
    at scala.collection.AbstractIterator.foreach(Iterator.scala:1431)
    at scala.collection.IterableLike.foreach(IterableLike.scala:74)
    at scala.collection.IterableLike.foreach$(IterableLike.scala:73)
    at scala.collection.AbstractIterable.foreach(Iterable.scala:56)
    at scala.collection.TraversableLike.flatMap(TraversableLike.scala:280)
    at scala.collection.TraversableLike.flatMap$(TraversableLike.scala:277)
    at scala.collection.AbstractTraversable.flatMap(Traversable.scala:108)
    at scala.meta.internal.implementation.SuperMethodProvider$.$anonfun$findSuperForMethodOrFieldChecked$5(SuperMethodProvider.scala:212)
    at scala.meta.internal.implementation.SuperMethodProvider$$$Lambda$2008/0x00000008408e3040.apply(Unknown Source)
    at scala.collection.immutable.List.flatMap(List.scala:338)
    at scala.meta.internal.implementation.SuperMethodProvider$.$anonfun$findSuperForMethodOrFieldChecked$4(SuperMethodProvider.scala:209)
    at scala.meta.internal.implementation.SuperMethodProvider$$$Lambda$2007/0x00000008408e2840.apply(Unknown Source)
    at scala.collection.TraversableLike$WithFilter.$anonfun$flatMap$2(TraversableLike.scala:893)
    at scala.collection.TraversableLike$WithFilter$$Lambda$1876/0x0000000840853840.apply(Unknown Source)
    at scala.collection.immutable.List.foreach(List.scala:392)
    at scala.collection.TraversableLike$WithFilter.flatMap(TraversableLike.scala:892)
    at scala.meta.internal.implementation.SuperMethodProvider$.$anonfun$findSuperForMethodOrFieldChecked$2(SuperMethodProvider.scala:204)
    at scala.meta.internal.implementation.SuperMethodProvider$$$Lambda$1915/0x0000000840873840.apply(Unknown Source)
    at scala.collection.TraversableLike.$anonfun$flatMap$1(TraversableLike.scala:280)
    at scala.collection.TraversableLike$$Lambda$330/0x00000008403ae840.apply(Unknown Source)
    at scala.collection.immutable.List.foreach(List.scala:392)
    at scala.collection.TraversableLike.flatMap(TraversableLike.scala:280)
    at scala.collection.TraversableLike.flatMap$(TraversableLike.scala:277)
    at scala.collection.immutable.List.flatMap(List.scala:355)
    at scala.meta.internal.implementation.SuperMethodProvider$.findSuperForMethodOrFieldChecked(SuperMethodProvider.scala:201)
    at scala.meta.internal.implementation.SuperMethodProvider$.$anonfun$findSuperForMethodOrField$1(SuperMethodProvider.scala:33)
    at scala.meta.internal.implementation.SuperMethodProvider$$$Lambda$1913/0x0000000840872040.apply(Unknown Source)
    at scala.Option.flatMap(Option.scala:271)
    at scala.meta.internal.implementation.SuperMethodProvider$.findSuperForMethodOrField(SuperMethodProvider.scala:24)
    at scala.meta.internal.metals.codelenses.SuperMethodCodeLens.$anonfun$createSuperMethodCommand$1(SuperMethodCodeLens.scala:73)
    at scala.meta.internal.metals.codelenses.SuperMethodCodeLens$$Lambda$1911/0x0000000840870840.apply(Unknown Source)
    at scala.Option.flatMap(Option.scala:271)
    at scala.meta.internal.metals.codelenses.SuperMethodCodeLens.createSuperMethodCommand(SuperMethodCodeLens.scala:67)
    at scala.meta.internal.metals.codelenses.SuperMethodCodeLens.$anonfun$codeLenses$3(SuperMethodCodeLens.scala:51)
    at scala.meta.internal.metals.codelenses.SuperMethodCodeLens$$Lambda$1907/0x000000084086e840.apply(Unknown Source)
    at scala.collection.TraversableLike.$anonfun$flatMap$1(TraversableLike.scala:280)
    at scala.collection.TraversableLike$$Lambda$330/0x00000008403ae840.apply(Unknown Source)
    at scala.collection.Iterator.foreach(Iterator.scala:943)
    at scala.collection.Iterator.foreach$(Iterator.scala:943)
    at scala.collection.AbstractIterator.foreach(Iterator.scala:1431)
    at scala.collection.IterableLike.foreach(IterableLike.scala:74)
    at scala.collection.IterableLike.foreach$(IterableLike.scala:73)
    at scala.collection.AbstractIterable.foreach(Iterable.scala:56)
    at scala.collection.TraversableLike.flatMap(TraversableLike.scala:280)
    at scala.collection.TraversableLike.flatMap$(TraversableLike.scala:277)
    at scala.collection.AbstractTraversable.flatMap(Traversable.scala:108)
    at scala.meta.internal.metals.codelenses.SuperMethodCodeLens.codeLenses(SuperMethodCodeLens.scala:43)
    at scala.meta.internal.metals.CodeLensProvider.$anonfun$findLenses$3(CodeLensProvider.scala:20)
    at scala.meta.internal.metals.CodeLensProvider$$Lambda$1812/0x000000084082d040.apply(Unknown Source)
    at scala.collection.immutable.List.flatMap(List.scala:338)
    at scala.meta.internal.metals.CodeLensProvider.$anonfun$findLenses$1(CodeLensProvider.scala:20)
    at scala.meta.internal.metals.CodeLensProvider$$Lambda$1809/0x000000084082b040.apply(Unknown Source)
    at scala.Option.map(Option.scala:230)
    at scala.meta.internal.metals.CodeLensProvider.findLenses(CodeLensProvider.scala:18)
    at scala.meta.internal.metals.MetalsLanguageServer.$anonfun$codeLens$1(MetalsLanguageServer.scala:1186)
    at scala.meta.internal.metals.MetalsLanguageServer$$Lambda$1729/0x00000008407ff840.apply(Unknown Source)
    at scala.meta.internal.metals.CancelTokens$.$anonfun$apply$2(CancelTokens.scala:24)
    at scala.meta.internal.metals.CancelTokens$$$Lambda$1673/0x00000008407eb440.apply(Unknown Source)
    at scala.concurrent.Future$.$anonfun$apply$1(Future.scala:659)
    at scala.concurrent.Future$$$Lambda$116/0x00000008401d6840.apply(Unknown Source)
    at scala.util.Success.$anonfun$map$1(Try.scala:255)
    at scala.util.Success.map(Try.scala:213)
    at scala.concurrent.Future.$anonfun$map$1(Future.scala:292)
    at scala.concurrent.Future$$Lambda$117/0x00000008401d6040.apply(Unknown Source)
    at scala.concurrent.impl.Promise.liftedTree1$1(Promise.scala:33)
    at scala.concurrent.impl.Promise.$anonfun$transform$1(Promise.scala:33)
    at scala.concurrent.impl.Promise$$Lambda$118/0x00000008401d5040.apply(Unknown Source)
    at scala.concurrent.impl.CallbackRunnable.run(Promise.scala:64)
    at java.util.concurrent.ThreadPoolExecutor.runWorker([email protected]/ThreadPoolExecutor.java:1128)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run([email protected]/ThreadPoolExecutor.java:628)
    at java.lang.Thread.run([email protected]/Thread.java:834)

bug

Source

dos65

👍1

Most helpful comment

Can you try to capture a CPU profile with https://github.com/jvm-profiling-tools/async-profiler ?

profiler.sh collect -d 5 -e cpu -f /tmp/metals.svg $METALS_PROCESS

That would give a better hint to what's causing the slow performance.

olafurpg on 24 Apr 2020

👍2

All 15 comments

Thanks for reporting! This is something we should for sure investigate.

tgodzik on 20 Apr 2020

@dos65 can you disable super method Code Lenses and see if this problem disappear? Just to be sure it is related to generating those lenses.

kpbochenek on 20 Apr 2020

@kpbochenek
I've just checked that.
This problem reproduces constantly with enabled CodeLens settings. Disabling them doesn't lead to any problematic behavior.

dos65 on 20 Apr 2020

👍1

@dos65 Thank you for confirming that! A design principle in Metals is that we try to limit user-facing configuration options. We should disable parent lenses by default (unless there is an easy fix).

olafurpg on 21 Apr 2020

One possible solution would be to emit overridden symbols in the *.semanticdb files. I believe this can be done with low-ish overhead and it would unblock some other useful applications.

olafurpg on 21 Apr 2020

Maybe unrelated, but when I open this file I can see error in metals logs:

SEVERE: class scala.annotation.StaticAnnotation in compiler mirror not found.
scala.reflect.internal.MissingRequirementError: class scala.annotation.StaticAnnotation in compiler mirror not found.
    at scala.reflect.internal.MissingRequirementError$.notFound(MissingRequirementError.scala:24)
    at scala.reflect.internal.Mirrors$RootsBase.$anonfun$getModuleOrClass$6(Mirrors.scala:66)
    at scala.reflect.internal.Mirrors$RootsBase.getRequiredClass(Mirrors.scala:66)
    at scala.reflect.internal.Mirrors$RootsBase.requiredClass(Mirrors.scala:125)
    at scala.reflect.internal.Definitions$DefinitionsClass.StaticAnnotationClass$lzycompute(Definitions.scala:1257)
    at scala.reflect.internal.Definitions$DefinitionsClass.StaticAnnotationClass(Definitions.scala:1257)
    at scala.reflect.internal.Definitions$DefinitionsClass.AnnotationDefaultAttr$lzycompute(Definitions.scala:1341)
    at scala.reflect.internal.Definitions$DefinitionsClass.AnnotationDefaultAttr(Definitions.scala:1339)
    at scala.reflect.internal.Definitions$DefinitionsClass.syntheticCoreClasses$lzycompute(Definitions.scala:1488)
    at scala.reflect.internal.Definitions$DefinitionsClass.syntheticCoreClasses(Definitions.scala:1487)
    at scala.reflect.internal.Definitions$DefinitionsClass.symbolsNotPresentInBytecode$lzycompute(Definitions.scala:1531)
    at scala.reflect.internal.Definitions$DefinitionsClass.symbolsNotPresentInBytecode(Definitions.scala:1531)
    at scala.reflect.internal.Definitions$DefinitionsClass.init(Definitions.scala:1587)
    at scala.tools.nsc.Global$Run.<init>(Global.scala:1205)
    at scala.tools.nsc.interactive.Global$TyperRun.<init>(Global.scala:1327)
    at scala.tools.nsc.interactive.Global.newTyperRun(Global.scala:1350)
    at scala.tools.nsc.interactive.Global.<init>(Global.scala:294)
    at scala.meta.internal.pc.MetalsGlobal.<init>(MetalsGlobal.scala:31)

kpbochenek on 22 Apr 2020

does confirm-reproduction means it requires confirmation it is a bug or it is already confirmed? (@tgodzik )

kpbochenek on 22 Apr 2020

Okay I can confirm lenses generation takes long time for Global.scala. Problem has 2 parts:
One:

def defaultSymbolSearch(...) =
      textDocument.symbols
        .find(_.symbol == symbol)
          .orElse(findSymbolInformation(symbol))
          .orElse(global.flatMap(_.safeInfo(symbol)))

For every symbol we search we firstly do linear check if currently opened document contains searched symbol, then we move to search in workspace then deps. Because Global.scala contains over 10k symbols and we search for multiple external symbols, you got it...
To fix this we can preprocess current document to generate Map[String, SymbolInformation] and perform search in current document in O(logn) this way(smap would be cached between requests):

val smap: Map[String, SymbolInformation] = textDocument.symbols.map(s => s.symbol -> s).toMap
      smap.get(symbol)
        .orElse(findSymbolInformation(symbol))
        .orElse(global.flatMap(_.safeInfo(symbol))

Two:
When we have method X#f() and parent class is Y, we search for Y, then get list of methods, then search each method of Y, then do compare. We search Y#a() and compare to X#f(), then search Y#b() and compare to X#f() etc. but even before searching we know that X#f() will never match with Y#a()
There is completely no point searching for a method and do comparison if a method name doesn't match.
Currently:

methodName <- getMethods(Y)
method <- search(methodName)
if equal(method, baseMethod)
-> generate lens

if can be improved to:

methodName <- getMethods(Y)
 //this is quick check and in most cases will eliminate heavy search.
if potentialMatch(methodName, baseMethod) 
method <- search(methodName)
if equal(method, baseMethod)
-> generate lens

Unless there is already a helper function to fetch a method name from signature it might be tricky to properly implement it, e.g.
Global#withPropagateCyclicReferences().(t).
Global#withPropagateCyclicReferences().[T].
Global#Run#posterasurePhase.
Global#global.run.
Have to be careful.

With 'good enough' method name comparision I get those results:

2020.04.22 22:58:06 INFO  CODE LENS REQ => /compiler/scala/tools/nsc/Global.scala
2020.04.22 22:58:06 INFO  STARTING LENSES
2020.04.22 22:58:13 INFO  DONE LENSES

2020.04.22 22:59:48 INFO  CODE LENS REQ => /compiler/scala/tools/nsc/SubComponent.scala
2020.04.22 22:59:48 INFO  STARTING LENSES
2020.04.22 22:59:48 INFO  DONE LENSES

For huge files with complex inheritance hierarchy as Global.scala it can be easily reduced to ~7s to generate lenses.
Is that good enough to be considered a fix or should we disable lenses by default is your decision.

Having information in semanticdb if symbol has parent would definitely be awesome here. We would not even need an information what symbol is a parent only if parent method exists, we could calculate parent symbol when user decides to go to parent as lookup for single symbol is almost instant.

kpbochenek on 23 Apr 2020

👍1

@kpbochenek thank you for the detailed investigation. It's good to know we can introduce performance optimizations. I think 7 seconds is still too much, computing the code lenses should ideally not consume more than ~100-200ms of full CPU time.

I think it's best to disable super code lenses for now since I think it's important that the out of the box experience in Metals performs reliably, users should not have to find custom settings to get a usable experience.

Unless there is already a helper function to fetch a method name from signature it might be tricky to properly implement it, e.g.

Can you elaborate? There are many helper methods here https://github.com/scalameta/scalameta/blob/059f035259e180aa6bfee4b70fd5f16f3155ea7e/semanticdb/semanticdb/src/main/scala/scala/meta/internal/semanticdb/Scala.scala#L36

olafurpg on 23 Apr 2020

I'm working on upgrading scalameta for 2.13.2 which would be nice to include in the next release.

olafurpg on 23 Apr 2020

Can you elaborate? -> Ahh maybe I could do symbol.desc.name I will check :+1:

kpbochenek on 23 Apr 2020

We would not even need an information what symbol is a parent only if parent method exists, we could calculate parent symbol when user decides to go to parent as lookup for single symbol is almost instant.

Would it help to ignore symbols that are not global method symbols? That should filter out all local symbols, class symbols, parameter symbols, etc, that cannot have overridden symbols.

olafurpg on 23 Apr 2020

I think I noticed the scalameta parser being run a lot of times, which might be the cause of the issues here really.

The stacktrace:
codelens.txt

Maybe if we use the compiler to find the path to the file it would be better? Or maybe there is a race condition inside of Mtags class that will run many times for the same file even, which for Global might be the cause of this issue.

We should most likely use a ConcurrentHashMap there, which might help and maybe introduce parallel collections for differetn symbols.

I agree that we might need to turn it off at the state it is in. I will do that befor ethe next release if we cannot fix it here.

tgodzik on 24 Apr 2020

Can you try to capture a CPU profile with https://github.com/jvm-profiling-tools/async-profiler ?

profiler.sh collect -d 5 -e cpu -f /tmp/metals.svg $METALS_PROCESS

That would give a better hint to what's causing the slow performance.

olafurpg on 24 Apr 2020

👍2

That stack trace was actually after I closed all files and waited a bit :/ That's why I am thinking this might be an issue. But I agree CPU profile would be super useful.

tgodzik on 24 Apr 2020

Was this page helpful?

0 / 5 - 0 ratings