Review request (m): 7160728: Introduce an extra logging level for G1 logging

Fri Apr 13 15:17:52 UTC 2012

Hi Kirk,

You have good points and I think it would be great if you have time to 
make comments on the logging proposal that is coming soon.

If you look closely at the change I am proposing you will notices that 
the PrintGC and PrintGCDetails flags are still respected. These are the 
once I expect will be used in production. The new level flag that I 
introduce is intentionally made experimental to avoid that it is used in 
production. All it does now is control whether or not to print the per 
thread information. This information is sometimes very useful for 
developers, but now we are in a phase with G1 where we do a lot of 
performance work. We have been running on machines where we have up to 
200 GC worker threads. The log files become very hard to  analyze with 
all this information.

Since we know that some type of logging level will be coming soon it 
does not make sense to keep introducing special flags to control parts 
of the log output. We'd much rather start structuring the code to be 
easy to convert to a new logging framework.

Regards,
Bengt

On 2012-04-13 08:04, Kirk Pepperdine wrote:
> Hi Bengt,
>
> I look forward to the JEP and would be happy to offer comments before the document is finished.
>
> I agree that more G1 logging is needed but the style of logging proposed does not fit with the current style of logging in that the flags are descriptive of what will be logged. Unlike the logging frameworks used for general application logging, it is possible to maintain this level of readability. I also see a reasonable chance of confusion by using flags that mimic those currently employed by these generic logging frameworks. I have trouble enough getting people to turn on gc logging in production as it is and I'm very much concerned about anything that may add to the uncertainly and confusion. And, don't forget. Even though this is a temporary fix until the new logging is in play, it will be out there in production systems for some time to come. For this reason alone I would suggest sticking to the feature specific logging conventions that are currently employed. The logs maybe ugly but IMHO the flags are more than reasonable.
>
> Regards,
> Kirk
>
> On 2012-04-13, at 7:32 AM, Bengt Rutisson wrote:
>
>> Hi Kirk
>>
>> On 2012-04-13 06:55, Kirk Pepperdine wrote:
>>> Sorry to be late to the game for this one but IMHO that instead of using log levels a better implementation would be a feature by feature binary switch. Quite often I find that I'm interested in one or two entries in the log but with levels I'm going to have to eat the entire elephant to get to them. Also, how do you make a decision as to what is fine, finer and finest? GC logging is in a messy enough state as it is. I'd hate to further add to that mess by not having a well thought out deliberate strategy moving forward
>> You are absolutely right about the messy state of the GC logging and that we need the possibility to turn on and off logging at a finer granularity.
>>
>> However, there is a proposal coming soon to address the whole Hotspot logging in a more general fashion. There is active work on a JEP for that and I hope it will be published soon. I think these comments will fit well into that JEP.
>>
>> For G1 we need this extra level in the logging before that project will be finished. I fully expect most of this change to be replaced with the general framework in the near future.
>>
>> Thanks for your feedback!
>> Bengt
>>
>>> Regards,
>>> Kirk
>>>
>>> On 2012-04-13, at 2:24 AM, Tony Printezis wrote:
>>>
>>>> Bengt,
>>>>
>>>> Looks good, ship it.
>>>>
>>>> Tony
>>>>
>>>> On 04/12/2012 07:41 PM, Bengt Rutisson wrote:
>>>>> Hi all,
>>>>>
>>>>> Thanks Stefan, Jesper and Tony for looking at this!
>>>>>
>>>>> Here is an updated webrev that I hope include all of your comments:
>>>>> http://cr.openjdk.java.net/~brutisso/7160728/webrev.01/
>>>>>
>>>>> If I don't hear any complaints I'll go ahead and push this tomorrow.
>>>>>
>>>>> Thanks again for the reivews!
>>>>> Bengt

