RFR: 8142366: Add develop_debug and develop_trace levels to Unified Logging

Thu Nov 12 19:16:18 UTC 2015

On 11/12/15 5:52 AM, Staffan Larsen wrote:
>> On 11 nov. 2015, at 21:32, Coleen Phillimore <coleen.phillimore at oracle.com> wrote:
>>
>>
>> I agree with what Rachel has written.   Many of the runtime debug/tracing flags are not appropriate for product level logging.
> Why is that? Just because there is lots of it? Or are there other reasons you don’t want to include that logging in the product. As Bengt suggests, you can always add another tag to limit the amount of details. I’m thinking that if this logging exists and was somehow useful during development, are we sure that it will never be useful for sustaining in a product build? Why jump through hoops to disable it?

Well, much of the logging that we have in the runtime is purely 
development logging.  It would be 100% not useful to give to a 
customer.  Can you imaging giving TraceItables to a customer to try to 
find a problem?  It makes no sense.   These flags have multiple levels 
of logging, just like product level logging.

So we've gotten this question on each of the flag conversions from DEBUG 
to PRODUCT, so I'll try to summarize how the runtime is planning to use 
the Unified Logging framework.   We have about 75 potential logging 
options.  The decision graph goes like this:

1. Trace option is converted to UL in product mode at (primarily) 
debugging level, with trace level for further verbosity.   So 
default=product
2.  Evaluate whether this makes sense with 3 criteria:

          1. Does the logging cost runtime performance in testing 
whether the tag is off?
          2. Does the option cause a significant(*) increase in the size 
of  libjvm.so because #ifndef PRODUCT is removed for printing?
          3. Does the option make any sense for a customer to turn on?  
There are two subcases:
                    a. Is the logging too verbose to be useful
                    b. Could we imagine in a million years that this 
would help a customer situation

3.  If any of 1,2,3 above is yes, yes, no, then we will only convert the 
logging option in Develop mode.

I see the Develop logging options as siblings of the Product logging.   
This is why we have this change to have Develop info, debug and trace 
levels in parallel to the Product levels.

Thanks,
Coleen

