Scala 2 forwardport: `-Yprofile-trace` #19897

WojciechMazur · 2024-03-07T17:59:48Z

Scala 2 tracing profiler backport from Emit detailed compiler trace under -Yprofile-trace scala#7364 extended with more Scala 3 idiomatic syntax based on inlined methods
Fixes the context.profiler which could have been null, now it's initially a NoOp Profiler
Check dependencies of -Yprofile-enabled dependent tasks, now we get an error if -Yprofile-trace is set without -Yprofile-enabled

bishabosha · 2024-04-05T11:32:20Z

@keynmol petition here

keynmol · 2024-04-05T11:39:31Z

YES YES YES PLEASE
This would be so much better than the several formats currently enabled by 3 different flags

WojciechMazur · 2024-04-11T09:56:34Z

@nicolasstucki I think you we're doing the original backport of Profiler from Scala 2. Can you take a look at this and make a review?

compiler/src/dotty/tools/dotc/profile/Profiler.scala

nicolasstucki · 2024-04-18T08:57:10Z

I generated the profile for

enum Foo:
  case A
  case B
  case C

and got the following result

All metrics (except for GC) are missing in the type phase.

compiler/src/dotty/tools/dotc/profile/FileUtils.scala

compiler/src/dotty/tools/dotc/profile/Profiler.scala

WojciechMazur · 2024-05-03T11:43:12Z

The metrics are collected after the CompilationUnit with at least 10ms intervals. Parser used overriden runOn method that didn't run onUnit callback. Becouse there was only 1 compilation unit it seemed like collection of metrics started after the typer. In fact it works the same in Scala 2, but I've fixed to collect initial results in the constructor of the profiler - now we got statistics from the very beginning of the compilation run

mbovel

I've done a first quite-quick pass by just reading code. My only concern is the potential cost of the new *on operations, but that might be insignificant. Otherwise looks good to me at first sight.

I now need to experiment with the option to be able to provide further feedback.

compiler/src/dotty/tools/dotc/config/ScalaSettings.scala

compiler/src/dotty/tools/dotc/config/Settings.scala

mbovel · 2024-07-01T14:21:23Z

compiler/src/dotty/tools/dotc/core/SymbolLoaders.scala

