When will G1 GC trigger initial-mark besides IHOP

Question

I set -XX:InitiatingHeapOccupancyPercent=70 in JDK8 (no adaptive IHOP feature), but I found there are two initial-mark phase at the beginning of JVM start when HeapOccupancyPercent is far less than 70%, is there any other factor which will trigger G1 GC initial mark phase? Thanks in advance!

Excerpt of GC log:

2020-01-22T03:58:14.227+0000: 3.158: [GC pause (Metadata GC Threshold) (young) (initial-mark), 0.1583711 secs] [Eden: 1056.0M(81920.0M)->0.0B(81184.0M) Survivors: 0.0B->736.0M Heap: 1472.0M(160.0G)->1179.5M(160.0G)]

2020-01-22T04:13:07.073+0000: 896.004: [GC pause (G1 Evacuation Pause) (young) (initial-mark), 3.8512514 secs] [Eden: 81184.0M(81184.0M)->0.0B(71904.0M) Survivors: 736.0M->10016.0M Heap: 83643.5M(160.0G)->11744.0M(160.0G)]

JDK version:

openjdk version "1.8.0_222"

OpenJDK Runtime Environment (build 1.8.0_222-b10)

OpenJDK 64-Bit Server VM (build 25.222-b10, mixed mode)

Thanks

******Update on 2020/02/01 GC log************

2020-01-22T03:58:14.227+0000: 3.158: [GC pause (Metadata GC Threshold) (young) (initial-mark), 0.1583711 secs]

[Parallel Time: 143.8 ms, GC Workers: 33]
 [GC Worker Start (ms): Min: 3158.7, Avg: 3159.4, Max: 3159.8, Diff: 1.1]

 [Ext Root Scanning (ms): Min: 0.6, Avg: 1.1, Max: 2.7, Diff: 2.1, Sum: 35.9]

 [Update RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]

    [Processed Buffers: Min: 0, Avg: 0.1, Max: 2, Diff: 2, Sum: 4]

 [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.2]

 [Code Root Scanning (ms): Min: 0.0, Avg: 0.3, Max: 5.9, Diff: 5.9, Sum: 8.5]

 [Object Copy (ms): Min: 135.7, Avg: 141.1, Max: 141.5, Diff: 5.9, Sum: 4654.7]

 [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.7]

    [Termination Attempts: Min: 1, Avg: 9.1, Max: 15, Diff: 14, Sum: 301]

 [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.9]

 [GC Worker Total (ms): Min: 142.0, Avg: 142.5, Max: 143.1, Diff: 1.1, Sum: 4701.0]

 [GC Worker End (ms): Min: 3301.8, Avg: 3301.9, Max: 3301.9, Diff: 0.1]
[Code Root Fixup: 0.1 ms]

[Code Root Purge: 0.0 ms]

