Hotspot: GC "logs" from hell (was:FR(S): 8010738: G1: Output for full GCs with +PrintGCDetails should contain perm gen size/meta data change info)

[Bernd Eckenfels]

Please please please add a event based (ring buffer, single threaded writer) sane, documented and version controlled log format which also contains relevant information (without obscure diagnostic switches which sprinkle in unparseable text lines).

J9 is much ahead in that respect (and the fact that all those jrockit features are hidden and locked away does not make anything bettet)

Nearly ever 5th update breaks the log format and "parsers" are more heuristics than anything else.

Bernd (sorry for ranting)

-- 
http://itblog.eckenfels.net

Am 15.05.2013 um 21:33 schrieb Jon Masamitsu <jon.masamitsu at oracle.com>:

> John and I talked about it.  I had not known that with perm the information
> printed was (used, capacity, reserved).  At one point I had been printing
> all 4 for metaspace and breaking GC parsers along the way.  What seems
> like the right thing?
> 
> Jon
> 
> On 5/15/2013 10:28 AM, John Cuthbertson wrote:
>> Hi Ramki,
>> 
>> Sorry for the late response. The bug will take a couple of days before it's visible.
>> 
>> I didn't realize it was a bug. My impression was that you had to keep track of how the values change between GCs because I can see how all three values (used, capacity, reserved) would be useful.
>> 
>> JohnC
>> 
>> On 5/14/2013 11:40 PM, Srinivas Ramakrishna wrote:
>>> ah, thanks Jon! (i am guessing the CR will become visible eventually
>>> on bugs.sun.com? Or should I be looking elsewhere?)
>>> 
>>> On Tue, May 14, 2013 at 10:23 AM, Jon Masamitsu
>>> <jon.masamitsu at oracle.com> wrote:
>>>> On 5/13/13 5:40 PM, Srinivas Ramakrishna wrote:
>>>>> Hi John --
>>>>> 
>>>>> On Mon, May 6, 2013 at 3:23 PM, John Cuthbertson
>>>>> <john.cuthbertson at oracle.com> wrote:
>>>>> 
>>>>>>> 4.896: [Full GC (Allocation Failure) 512M->343M(512M), 4.3640117 secs]
>>>>>>>     [Eden: 0.0B(25.0M)->0.0B(97.0M) Survivors: 0.0B->0.0B Heap:
>>>>>>> 512.0M(512.0M)->343.3M(512.0M)], [Metaspace: 1611K->2433K(6448K)]
>>>>>>>   [Times: user=5.13 sys=0.15, real=4.36 secs]
>>>>>> 
>>>>>> The information that gets printed mirrors that of the other collectors.
>>>>>> Here's parallel GC:
>>>>>> 
>>>>>>> 33.245: [Full GC (Ergonomics) [PSYoungGen: 133632K->3423K(144640K)]
>>>>>>> [ParOldGen: 348158K->348158K(348160K)] 481790K->351581K(492800K),
>>>>>>> [Metaspace: 1612K->2433K(6448K)], 2.5788089 secs] [Times: user=9.96
>>>>>>> sys=0.00, real=2.58 secs]
>>>>>> 
>>>>>> The information that's printed is the amount of metaspace used before the
>>>>>> GC, the capacity, and the amount of reserved space.
>>>>>> 
>>>>> Do you know why the "used after" for the metadataspace increased after
>>>>> the full gc?
>>>>> Is that normal, common, rare or abnormal ? :-)
>>>> 
>>>> I think that is a bug.  The "capacity" should be "used" after GC .
>>>> 
>>>> CR is 8014546.
>>>> 
>>>> Thanks.
>>>> 
>>>> Jon
>>>> 
>>>> Jon
>>>> 
>>>>> thanks John!
>>>>> -- ramki
>>>> 
>> 
>