JEP 271: Unified GC Logging - Second pre-review

Kirk Pepperdine kirk.pepperdine at gmail.com
Thu Nov 12 17:02:28 UTC 2015


Unless you can read rust on a platter you need a program to read it… Anyways, I’m not suggesting this format be used, just too big a chasm to cross.

Regards,
Kirk

> On Nov 12, 2015, at 4:41 PM, charlie hunt <charlie.hunt at oracle.com> wrote:
> 
> If Twitter is doing it, it must be right. :-]
> 
> Also, what happens when one of their talented GC engineers or performance engineers wants to look manually at GC logs. ;-)
> 
> charlie
> 
>> On Nov 12, 2015, at 8:31 AM, Kirk Pepperdine <kirk.pepperdine at gmail.com <mailto:kirk.pepperdine at gmail.com>> wrote:
>> 
>> I should add the Twitter has moved to binary format for GC logging. This is actually my preferred format but it’s far from what anyone would consider here so…. I won’t even mention it.
>> 
>> Regards,
>> Kirk
>> 
>>> On Nov 12, 2015, at 9:56 AM, Bengt Rutisson <bengt.rutisson at oracle.com <mailto:bengt.rutisson at oracle.com>> wrote:
>>> 
>>> 
>>> 
>>> 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/67cac328/attachment.htm>


More information about the hotspot-gc-dev mailing list