Java 11 - G1GC - Need to understand young generation gc logs and their effect on application threads

user_10916892 0
Viewed 1191

I am running a java application with G1GC enabled and i am printing the gc logs as shown below:

[4074.182s][info][gc] GC(1017) Pause Young (Normal) (G1 Evacuation Pause) 6869M->6115M(16384M) 7430.860ms
[4082.328s][info][gc] GC(1018) Pause Young (Normal) (G1 Evacuation Pause) 6875M->6121M(16384M) 7058.485ms
[4089.592s][info][gc] GC(1019) Pause Young (Normal) (G1 Evacuation Pause) 6881M->6126M(16384M) 6172.693ms
[4105.799s][info][gc] GC(1021) Pause Young (Normal) (G1 Evacuation Pause) 6892M->6137M(16384M) 6845.922ms
[4114.418s][info][gc] GC(1022) Pause Young (Normal) (G1 Evacuation Pause) 6897M->6142M(16384M) 7563.613ms
[4122.805s][info][gc] GC(1023) Pause Young (Normal) (G1 Evacuation Pause) 6902M->6148M(16384M) 7326.923ms
[4131.270s][info][gc] GC(1024) Pause Young (Normal) (G1 Evacuation Pause) 6908M->6155M(16384M) 7402.222ms
[4140.574s][info][gc] GC(1025) Pause Young (Normal) (G1 Evacuation Pause) 6915M->6161M(16384M) 8226.283ms
[4149.429s][info][gc] GC(1026) Pause Young (Normal) (G1 Evacuation Pause) 6921M->6167M(16384M) 7779.282ms
[4157.078s][info][gc] GC(1027) Pause Young (Normal) (G1 Evacuation Pause) 6927M->6172M(16384M) 6559.166ms

My understanding of this log is:

[4074.182s][info][gc] GC(1017) Pause Young (Normal) (G1 Evacuation Pause) 6869M->6115M(16384M) 7430.860ms

As per my understanding this shows that 4074.182 seconds after application started, a young generation 
Stop the world gc was kicked in, and heap size before gc heap size was 6869M 
and after gc it reduced to 6115M and it took 7430.860ms (more than 7 seconds).

My questions:

1. Is this young gc stopping all the application threads ?
2. If it is stopping all the application threads then looks like application is not 
   running at all during all these gc logs were printed because:
    after [4074.182s] young gc kicked in and it took aroung 7.5 seconds (7430.860ms)
    after ~8 seconds, [4082.328s] yound gc kicked in again and took around 7 seonds and so on.
   So it looks like application is not getting any free slot here to run ?
g1gc garbage-collection java
1 Answers

Yes, your application is stopped, all threads are paused during this period. It is interesting that the GC could only reclaim around 700MB in around 6-7 seconds, which is absolutely terrible. Without debug messages, it is impossible to say why that happens, may be there were threads started on the machine, may be there are too many connections between regions and thus it took a lot of time scanning the remembered sets, or any other reason.

But the bottom line is that during these cycles, your application is performing terribly bad; you got that right.

user_10593720
Related