JEP 271: Unified GC Logging - Second pre-review
Bengt Rutisson
bengt.rutisson at oracle.com
Thu Nov 12 08:56:25 UTC 2015
On 2015-11-11 16:20, Vitaly Davidovich wrote:
>
> That was my motivation as well. Unfortunately for Bengt, both use
> cases are valid and real.
>
Yes, I think both use cases are important. So, we have to find a good
balance of making the logs easily parsable for tools and at the same
time as readable as possible for humans.
Bengt
> sent from my phone
>
> On Nov 11, 2015 10:17 AM, "charlie hunt" <charlie.hunt at oracle.com
> <mailto: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 <mailto: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 <mailto: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 <mailto:charlie.hunt at oracle.com>> wrote:
>>>
>>>
>>> On Nov 10, 2015, at 11:02 AM, Vitaly Davidovich
>>> <vitalyd at gmail.com <mailto: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
>>>> <mailto: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/20151112/f2c3f0a2/attachment.htm>
More information about the hotspot-gc-dev
mailing list