JEP 158: Unified JVM logging

Wed Aug 15 08:51:59 UTC 2012

I'll only add to this that an option to provide a Human Readable
format out of the box would be desirable, but not as a default.

On 15 August 2012 09:44, Kirk Pepperdine <kirk at kodewerk.com> 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.
>
> 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. 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. In the 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). 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.
>
> I'll leave it at this for now.
>
> -- Kirk
>
> On 2012-08-14, at 12:17 PM, Dmitry Samersoff <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> 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>> 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 ...
>
>
>