+    ctx.profiler.onCompletion(sym, associatedFile)(body)
+  }
+
+  override def complete(root: SymDenotation)(using Context): Unit = profileCompletion(root) {


I checked that the associatedFile callback above doesn't run when profiling is disabled ✅

But I am still not 100% convinced that is zero cost—it seems that calls to default implementations of beforeCompletion and afterCompilation will still exist after inlining? This would just be 2 method calls and a pair allocation, so maybe harmless in terms for performance?

Unfortunately, the benchmarks bot is currently down, so we can't run the benchmarks now.

The allocations have been reduced by preallocating empty (default) outputs. This should reduce any overhead when -Yprofile-trace is disabled. The 2 additional calls to before/after completion might still be present, but maybe JVM can optimize these?

Do you maybe know if the benchmarks bot is working now? We could run it now, after the rebase, to ensure the overhead is not significant when profile-tracing is disabled.

mbovel · 2024-07-01T14:27:28Z

compiler/src/dotty/tools/dotc/profile/Profiler.scala

-  def beforePhase(phase: Phase): ProfileSnap
-
-  def afterPhase(phase: Phase, profileBefore: ProfileSnap): Unit
+  inline def onPhase[T](phase: Phase)(inline body: T): T =


Same comment as above for all on* methods; we now allocate a pair on each call. I don't now if that's significant, but maybe we could just extract (TracedEventId.Empty, Profiler.emptySnap) and so on to constants, in order to avoid the allocations?

mbovel · 2024-07-01T14:43:47Z

compiler/src/dotty/tools/dotc/profile/ChromeTrace.scala

+
+import scala.collection.mutable
+
+object ChromeTrace {


I haven't read this class and FileUtils in details. Should we have a few unit tests for these, or is it not worth it?

I've ported the FileUtilsTest from Scala 2 repo and added a ChromeTraceTest to check the outputs and structure of tracing files

mbovel

Sorry I took so long to come back to this! I finally tried compiling "hello world" with tracing enabled this morning. Here is what I did:

scalac -Yprofile-enabled -Yprofile-trace trace.json hello.scala

I was then able to visualize its easily using https://ui.perfetto.dev/:

Is this the expected workflow? It seems to work well, even if Perfetto warned me that it would prefer a trace in protobuf format.

compiler/src/dotty/tools/dotc/profile/ChromeTrace.scala

mbovel · 2024-08-05T11:23:06Z

compiler/src/dotty/tools/dotc/profile/Profiler.scala

+    else
+      val completionName=  this.completionName(root, associatedFile)
+      val event = TracedEventId(associatedFile.name)
+      chromeTrace.traceDurationEventStart(Category.Completion.name, "↯", colour = "thread_state_sleeping")


Am I correct that this always generate 3 events with the same timing information for each completion? Is this to ease filtering by file and symbol? What was the rational for the ↯ events; do we really need them?

Yes, 3 events would be always generated. I'm not sure what the purpose of the ↯ events was. If I had to guess I'd say that it only exists to inform about the bounds of IO operations, which might make some sense. All other operations are CPU-bound. The 2 remaining symbols might be used to ease filtering, especially because the associated file might not always be present.
We could remove the ↯ and associated file events, but initially I wanted to make the traces compliant with the outputs of Scala 2.

compiler/src/dotty/tools/dotc/config/ScalaSettings.scala

mbovel · 2024-08-05T11:40:07Z

compiler/src/dotty/tools/dotc/profile/Profiler.scala

+        chromeTrace.traceCounterEvent("jitCompilationTime", "jitCompilationTime", initialSnap.totalJITCompilationTime, processWide = true)
+        chromeTrace.traceCounterEvent("userTime", "userTime", initialSnap.userTimeNanos, processWide = false)
+        chromeTrace.traceCounterEvent("cpuTime", "cpuTime", initialSnap.cpuTimeNanos, processWide = false)
+        chromeTrace.traceCounterEvent("idleTime", "idleTime", initialSnap.idleTimeNanos, processWide = false)


Why do we record these metrics only in afterUnit? This means that they are only available after the first unit processed during typer, so we don't know how much memory was used for parsing or for typing for example. Couldn't we sample them also before/after each phase, and before each unit? Or would that be too expensive?

I've refactored this part out. Now it's invoked in all 4 before/after phase/unit combinations. This should not impose a significant overhead

Cool, I confirm I now see the memory starting from parser!

WojciechMazur · 2024-09-13T11:07:12Z

I needed to rebase the PR which is not good news for the reviewing. The improvements after the first review round start with 592a892

Adapt PresentationCompiler to always set (by default noop) profiler

…unId instead of 2

…ns and to match the store non-nullable signature

…-enabled. Allow to define dependencies in String/Phase settings (previously unused)

…by appending GC events after profiling is done.

…ems with scala2-library-bootstrapped compilation

… other cleanups

WojciechMazur · 2024-09-23T14:18:05Z

test performance please

dottybot · 2024-09-23T14:19:00Z

performance test scheduled: 1 job(s) in queue, 1 running.

dottybot · 2024-09-23T14:41:30Z

Performance test finished successfully:

Visit https://dotty-bench.epfl.ch/19897/ to see the changes.

Benchmarks is based on merging with main (3097a84)

WojciechMazur force-pushed the backport/Yprofiler-trace branch from 3eeaa3d to 8c55116 Compare March 7, 2024 19:54

WojciechMazur mentioned this pull request Mar 11, 2024

Project compiles in 18 seconds on scala 2, compilation never ends on scala 3 #19892

Closed

WojciechMazur added this to the 3.5.0 milestone Apr 5, 2024

WojciechMazur mentioned this pull request Apr 8, 2024

Slow compilation times when inferring type HKT with intersection types #20120

Closed

WojciechMazur force-pushed the backport/Yprofiler-trace branch 2 times, most recently from 880e2a7 to 70523b7 Compare April 10, 2024 12:12

WojciechMazur marked this pull request as ready for review April 11, 2024 09:47

WojciechMazur requested a review from nicolasstucki April 11, 2024 09:55

nicolasstucki reviewed Apr 12, 2024

View reviewed changes

nicolasstucki self-requested a review April 12, 2024 10:03

nicolasstucki suggested changes Apr 18, 2024

View reviewed changes

nicolasstucki assigned WojciechMazur Apr 18, 2024

lrytz mentioned this pull request Apr 18, 2024

~5x compilation slowdown compared to 2.13 on ~400 files #20217

Closed

dwijnand changed the title ~~Scala 2 backport: -Yprofile-trace~~ Scala 2 forwardport: -Yprofile-trace Apr 18, 2024

WojciechMazur mentioned this pull request May 2, 2024

False-positive globally reachable private Java vars under -Ycheck-reentrant #20324

Closed

WojciechMazur force-pushed the backport/Yprofiler-trace branch from 16795d6 to 6eb6a23 Compare May 3, 2024 12:29

WojciechMazur requested a review from nicolasstucki May 6, 2024 16:03

WojciechMazur force-pushed the backport/Yprofiler-trace branch 3 times, most recently from cc05d6a to 72d5e0e Compare May 8, 2024 11:04

Gedochao requested review from sjrd and rochala May 9, 2024 08:32

Gedochao assigned sjrd May 9, 2024

Kordyjan removed this from the 3.5.0 milestone May 10, 2024

Gedochao assigned mbovel Jul 1, 2024

Gedochao requested a review from mbovel July 1, 2024 09:53

mbovel reviewed Jul 1, 2024

View reviewed changes

mbovel reviewed Aug 5, 2024

View reviewed changes

WojciechMazur force-pushed the backport/Yprofiler-trace branch from 72d5e0e to f078a0a Compare September 13, 2024 10:55

WojciechMazur added 11 commits September 14, 2024 15:55

Backport -Yprofile-trace from Scala 2

b9af5a2

Adapt PresentationCompiler to always set (by default noop) profiler

Profile more events, make the profiler more Scala3 idiomatic

3450dfb

Fix assignment of RunIds - make sure they'll start with 1 == InitialR…

016dfdd

…unId instead of 2

Initialize context with NoOpProfiler to prevent null pointer exceptio…

4077575

…ns and to match the store non-nullable signature

Give compilation error when -Yprofile-trace is used without -Yprofile…

94f7613

…-enabled. Allow to define dependencies in String/Phase settings (previously unused)

More idiomatic trace-profiler integraiton. Prevent malformed outputs …

c0ecfe0

…by appending GC events after profiling is done.

Workaround changes to runId starting with 1 instead of 2 due to probl…

485c044

…ems with scala2-library-bootstrapped compilation

Remove commented out withPostSetHook actions

592a892

Document SettingDependencies type

dc10c53

Add unit tests for ChromeTrace and port FileUtilsTest from Scala2

e76fce4

Reduce ammount of allocations, increase ammontof counters tracing and…

718af3a

… other cleanups

WojciechMazur force-pushed the backport/Yprofiler-trace branch from dc9766c to 718af3a Compare September 14, 2024 13:57

Fix compilation failure under -Yexplicit-nulls

b8c501d

filipwiech mentioned this pull request Sep 23, 2024

Slow performance in a combination of features #18763

Open

WojciechMazur requested a review from mbovel October 3, 2024 18:21

mbovel approved these changes Oct 22, 2024

View reviewed changes

WojciechMazur merged commit ecc332f into main Oct 22, 2024
50 checks passed

WojciechMazur deleted the backport/Yprofiler-trace branch October 22, 2024 16:56

tgodzik added the release-notes Should be mentioned in the release notes label Oct 28, 2024

WojciechMazur added this to the 3.6.3 milestone Dec 9, 2024

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Scala 2 forwardport: `-Yprofile-trace` #19897

Scala 2 forwardport: `-Yprofile-trace` #19897

WojciechMazur commented Mar 7, 2024 •

edited

Loading

bishabosha commented Apr 5, 2024

keynmol commented Apr 5, 2024

WojciechMazur commented Apr 11, 2024

nicolasstucki commented Apr 18, 2024

WojciechMazur commented May 3, 2024

mbovel left a comment •

edited

Loading

mbovel Jul 1, 2024

WojciechMazur Sep 13, 2024

mbovel Jul 1, 2024

mbovel Jul 1, 2024 •

edited

Loading

WojciechMazur Sep 13, 2024

mbovel left a comment

mbovel Aug 5, 2024

WojciechMazur Sep 13, 2024

mbovel Aug 5, 2024

WojciechMazur Sep 13, 2024

mbovel Oct 22, 2024

WojciechMazur commented Sep 13, 2024 •

edited

Loading

WojciechMazur commented Sep 23, 2024

dottybot commented Sep 23, 2024

dottybot commented Sep 23, 2024


		import scala.collection.mutable

		object ChromeTrace {

Scala 2 forwardport: -Yprofile-trace #19897

Scala 2 forwardport: -Yprofile-trace #19897

Conversation

WojciechMazur commented Mar 7, 2024 • edited Loading

bishabosha commented Apr 5, 2024

keynmol commented Apr 5, 2024

WojciechMazur commented Apr 11, 2024

nicolasstucki commented Apr 18, 2024

WojciechMazur commented May 3, 2024

mbovel left a comment • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

mbovel Jul 1, 2024 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

mbovel left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

WojciechMazur commented Sep 13, 2024 • edited Loading

WojciechMazur commented Sep 23, 2024

dottybot commented Sep 23, 2024

dottybot commented Sep 23, 2024

Scala 2 forwardport: `-Yprofile-trace` #19897

Scala 2 forwardport: `-Yprofile-trace` #19897

WojciechMazur commented Mar 7, 2024 •

edited

Loading

mbovel left a comment •

edited

Loading

mbovel Jul 1, 2024 •

edited

Loading

WojciechMazur commented Sep 13, 2024 •

edited

Loading