Garbage Collection log entries

Hi!
Can someone tell me if this is normal GC behavior? It is my understanding that “GC Allocation Failure” is the result of the GC kicking in and releasing memory; however, it seems to be happening very often, which is somewhat concerning…

2019-07-19T09:04:11.255-0400: 4051571.236: [GC (Allocation Failure) 2019-07-19T09:04:11.255-0400: 4051571.236: [ParNew: 434457K->30233K(460096K), 0.0277770 secs] 6888752K->6486504K(8239232K), 0.0283993 secs] [Times: user=0.19 sys=0.00, real=0.03 secs] 
2019-07-19T09:04:11.377-0400: 4051571.357: [CMS-concurrent-preclean: 0.373/0.509 secs] [Times: user=2.58 sys=0.09, real=0.51 secs] 
2019-07-19T09:04:11.377-0400: 4051571.358: [CMS-concurrent-abortable-preclean-start]
2019-07-19T09:04:11.397-0400: 4051571.378: [GC (Allocation Failure) 2019-07-19T09:04:11.397-0400: 4051571.378: [ParNew: 439257K->33570K(460096K), 0.0303362 secs] 6895528K->6492108K(8239232K), 0.0309745 secs] [Times: user=0.19 sys=0.00, real=0.03 secs] 
2019-07-19T09:04:11.487-0400: 4051571.468: [CMS-concurrent-abortable-preclean: 0.070/0.111 secs] [Times: user=0.58 sys=0.00, real=0.11 secs] 
2019-07-19T09:04:11.494-0400: 4051571.475: [GC (CMS Final Remark) [YG occupancy: 193836 K (460096 K)]2019-07-19T09:04:11.494-0400: 4051571.475: [Rescan (parallel) , 0.0281441 secs]2019-07-19T09:04:11.522-0400: 4051571.503: [weak refs processing, 0.0010069 secs]2019-07-19T09:04:11.523-0400: 4051571.504: [class unloading, 0.0788624 secs]2019-07-19T09:04:11.602-0400: 4051571.583: [scrub symbol table, 0.0266422 secs]2019-07-19T09:04:11.629-0400: 4051571.610: [scrub string table, 0.0046414 secs][1 CMS-remark: 6458537K(7779136K)] 6652374K(8239232K), 0.1398428 secs] [Times: user=0.30 sys=0.00, real=0.14 secs] 
2019-07-19T09:04:11.634-0400: 4051571.615: [CMS-concurrent-sweep-start]
2019-07-19T09:04:11.725-0400: 4051571.706: [GC (Allocation Failure) 2019-07-19T09:04:11.725-0400: 4051571.706: [ParNew: 442594K->40494K(460096K), 0.0324411 secs] 6901126K->6501012K(8239232K), 0.0331583 secs] [Times: user=0.19 sys=0.00, real=0.03 secs] 
2019-07-19T09:04:11.862-0400: 4051571.843: [GC (Allocation Failure) 2019-07-19T09:04:11.863-0400: 4051571.843: [ParNew: 449518K->37142K(460096K), 0.0385494 secs] 6910035K->6510503K(8239232K), 0.0391832 secs] [Times: user=0.19 sys=0.00, real=0.04 secs] 
2019-07-19T09:04:11.992-0400: 4051571.973: [GC (Allocation Failure) 2019-07-19T09:04:11.992-0400: 4051571.973: [ParNew: 446166K->43415K(460096K), 0.0417083 secs] 6919435K->6516683K(8239232K), 0.0423618 secs] [Times: user=0.28 sys=0.00, real=0.04 secs] 
2019-07-19T09:04:12.215-0400: 4051572.196: [GC (Allocation Failure) 2019-07-19T09:04:12.216-0400: 4051572.197: [ParNew: 452439K->26848K(460096K), 0.0458081 secs] 6925092K->6510786K(8239232K), 0.0464680 secs] [Times: user=0.20 sys=0.00, real=0.05 secs] 
2019-07-19T09:04:12.538-0400: 4051572.519: [GC (Allocation Failure) 2019-07-19T09:04:12.538-0400: 4051572.519: [ParNew: 435872K->37041K(460096K), 0.0369986 secs] 6914945K->6516114K(8239232K), 0.0376661 secs] [Times: user=0.28 sys=0.00, real=0.04 secs] 
2019-07-19T09:04:12.863-0400: 4051572.843: [GC (Allocation Failure) 2019-07-19T09:04:12.863-0400: 4051572.844: [ParNew: 446065K->27526K(460096K), 0.0403236 secs] 6882153K->6476155K(8239232K), 0.0410237 secs] [Times: user=0.20 sys=0.00, real=0.04 secs] 
2019-07-19T09:04:13.184-0400: 4051573.165: [GC (Allocation Failure) 2019-07-19T09:04:13.185-0400: 4051573.166: [ParNew: 436550K->28354K(460096K), 0.0277038 secs] 6725768K->6317572K(8239232K), 0.0292299 secs] [Times: user=0.11 sys=0.00, real=0.03 secs] 
2019-07-19T09:04:13.488-0400: 4051573.469: [GC (Allocation Failure) 2019-07-19T09:04:13.489-0400: 4051573.470: [ParNew: 437378K->34118K(460096K), 0.0298564 secs] 6495072K->6091812K(8239232K), 0.0305186 secs] [Times: user=0.19 sys=0.00, real=0.03 secs] 
2019-07-19T09:04:13.786-0400: 4051573.767: [GC (Allocation Failure) 2019-07-19T09:04:13.786-0400: 4051573.767: [ParNew: 443142K->30197K(460096K), 0.0404454 secs] 6252445K->5850107K(8239232K), 0.0411436 secs] [Times: user=0.19 sys=0.00, real=0.04 secs] 
2019-07-19T09:04:14.998-0400: 4051574.979: [CMS-concurrent-sweep: 2.930/3.364 secs] [Times: user=12.64 sys=0.48, real=3.36 secs] 
2019-07-19T09:04:14.998-0400: 4051574.979: [CMS-concurrent-reset-start]
2019-07-19T09:04:15.018-0400: 4051574.999: [CMS-concurrent-reset: 0.020/0.020 secs] [Times: user=0.03 sys=0.00, real=0.02 secs] 
2019-07-19T09:04:15.941-0400: 4051575.922: [GC (Allocation Failure) 2019-07-19T09:04:15.941-0400: 4051575.922: [ParNew: 439221K->25941K(460096K), 0.0339839 secs] 5367124K->4953843K(8239232K), 0.0347034 secs] [Times: user=0.19 sys=0.00, real=0.04 secs] 
2019-07-19T09:04:16.528-0400: 4051576.508: [GC (Allocation Failure) 2019-07-19T09:04:16.529-0400: 4051576.509: [ParNew: 434965K->35508K(460096K), 0.0297817 secs] 5362867K->4967732K(8239232K), 0.0304902 secs] [Times: user=0.11 sys=0.00, real=0.03 secs] 
2019-07-19T09:04:17.720-0400: 4051577.700: [GC (Allocation Failure) 2019-07-19T09:04:17.720-0400: 4051577.701: [ParNew: 444532K->38117K(460096K), 0.0407279 secs] 5376756K->4979186K(8239232K), 0.0414307 secs] [Times: user=0.19 sys=0.00, real=0.04 secs] 
2019-07-19T09:04:19.717-0400: 4051579.697: [GC (Allocation Failure) 2019-07-19T09:04:19.717-0400: 4051579.698: [ParNew: 447141K->30079K(460096K), 0.0396743 secs] 5388210K->4982459K(8239232K), 0.0404074 secs] [Times: user=0.19 sys=0.00, real=0.04 secs] 
2019-07-19T09:04:20.173-0400: 4051580.153: [GC (Allocation Failure) 2019-07-19T09:04:20.173-0400: 4051580.153: [ParNew: 438045K->30699K(460096K), 0.0240265 secs] 5390425K->4983080K(8239232K), 0.0247433 secs] [Times: user=0.09 sys=0.00, real=0.02 secs] 
2019-07-19T09:04:20.340-0400: 4051580.320: [GC (Allocation Failure) 2019-07-19T09:04:20.340-0400: 4051580.321: [ParNew: 439723K->22773K(460096K), 0.0299289 secs] 5392104K->4987630K(8239232K), 0.0306187 secs] [Times: user=0.09 sys=0.00, real=0.03 secs] 
2019-07-19T09:04:20.821-0400: 4051580.801: [GC (Allocation Failure) 2019-07-19T09:04:20.821-0400: 4051580.802: [ParNew: 431797K->18033K(460096K), 0.0249970 secs] 5396654K->4982890K(8239232K), 0.0257202 secs] [Times: user=0.19 sys=0.00, real=0.03 secs] 
2019-07-19T09:04:24.018-0400: 4051583.998: [GC (Allocation Failure) 2019-07-19T09:04:24.018-0400: 4051583.999: [ParNew: 427057K->25677K(460096K), 0.0277189 secs] 5391914K->4990534K(8239232K), 0.0284244 secs] [Times: user=0.19 sys=0.00, real=0.03 secs] 
2019-07-19T09:04:26.815-0400: 4051586.796: [GC (Allocation Failure) 2019-07-19T09:04:26.815-0400: 4051586.796: [ParNew: 434701K->27494K(460096K), 0.0303483 secs] 5399558K->4992351K(8239232K), 0.0310587 secs] [Times: user=0.19 sys=0.00, real=0.03 secs] 
2019-07-19T09:04:30.459-0400: 4051590.439: [GC (Allocation Failure) 2019-07-19T09:04:30.459-0400: 4051590.439: [ParNew: 436518K->25402K(460096K), 0.0307731 secs] 5401375K->4990259K(8239232K), 0.0315593 secs] [Times: user=0.19 sys=0.00, real=0.03 secs] 
2019-07-19T09:04:34.211-0400: 4051594.191: [GC (Allocation Failure) 2019-07-19T09:04:34.211-0400: 4051594.191: [ParNew: 434426K->31900K(460096K), 0.0320728 secs] 5399283K->4997628K(8239232K), 0.0327949 secs] [Times: user=0.19 sys=0.00, real=0.03 secs] 
2019-07-19T09:04:37.533-0400: 4051597.513: [GC (Allocation Failure) 2019-07-19T09:04:37.534-0400: 4051597.514: [ParNew: 439908K->23964K(460096K), 0.0315468 secs] 5405635K->4990716K(8239232K), 0.0322822 secs] [Times: user=0.19 sys=0.00, real=0.03 secs] 
2019-07-19T09:04:41.255-0400: 4051601.235: [GC (Allocation Failure) 2019-07-19T09:04:41.255-0400: 4051601.236: [ParNew: 432988K->31438K(460096K), 0.0383321 secs] 5399740K->4998190K(8239232K), 0.0391703 secs] [Times: user=0.20 sys=0.00, real=0.04 secs] 

Here are my relevant ignition.conf settings:

wrapper.java.additional.1=-XX:+UseConcMarkSweepGC
wrapper.java.additional.2=-XX:MaxGCPauseMillis=100
wrapper.java.additional.3=-Ddata.dir=data
wrapper.java.additional.4=-Dorg.apache.catalina.loader.WebappClassLoader.ENABLE_CLEAR_REFERENCES=false
wrapper.java.additional.5=-Xloggc:"C:\Program Files\Inductive Automation\Ignition\logs\javagc-%WRAPPER_TIME_YYYYMMDDHHIISS%.log"
wrapper.java.additional.6=-XX:+PrintGCDetails
wrapper.java.additional.7=-XX:+PrintGCTimeStamps
wrapper.java.additional.8=-XX:+PrintGCDateStamps
wrapper.java.additional.9=-javaagent:"C:\Program Files\jolokia-1.6.0\agents\jolokia-jvm.jar=port=8778,host=NA-LAMS-PROD79"

# Initial Java Heap Size (in MB)
wrapper.java.initmemory=2048

# Maximum Java Heap Size (in MB)
wrapper.java.maxmemory=8096

Cheers!

Unless you have an actual problem to troubleshoot, I would highly recommend 1. not having the PrintGC arguments enabled, and 2. not worrying about what the GC is actually doing. Garbage collectors are incredibly complicated, and their inner workings are intentionally something you are not meant to have to worry about in 99% of situations.

If you do have a specific problem, then you should contact support, first and foremost; but likely the first recommendation they will make is to switch to the G1 garbage collector (which is standard in Java 9+, but available on 8 via a flag).

Yes, search forum for “G1GC” and make the switch; performance is far superior to the CMS algorithm the logs show you are currently using.

1 Like