CRR (M): 7050392: G1: Introduce flag to generate a log of the G1 ergonomic decisions

[Tony Printezis]

Hi all,

I would like a couple of code reviews for this change which consolidates 
and extends a lot of the ad-hoc ergonomic decision output we have in G1:

http://cr.openjdk.java.net/~tonyp/7050392/webrev.0/

This is the first batch of changes related to the ergonomic decision 
output and covers decisions that affect the following heuristics:

* Heap Resizing : when and why we resize the heap
* CSet Construction : how we construct the collection set, which old 
regions we add to it, when and why we stop adding old regions, etc.
* Concurrent Cycles : when we initiate a concurrent cycle and why, 
what's the state of the heap at the end of a concurrent cycle, etc.
* Partially-Young GCs : when we start and end partially-young GCs and why

This will be extended with output for two additional heuristics

* Young Gen Sizing : how we grow the young gen, why we stop allocating 
young gen regions, etc.
* Pause Prediction : details of how the pause prediction mechanism works

on a separate CR (7084525) as it requires some non-trivial code 
refactoring (7084509). I decided to split the work into three CRs to 
make the code reviews a bit more manageable.

Probably, the most controversial part of this CR are the set of macros I 
introduced in order to generate the ergo decision records. I definitely 
wanted to have a standard way to construct the records in order to 
ensure consistency in their formatting (to make any potential parsing of 
the output easier). But the problem is that different ergo decision 
records have quite different information on them which made generating 
them in a standard way quite tricky. So, this is the approach that I 
took. Let's consider the following log record, which is in the format 
generated by the new code:

8.675: [G1Ergonomics (Concurrent Cycles) request concurrent cycle 
initiation, reason: occupancy higher than threshold, occupancy: 31346656 
bytes, threshold: 30198960 bytes (45.00 %)]

The log record consists of the following:

1) 8.675 : a time stamp in the same format enabled with the 
-XX:+PrintGCTimeStamps which is always enabled
2) [G1Ergonomics ... ] : standard prefix / suffix to be able to easily 
identify such records
3) (Concurrent Cycles) : the heuristic the record corresponds to
4) request concurrent cycle initiation : a string describing the action 
the ergonomic decision took
5) reason: occupancy higher than threshold : an optional string 
describing the reason for the above action
6) occupancy / threshold : optional values that contributed to the decision

1), 2), 3), and 4) always appear on each record, 5) and 6) are optional.

I wanted each record to be printed with a single print command so that 
it's not split by concurrent output. I also wanted the format string of 
each record to be statically allocated to avoid having to stack-allocate 
char[] buffers, etc. These two requirements, and the fact that some of 
the compilers we use do not support var-arg macros, made constructing 
the macros I needed a bit ugly. Here's an example of such a macro; in 
fact it's the one that generates the above record (BTW: this is a good 
time to take your anti-nausea medication):

         ergo_verbose3(ErgoConcCycles,
                       "request concurrent cycle initiation",
                       ergo_reason_format("occupancy higher than threshold")
                       ergo_byte_format("occupancy")
                       ergo_byte_perc_format("threshold"),
                       cur_used_bytes,
                       min_used_targ, (double) 
InitiatingHeapOccupancyPercent);

The parameters are:

arg 1 : The heuristic ID.
arg 2 : The action string.
arg 3 : Concatenation of the format string, generated using the 
ergo_*_format() macros, that includes the optional parts of the record 
(reason and values).
arg 4-6 : The optional values. Given that we don't have var-arg macros, 
this takes exactly 3 extra args (which is why it's named 
ergo_verbose3()). I have separate macros for between 0 and 6 args, they 
are wrappers around a common macro, and they pass to it dummy values for 
any args that are not needed.

I'm not 100% happy with this but I can't think of a better way to do 
this. Let's go with it if it's not totally awful (or if there are no 
better alternative suggestions).

Even though there's a fair amount of changes to the code, once you get 
past the ergo_verbose*() macros and friends :-), the rest of the changes 
are reasonably straightforward and mostly self-contained. I did very 
light refactoring in a few places in order to split some code paths 
which were taken by different ergonomic decisions so that I can generate 
the appropriate output.

Tony