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!