Detect significant events in child VM for logging

[GoogleCodeExporter]

Once we are logging the full "play-by-play", it'd be helpful to turn on 
-verbosegc and -
XX:PrintInlining (or whatever it's called) and options like that, and watch for 
these messages in the 
child processes stdout so they can be logged.   The goal for the logging is to 
really give you a clear 
picture of "what's happening", and this is a key part of that.

Original issue reported on code.google.com by kevinb@google.com on 22 Jan 2010 at 12:43

[GoogleCodeExporter]

It would be quite excellent if we can capture this kinda stuff during warmup, 
or during 
a warmup-only run on a separate VM. Spitting data out to files distracts the 
process.

Original comment by limpbizkit on 22 Jan 2010 at 8:57

[GoogleCodeExporter]

Actually, look at it this way:  the kinds of events that would cause us to 
"spit data 
out to files" are things that should not be happening during a post-warmup 
timing loop 
anyway.  We could even automatically disregard measurements that were 
interrupted by 
any such messages.  And any time we see a hotspot compilation event, we should 
disregard that measurement and all the ones that came before it!  More later.

Original comment by kevinb@google.com on 22 Jan 2010 at 7:52

[GoogleCodeExporter]

Brought this over from a dup bug:

Rather than thinking of this as "-verbose", let's think of it as an event log 
that is 
*always* recorded, and even archived in the webapp!

And when I'm viewing a result on the web app, I should be able to drill into 
that 
result to see the full "narrative" of what happened.

Log entries would include:

* hotspot recompilation events
* GC events
* starting run of N reps now
* finished run
* warmup period ending
* declaring victory and terminating
* etc.

Original comment by kevinb@google.com on 7 Jun 2010 at 5:45

[GoogleCodeExporter]

Issue 28 has been merged into this issue.

Original comment by kevinb@google.com on 7 Jun 2010 at 5:46

[GoogleCodeExporter]

Original comment by kevinb@google.com on 7 Jun 2010 at 5:55

• Added labels: Milestone-0.5

[GoogleCodeExporter]

Might as well paste in Brian Goetz's description of this:

====

To avoid compilation distortions in hand-run benchmarks, I use 
-Xx:+PrintCompilation, and print out indicators like
 - Starting warmup run
 - Ending warmup run
 - Starting measured run 1
 - Ending measured run 1

etc.  Then I visually scan the logs for compilation events inside the measure 
runs, and if they occur, I judge the run to be potentially distorted by 
compilation, and try to adjust the warmup to pull the compilation earlier.

A framework should automate this by capturing standard out and parsing messages 
that come from verbose GC, PrintCompilation, etc, and create a timeline of 
events which merges the VM-emitted events with the framework-emitted events 
(such as "starting measured run 1").  It can then use the timeline to warn the 
user about potential distortions or adaptively adjust the number of iterations 
to see if the distortion can be made to go away.

Original comment by kevinb@google.com on 11 Jun 2010 at 11:26

[GoogleCodeExporter]

Original comment by kevinb@google.com on 13 Jul 2010 at 6:42

[GoogleCodeExporter]

I think this is a great idea and we should build it.

Original comment by jessewil...@google.com on 15 Jul 2010 at 6:19

[GoogleCodeExporter]

Original comment by kevinb@google.com on 17 Jul 2010 at 3:06

[GoogleCodeExporter]

Out of these:

* hotspot recompilation events
* GC events
* starting run of N reps now
* finished run
* warmup period ending
* declaring victory and terminating
* etc.

All are done now except the first.

Results are viewable through the webapp by clicking on a measurement for a 
scenario.

It should be trivial (and I'll do it) to extend this to recompilation events as 
well.

Original comment by jsha...@google.com on 9 Aug 2010 at 11:55

[GoogleCodeExporter]

looks like this can be closed now eh?  I'll be playing with the results soon -- 
I'm excited!

Original comment by kevinb@google.com on 16 Aug 2010 at 5:50

[GoogleCodeExporter]

Original comment by kevinb@google.com on 14 Jan 2011 at 11:09

• Added labels: Milestone-1.0

[GoogleCodeExporter]

Original comment by kevinb@google.com on 14 Jan 2011 at 11:50

• Changed state: Fixed