[renamed] RFR: 8246135: Save important GC log lines and print them when dumping hs_err files

[Stefan Karlsson]

Thanks, StefanJ!

StefanK

On 2020-06-03 13:24, stefan.johansson at oracle.com wrote:
> Hi Stefan,
>
> On 2020-06-03 10:30, Stefan Karlsson wrote:
>> After further deliberations and discussions with Per, Erik and 
>> StefanJ, I'm going to make this patch more generic, and split this CR 
>> into two parts:
>>   JDK-8246135: Save important GC log lines and print them when 
>> dumping hs_err files
>>   JDK-8246404: ZGC: Use GCLogPrecious for important logging lines
>>
>> As StefanJ mentioned earlier there are a separate task for G1, 
>> Parallel, and Serial:
>>   JDK-8246272: Make use of GCLogPrecious for G1, Parallel and Serial
>>
>> Since this patch is becoming more generic than it started out as, 
>> I've done some more changes to accommodate that:
>>   https://cr.openjdk.java.net/~stefank/8246135/webrev.06
>>
>> - Moved the ZGC usages out of this patch
>> - Moved initialization out of ZGC so that all GCs can simply start to 
>> use this functionality
>> - Added a lock to allow for concurrent usage
>> - Don't print the GC Precious Log section if the GC isn't using it
>> - Added a temp buffer to simplify generation of messages
> Looks good!
>
> StefanJ
>>
>> The ZGC part has not changed and has already been reviewed:
>>   https://cr.openjdk.java.net/~stefank/8246404/webrev.01/
>>
>> Some of the stylistic changes in the patch is done to prepare for:
>>   https://cr.openjdk.java.net/~stefank/8246405/webrev.01/
>>
>> Thanks,
>> StefanK
>>
>>
>> On 2020-06-02 15:51, Stefan Karlsson wrote:
>>> Hi all,
>>>
>>> While working on getting more information when dumping early during 
>>> initialization, it became apparent that we don't print these log 
>>> lines as early as we could. In ZGC we can assert and/or fail during 
>>> the set up of the heap. I'd like to print the precious lines even 
>>> when that happens. The following patch moves the the precious line 
>>> printing out of ZCollectedHeap and into a direct call from the 
>>> VMError code. GCs that populate these lines will now automatically 
>>> get them printed.
>>>
>>> https://cr.openjdk.java.net/~stefank/8246135/webrev.04.delta
>>> https://cr.openjdk.java.net/~stefank/8246135/webrev.04
>>>
>>> Thanks,
>>> StefanK
>>>
>>> On 2020-05-29 12:23, Stefan Karlsson wrote:
>>>> Hi all,
>>>>
>>>> Please review this patch to save some of the important ZGC log 
>>>> lines and print them when dumping hs_err files.
>>>>
>>>> https://cr.openjdk.java.net/~stefank/8246135/webrev.01/
>>>> https://bugs.openjdk.java.net/browse/JDK-8246135
>>>>
>>>> The patch adds a concept of "precious" log lines. What's typically 
>>>> logged are GC initialization lines, but also error messages are 
>>>> saved. These lines are then dumped in the hs_err file if the JVM 
>>>> crashes or hits an assert. The lines can also be printed in a 
>>>> debugger to get a quick overview when debugging.
>>>>
>>>> The precious lines are always saved, but just like any other 
>>>> Unified Logging calls, only logged if the tags are enabled.
>>>>
>>>> The patch builds on the JDK-8246134 patch. The hs_err output looks 
>>>> like this:
>>>>
>>>> ZGC Precious Log:
>>>>  NUMA Support: Disabled
>>>>  CPUs: 8 total, 8 available
>>>>  Memory: 16384M
>>>>  Large Page Support: Disabled
>>>>  Medium Page Size: 32M
>>>>  Workers: 5 parallel, 1 concurrent
>>>>  Address Space Type: Contiguous/Unrestricted/Complete
>>>>  Address Space Size: 65536M x 3 = 196608M
>>>>  Min Capacity: 42M
>>>>  Initial Capacity: 256M
>>>>  Max Capacity: 4096M
>>>>  Max Reserve: 42M
>>>>  Pre-touch: Disabled
>>>>  Uncommit: Enabled
>>>>  Uncommit Delay: 300s
>>>>  Runtime Workers: 5 parallel
>>>>
>>>> ZGC Globals:
>>>>  GlobalPhase:       2 (Relocate)
>>>>  GlobalSeqNum:      1
>>>>  Offset Max:        4096G (0x0000040000000000)
>>>>  Page Size Small:   2M
>>>>  Page Size Medium:  32M
>>>>
>>>> ZGC Metadata Bits:
>>>>  Good:              0x0000100000000000
>>>>  Bad:               0x00002c0000000000
>>>>  WeakBad:           0x00000c0000000000
>>>>  Marked:            0x0000040000000000
>>>>  Remapped:          0x0000100000000000
>>>>
>>>> Heap:
>>>>  ZHeap           used 12M, capacity 256M, max capacity 4096M
>>>>  Metaspace       used 6501K, capacity 6615K, committed 6784K, 
>>>> reserved 1056768K
>>>>   class space    used 559K, capacity 588K, committed 640K, reserved 
>>>> 1048576K
>>>>
>>>> ZGC Page Table:
>>>>  Small   0x0000000000000000 0x0000000000200000 0x0000000000200000 
>>>> Allocating
>>>>  Small   0x0000000000200000 0x0000000000240000 0x0000000000400000 
>>>> Allocating
>>>>  Small   0x0000000000400000 0x0000000000600000 0x0000000000600000 
>>>> Allocating
>>>>  Small   0x0000000000600000 0x0000000000800000 0x0000000000800000 
>>>> Allocating
>>>>  Small   0x0000000000800000 0x00000000009c0000 0x0000000000a00000 
>>>> Allocating
>>>>  Small   0x0000000000a00000 0x0000000000a40000 0x0000000000c00000 
>>>> Allocating
>>>>
>>>> Thanks,
>>>> StefanK
>>>
>>