>>>>>
>>>>>
>>>>> On 2012-04-12 22:21, Bengt Rutisson wrote:
>>>>>> Tony,
>>>>>>
>>>>>> Thanks for looking at this!
>>>>>>
>>>>>> On 2012-04-12 21:00, Tony Printezis wrote:
>>>>>>> Bengt,
>>>>>>>
>>>>>>> Thanks for doing this. It looks good. Some minor comments:
>>>>>>>
>>>>>>> g1CollectedHeap.cpp
>>>>>>>
>>>>>>> 3617     TraceTime t(verbose_str, G1Log::fine()&&    !G1Log::finer(), true, gclog_or_tty);
>>>>>>>
>>>>>>> Is it worth introducing something like G1Log::fine_only() which evaluates to _level == level_fine?
>>>>>> I think this is the only place where it appears, so personally I don't really think it is worth it. I hope that we can clean this up a bit further in one of the other logging projects. Unless you object strongly, I'll leave it as it is.
>>>>>>
>>>>>>> g1CollectorPolicy.cpp
>>>>>>>
>>>>>>> 1029     if (G1Log::finest()) {
>>>>>>> 1030       buf.append("  %3.1lf", val);
>>>>>>> 1031     }
>>>>>>>
>>>>>>> Do you want to change %3.1lf to %.1lf to be consistent with what you have for the avg / min / etc? (and %3.1lf should be equivalent to %.1lf, right?)
>>>>>> Good point. Fixed.
>>>>>>
>>>>>>> g1_globals.hpp
>>>>>>>
>>>>>>> 28 #include "gc_implementation/g1/g1Log.hpp" // make sure the logging module is available to all g1 modules
>>>>>>>
>>>>>>> I would actually skip this and only include it in the appropriate files (which will all be .cpp files) to avoid getting it compiled for everything else.
>>>>>> OK. Done.
>>>>>>
>>>>>>> universe.cpp:
>>>>>>>
>>>>>>> 896     G1Log::init();
>>>>>>>
>>>>>>> I would actually initialize this in G1CollectedHeap::initialize(). Do we do any logging before that so that we need to initialize it earlier?
>>>>>> Yes, I was thinking about where to initialize it. I'll move it to G1CollectedHeap::initialize().
>>>>>>
>>>>>>> g1Log.hpp
>>>>>>>
>>>>>>>   31   typedef enum {
>>>>>>>   32     level_none,
>>>>>>>   33     level_fine,
>>>>>>>   34     level_finer,
>>>>>>>   35     level_finest
>>>>>>>   36   } LogLevel;
>>>>>>>
>>>>>>> I think the convention for enums is: LevelNone, LevelFine, LevelFiner, LevelFinest?
>>>>>> I don't think hotspot is really consistent about the naming for enums, but I'll change to your suggestion.
>>>>>>
>>>>>>> g1Log.cpp
>>>>>>>
>>>>>>> Is it worth turning G1LogLevel into lowercase to make the comparison case-insensitive?
>>>>>> I don't think we need to have them case insensitive. The command line option are case sensitive.
>>>>>>
>>>>>> Thanks again for looking at this. I'll send out an updated webrev shortly.
>>>>>>
>>>>>> Bengt
>>>>>>
>>>>>>> Tony
>>>>>>>
>>>>>>>
>>>>>>> On 04/11/2012 03:43 PM, Bengt Rutisson wrote:
>>>>>>>> Hi all,
>>>>>>>>
>>>>>>>> I'd like some review for this change:
>>>>>>>> http://cr.openjdk.java.net/~brutisso/7160728/webrev.00/
>>>>>>>>
>>>>>>>> It introduces an extra logging level for G1. This is needed to do efficient performance analysis on G1 log files. Most of this will later on be replaced by a more general framework for the whole JVM.
>>>>>>>>
>>>>>>>> This is part of the work for this CR:
>>>>>>>> 7132559: G1: enhance / cleanup the PrintGCDetails output
>>>>>>>>
>>>>>>>> Thanks,
>>>>>>>> Bengt