>
> /Staffan
>
>> Should they not be converted?    If we can't have multiple Develop levels for TraceItables and PrintVtables, we can't convert them to UL.    It would have been nice to remove all of these command line flags and use UL tags though.
>>
>> Coleen
>>
>> On 11/11/15 3:05 PM, Rachel Protacio wrote:
>>> Hi,
>>>
>>> Thanks for the feedback. I appreciate the justification behind wanting a single develop level, but our desire for multiple levels I think comes again from letting the user have fine control over the amount of output. In particular, I am working on TraceItables and PrintVtables, which contain code that (before the change) has regular and verbose output. This would translate to "debug" and "trace" levels in the product mode, but I don't think anyone will argue that the hundreds of lines that print out about itables and vtables need to be in the product. So if we move all the code to a single develop level, the user loses the ability to distinguish between some extra information and tons of extra information. I think it would be wrong to rob them of this amount of control, when the existing non-product implementation allows them to have it. I don't think, though, that the non-product levels should be in a separate system; I think it is right for them to aggregate below the product levels. As you and Marcus pointed out, it would be confusing to have non-product and product logging appear together as if it were the same level. The develop logging is more detailed, so it should still be below. I just think we need to have multiple levels below - ones that do not need to take up space in the product release but should still allow users to control their verbosity.
>>>
>>> Does that make sense?
>>>
>>> Thanks,
>>> Rachel
>>>
>>> On 11/11/2015 2:25 PM, Bengt Rutisson wrote:
>>>> Hi all,
>>>>
>>>> I agree with Marcus here. Adding more levels below the Trace level seems odd.
>>>>
>>>> I interpret Marcus' suggestion 2) as that there would be for example a log_develop_trace() macro that does nothing in product builds and that calls log_trace() in debug builds. Similarly for info and debug.
>>>>
>>>> To me that seems like a reasonable approach. But I do see the problem that Marcus mentions. That it will be hard to distinguish develop logging from normal logging in the output.
>>>>
>>>> So far it's been enough for me with the single Develop level. Can you give an example of a use case where the different develop levels are needed?
>>>>
>>>> Thanks,
>>>> Bengt
>>>>
>>>> On 2015-11-11 15:01, Marcus Larsson wrote:
>>>>> Hi,
>>>>>
>>>>> I don't think this is the right approach for this problem.
>>>>>
>>>>> These new develop levels are introduced as even finer levels than the trace, but have names that somewhat say otherwise.
>>>>> For example, develop_info is finer than trace, but it isn't unreasonable to expect that develop_info actually shares verbosity with the regular info level.
>>>>>
>>>>>
>>>>> I see two ways to look at this:
>>>>>
>>>>> 1) develop is a level, which is so verbose/expensive that it is not possible to include it in the product (current implementation).
>>>>> The following levels are used: error, warning, info, debug, trace and develop. There is no concept of levels for the develop only logging (it IS the level).
>>>>> Selecting/distinguishing different logging on develop level is done by using tags.
>>>>>
>>>>> 2) There is no concept of a develop level, either the logging is included in product or it isn't (compare to using #ifdefs around the logging calls).
>>>>> Development-only logging is orthogonal to the regular log levels, i.e. some log_info calls should only be made in non-product builds (log_develop_info),
>>>>> but should still follow the regular log level system (as all other logging does) and use the info level.
>>>>> The following levels are used: error, warning, info, debug, trace, and convenience macros are used to strip develop-logging from non-product builds.
>>>>>
>>>>> The downside of this approach is that it becomes harder to distinguish what is logged only in non-product builds and what is always logged.
>>>>> Depending on if the build is non-product or not one can get different output for "-Xlog".
>>>>>
>>>>>
>>>>> The current proposal mixes these two approaches and adds develop "levels" that are all finer than trace, which is confusing.
>>>>>
>>>>> In my opinion, there should be no reason to require multiple levels for non-product logging. I would assume all develop level logging to be very specific, i.e. have a very specific tagset,
>>>>> and require no support for selection/separation using log levels. If it does, then I would argue for that the logging is missing some classifying log tag that could be used instead of a level.
>>>>> The logging has already been classified as verbose/expensive, why classify it further on a level scale?
>>>>>
>>>>> Thanks,
>>>>> Marcus
>>>>>
>>>>>
>>>>> On 2015-11-11 00:13, Coleen Phillimore wrote:
>>>>>> I think this looks good.   I added serviceability-dev to the mailing list.
>>>>>>
>>>>>> Coleen
>>>>>>
>>>>>> On 11/10/15 2:18 PM, Rachel Protacio wrote:
>>>>>>> Good point. I have changed Develop to DevelopInfo. I think it's better to maintain the same levels of levels on the develop side so that the logging can just shift laterally to non-product, as it were.
>>>>>>>
>>>>>>> And yes, they are specified as -Xlog:<tag>=develop_debug
>>>>>>>
>>>>>>> Updated webrev: http://cr.openjdk.java.net/~rprotacio/8142366.01/
>>>>>>> I re-tested with logging jtreg tests and ExecuteInternalVMTests test, and for anyone who was curious (namely Max who had the good idea for me to check), the debug levels do correctly "nest" with more verbose ones printing out the less verbose and product mode logging as well.
>>>>>>>
>>>>>>> Thanks,
>>>>>>> Rachel
>>>>>>>
>>>>>>> On 11/9/2015 6:05 PM, Coleen Phillimore wrote:
>>>>>>>> Hi Rachel,
>>>>>>>>
>>>>>>>> I sort of thought DevelopDebug would replace plain Develop, and DevelopTrace would be additional lower level.   Maybe plain Develop should be DevelopInfo then?
>>>>>>>>
>>>>>>>> Another question - how do you specify these levels?  Is it -Xlog:itables=develop_debug ?
>>>>>>>>
>>>>>>>> Thanks,
>>>>>>>> Coleen
>>>>>>>>
>>>>>>>> On 11/9/15 5:55 PM, Rachel Protacio wrote:
>>>>>>>>> Hello,
>>>>>>>>>
>>>>>>>>> Please see my small changeset to add two develop levels to UL.
>>>>>>>>>
>>>>>>>>> Summary: This adds develop (that is, non-product) logging levels to the Unified Logging framework in order to support performance, footprint, and usefulness-of-output considerations while maintaining the ability for the user to specify levels of verbosity, i.e. default, "debug," and "trace" levels.
>>>>>>>>> Open webrev: http://cr.openjdk.java.net/~rprotacio/8142366/
>>>>>>>>> Bug: https://bugs.openjdk.java.net/browse/JDK-8142366
>>>>>>>>>
>>>>>>>>> I tested the added levels locally with sample log messages to ensure proper functioning. When I convert future tags to logging with these levels, those tags will have their own tests and inherently exercise the added levels.
>>>>>>>>>
>>>>>>>>> Thank you,
>>>>>>>>> Rachel