JEP 158: Unified JVM logging

Dmitry Samersoff Dmitry.Samersoff at oracle.com
Wed Aug 15 14:19:47 UTC 2012


Kirk,

Please see below.

** Staffan, please correct me if I misunderstood something.

On 2012-08-15 12:44, Kirk Pepperdine wrote:
> Hi Dmitry,
> 
> Lets start with this.
> 
>   * Common logging command-line options for all components
>   * Logging is performed at different levels: error, warning, info,
>     debug, trace
>   * Logging messages are in human-readable plain text
> 
> 
> IMHO, these current set of goals are based on the assumptions that all
> component is hierarchical in nature and that they will log the same way
> without the possibility of binary dumps. I would argue these assumptions
> over-reach and preclude certain types of logging that take place in the
> JVM today.

Components should be independent.

  With plain tag systems we for sure end up with the same tags in
different areas and messed log in result.

Treat categories as namespaces rather than true hierarchy.

> The current system of command-line (experimental) options follow a
> format that is quite consistent. The options provide semantic meaning as
> to what will be logged. This semantic meaning is lost when we reduce
> everything to the level of error, warning, info, debug and trace. 

I guess Levels are independent to categories. i.e. I think

Log:info,gc,younggen should be possible.

Levels - warning, info etc primary intended to indicate production
system impact caused by logging.

debug should never used in production.
info is ok for production but has some performance impact
warning has no performance impact

etc.

> It's
> sets up arbitrary categories in which developers will be left to decide
> what level a particular activity should be logged at. To make this real
> I'll use the -XX:+PrintTenuringDistribution flag as an example. When I
> set that flag it's very clear what's to be logged. My question is,
> should this be logged at the info level? How about debug? Maybe trace?
> And if I set those levels, what else comes along for the ride? IOWs, if
> I attempt to keep the same model of GC logging, we'd need different
> levels. If we need different levels then we're about to violate the
> first goal.
> 
> What this example suggests is that gc logging would be better served by
> using categories (or subjects if we can take something from the pub/sub
> metaphor) or tags or labels or what ever you want to call them. Using
> tags, I can create a system of levels using error, warning, info, debug,
> and trace if that fits how I'm setting up logging. But from levels it's
> difficult to implement things using categories. This is a case where the
> one of the non-goals should be, we shouldn't prevent people from
> structuring their logs as they see best fits the component they are
> instrumenting.
> 
> The non-goals that should be reconsidered is to force human-readability.
> I would argue that this is again over-reaching in that properly
> structured log files should almost *never* be read by a human.


Human readable means that human can use grep to check
for (e.g) error presence. It doesn't mean that people would load logs to
theirs iPADs and read with family at the evening.

Lots of big customers uses dedicated log servers and often this log
servers don't have java. (e.g. in the past I used to use OpenBSD or
FreeBSD for all infrastructure tasks).

We shouldn't require all admins have special decoding tool installed
on all machines they works with.

