RFR: JDK-8152300: Convert G1_ALLOC_REGION_TRACING to unified logging
Bengt Rutisson
bengt.rutisson at oracle.com
Mon Mar 21 13:40:10 UTC 2016
Hi all,
Could I have a couple of reviews for this change?
http://cr.openjdk.java.net/~brutisso/8152300/webrev.00/
https://bugs.openjdk.java.net/browse/JDK-8152300
Currently there is a define called G1_ALLOC_REGION_TRACING in the G1
code. It respresents two levels of logging in non-product builds.
We should use the unified logging framework for this logging instead.
The proposed patch converts the two levels of logging guarded by
G1_ALLOC_REGION_TRACING to debug and trace level logging at develop
level. This means that the logging is not available in product builds.
The call to the trace() method is now guarded by ifndef PRODUCT to make
sure we don't have any regressions in the production code.
I am not convinced the logic inside the trace method is completely
correct. But it is the same as the old logging. Maybe now that the
logging is easier to find someone will take the time to use it and see
if it logs the relevant information. This patch merely converts the old
logging to use the unified logging framework.
An unusual part of this logging is that you will get either the debug
or the trace logging. Normally I have tried to avoid that type of
situation and instead log one line at debug and another at trace.
However, since I wanted to keep the format intact with the old version I
opted for this solution now.
Below are some examples.
Thanks,
Bengt
Old G1_ALLOC_REGION_TRACING=2 logging:
[3,135s][info][gc] GC(4) Pause Young (G1 Evacuation Pause) 16M->17M(64M)
(3,000s, 3,135s) 135,927ms
[Mutator Alloc Region] 0 DUMMY : alloc failed min 256 desired 256
[Mutator Alloc Region] 0 DUMMY : retiring
[Mutator Alloc Region] 0 DUMMY : retired
[Mutator Alloc Region] 0 DUMMY : attempting region allocation
[Mutator Alloc Region] 0 DUMMY : update
[Mutator Alloc Region] 1
63:(E)[0x00000000fff00000,0x00000000fff00800,0x0000000100000000] : updated
[Mutator Alloc Region] 1
63:(E)[0x00000000fff00000,0x00000000fff00800,0x0000000100000000] :
region allocation successful
[Mutator Alloc Region] 1
63:(E)[0x00000000fff00000,0x00000000fff00800,0x0000000100000000] : alloc
locked (second attempt) min 256 desired 256 actual 256 0x00000000fff00000
[Mutator Alloc Region] 1
63:(E)[0x00000000fff00000,0x00000000fff0a890,0x0000000100000000] : alloc
min 5138 desired 5138 actual 5138 0x00000000fff00800
[Mutator Alloc Region] 1
63:(E)[0x00000000fff00000,0x00000000fff14920,0x0000000100000000] : alloc
min 5138 desired 5138 actual 5138 0x00000000fff0a890
[Mutator Alloc Region] 1
63:(E)[0x00000000fff00000,0x00000000fff1e9b0,0x0000000100000000] : alloc
min 5138 desired 5138 actual 5138 0x00000000fff14920
[Mutator Alloc Region] 1
63:(E)[0x00000000fff00000,0x00000000fff28a40,0x0000000100000000] : alloc
min 5138 desired 5138 actual 5138 0x00000000fff1e9b0
[Mutator Alloc Region] 1
63:(E)[0x00000000fff00000,0x00000000fff32ad0,0x0000000100000000] : alloc
min 5138 desired 5138 actual 5138 0x00000000fff28a40
[Mutator Alloc Region] 1
63:(E)[0x00000000fff00000,0x00000000fff3cb60,0x0000000100000000] : alloc
min 5138 desired 5138 actual 5138 0x00000000fff32ad0
[Mut[2,005s][info][gc] GC(38) Pause Young (G1 Evacuation Pause)
62M->61M(64M) (1,994s, 2,005s) 11,055ms
[Mutator Alloc Region] 0 DUMMY : alloc failed
[Mutator Alloc Region] 0 DUMMY : retiring
[Mutator Alloc Region] 0 DUMMY : retired
[Mutator Alloc Region] 0 DUMMY : attempting region allocation
[Mutator Alloc Region] 0 DUMMY : update
[Mutator Alloc Region] 1
63:(E)[0x00000000fff00000,0x00000000fff00800,0x0000000100000000] : updated
[Mutator Alloc Region] 1
63:(E)[0x00000000fff00000,0x00000000fff00800,0x0000000100000000] :
region allocation successful
[Mutator Alloc Region] 1
63:(E)[0x00000000fff00000,0x0000000100000000,0x0000000100000000] : alloc
failed
[Mutator Alloc Region] 1
63:(E)[0x00000000fff00000,0x0000000100000000,0x0000000100000000] : alloc
failed
[Mutator Alloc Region] 1
63:(E)[0x00000000fff00000,0x0000000100000000,0x0000000100000000] : retiring
[Mutator Alloc Region] 1 DUMMY : retired
[Mutator Alloc Region] 1 DUMMY : attempting region allocation
[Mutator Alloc Region] 1 DUMMY : update
[Mutator Alloc Region] 2
62:(E)[0x00000000ffe00000,0x00000000ffe00800,0x00000000fff00000] : updated
[Mutator Alloc Region] 2
62:(E)[0x00000000ffe00000,0x00000000ffe00800,0x00000000fff00000] :
region allocation successful
[Mutator Alloc Region] 2
62:(E)[0x00000000ffe00000,0x00000000fff00000,0x00000000fff00000] : alloc
failed
[Mutator Alloc Region] 2
62:(E)[0x00000000ffe00000,0x00000000fff00000,0x00000000fff00000] : alloc
failed
[Mutator Alloc Region] 2
62:(E)[0x00000000ffe00000,0x00000000fff00000,0x00000000fff00000] : retiring
[Mutator Alloc Region] 2 DUMMY : retired
[Mutator Alloc Region] 2 DUMMY : attempting region allocation
[Mutator Alloc Region] 2 DUMMY : region allocation failed
[Mutator Alloc Region] 2 DUMMY : alloc locked failed
[Mutator Alloc Region] 2 DUMMY : alloc failed
[Mutator Alloc Region] 2 DUMMY : retiring
[Mutator Alloc Region] 2 DUMMY : retired
[Mutator Alloc Region] 2 DUMMY : attempting region allocation
[Mutator Alloc Region] 2 DUMMY : region allocation failed
[Mutator Alloc Region] 2 DUMMY : alloc locked failed
[Mutator Alloc Region] 2 DUMMY : releasing
[Mutator Alloc Region] 2 DUMMY : retiring
[Mutator Alloc Region] 2 DUMMY : retired
[Mutator Alloc Region] 2 NULL : released
[Survivor GC Alloc Region] 1 NULL : initializing
[Survivor GC Alloc Region] 0 DUMMY : initialized
ator Alloc Region] 1
63:(E)[0x00000000fff00000,0x00000000fff46bf0,0x0000000100000000] : alloc
min 5138 desired 5138 actual 5138 0x00000000fff3cb60
[Mutator Alloc Region] 1
63:(E)[0x00000000fff00000,0x00000000fff50c80,0x0000000100000000] : alloc
min 5138 desired 5138 actual 5138 0x00000000fff46bf0
[Mutator Alloc Region] 1
63:(E)[0x00000000fff00000,0x00000000fff5ad10,0x0000000100000000] : alloc
min 5138 desired 5138 actual 5138 0x00000000fff50c80
[Mutator Alloc Region] 1
63:(E)[0x00000000fff00000,0x00000000fff64da0,0x0000000100000000] : alloc
min 5138 desired 5138 actual 5138 0x00000000fff5ad10
[Mutator Alloc Region] 1
63:(E)[0x00000000fff00000,0x00000000fff6ee30,0x0000000100000000] : alloc
min 5138 desired 5138 actual 5138 0x00000000fff64da0
[Mutator Alloc Region] 1
63:(E)[0x00000000fff00000,0x00000000fff78ec0,0x0000000100000000] : alloc
min 5138 desired 5138 actual 5138 0x00000000fff6ee30
[Mutator Alloc Region] 1
63:(E)[0x00000000fff00000,0x00000000fff82f50,0x0000000100000000] : alloc
min 5138 desired 5138 actual 5138 0x00000000fff78ec0
[Mutator Alloc Region] 1
63:(E)[0x00000000fff00000,0x00000000fff8cfe0,0x0000000100000000] : alloc
min 5138 desired 5138 actual 5138 0x00000000fff82f50
[Mutator Alloc Region] 1
63:(E)[0x00000000fff00000,0x00000000fff97070,0x0000000100000000] : alloc
min 5138 desired 5138 actual 5138 0x00000000fff8cfe0
[Mutator Alloc Region] 1
63:(E)[0x00000000fff00000,0x00000000fffa1100,0x0000000100000000] : alloc
min 5138 desired 5138 actual 5138 0x00000000fff97070
[Mutator Alloc Region] 1
63:(E)[0x00000000fff00000,0x00000000fffab190,0x0000000100000000] : alloc
min 5138 desired 5138 actual 5138 0x00000000fffa1100
[Mutator Alloc Region] 1
63:(E)[0x00000000fff00000,0x00000000fffb5220,0x0000000100000000] : alloc
min 5138 desired 5138 actual 5138 0x00000000fffab190
[Mutator Alloc Region] 1
63:(E)[0x00000000fff00000,0x00000000fffbf2b0,0x0000000100000000] : alloc
min 5138 desired 5138 actual 5138 0x00000000fffb5220
[Mutator Alloc Region] 1
63:(E)[0x00000000fff00000,0x00000000fffc9340,0x0000000100000000] : alloc
min 5138 desired 5138 actual 5138 0x00000000fffbf2b0
[Mutator Alloc Region] 1
63:(E)[0x00000000fff00000,0x00000000fffd33d0,0x0000000100000000] : alloc
min 5138 desired 5138 actual 5138 0x00000000fffc9340
[Mutator Alloc Region] 1
63:(E)[0x00000000fff00000,0x00000000fffdd460,0x0000000100000000] : alloc
min 5138 desired 5138 actual 5138 0x00000000fffd33d0
[Mutator Alloc Region] 1
63:(E)[0x00000000fff00000,0x00000000fffe74f0,0x0000000100000000] : alloc
min 5138 desired 5138 actual 5138 0x00000000fffdd460
[Mutator Alloc Region] 1
63:(E)[0x00000000fff00000,0x00000000ffff1580,0x0000000100000000] : alloc
min 5138 desired 5138 actual 5138 0x00000000fffe74f0
[Mutator Alloc Region] 1
63:(E)[0x00000000fff00000,0x00000000ffffb610,0x0000000100000000] : alloc
min 5138 desired 5138 actual 5138 0x00000000ffff1580
[Mutator Alloc Region] 1
63:(E)[0x00000000fff00000,0x0000000100000000,0x0000000100000000] : alloc
min 2366 desired 2366 actual 2366 0x00000000ffffb610
[Mutator Alloc Region] 1
63:(E)[0x00000000fff00000,0x0000000100000000,0x0000000100000000] : alloc
failed min 256 desired 256
[Mutator Alloc Region] 1
63:(E)[0x00000000fff00000,0x0000000100000000,0x0000000100000000] : alloc
failed min 256 desired 256
[Mutator Alloc Region] 1
63:(E)[0x00000000fff00000,0x0000000100000000,0x0000000100000000] : retiring
[Mutator Alloc Region] 1 DUMMY : retired
[Mutator Alloc Region] 1 DUMMY : attempting region allocation
[Mutator Alloc Region] 1 DUMMY : update
[Mutator Alloc Region] 2
62:(E)[0x00000000ffe00000,0x00000000ffe00800,0x00000000fff00000] : updated
[Mutator Alloc Region] 2
62:(E)[0x00000000ffe00000,0x00000000ffe00800,0x00000000fff00000] :
region allocation successful
[Mutator Alloc Region] 2
62:(E)[0x00000000ffe00000,0x00000000ffe00800,0x00000000fff00000] : alloc
locked (second attempt) min 256 desired 256 actual 256 0x00000000ffe00000
[Mutator Alloc Region] 2
62:(E)[0x00000000ffe00000,0x00000000ffe0a890,0x00000000fff00000] : alloc
min 5138 desired 5138 actual 5138 0x00000000ffe00800
Old G1_ALLOC_REGION_TRACING=1 logging:
[Mutator Alloc Region] 0 DUMMY : alloc failed
[Mutator Alloc Region] 0 DUMMY : retiring
[Mutator Alloc Region] 0 DUMMY : retired
[Mutator Alloc Region] 0 DUMMY : attempting region allocation
[Mutator Alloc Region] 0 DUMMY : update
[Mutator Alloc Region] 1
63:(E)[0x00000000fff00000,0x00000000fff00800,0x0000000100000000] : updated
[Mutator Alloc Region] 1
63:(E)[0x00000000fff00000,0x00000000fff00800,0x0000000100000000] :
region allocation successful
[Mutator Alloc Region] 1
63:(E)[0x00000000fff00000,0x0000000100000000,0x0000000100000000] : alloc
failed
[Mutator Alloc Region] 1
63:(E)[0x00000000fff00000,0x0000000100000000,0x0000000100000000] : alloc
failed
[Mutator Alloc Region] 1
63:(E)[0x00000000fff00000,0x0000000100000000,0x0000000100000000] : retiring
[Mutator Alloc Region] 1 DUMMY : retired
[Mutator Alloc Region] 1 DUMMY : attempting region allocation
[Mutator Alloc Region] 1 DUMMY : update
[Mutator Alloc Region] 2
62:(E)[0x00000000ffe00000,0x00000000ffe00800,0x00000000fff00000] : updated
[Mutator Alloc Region] 2
62:(E)[0x00000000ffe00000,0x00000000ffe00800,0x00000000fff00000] :
region allocation successful
[Mutator Alloc Region] 2
62:(E)[0x00000000ffe00000,0x00000000fff00000,0x00000000fff00000] : alloc
failed
[Mutator Alloc Region] 2
62:(E)[0x00000000ffe00000,0x00000000fff00000,0x00000000fff00000] : alloc
failed
[Mutator Alloc Region] 2
62:(E)[0x00000000ffe00000,0x00000000fff00000,0x00000000fff00000] : retiring
[Mutator Alloc Region] 2 DUMMY : retired
[Mutator Alloc Region] 2 DUMMY : attempting region allocation
[Mutator Alloc Region] 2 DUMMY : region allocation failed
[Mutator Alloc Region] 2 DUMMY : alloc locked failed
[Mutator Alloc Region] 2 DUMMY : alloc failed
[Mutator Alloc Region] 2 DUMMY : retiring
[Mutator Alloc Region] 2 DUMMY : retired
[Mutator Alloc Region] 2 DUMMY : attempting region allocation
[Mutator Alloc Region] 2 DUMMY : region allocation failed
[Mutator Alloc Region] 2 DUMMY : alloc locked failed
[Mutator Alloc Region] 2 DUMMY : releasing
[Mutator Alloc Region] 2 DUMMY : retiring
[Mutator Alloc Region] 2 DUMMY : retired
[Mutator Alloc Region] 2 NULL : released
[Survivor GC Alloc Region] 1 NULL : initializing
[Survivor GC Alloc Region] 0 DUMMY : initialized
New -Xlog:gc+alloc+region=debug logging:
[1,598s][debug][gc,alloc,region] Mutator Alloc Region: 0 DUMMY : retired
[1,598s][debug][gc,alloc,region] Mutator Alloc Region: 0 DUMMY :
attempting region allocation
[1,598s][debug][gc,alloc,region] Mutator Alloc Region: 0 DUMMY : region
allocation failed
[1,598s][debug][gc,alloc,region] Mutator Alloc Region: 0 DUMMY : alloc
locked failed
[1,598s][debug][gc,alloc,region] Mutator Alloc Region: 0 DUMMY : alloc
failed
[1,598s][debug][gc,alloc,region] Mutator Alloc Region: 0 DUMMY : retiring
[1,598s][debug][gc,alloc,region] Mutator Alloc Region: 0 DUMMY : retired
[1,598s][debug][gc,alloc,region] Mutator Alloc Region: 0 DUMMY :
attempting region allocation
[1,598s][debug][gc,alloc,region] Mutator Alloc Region: 0 DUMMY : region
allocation failed
[1,598s][debug][gc,alloc,region] Mutator Alloc Region: 0 DUMMY : alloc
locked failed
[1,598s][debug][gc,alloc,region] GC(14) Mutator Alloc Region: 0 DUMMY :
releasing
[1,598s][debug][gc,alloc,region] GC(14) Mutator Alloc Region: 0 DUMMY :
retiring
[1,598s][debug][gc,alloc,region] GC(14) Mutator Alloc Region: 0 DUMMY :
retired
[1,598s][debug][gc,alloc,region] GC(14) Mutator Alloc Region: 0 NULL :
released
[1,598s][debug][gc,alloc,region] GC(14) Survivor GC Alloc Region: 1 NULL
: initializing
[1,598s][debug][gc,alloc,region] GC(14) Survivor GC Alloc Region: 0
DUMMY : initialized
[1,598s][debug][gc,alloc,region] GC(14) Old GC Alloc Region: 2 NULL :
initializing
[1,598s][debug][gc,alloc,region] GC(14) Old GC Alloc Region: 0 DUMMY :
initialized
[1,599s][debug][gc,alloc,region] GC(14) Old GC Alloc Region: 0 DUMMY :
alloc failed
[1,599s][debug][gc,alloc,region] GC(14) Old GC Alloc Region: 0 DUMMY :
alloc failed
New -Xlog:gc+alloc+region=trace logging:
[3,109s][trace][gc,alloc,region] GC(0) Old GC Alloc Region: 9
8:(O)[0x00000000fc800000,0x00000000fc89e3a0,0x00000000fc900000] : alloc
min 5 desired 258 actual 258 0x00000000fc89db90
[3,142s][trace][gc,alloc,region] GC(0) Old GC Alloc Region: 9
8:(O)[0x00000000fc800000,0x00000000fc8a1400,0x00000000fc900000] : alloc
min 5 desired 258 actual 258 0x00000000fc8a0bf0
[3,108s][trace][gc,alloc,region] GC(0) Old GC Alloc Region: 9
8:(O)[0x00000000fc800000,0x00000000fc894260,0x00000000fc900000] : alloc
min 5 desired 258 actual 258 0x00000000fc893a50
[3,141s][trace][gc,alloc,region] GC(0) Old GC Alloc Region: 9
8:(O)[0x00000000fc800000,0x00000000fc8a03e0,0x00000000fc900000] : alloc
min 5 desired 258 actual 258 0x00000000fc89fbd0
[3,141s][trace][gc,alloc,region] GC(0) Old GC Alloc Region: 9
8:(O)[0x00000000fc800000,0x00000000fc8a0bf0,0x00000000fc900000] : alloc
min 5 desired 258 actual 258 0x00000000fc8a03e0
[3,108s][trace][gc,alloc,region] GC(0) Old GC Alloc Region: 9
8:(O)[0x00000000fc800000,0x00000000fc8972c0,0x00000000fc900000] : alloc
min 5 desired 258 actual 258 0x00000000fc896ab0
[3,108s][trace][gc,alloc,region] GC(0) Old GC Alloc Region: 9
8:(O)[0x00000000fc800000,0x00000000fc897ad0,0x00000000fc900000] : alloc
min 5 desired 258 actual 258 0x00000000fc8972c0
[3,147s][trace][gc,alloc,region] GC(0) Survivor GC Alloc Region: 2 DUMMY
: releasing
[3,147s][trace][gc,alloc,region] GC(0) Survivor GC Alloc Region: 2 DUMMY
: retiring
[3,147s][trace][gc,alloc,region] GC(0) Survivor GC Alloc Region: 2 DUMMY
: retired
[3,147s][trace][gc,alloc,region] GC(0) Survivor GC Alloc Region: 2 NULL
: released
[3,147s][trace][gc,alloc,region] GC(0) Old GC Alloc Region: 9
8:(O)[0x00000000fc800000,0x00000000fc8a1400,0x00000000fc900000] : releasing
[3,148s][trace][gc,alloc,region] GC(0) Old GC Alloc Region: 9
8:(O)[0x00000000fc800000,0x00000000fc8a1400,0x00000000fc900000] : retiring
[3,148s][trace][gc,alloc,region] GC(0) Old GC Alloc Region: 9 DUMMY :
retired
[3,148s][trace][gc,alloc,region] GC(0) Old GC Alloc Region: 9 NULL :
released
[3,151s][trace][gc,alloc,region] GC(0) Mutator Alloc Region: 12 NULL :
initializing
[3,151s][trace][gc,alloc,region] GC(0) Mutator Alloc Region: 0 DUMMY :
initialized
[3,151s][trace][gc,alloc,region] Mutator Alloc Region: 0 DUMMY : alloc
failed min 256 desired 256
[3,151s][trace][gc,alloc,region] Mutator Alloc Region: 0 DUMMY : retiring
[3,151s][trace][gc,alloc,region] Mutator Alloc Region: 0 DUMMY : retired
[3,151s][trace][gc,alloc,region] Mutator Alloc Region: 0 DUMMY :
attempting region allocation
[3,151s][trace][gc,alloc,region] Mutator Alloc Region: 0 DUMMY : update
[3,151s][trace][gc,alloc,region] Mutator Alloc Region: 1
63:(E)[0x00000000fff00000,0x00000000fff00800,0x0000000100000000] : updated
[3,151s][trace][gc,alloc,region] Mutator Alloc Region: 1
63:(E)[0x00000000fff00000,0x00000000fff00800,0x0000000100000000] :
region allocation successful
[3,151s][trace][gc,alloc,region] Mutator Alloc Region: 1
63:(E)[0x00000000fff00000,0x00000000fff00800,0x0000000100000000] : alloc
locked (second attempt) min 256 desired 256 actual 256 0x00000000fff00000
[3,151s][trace][gc,alloc,region] Mutator Alloc Region: 1
63:(E)[0x00000000fff00000,0x00000000fff05768,0x0000000100000000] : alloc
min 2541 desired 2541 actual 2541 0x00000000fff00800
[3,152s][trace][gc,alloc,region] Mutator Alloc Region: 1
63:(E)[0x00000000fff00000,0x00000000fff0a6d0,0x0000000100000000] : alloc
min 2541 desired 2541 actual 2541 0x00000000fff05768
[3,152s][trace][gc,alloc,region] Mutator Alloc Region: 1
63:(E)[0x00000000fff00000,0x00000000fff0f638,0x0000000100000000] : alloc
min 2541 desired 2541 actual 2541 0x00000000fff0a6d0
[3,152s][trace][gc,alloc,region] Mutator Alloc Region: 1
63:(E)[0x00000000fff00000,0x00000000fff145a0,0x0000000100000000] : alloc
min 2541 desired 2541 actual 2541 0x00000000fff0f638
[3,152s][trace][gc,alloc,region] Mutator Alloc Region: 1
63:(E)[0x00000000fff00000,0x00000000fff19508,0x0000000100000000] : alloc
min 2541 desired 2541 actual 2541 0x00000000fff145a0
[3,152s][trace][gc,alloc,region] Mutator Alloc Region: 1
63:(E)[0x00000000fff00000,0x00000000fff1e470,0x0000000100000000] : alloc
min 2541 desired 2541 actual 2541 0x00000000fff19508
[3,152s][trace][gc,alloc,region] Mutator Alloc Region: 1
63:(E)[0x00000000fff00000,0x00000000fff236c0,0x0000000100000000] : alloc
min 2634 desired 2634 actual 2634 0x00000000fff1e470
[3,152s][trace][gc,alloc,region] Mutator Alloc Region: 1
63:(E)[0x00000000fff00000,0x00000000fff28628,0x0000000100000000] : alloc
min 2541 desired 2541 actual 2541 0x00000000fff236c0
[3,152s][trace][gc,alloc,region] Mutator Alloc Region: 1
63:(E)[0x00000000fff00000,0x00000000fff2d590,0x0000000100000000] : alloc
min 2541 desired 2541 actual 2541 0x00000000fff28628
[3,152s][trace][gc,alloc,region] Mutator Alloc Region: 1
63:(E)[0x00000000fff00000,0x00000000fff324f8,0x0000000100000000] : alloc
min 2541 desired 2541 actual 2541 0x00000000fff2d590
[3,152s][trace][gc,alloc,region] Mutator Alloc Region: 1
63:(E)[0x00000000fff00000,0x00000000fff37460,0x0000000100000000] : alloc
min 2541 desired 2541 actual 2541 0x00000000fff324f8
[3,152s][trace][gc,alloc,region] Mutator Alloc Region: 1
63:(E)[0x00000000fff00000,0x00000000fff3c3c8,0x0000000100000000] : alloc
min 2541 desired 2541 actual 2541 0x00000000fff37460
More information about the hotspot-gc-dev
mailing list