[String Dedup Fixup: 0.9 ms, GC Workers: 33]
 [Queue Fixup (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]

 [Table Fixup (ms): Min: 0.0, Avg: 0.0, Max: 0.7, Diff: 0.7, Sum: 0.7]
[Clear CT: 0.4 ms]

[Other: 13.1 ms]
 [Choose CSet: 0.0 ms]

 [Ref Proc: 9.4 ms]

 [Ref Enq: 0.9 ms]

 [Redirty Cards: 0.6 ms]

 [Humongous Register: 0.2 ms]

 [Humongous Reclaim: 0.0 ms]

 [Free CSet: 0.1 ms]
[Eden: 1056.0M(81920.0M)->0.0B(81184.0M) Survivors: 0.0B->736.0M Heap: 1472.0M(160.0G)->1179.5M(160.0G)]

[Times: user=1.77 sys=2.98, real=0.15 secs]

2020-01-22T03:58:14.386+0000: 3.316: [GC concurrent-root-region-scan-start]

2020-01-22T03:58:14.458+0000: 3.388: [GC concurrent-mark-start]

2020-01-22T03:58:14.458+0000: 3.388: [GC concurrent-root-region-scan-end, 0.0718879 secs]

2020-01-22T03:58:14.485+0000: 3.416: [GC remark 2020-01-22T03:58:14.485+0000: 3.416: [Finalize Marking, 0.0011542 secs] 2020-01-22T03:58:14.486+0000: 3.417: [GC ref-proc, 0.0072547 secs] 2020-01-22T03:58:14.494+0000: 3.424: [Unloading, 0.0050159 secs], 0.0151448 secs]

[Times: user=0.19 sys=0.02, real=0.02 secs]

2020-01-22T03:58:14.485+0000: 3.415: [GC concurrent-mark-end, 0.0271495 secs]

2020-01-22T03:58:14.500+0000: 3.431: [GC cleanup 1259M->1259M(160G), 0.0033890 secs]

[Times: user=0.06 sys=0.00, real=0.00 secs]

2020-01-22T04:13:07.073+0000: 896.004: [GC pause (G1 Evacuation Pause) (young) (initial-mark), 3.8512514 secs]

[Parallel Time: 3822.9 ms, GC Workers: 33]
 [GC Worker Start (ms): Min: 896005.5, Avg: 896006.2, Max: 896006.6, Diff: 1.1]

 [Ext Root Scanning (ms): Min: 4.3, Avg: 5.3, Max: 8.4, Diff: 4.1, Sum: 175.2]

 [Update RS (ms): Min: 0.0, Avg: 0.2, Max: 0.8, Diff: 0.8, Sum: 7.6]

    [Processed Buffers: Min: 0, Avg: 1.3, Max: 6, Diff: 6, Sum: 44]

 [Scan RS (ms): Min: 2254.9, Avg: 2266.4, Max: 2268.2, Diff: 13.3, Sum: 74790.0]

 [Code Root Scanning (ms): Min: 0.0, Avg: 0.7, Max: 10.4, Diff: 10.4, Sum: 23.8]

 [Object Copy (ms): Min: 1535.2, Avg: 1537.7, Max: 1548.1, Diff: 13.0, Sum: 50745.7]

 [Termination (ms): Min: 0.0, Avg: 11.2, Max: 13.3, Diff: 13.2, Sum: 368.0]

    [Termination Attempts: Min: 1, Avg: 2270.1, Max: 2464, Diff: 2463, Sum: 74914]

 [GC Worker Other (ms): Min: 0.0, Avg: 0.2, Max: 0.5, Diff: 0.5, Sum: 8.1]

 [GC Worker Total (ms): Min: 3821.2, Avg: 3821.8, Max: 3822.5, Diff: 1.3, Sum: 126118.4]

 [GC Worker End (ms): Min: 899827.7, Avg: 899827.9, Max: 899828.2, Diff: 0.5]
[Code Root Fixup: 0.5 ms]

[Code Root Purge: 0.1 ms]

[String Dedup Fixup: 1.1 ms, GC Workers: 33]
 [Queue Fixup (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]

 [Table Fixup (ms): Min: 0.0, Avg: 0.1, Max: 1.0, Diff: 1.0, Sum: 1.9]
[Clear CT: 4.7 ms]

[Other: 21.9 ms]
 [Choose CSet: 0.0 ms]

 [Ref Proc: 8.5 ms]

 [Ref Enq: 0.9 ms]

 [Redirty Cards: 4.1 ms]

 [Humongous Register: 0.2 ms]

 [Humongous Reclaim: 0.0 ms]

 [Free CSet: 6.2 ms]
[Eden: 81184.0M(81184.0M)->0.0B(71904.0M) Survivors: 736.0M->10016.0M Heap: 83643.5M(160.0G)->11744.0M(160.0G)]

[Times: user=50.77 sys=10.33, real=3.85 secs]

Eugene Eugene · Accepted Answer · 2020-01-31T04:16:18

Well one of them is obvious and it has to do with Metaspace, here are more details about it. I mean when a Full GC is triggered, the initial phase is mark.

I am aware of 3 other cases when a mark phase would (read below) be triggered:

 1) IHOP is reached
 2) G1ReservePercent is reached
 3) a humongous allocation happens

What happens after the mark phase depends on a few parameters, for example mixed GCs will depend on G1HeapWastePercent parameter; but either way a young GC will be triggered after mark phase anyway.

The first point is that a humongous allocation might start a concurrent cycle, you can analyze yourself if and when it does that.

The second point (from your comments): I was saying that in general, that is cause for a concurrent mark phase to be triggered, not to your case specific.

But let's look at your log (I slightly formatted it):

[GC pause (G1 Evacuation Pause) (young) (initial-mark), 3.8512514 secs]    
    [  Eden: 81184.0M(81184.0M)->0.0B(71904.0M) 
       Survivors: 736.0M->10016.0M 
       Heap: 83643.5M(160.0G)->11744.0M(160.0G)
    ]

This shows a few things. Your eden is 80GB, 70GB of which where dead objects. As such Eden was reduced to 71904.0M and Survivor was made bigger to 10016 M. Since you have set InitiatingHeapOccupancyPercent = 70, this will never happen when Eden is that big, this value will never hit 70%. Think about it, you say: "initiate a marking phase when I am 70% of the total heap in the old generation"; but your eden is 50% of the heap... That was just a minor observation here.

As to why this is triggered - this is obvious: your eden was full (81184.0M(81184.0M)). AS to why initial-mark also? It is always triggered as part of a young collection.

The third point

I am not sure I understand what you mean. It clearly says in the logs that initial-mark, that is a STW event, that does a young GC.

When will G1 GC trigger initial-mark besides IHOP

1 Answers