2

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 ?
user10916892
  • 825
  • 12
  • 33
  • 2
    overall you are correct, your application is struggling badly under those times. can you enable debug and show the output of the GC logs? – Eugene Dec 22 '20 at 22:07
  • without logs in debug mode, btw, this is impossible to answer... – Eugene Dec 28 '20 at 20:09
  • I don't have logs from that point in time but i will see if i can paste most recent and detailed gc logs here. – user10916892 Dec 29 '20 at 10:43
  • @Eugene As of now i don't have appropriate logs which would show similar behavior, and your first comment kind of answers the questions i posted in this post. Please post it and i will mark it answered. – user10916892 Dec 30 '20 at 08:05

1 Answers1

1

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.

Eugene
  • 117,005
  • 15
  • 201
  • 306