Skip to content

Add a JMH profiler to record cpu time based on ThreadMxBean#61

Merged
retronym merged 3 commits intoscala:masterfrom
retronym:topic/thread-user-cpu-time
Mar 27, 2018
Merged

Add a JMH profiler to record cpu time based on ThreadMxBean#61
retronym merged 3 commits intoscala:masterfrom
retronym:topic/thread-user-cpu-time

Conversation

@retronym
Copy link
Member

No description provided.

@retronym
Copy link
Member Author

retronym commented Feb 28, 2018

Sample output of the prof basic run.

> prof hot -psource=scalap -f1 -wi 4 -i 3
[info] Running scala.bench.ScalacBenchmarkRunner HotScalacBenchmark -foe true -psource=scalap -f1 -wi 4 -i 3 -jvmArgs -Dsun.reflect.inflationThreshold=0 -jvmArgs -Xprof -prof hs_comp -prof gc -prof stack -prof hs_rt -prof scala.tools.nsc.ThreadCpuTimeProfiler -o /Users/jz/code/compiler-benchmark/target/profile-basic/jmh.log -rf json -rff /Users/jz/code/compiler-benchmark/target/profile-basic/result.json
[success] Total time: 84 s, completed 28/02/2018 9:58:38 PM
#  /Users/jz/code/compiler-benchmark/target/profile-basic/jmh.log
...
Benchmark                                                    (corpusVersion)  (extraArgs)  (resident)  (source)    Mode  Cnt          Score            Error     Units
HotScalacBenchmark.compile                                           a8c43dc                    false    scalap  sample   21       1505.655 ±        108.897     ms/op
HotScalacBenchmark.compile:compile·p0.00                             a8c43dc                    false    scalap  sample            1350.566                      ms/op
HotScalacBenchmark.compile:compile·p0.50                             a8c43dc                    false    scalap  sample            1486.881                      ms/op
HotScalacBenchmark.compile:compile·p0.90                             a8c43dc                    false    scalap  sample            1707.082                      ms/op
HotScalacBenchmark.compile:compile·p0.95                             a8c43dc                    false    scalap  sample            1850.527                      ms/op
HotScalacBenchmark.compile:compile·p0.99                             a8c43dc                    false    scalap  sample            1864.368                      ms/op
HotScalacBenchmark.compile:compile·p0.999                            a8c43dc                    false    scalap  sample            1864.368                      ms/op
HotScalacBenchmark.compile:compile·p0.9999                           a8c43dc                    false    scalap  sample            1864.368                      ms/op
HotScalacBenchmark.compile:compile·p1.00                             a8c43dc                    false    scalap  sample            1864.368                      ms/op
HotScalacBenchmark.compile:·compiler.nmethodCodeSize                 a8c43dc                    false    scalap  sample    3      62459.844                         Kb
HotScalacBenchmark.compile:·compiler.nmethodSize                     a8c43dc                    false    scalap  sample    3     131517.602                         Kb
HotScalacBenchmark.compile:·compiler.osrBytes                        a8c43dc                    false    scalap  sample    3         64.122                         Kb
HotScalacBenchmark.compile:·compiler.osrCompiles                     a8c43dc                    false    scalap  sample    3        117.000                    methods
HotScalacBenchmark.compile:·compiler.osrTime                         a8c43dc                    false    scalap  sample    3        714.851                         ms
HotScalacBenchmark.compile:·compiler.standardBytes                   a8c43dc                    false    scalap  sample    3       8078.639                         Kb
HotScalacBenchmark.compile:·compiler.standardCompiles                a8c43dc                    false    scalap  sample    3      25420.000                    methods
HotScalacBenchmark.compile:·compiler.standardTime                    a8c43dc                    false    scalap  sample    3     102095.567                         ms
HotScalacBenchmark.compile:·compiler.totalBailouts                   a8c43dc                    false    scalap  sample    3          4.000                    methods
HotScalacBenchmark.compile:·compiler.totalCompiles                   a8c43dc                    false    scalap  sample    3      25537.000                    methods
HotScalacBenchmark.compile:·compiler.totalInvalidates                a8c43dc                    false    scalap  sample    3            ≈ 0                    methods
HotScalacBenchmark.compile:·compiler.totalTime                       a8c43dc                    false    scalap  sample    3     102810.418                         ms
HotScalacBenchmark.compile:·gc.alloc.rate                            a8c43dc                    false    scalap  sample    3        314.072 ±        324.718    MB/sec
HotScalacBenchmark.compile:·gc.alloc.rate.norm                       a8c43dc                    false    scalap  sample    3  519368864.762 ±    3787778.274      B/op
HotScalacBenchmark.compile:·gc.churn.PS_Eden_Space                   a8c43dc                    false    scalap  sample    3        281.972 ±        978.741    MB/sec
HotScalacBenchmark.compile:·gc.churn.PS_Eden_Space.norm              a8c43dc                    false    scalap  sample    3  468463811.048 ± 1802457866.430      B/op
HotScalacBenchmark.compile:·gc.churn.PS_Survivor_Space               a8c43dc                    false    scalap  sample    3          1.784 ±          2.465    MB/sec
HotScalacBenchmark.compile:·gc.churn.PS_Survivor_Space.norm          a8c43dc                    false    scalap  sample    3    2957915.810 ±    5580283.630      B/op
HotScalacBenchmark.compile:·gc.count                                 a8c43dc                    false    scalap  sample    3          8.000                     counts
HotScalacBenchmark.compile:·gc.time                                  a8c43dc                    false    scalap  sample    3        231.000                         ms
HotScalacBenchmark.compile:·rt.safepointSyncTime                     a8c43dc                    false    scalap  sample    3        665.213                         ms
HotScalacBenchmark.compile:·rt.safepointTime                         a8c43dc                    false    scalap  sample    3       3206.963                         ms
HotScalacBenchmark.compile:·rt.safepoints                            a8c43dc                    false    scalap  sample    3      11816.000                     counts
HotScalacBenchmark.compile:·rt.sync.contendedLockAttempts            a8c43dc                    false    scalap  sample    3       7191.000                      locks
HotScalacBenchmark.compile:·rt.sync.fatMonitors                      a8c43dc                    false    scalap  sample    3        128.000                   monitors
HotScalacBenchmark.compile:·rt.sync.futileWakeups                    a8c43dc                    false    scalap  sample    3       4358.000                     counts
HotScalacBenchmark.compile:·rt.sync.monitorDeflations                a8c43dc                    false    scalap  sample    3        279.000                   monitors
HotScalacBenchmark.compile:·rt.sync.monitorInflations                a8c43dc                    false    scalap  sample    3        281.000                   monitors
HotScalacBenchmark.compile:·rt.sync.notifications                    a8c43dc                    false    scalap  sample    3         68.000                     counts
HotScalacBenchmark.compile:·rt.sync.parks                            a8c43dc                    false    scalap  sample    3       5241.000                     counts
HotScalacBenchmark.compile:·stack                                    a8c43dc                    false    scalap  sample                 NaN                        ---
HotScalacBenchmark.compile:·threads.cpu.time.norm                    a8c43dc                    false    scalap  sample            1421.381                      ms/op
HotScalacBenchmark.compile:·threads.user.time.norm                   a8c43dc                    false    scalap  sample            1307.333                      ms/op

@retronym
Copy link
Member Author

After we get a bit of experience with this profiler, and can convince ourselves it isn't skewing the results at all, we could turn it on in our measurement runs and add it as an extra data series to our charts.

/cc @mkeskells @rorygraves

@retronym retronym merged commit 8fe0458 into scala:master Mar 27, 2018
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant