RE: Increase in GC Pause time in tomcat http2 9.0.56
Any comments on this please . Thanks and Regards Arshiya Shariff -Original Message- From: Arshiya Shariff Sent: 30 August 2022 20:08 To: Tomcat Users List Subject: RE: Increase in GC Pause time in tomcat http2 9.0.56 Thanks Zdeněk for the response . 1)We have enabled GC logs and we see that mixed GC takes more than 1 sec and it occurs once in 2 hours approximately , whereas with tomcat 9.0.38 mixed GC occurs every 20 mins approximately with very small GC Pause, both the GC log comparisons i.e. with tomcat 9.0.56 and 9.0.38 were done with the same object allocation rate 2022-08-18T12:58:47.240-0400: 4956324.814: [GC pause (G1 Evacuation Pause) (mixed), 1.8309540 secs] [Parallel Time: 1778.2 ms, GC Workers: 6] [GC Worker Start (ms): Min: 4956324838.5, Avg: 4956324838.9, Max: 4956324839.2, Diff: 0.7] [Ext Root Scanning (ms): Min: 19.5, Avg: 19.9, Max: 20.9, Diff: 1.4, Sum: 119.6] [Update RS (ms): Min: 5.4, Avg: 5.4, Max: 5.5, Diff: 0.0, Sum: 32.6] [Processed Buffers: Min: 71, Avg: 109.3, Max: 128, Diff: 57, Sum: 656] [Scan RS (ms): Min: 1137.0, Avg: 1138.0, Max: 1138.6, Diff: 1.6, Sum: 6827.8] [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.1] [Object Copy (ms): Min: 613.2, Avg: 613.8, Max: 614.8, Diff: 1.6, Sum: 3682.5] [Termination (ms): Min: 0.0, Avg: 0.3, Max: 0.4, Diff: 0.4, Sum: 1.8] [Termination Attempts: Min: 1, Avg: 893.3, Max: 1141, Diff: 1140, Sum: 5360] [GC Worker Other (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 0.5] [GC Worker Total (ms): Min: 1777.1, Avg: 1777.5, Max: 1777.9, Diff: 0.8, Sum: 10664.9] [GC Worker End (ms): Min: 4956326616.4, Avg: 4956326616.4, Max: 4956326616.5, Diff: 0.1] [Code Root Fixup: 0.0 ms] [Code Root Purge: 0.0 ms] [Clear CT: 1.8 ms] [Other: 51.0 ms] [Choose CSet: 23.1 ms] [Ref Proc: 2.4 ms] [Ref Enq: 0.2 ms] [Redirty Cards: 2.6 ms] [Humongous Register: 0.1 ms] [Humongous Reclaim: 0.0 ms] [Free CSet: 20.8 ms] [Eden: 2144.0M(2144.0M)->0.0B(2128.0M) Survivors: 104.0M->120.0M Heap: 6632.0M(22.0G)->3296.0M(22.0G)] [Times: user=8.61 sys=2.00, real=1.83 secs] 2)The 5gb of swap that is used is not completely by this process , we have few other processes running . 3)These parameters in production are fine-tuned for the process. Thanks and Regards Arshiya Shariff -Original Message- From: Zdeněk Henek Sent: 30 August 2022 19:43 To: Tomcat Users List Subject: Re: Increase in GC Pause time in tomcat http2 9.0.56 HI Arshiya, MaxGCPauseMillis=100 maybe this is too strict? Causing you run into full gc. Jdk8 G1GC implementation has single thread full gc and these take more time to finish? Just guessing as you have not written if the long pause gcs are young gen pauses or full gc pauses. Another option which could cause longer gc pauses could be usage of swap file / swap partition. Check and monitor how much memory is used and how the swap is used. Your system has 120gb of ram. That is a lot, but still it does use approx 18gb swap file! There is used 5gb of that swap. I think it may be better to remove that swap file completely or reduce swappiness param in your OS. There is assigned 22gb heap, G1GC in jdk8 uses a lot of memory for G1 GC metadata. It could be up to 6gb in your case. I would consider upgrade to jdk17 and plan upgrades to newer jdk frequently if you can. There are significant improvements in G1GC in new jdk versions, not only metadatas size. I would start troubleshooting removing all gc related params and let G1GC decide all the params during runtime. It is usually a good starting point to troubleshooting G1GC if you don't know what is wrong. Enable gc logs and use gc log analyser to see what is going on there. There is page with list of available GC analyzers here https://protect2.fireeye.com/v1/url?k=31323334-501d5122-313273af-45444731-3a2e7b00ac43e57a=1=b7c12870-06e4-4332-b0b8-6462d5cfa43d=http%3A%2F%2Ffasterj.com%2Ftools%2Fgcloganalysers.shtml Regards, Zdenek On Tue, Aug 30, 2022 at 3:31 PM Arshiya Shariff wrote: > We haven’t made any changes to the gc params when migrating tomcat : > > Please find the configurations: > > Java HotSpot(TM) 64-Bit Server VM (25.241-b07) for linux-amd64 JRE > (1.8.0_241-b07), built on Dec 11 2019 02:22:16 by "java_re" with gcc > 7.3.0 > Memory: 4k page, physical 119478416k(781944k free), swap > 18862076k(13762004k free) > -XX:ConcGCThreads=3 -XX:G1HeapRegionSize=8388608 > -XX:G1NewSizePercent=10 > -XX:G1ReservePercent=20 -XX:InitialHeapSize=23622320128 > -XX:InitiatingHeapOccupancyPercent=60 -XX:MaxGCPauseMillis=100 > -XX:MaxHeapSize=23622320128 -XX:MaxMetaspaceSize=268435456 > -XX:MaxNewSize=14168358912 -XX:MinHeapDeltaBytes=8388608 > -XX:ParallelGCThreads=6 -XX:+UnlockExperimentalVMOptions > -XX:+UseCompressedClassPoi
RE: Increase in GC Pause time in tomcat http2 9.0.56
Thanks Zdeněk for the response . 1)We have enabled GC logs and we see that mixed GC takes more than 1 sec and it occurs once in 2 hours approximately , whereas with tomcat 9.0.38 mixed GC occurs every 20 mins approximately with very small GC Pause, both the GC log comparisons i.e. with tomcat 9.0.56 and 9.0.38 were done with the same object allocation rate 2022-08-18T12:58:47.240-0400: 4956324.814: [GC pause (G1 Evacuation Pause) (mixed), 1.8309540 secs] [Parallel Time: 1778.2 ms, GC Workers: 6] [GC Worker Start (ms): Min: 4956324838.5, Avg: 4956324838.9, Max: 4956324839.2, Diff: 0.7] [Ext Root Scanning (ms): Min: 19.5, Avg: 19.9, Max: 20.9, Diff: 1.4, Sum: 119.6] [Update RS (ms): Min: 5.4, Avg: 5.4, Max: 5.5, Diff: 0.0, Sum: 32.6] [Processed Buffers: Min: 71, Avg: 109.3, Max: 128, Diff: 57, Sum: 656] [Scan RS (ms): Min: 1137.0, Avg: 1138.0, Max: 1138.6, Diff: 1.6, Sum: 6827.8] [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.1] [Object Copy (ms): Min: 613.2, Avg: 613.8, Max: 614.8, Diff: 1.6, Sum: 3682.5] [Termination (ms): Min: 0.0, Avg: 0.3, Max: 0.4, Diff: 0.4, Sum: 1.8] [Termination Attempts: Min: 1, Avg: 893.3, Max: 1141, Diff: 1140, Sum: 5360] [GC Worker Other (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 0.5] [GC Worker Total (ms): Min: 1777.1, Avg: 1777.5, Max: 1777.9, Diff: 0.8, Sum: 10664.9] [GC Worker End (ms): Min: 4956326616.4, Avg: 4956326616.4, Max: 4956326616.5, Diff: 0.1] [Code Root Fixup: 0.0 ms] [Code Root Purge: 0.0 ms] [Clear CT: 1.8 ms] [Other: 51.0 ms] [Choose CSet: 23.1 ms] [Ref Proc: 2.4 ms] [Ref Enq: 0.2 ms] [Redirty Cards: 2.6 ms] [Humongous Register: 0.1 ms] [Humongous Reclaim: 0.0 ms] [Free CSet: 20.8 ms] [Eden: 2144.0M(2144.0M)->0.0B(2128.0M) Survivors: 104.0M->120.0M Heap: 6632.0M(22.0G)->3296.0M(22.0G)] [Times: user=8.61 sys=2.00, real=1.83 secs] 2)The 5gb of swap that is used is not completely by this process , we have few other processes running . 3)These parameters in production are fine-tuned for the process. Thanks and Regards Arshiya Shariff -Original Message- From: Zdeněk Henek Sent: 30 August 2022 19:43 To: Tomcat Users List Subject: Re: Increase in GC Pause time in tomcat http2 9.0.56 HI Arshiya, MaxGCPauseMillis=100 maybe this is too strict? Causing you run into full gc. Jdk8 G1GC implementation has single thread full gc and these take more time to finish? Just guessing as you have not written if the long pause gcs are young gen pauses or full gc pauses. Another option which could cause longer gc pauses could be usage of swap file / swap partition. Check and monitor how much memory is used and how the swap is used. Your system has 120gb of ram. That is a lot, but still it does use approx 18gb swap file! There is used 5gb of that swap. I think it may be better to remove that swap file completely or reduce swappiness param in your OS. There is assigned 22gb heap, G1GC in jdk8 uses a lot of memory for G1 GC metadata. It could be up to 6gb in your case. I would consider upgrade to jdk17 and plan upgrades to newer jdk frequently if you can. There are significant improvements in G1GC in new jdk versions, not only metadatas size. I would start troubleshooting removing all gc related params and let G1GC decide all the params during runtime. It is usually a good starting point to troubleshooting G1GC if you don't know what is wrong. Enable gc logs and use gc log analyser to see what is going on there. There is page with list of available GC analyzers here https://protect2.fireeye.com/v1/url?k=31323334-501d5122-313273af-45444731-3a2e7b00ac43e57a=1=b7c12870-06e4-4332-b0b8-6462d5cfa43d=http%3A%2F%2Ffasterj.com%2Ftools%2Fgcloganalysers.shtml Regards, Zdenek On Tue, Aug 30, 2022 at 3:31 PM Arshiya Shariff wrote: > We haven’t made any changes to the gc params when migrating tomcat : > > Please find the configurations: > > Java HotSpot(TM) 64-Bit Server VM (25.241-b07) for linux-amd64 JRE > (1.8.0_241-b07), built on Dec 11 2019 02:22:16 by "java_re" with gcc > 7.3.0 > Memory: 4k page, physical 119478416k(781944k free), swap > 18862076k(13762004k free) > -XX:ConcGCThreads=3 -XX:G1HeapRegionSize=8388608 > -XX:G1NewSizePercent=10 > -XX:G1ReservePercent=20 -XX:InitialHeapSize=23622320128 > -XX:InitiatingHeapOccupancyPercent=60 -XX:MaxGCPauseMillis=100 > -XX:MaxHeapSize=23622320128 -XX:MaxMetaspaceSize=268435456 > -XX:MaxNewSize=14168358912 -XX:MinHeapDeltaBytes=8388608 > -XX:ParallelGCThreads=6 -XX:+UnlockExperimentalVMOptions > -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseG1GC > -XX:+UseGCLogFileRotation > > Thanks and Regards > Arshiya Shariff > > -Original Message- > From: Rob Sargent > Sent: 30 August 2022 18:22 > To: users@
Re: Increase in GC Pause time in tomcat http2 9.0.56
HI Arshiya, MaxGCPauseMillis=100 maybe this is too strict? Causing you run into full gc. Jdk8 G1GC implementation has single thread full gc and these take more time to finish? Just guessing as you have not written if the long pause gcs are young gen pauses or full gc pauses. Another option which could cause longer gc pauses could be usage of swap file / swap partition. Check and monitor how much memory is used and how the swap is used. Your system has 120gb of ram. That is a lot, but still it does use approx 18gb swap file! There is used 5gb of that swap. I think it may be better to remove that swap file completely or reduce swappiness param in your OS. There is assigned 22gb heap, G1GC in jdk8 uses a lot of memory for G1 GC metadata. It could be up to 6gb in your case. I would consider upgrade to jdk17 and plan upgrades to newer jdk frequently if you can. There are significant improvements in G1GC in new jdk versions, not only metadatas size. I would start troubleshooting removing all gc related params and let G1GC decide all the params during runtime. It is usually a good starting point to troubleshooting G1GC if you don't know what is wrong. Enable gc logs and use gc log analyser to see what is going on there. There is page with list of available GC analyzers here http://fasterj.com/tools/gcloganalysers.shtml Regards, Zdenek On Tue, Aug 30, 2022 at 3:31 PM Arshiya Shariff wrote: > We haven’t made any changes to the gc params when migrating tomcat : > > Please find the configurations: > > Java HotSpot(TM) 64-Bit Server VM (25.241-b07) for linux-amd64 JRE > (1.8.0_241-b07), built on Dec 11 2019 02:22:16 by "java_re" with gcc 7.3.0 > Memory: 4k page, physical 119478416k(781944k free), swap > 18862076k(13762004k free) > -XX:ConcGCThreads=3 -XX:G1HeapRegionSize=8388608 -XX:G1NewSizePercent=10 > -XX:G1ReservePercent=20 -XX:InitialHeapSize=23622320128 > -XX:InitiatingHeapOccupancyPercent=60 -XX:MaxGCPauseMillis=100 > -XX:MaxHeapSize=23622320128 -XX:MaxMetaspaceSize=268435456 > -XX:MaxNewSize=14168358912 -XX:MinHeapDeltaBytes=8388608 > -XX:ParallelGCThreads=6 -XX:+UnlockExperimentalVMOptions > -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseG1GC > -XX:+UseGCLogFileRotation > > Thanks and Regards > Arshiya Shariff > > -Original Message- > From: Rob Sargent > Sent: 30 August 2022 18:22 > To: users@tomcat.apache.org > Subject: Re: Increase in GC Pause time in tomcat http2 9.0.56 > > > > On 8/30/22 06:11, Arshiya Shariff wrote: > > Hi All , > > We have migrated our application (which transports http/2 packets) from > embedded tomcat version 9.0.38 to 9.0.56 in production . > > > > We observe that , in 9.0.56 mixed GC occurs less frequently than in > 9.0.38 , but when it happens there are GC Pauses for more than 1 second , > which is causing the application to be unresponsive during that time and as > a side effect we are facing other issues like delay in WINDOW_UPDATE frames > being sent. > > > > Has anyone faced similar issue with increased GC Pause time ? > > > > Thanks and Regards > > Arshiya Shariff > > > And no change to the JVM? > > - > To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org > For additional commands, e-mail: users-h...@tomcat.apache.org >
RE: Increase in GC Pause time in tomcat http2 9.0.56
We haven’t made any changes to the gc params when migrating tomcat : Please find the configurations: Java HotSpot(TM) 64-Bit Server VM (25.241-b07) for linux-amd64 JRE (1.8.0_241-b07), built on Dec 11 2019 02:22:16 by "java_re" with gcc 7.3.0 Memory: 4k page, physical 119478416k(781944k free), swap 18862076k(13762004k free) -XX:ConcGCThreads=3 -XX:G1HeapRegionSize=8388608 -XX:G1NewSizePercent=10 -XX:G1ReservePercent=20 -XX:InitialHeapSize=23622320128 -XX:InitiatingHeapOccupancyPercent=60 -XX:MaxGCPauseMillis=100 -XX:MaxHeapSize=23622320128 -XX:MaxMetaspaceSize=268435456 -XX:MaxNewSize=14168358912 -XX:MinHeapDeltaBytes=8388608 -XX:ParallelGCThreads=6 -XX:+UnlockExperimentalVMOptions -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseG1GC -XX:+UseGCLogFileRotation Thanks and Regards Arshiya Shariff -Original Message- From: Rob Sargent Sent: 30 August 2022 18:22 To: users@tomcat.apache.org Subject: Re: Increase in GC Pause time in tomcat http2 9.0.56 On 8/30/22 06:11, Arshiya Shariff wrote: > Hi All , > We have migrated our application (which transports http/2 packets) from > embedded tomcat version 9.0.38 to 9.0.56 in production . > > We observe that , in 9.0.56 mixed GC occurs less frequently than in 9.0.38 , > but when it happens there are GC Pauses for more than 1 second , which is > causing the application to be unresponsive during that time and as a side > effect we are facing other issues like delay in WINDOW_UPDATE frames being > sent. > > Has anyone faced similar issue with increased GC Pause time ? > > Thanks and Regards > Arshiya Shariff > And no change to the JVM? - To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org For additional commands, e-mail: users-h...@tomcat.apache.org
Re: Increase in GC Pause time in tomcat http2 9.0.56
On 8/30/22 06:11, Arshiya Shariff wrote: Hi All , We have migrated our application (which transports http/2 packets) from embedded tomcat version 9.0.38 to 9.0.56 in production . We observe that , in 9.0.56 mixed GC occurs less frequently than in 9.0.38 , but when it happens there are GC Pauses for more than 1 second , which is causing the application to be unresponsive during that time and as a side effect we are facing other issues like delay in WINDOW_UPDATE frames being sent. Has anyone faced similar issue with increased GC Pause time ? Thanks and Regards Arshiya Shariff And no change to the JVM? - To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org For additional commands, e-mail: users-h...@tomcat.apache.org
Increase in GC Pause time in tomcat http2 9.0.56
Hi All , We have migrated our application (which transports http/2 packets) from embedded tomcat version 9.0.38 to 9.0.56 in production . We observe that , in 9.0.56 mixed GC occurs less frequently than in 9.0.38 , but when it happens there are GC Pauses for more than 1 second , which is causing the application to be unresponsive during that time and as a side effect we are facing other issues like delay in WINDOW_UPDATE frames being sent. Has anyone faced similar issue with increased GC Pause time ? Thanks and Regards Arshiya Shariff
