2

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]

Roy Zhang
  • 41
  • 2

1 Answers1

0

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.

Eugene
  • 117,005
  • 15
  • 201
  • 306
  • Thanks Eugene for ur comment! Regarding 3) a humongous allocation happens, I have different idea. There are many humongous objection (50+) allocated, but it will not trigger so many initial-mark. – Roy Zhang Jan 31 '20 at 06:06
  • Regarding 2) G1ReservePercent is reached, I have different idea as well. It is in the beginning of JVM start up, max used heap is 80G (total heap is 160G), and there is no to-space overflow in the gc log. – Roy Zhang Jan 31 '20 at 06:09
  • Regarding "I mean when a Full GC is triggered, the initial phase is mark.", I think it is concurrent mark cycle instead of full GC. My assumption is based on gc cause "[GC pause (Metadata GC Threshold) (young) (initial-mark),", pls feel free to let me know if there is any different idea, thx! – Roy Zhang Jan 31 '20 at 06:12
  • thx for ur comment, regarding "third point", you mentioned that "a humongous allocation happens" would trigger mark phase. I don't think it is the case, that is my point, hope it clarifies. Thx! – Roy Zhang Feb 01 '20 at 03:43
  • @RoyZhang you don't think this the case in _your_ case right? meaning you do not think that the log that you presented (the one that contains `(G1 Evacuation Pause) (young) (initial-mark)`), is triggered by a humongous allocation. correct? – Eugene Feb 01 '20 at 03:47
  • Regarding "As to why this is triggered - you need to provide more logs that follow, it's impossible to say otherwise, at least for me.", it is the first 4 gc (initial mark, remark, clean, initial mark again), i provide in the "*****Update on 2020/02/01 GC log************" section, thx! – Roy Zhang Feb 01 '20 at 04:28
  • "@RoyZhang you don't think this the case in your case right? meaning you do not think that the log that you presented (the one that contains (G1 Evacuation Pause) (young) (initial-mark)), is triggered by a humongous allocation. correct?", @Eugene, yes, that is my point. There are several humongous allocations, but it doesn't trigger so many initial-mark – Roy Zhang Feb 01 '20 at 04:29
  • @RoyZhang I have edited my second point, this was so obvious I am ashamed I missed it: `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.` – Eugene Feb 01 '20 at 19:16
  • @RoyZhang did that answer your question? – Eugene Mar 01 '20 at 14:28