JEP 271: Unified GC Logging - Second pre-review

Vitaly Davidovich vitalyd at gmail.com
Wed Nov 11 15:20:56 UTC 2015


That was my motivation as well.  Unfortunately for Bengt, both use cases
are valid and real.

sent from my phone
On Nov 11, 2015 10:17 AM, "charlie hunt" <charlie.hunt at oracle.com> wrote:

> Hi Kirk,
>
> I was just about to say a similar thing … visualizations offer a good way
> to spot trends and other subtleties.
>
> To be quite honest, my motivation for jumping in on this thread was to
> highlight that there are many use cases where manually looking logs are
> useful, i.e. GC log information shouldn’t be tailored only for tooling. It
> should also be easily human readable too.
>
> In other words, both general uses are useful, needed, and should be
> accounted for in Bengt’s unified GC logging implementation.
>
> It is probably also worth saying that whatever the ending implementation
> looks, there will likely be someone who will not be happy with it. :-]
>
> thanks,
>
> charlie
>
> On Nov 11, 2015, at 9:09 AM, Kirk Pepperdine <kirk.pepperdine at gmail.com>
> wrote:
>
> Hi all,
>
> I think there are things that you can’t find when looking at things
> manually like subtile trends and frequencies and relationships between
> trends of different metrics. Plus, I have analytics that I can run over the
> logs that can show you things that would be hard to see otherwise. In
> addition, I did a talk at Devoxx yesterday where looking at a GC log was
> part a demo I was doing. During the demo, something interesting showed up
> that caused the GC threads to accumulate a lot of Kernel time. Without the
> analytic, I would have completely missed these events and a great
> opportunity to run off-script with something interesting and useful. There
> is no way under those conditions I’d see this interesting event. In
> addition, I just got a zip of about 20GC logs from a customer. That is a
> small zip as can get logs from systems to 100s of JVMs. The only way to get
> through this many logs in a reasonable amount of time is with tooling.
>
> Regards,
> Kirk
>
> On Nov 10, 2015, at 6:19 PM, Vitaly Davidovich <vitalyd at gmail.com> wrote:
>
> I think it's more of whether the GC log info is noise or signal.  If a
> process is GC'ing very frequently, looking at it manually doesn't strike me
> as practical -- you'll need a tool to make sense of it (i.e. each GC
> occurrence is noise).
>
> On Tue, Nov 10, 2015 at 12:16 PM, charlie hunt <charlie.hunt at oracle.com>
> wrote:
>
>>
>> On Nov 10, 2015, at 11:02 AM, Vitaly Davidovich <vitalyd at gmail.com>
>> wrote:
>>
>> I’m sorry to say but what you are saying just doesn’t correlate well with
>>> my experience. In my experience people rarely look at GC logging. That
>>> said, you are right, readability is not overly important to me however
>>> being completely unreadable wouldn’t be great either because I also open
>>> them up and read them.
>>
>>
>> I do occasionally look at GC logs manually.  The reason is because GC is
>> unexpected and/or rare event on some daemons.  I agree that on daemons
>> where GC is a frequent occurrence nobody is likely to look at it manually
>> unless they're examining a particular outlier.
>>
>>
>> I may not be the norm ... I almost always look at GC logs manually.
>>
>> And in those cases where look at GC logs via tools / visualization I
>> always end up looking at the logs to see was happening leading up to some
>> GC event of interest.
>>
>> That said ... on the one hand I agree that many folks don't read GC logs,
>> but on the other hand, for my selfish purposes, I look at them, and I'd
>> like something that's easy to read. (Put whatever definition you'd like on
>> "easy to read").
>>
>> Don't know if that helps or complicates things for Bengt?
>>
>> Charlie
>>
>> On Tue, Nov 10, 2015 at 10:51 AM, Kirk Pepperdine <
>> kirk.pepperdine at gmail.com> wrote:
>>
>>>
>>> >>>>
>>> >>>>>> [11.247s][info   ][gc,heap     ] GC#265 38912K->0K(2048K)
>>> 4096K->4096K(6144K) 68990K->73147K(131072K) 2993K->2993K(1056768K)
>>> >>> This format may be fine for machine parsing but it is not very
>>> readable to humans. Readability is an important use case,
>>> >> Trust me on this one... no one reads these things. Even when I tell
>>> attendees of my workshop to read the GC log, they still don’t. Readability
>>> might be an important an interesting use case from your POV. From mine it
>>> really isn’t. As an FYI, you should look at HP and Azul GC logs.
>>> >
>>> > I understand that readability is not important to you. But there are
>>> many other users than you and many of them depend on being able to read the
>>> GC logs in a reasonable way.
>>>
>>> I’m sorry to say but what you are saying just doesn’t correlate well
>>> with my experience. In my experience people rarely look at GC logging. That
>>> said, you are right, readability is not overly important to me however
>>> being completely unreadable wouldn’t be great either because I also open
>>> them up and read them.
>>>
>>> >
>>> >>
>>> >>> so we will need to at least add information about what the numbers
>>> map to. As I stated in a previous mail I would prefer these on separate
>>> lines, but if we want them on a single line I think the format need to be
>>> something like:
>>> >>>
>>> >>> [11.247s][info   ][gc,heap     ] GC#265 Eden: 38912K->0K(2048K),
>>> Survivor: 4096K->4096K(6144K), Old: 68990K->73147K(131072K), Metaspace:
>>> 2993K->2993K(1056768K)
>>> >>>
>>> >>> To me this is line is too long to ready quickly. In particular if I
>>> am just trying to follow how, for example, the Eden size changes over time.
>>> >> My concern is here and why I believe they should be combined is to
>>> minimize the frequency of logging.
>>> >
>>> > The frequency as in logging three lines instead of one line per GC?
>>> You would have to show me some performance numbers if you want to convince
>>> me that this would be a problem.
>>>
>>> This is a problem that you can’t see in the small. It is my experience
>>> tuning systems (sorry for the blatant hand-waving) that the way to choke a
>>> logging frame work is to have it work very frequently. The size of the
>>> message is secondary in that many small writes are far worse than fewer
>>> larger ones. For example, if you have a system that is logging to NAS on a
>>> system that is shy on network capacity, GC logging will degrade
>>> performance. Frequency in this situation hurts quite a bit. So, per GC
>>> logging, I’d agree with you 99% of the time. However it’s that 1% of the
>>> time that is important because those are the cases where you need the data
>>> and it very hard to get it when collecting it puts more pressure on the
>>> system.
>>>
>>> I find it very ironic that logging, which is intended to improve the
>>> visibility of your application, is so often a bottleneck in applications
>>> simply because the way it works isn’t visible.
>>>
>>> All said, I think I’ve offered all I can in terms of my experiences on
>>> this subject so no worries, I’ll just let you get on with it.
>>>
>>> Kind regards,
>>> Kirk
>>>
>>>
>>
>
>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://mail.openjdk.org/pipermail/hotspot-gc-dev/attachments/20151111/f5f2e93b/attachment.htm>


More information about the hotspot-gc-dev mailing list