Skip to content

Report per-phase JVM statistics (e.g cpu time, user time, allocated bytes)#5758

Closed
mkeskells wants to merge 3 commits intoscala:2.12.xfrom
rorygraves:2.12.x_profile_baseline
Closed

Report per-phase JVM statistics (e.g cpu time, user time, allocated bytes)#5758
mkeskells wants to merge 3 commits intoscala:2.12.xfrom
rorygraves:2.12.x_profile_baseline

Conversation

@mkeskells
Copy link
Contributor

@mkeskells mkeskells commented Mar 5, 2017 •
edited
Loading

add some profiling support to scalac

This adds a few -Yprofile... options that assist in profiling scalac

This has proved useful so far in https://github.com/rorygraves/scalac_perf for identification of opportunities for optimisation

The output can be generated to a console, or a CSV.
This could enable the generation of CI tasks that error if some indicator goes out of bounds, but that is outside the scope of this PR.

console output is in the form

Profiler compile 1 after phase  4:               typer wallClockTime:   13088.2065ms, cpuTime   12609.3750ms, userTime   12500.0000ms, allocatedBytes     651.6394MB, retainedHeapBytes     681.0260MB, gcTime      0ms
Profiler compile 1 after phase  5:              patmat wallClockTime:    2128.9528ms, cpuTime    2062.5000ms, userTime    2062.5000ms, allocatedBytes     132.4393MB, retainedHeapBytes     153.0780MB, gcTime      0ms
Profiler compile 1 after phase  6:      superaccessors wallClockTime:     349.0044ms, cpuTime     328.1250ms, userTime     328.1250ms, allocatedBytes      27.4235MB, retainedHeapBytes      43.8591MB, gcTime      0ms
Profiler compile 1 after phase  7:          extmethods wallClockTime:     130.9848ms, cpuTime      93.7500ms, userTime      93.7500ms, allocatedBytes       5.7003MB, retainedHeapBytes       0.0000MB, gcTime      0ms
Profiler compile 1 after phase  8:             pickler wallClockTime:     371.8387ms, cpuTime     375.0000ms, userTime     375.0000ms, allocatedBytes      23.6769MB, retainedHeapBytes      21.9295MB, gcTime      0ms
Profiler compile 1 after phase  9:            xsbt-api wallClockTime:    2040.5242ms, cpuTime    2031.2500ms, userTime    2031.2500ms, allocatedBytes     314.7573MB, retainedHeapBytes     307.0130MB, gcTime      0ms
Profiler compile 1 after phase 10:     xsbt-dependency wallClockTime:    1410.9184ms, cpuTime    1406.2500ms, userTime    1078.1250ms, allocatedBytes     436.6854MB, retainedHeapBytes     438.5903MB, gcTime      0ms

@scala-jenkins scala-jenkins added this to the 2.12.2 milestone Mar 5, 2017
@retronym
Copy link
Member

retronym commented Mar 6, 2017

I've tried to use the ExternalToolHook feature with YourKit, but I'm having mixed results.

⚡ cat /tmp/trigger
MethodListener methodPattern=scala.tools.nsc.profile.ExternalToolHook\s:\sbefore\s(*) instanceOf= fillThis=true fillParams=true fillReturnValue=true maxTriggerCount=-1
  onenter: StartCPUSampling
  onenter: PrintMessage message=Entering:\s${CLASS}:${METHOD}${PARAM_TYPES}\n\s\sthis:\s${THIS}\n\s\sparams:\n${PARAMS} output=stdout
MethodListener methodPattern=scala.tools.nsc.profile.ExternalToolHook\s:\after\s(*) instanceOf= fillThis=true fillParams=true fillReturnValue=true maxTriggerCount=-1
  onenter: StopCPUSampling
  onenter: CapturePerformanceSnapshot fileName=partial
  onenter: PrintMessage message=Entering:\s${CLASS}:${METHOD}${PARAM_TYPES}\n\s\sthis:\s${THIS}\n\s\sparams:\n${PARAMS} output=stdout

⚡ ./build/quick/bin/scalac -Yprofile-external-tool -J-agentpath:/Applications/YourKit-Java-Profiler-2016.02.app/Contents/Resources/bin/mac/libyjpagent.jnilib=onexit=snapshot,triggers=/tmp/trigger sandbox/test.scala
...
Profile hook start
Entering: scala.tools.nsc.profile.ExternalToolHook:before()
  this: scala.tools.nsc.profile.ExternalToolHook
  params:

Profile hook stop
Entering: scala.tools.nsc.profile.ExternalToolHook:after()
  this: scala.tools.nsc.profile.ExternalToolHook
  params:

So far, so good. The partial performance snapshot contains is limited to the typer phase. But the onexit snapshot contains a profile of the typer phase and everything that follows. So it seems that YourKit isn't processing my request to StopCPUSampling.

I think this is important, because to get useful data out of this, it would be best to run the compiler in a loop, each time collecting some more samples for the part we're focussed on.

Assuming we get to the bottom of this, I really like the approach of using YourKit's own config to turn the profiling on and off, rather than trying to drive it with the YourKit API. We've tried that before, but it adds unwanted complexity to our build.

@retronym
Copy link
Member

retronym commented Mar 6, 2017

I've suggested a few code style fixes in e90b7de...retronym:review/5758

@retronym retronym changed the title 2.12.x profile baseline Report per-phase JVM statistics (e.g cpu time, user time, allocated bytes) Mar 6, 2017
@mkeskells
Copy link
Contributor Author

mkeskells commented Mar 7, 2017

@retronym code style changes look good to me - can we include them in this PR, or seperate

@retronym
Copy link
Member

retronym commented Mar 7, 2017 •
edited
Loading

Yes, please incorporate my commit into this PR. While you're rebasing this, it would be good to improve the commit comment for the first commit.

If you'd prefer, I'm also happy to submit a new PR with all that done.

EDIT: I've submitted that PR in #5760, I'll close this one.

@retronym retronym closed this Mar 7, 2017
@retronym retronym mentioned this pull request Mar 7, 2017
Closed
@SethTisue SethTisue removed this from the 2.12.2 milestone Apr 10, 2017
@rorygraves rorygraves deleted the 2.12.x_profile_baseline branch May 24, 2017 20:09
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Reviewers

No reviews

Assignees

No one assigned

Labels

None yet

Projects

None yet

Milestone

No milestone

Development

Successfully merging this pull request may close these issues.

4 participants

@mkeskells @retronym @SethTisue @scala-jenkins