> In thee 
> cases why force an unnecessary requirement. I say this because I've run
> into a number of applications where logging was the primary bottleneck.
> In those cases there were two primary problems, one was bulk and the
> other was threading (lock contention which I shan't address here).

I'm no ready to talk about treading.

But IMHO, bulk should be beaten on other levels:

   From separate log servers to good piece of software to analyze raw
logs and store important counters only. Also we should reduce *needs* of
logging.


> Now
> while trying to solve the problem of bulkiness and lock contention might
> be considered a premature optimization at this stage and I certainty
> wouldn't disagree, I would not like to see designs or specifications
> that would naturally preclude some very obvious solutions. One of the
> solutions to bulk is to use a more compact format be some form of
> binary. That option has been taken away for what I would call an
> ideological requirement. There is no technical reason why I shouldn't be
> able to log in binary other than connivence. In addition, you don't know
> what else is happening on the system (disk??) you're logging to so it
> behoves you to be as light as possible.

-Dmitry


> 
> I'll leave it at this for now.
> 
> -- Kirk
> 
> On 2012-08-14, at 12:17 PM, Dmitry Samersoff
> <Dmitry.Samersoff at oracle.com <mailto:Dmitry.Samersoff at oracle.com>> wrote:
> 
>> Kirk,
>>
>>> However I do have very serious concerns about this JEP in that it
>>> doesn't fix the problems that exist in current logging frameworks,
>>> it only mimics them.
>>
>>> http://openjdk.java.net/jeps/158
>>
>> Any comments is much appreciated.
>>
>> Personally, I think that log rotation is out of scope and responsibility
>> of JVM.
>>
>> -Dmitry
>>
>>
>> On 2012-08-14 13:26, Kirk Pepperdine wrote:
>>> Hi Yasumasa,
>>>
>>> I'm not sure that log file rotation is a part of this JEP.
>>> However I do have very serious concerns about this JEP in that it
>>> doesn't fix the problems that exist in current logging frameworks, it
>>> only mimics them.
>>>
>>> Regards,
>>> Kirk
>>>
>>> On 2012-08-14, at 11:20 AM, Yasumasa Suenaga
>>> <suenaga.yasumasa at lab.ntt.co.jp
>>> <mailto:suenaga.yasumasa at lab.ntt.co.jp>> wrote:
>>>
>>>> Hi Staffan,
>>>>
>>>> May I ask you 2 questions about this JEP?
>>>>
>>>> 1. One of goals of this JEP is defined as following:
>>>>     "File rotation of log files by size (similar to what is
>>>> available for GC logs today)"
>>>>   My patch realizes log rotation by external trigger.
>>>>   7090324 is included in this JEP?
>>>>   (Is 7090324 included in "Logging can be configured dynamically at
>>>> runtime via jcmd or MBeans" ? )
>>>>
>>>> 2. I've posted a patch for "6950794: Make the GC log file name
>>>> parameterized" .
>>>>     http://mail.openjdk.java.net/pipermail/hotspot-gc-dev/2012-July/004758.html
>>>>   Could you include this RFE in this JEP?
>>>>   If we use log rotation, I think that name of logs is very
>>>> important for log management.
>>>>
>>>>
>>>> Thanks,
>>>>
>>>> Yasumasa
>>>>
>>>>
>>>> On 2012/08/14 16:50, Staffan Larsen wrote:
>>>>> Hi Yasumasa,
>>>>>
>>>>> This work should be done in the context of the Unified Logging JEP
>>>>> [1]. Unfortunately, that work has not yet started due to resource
>>>>> constraints. Comments on the proposal are welcome.
>>>>>
>>>>> [1] http://openjdk.java.net/jeps/158
>>>>>
>>>>> /Staffan
>>>>>
>>>>> On 31 jul 2012, at 12:45, Yasumasa Suenaga
>>>>> <suenaga.yasumasa at lab.ntt.co.jp
>>>>> <mailto:suenaga.yasumasa at lab.ntt.co.jp>
>>>>> <mailto:suenaga.yasumasa at lab.ntt.co.jp>> wrote:
>>>>>
>>>>>> Hi,
>>>>>>
>>>>>> I've posted a patch for gc log rotation via jinfo tool last year.
>>>>>> Then I received an email that essence of my patch will be
>>>>>> implemented as
>>>>>> "subcommands" of jcmd.
>>>>>>
>>>>>> Now, jcmd is provided by OpenJDK. However, current jcmd does not
>>>>>> seem to
>>>>>> implement function of gclog rotation.
>>>>>>
>>>>>> Will this RFE be implemented?
>>>>>>
>>>>>> I need to rotate gclog which is synchronized with signal, cron,
>>>>>> etc... on Linux.
>>>>>> So, if this RFE is not implemented for a while, I would like to
>>>>>> contribute
>>>>>> patch for jcmd.
>>>>>>
>>>>>>
>>>>>> Regards,
>>>>>>
>>>>>> Yasumasa
>>>>>>
>>>>>>
>>>>>> On 2011/09/29 21:15, James Melvin wrote:
>>>>>>> Hi Yasumasa,
>>>>>>>
>>>>>>> Thanks very much for your OpenJDK contribution! As part of the
>>>>>>> effort to
>>>>>>> port JRockit features to HotSpot, we plan to introduce a consolidated
>>>>>>> commandline serviceability tool (jcmd) to potentially replace many of
>>>>>>> the existing tools in the bin directory, such as jmap, jstack,
>>>>>>> jinfo and
>>>>>>> others. Over the next few update releases, we plan to add several
>>>>>>> jcmd
>>>>>>> *subcommands* instead to accomplish specific tasks or affect the
>>>>>>> running
>>>>>>> JVM instance. We'd like to use the essence of your contribution
>>>>>>> in one
>>>>>>> of the jcmd subcommands (instead of extending jinfo) to ask the
>>>>>>> JVM to
>>>>>>> begin rotating GC logs. We hope you find this attractive and hope you
>>>>>>> will help review and perfect the change.
>>>>>>>
>>>>>>> Thanks,
>>>>>>>
>>>>>>> Jim Melvin
>>>>>>> Sr. Engineering Manager
>>>>>>> Oracle
>>>>>>>
>>>>>>>
>>>>>>>
>>>>>>> On 9/26/11 6:38 AM, Yasumasa Suenaga wrote:
>>>>>>>> (I've changed subject of this email to new RFE.)
>>>>>>>>
>>>>>>>> This RFE is enhancement of current gclog implementation.
>>>>>>>> So, I'd like to discuss about rotating gclog.
>>>>>>>>
>>>>>>>> My customers need gclog rotation which is invoked by external
>>>>>>>> trigger.
>>>>>>>> So I've requested this RFE and made a patch.
>>>>>>>>
>>>>>>>>
>>>>>>>> In many case on Linux, logfile is rotated by signal (e.g. SIGHUP) .
>>>>>>>> The aim of this RFE is to synchronize gclog and the other logs.
>>>>>>>>
>>>>>>>>
>>>>>>>> Thanks,
>>>>>>>>
>>>>>>>> Yasumasa
>>>>>>>>
>>>>>>>> (2011/09/22 20:55), Rainer Jung wrote:
>>>>>>>>> On 22.09.2011 13:20, Dmitry Samersoff wrote:
>>>>>>>>>>
>>>>>>>>>> Yasumasa,
>>>>>>>>>>
>>>>>>>>>> On 2011-09-22 04:47, Yasumasa Suenaga wrote:
>>>>>>>>>>> If we can think Java on Linux and Solaris only, syslog is best
>>>>>>>>>>> solution.
>>>>>>>>>>> However, Windows usually doesn't have syslog.
>>>>>>>>>>>
>>>>>>>>>>> So, I think that gclog is needed for logging GC stats with
>>>>>>>>>>> platform
>>>>>>>>>>> independent in realtime.
>>>>>>>>>>
>>>>>>>>>> Windows has it's own logging API as reach as syslog is or ever
>>>>>>>>>> better
>>>>>>>>>> as well as numerous syslog implementations.
>>>>>>>>>>
>>>>>>>>>> Native windows logging API was completely redesigned for
>>>>>>>>>> Windows 2008
>>>>>>>>>> server and now it allows for developers to send a structured
>>>>>>>>>> events from
>>>>>>>>>> theirs application.
>>>>>>>>>
>>>>>>>>> AFAIK log rotation for loggc is already implemented though not
>>>>>>>>> necessarily yet released. The change discussed here is about
>>>>>>>>> supporting
>>>>>>>>> an externally generated rotation trigger, e.g. via a signal,
>>>>>>>>> instead of
>>>>>>>>> only rotating by size or time via a startup parameter.
>>>>>>>>>
>>>>>>>>> If you want support for syslog or Windows APIs included, it
>>>>>>>>> would be
>>>>>>>>> best to start a new discussion.
>>>>>>>>>
>>>>>>>>> A GC log for an application under load might easily produce a
>>>>>>>>> block of
>>>>>>>>> about 1.5 KB size every few seconds. I seriously doubt, that
>>>>>>>>> the need
>>>>>>>>> for log file rotation can be argued away by referring to syslog or
>>>>>>>>> Windows log API as the correct solution.
>>>>>>>>>
>>>>>>>>> The messages are not really line formatted, the format can vary
>>>>>>>>> a lot
>>>>>>>>> (depending on the excat XX switches), the traffic can be quite
>>>>>>>>> high and
>>>>>>>>> AFAIK the JVM writes it synchronously, so there must be
>>>>>>>>> absolutely no
>>>>>>>>> risk in writing it out with very little latency. In addition, for
>>>>>>>>> analysis, you wouldn't want to look at each event individually, but
>>>>>>>>> instead process the whole file through a script or tool, which
>>>>>>>>> should
>>>>>>>>> not depend on the output specifics of a platform specific log
>>>>>>>>> apparatus.
>>>>>>>>>
>>>>>>>>> Regards,
>>>>>>>>>
>>>>>>>>> Rainer
>>>>>>>>>
>>>>>>>>
>>>>>>
>>>>>
>>>>
>>>
>>
>>
>> -- 
>> Dmitry Samersoff
>> Java Hotspot development team, SPB04
>> * There will come soft rains ...
>>
>>
> 


-- 
Dmitry Samersoff
Java Hotspot development team, SPB04
* There will come soft rains ...





More information about the hotspot-gc-dev mailing list