Ignition 7.5 (LTS) Server - Wrapper "restarting" the JVM

ISDProj · September 3, 2018, 9:45pm

Our Ignition server is fairly “loaded” particularly with a lot of SQL queries and as of 24 hrs ago has been restarting about 5 times per hour. I’ve had a bit of a look at the wrapper logs and keep seeing this

INFO   | jvm 84   | 2018/09/04 07:28:27 | WARN  [ABControlLogixTransportPool   ] [07:28:26,541]: [T2Red] Reseting CIP connection for transaction ID of 2
INFO   | jvm 84   | 2018/09/04 07:28:30 | WARN  [ABControlLogixWriteRequest    ] [07:28:25,306]: Write Request failed due to TIMEOUT. First item: Global.S90_LivePieceRateFromPC, Transaction: 4930
INFO   | jvm 84   | 2018/09/04 07:28:30 | WARN  [TCPClientChannel              ] [07:28:19,275]: Unknown RequestId: 5357
INFO   | jvm 84   | 2018/09/04 07:28:30 | WARN  [ABControlLogixWriteRequest    ] [07:28:30,119]: Write Request failed due to TIMEOUT. First item: Global.S90_LivePieceRateFromPC, Transaction: 4930
INFO   | jvm 84   | 2018/09/04 07:28:41 | WARN  [TimeoutDaemon                 ] [07:28:17,478]: [ABControlLogixConnectRequest] request with key "1" failed due to timeout.
ERROR  | wrapper  | 2018/09/04 07:29:15 | JVM appears hung: Timed out waiting for signal from JVM.
ERROR  | wrapper  | 2018/09/04 07:29:15 | JVM did not exit on request, terminated
STATUS | wrapper  | 2018/09/04 07:29:20 | Reloading Wrapper configuration...
STATUS | wrapper  | 2018/09/04 07:29:20 | Launching a JVM...
INFO   | jvm 85   | 2018/09/04 07:29:21 | WrapperManager: Initializing...

Any Hints or suggestions as to where I should start looking to clean this up would be great, as you can appreciate this is impacting the accuracy of some of our recording/data-logging.

pturmel · September 3, 2018, 9:51pm

That sounds like memory exhaustion and Java’s “Pause the world” garbage collection. Consider turning on G1GC and browsing these topics. You’ll need Java7+ on the gateway for G1GC to be available. Consider trending Ignition’s internal memory utilization tags, too.

ISDProj · September 3, 2018, 10:20pm

Hi Phil,
I’m a bit rusty in this area but I think we are running Java 8 on the server (jre1.8.0.181)?
and would you suggest that this should be the preferred “block”

# Java Additional Parameters
wrapper.java.additional.1=-XX:+UseG1GC
wrapper.java.additional.2=-XX:MaxGCPauseMillis=100
wrapper.java.additional.3=-XX:PermSize=64m
wrapper.java.additional.4=-XX:MaxPermSize=128m
wrapper.java.additional.5=-XX:+UseConcMarkSweepGC
wrapper.java.additional.6=-XX:+CMSClassUnloadingEnabled
#wrapper.java.additional.7=-XX:+CMSPermGenSweepingEnabled
wrapper.java.additional.7=-Ddata.dir="D:\Ignition/data"
wrapper.java.additional.7.stripquotes=TRUE
wrapper.java.additional.8=-Dorg.apache.catalina.loader.WebappClassLoader.ENABLE_CLEAR_REFERENCES=false
#wrapper.java.additional.9=-Xdebug
#wrapper.java.additional.9=-Xrunjdwp:transport=dt_socket,server=y,suspend=n,address=8000

and just what do you mean by “trending Ignitions internal memory utilisation tags”?

Regards,

Peter.

ISDProj · September 3, 2018, 10:39pm

I have since Commented out .3, .4, and .5 parameters (3&4 at ignored in v8, 5 is incompatible)
We’ll see how that goes…
(I really must get our Ignition version upgraded at some stage 7.5LTS I take it is now getting past it?)

ISDProj · September 3, 2018, 11:26pm

FYI, The above changes have not remedied the “rebooting” issue. The wrapper log content has changed somewhat now though

INFO   | jvm 4    | 2018/09/04 09:18:26 | WARN  [TimeoutDaemon                 ] [09:18:17,556]: [ABControlLogixConnectRequest] request with key "4" failed due to timeout.
INFO   | jvm 4    | 2018/09/04 09:18:26 | WARN  [ABControlLogixTransportPool   ] [09:18:26,127]: [T2Blue] Reseting CIP connection for transaction ID of 4
INFO   | jvm 4    | 2018/09/04 09:18:26 | WARN  [TimeoutDaemon                 ] [09:18:08,444]: [ABControlLogixConnectRequest] request with key "3" failed due to timeout.
INFO   | jvm 4    | 2018/09/04 09:18:26 | WARN  [ABControlLogixTransportPool   ] [09:18:26,127]: [Planer] Reseting CIP connection for transaction ID of 3
INFO   | jvm 4    | 2018/09/04 09:18:26 | WARN  [ABSLCReadRequest              ] [09:18:26,127]: Read Request failed due to TIMEOUT. First item: F8:230, Transaction: 438
INFO   | jvm 4    | 2018/09/04 09:18:36 | WARN  [TimeoutDaemon                 ] [09:18:35,913]: [ABControlLogixConnectRequest] request with key "1" failed due to timeout.
INFO   | jvm 4    | 2018/09/04 09:18:44 | WARN  [TimeoutDaemon                 ] [09:18:35,914]: [ABControlLogixConnectRequest] request with key "1" failed due to timeout.
INFO   | jvm 4    | 2018/09/04 09:18:44 | WARN  [ABControlLogixTransportPool   ] [09:18:44,109]: [GM_Sorter2] Reseting CIP connection for transaction ID of 1
ERROR  | wrapper  | 2018/09/04 09:19:25 | JVM appears hung: Timed out waiting for signal from JVM.
ERROR  | wrapper  | 2018/09/04 09:19:25 | JVM did not exit on request, terminated
STATUS | wrapper  | 2018/09/04 09:19:30 | Reloading Wrapper configuration...
STATUS | wrapper  | 2018/09/04 09:19:31 | Launching a JVM...
INFO   | jvm 5    | 2018/09/04 09:19:31 | WrapperManager: Initializing...
INFO   | jvm 5    | 2018/09/04 09:19:31 | data.dir was not set. Defaulting to D:\Ignition/data
INFO   | jvm 5    | 2018/09/04 09:19:31 | Sep 04, 2018 9:19:31 AM org.apache.catalina.startup.Embedded start
INFO   | jvm 5    | 2018/09/04 09:19:31 | INFO: Starting tomcat server
INFO   | jvm 5    | 2018/09/04 09:19:31 | Sep 04, 2018 9:19:31 AM org.apache.catalina.core.StandardEngine start
INFO   | jvm 5    | 2018/09/04 09:19:31 | INFO: Starting Servlet Engine: Apache Tomcat/6.0.18
INFO   | jvm 5    | 2018/09/04 09:19:31 | Sep 04, 2018 9:19:31 AM org.apache.catalina.startup.DigesterFactory register
INFO   | jvm 5    | 2018/09/04 09:19:31 | WARNING: Could not get url for /javax/servlet/jsp/resources/jsp_2_0.xsd
INFO   | jvm 5    | 2018/09/04 09:19:31 | Sep 04, 2018 9:19:31 AM org.apache.catalina.startup.DigesterFactory register
INFO   | jvm 5    | 2018/09/04 09:19:31 | WARNING: Could not get url for /javax/servlet/jsp/resources/jsp_2_1.xsd
INFO   | jvm 5    | 2018/09/04 09:19:31 | Sep 04, 2018 9:19:31 AM org.apache.catalina.startup.DigesterFactory register
INFO   | jvm 5    | 2018/09/04 09:19:31 | WARNING: Could not get url for /javax/servlet/jsp/resources/web-jsptaglibrary_1_1.dtd
INFO   | jvm 5    | 2018/09/04 09:19:31 | Sep 04, 2018 9:19:31 AM org.apache.catalina.startup.DigesterFactory register
INFO   | jvm 5    | 2018/09/04 09:19:31 | WARNING: Could not get url for /javax/servlet/jsp/resources/web-jsptaglibrary_1_2.dtd
INFO   | jvm 5    | 2018/09/04 09:19:31 | Sep 04, 2018 9:19:31 AM org.apache.catalina.startup.DigesterFactory register
INFO   | jvm 5    | 2018/09/04 09:19:31 | WARNING: Could not get url for /javax/servlet/jsp/resources/web-jsptaglibrary_2_0.xsd
INFO   | jvm 5    | 2018/09/04 09:19:31 | Sep 04, 2018 9:19:31 AM org.apache.catalina.startup.DigesterFactory register
INFO   | jvm 5    | 2018/09/04 09:19:31 | WARNING: Could not get url for /javax/servlet/jsp/resources/web-jsptaglibrary_2_1.xsd

pturmel · September 4, 2018, 12:31am

You have two .7’s. .6 should also be eliminated. Collect the uncommented ones together and number them sequentially – I don’t remember when the wrapper gained the ability to tolerate skipped entries. Consider adding the PrintGC entries from this topic. (Adjust for windows paths.)
As for trending, look in the tag browser under System/Gateway for memory utilization. Then turn on tag history for those tags. And make a diagnostic screen that trends that tag.

ISDProj · September 4, 2018, 4:47am

Thanks for these tips, they’ve been really helpful.
I’ve ended up doing this with my config:

# Java Additional Parameters
wrapper.java.additional.1=-XX:+UseG1GC
wrapper.java.additional.2=-XX:MaxGCPauseMillis=100
wrapper.java.additional.3=-Ddata.dir="D:\Ignition/data"
wrapper.java.additional.4=-Dorg.apache.catalina.loader.WebappClassLoader.ENABLE_CLEAR_REFERENCES=false
wrapper.java.additional.5=-XX:+PrintGCDetails
wrapper.java.additional.6=-XX:+PrintGCTimeStamps
wrapper.java.additional.7=-XX:+PrintGCDateStamps

#wrapper.java.additional.1=-XX:+UseG1GC
#wrapper.java.additional.2=-XX:MaxGCPauseMillis=100
#wrapper.java.additional.3=-XX:PermSize=64m
#wrapper.java.additional.4=-XX:MaxPermSize=128m
#wrapper.java.additional.5=-XX:+UseConcMarkSweepGC
#wrapper.java.additional.6=-XX:+CMSClassUnloadingEnabled
#wrapper.java.additional.7=-XX:+CMSPermGenSweepingEnabled
#wrapper.java.additional.7=-Ddata.dir="D:\Ignition/data"
#wrapper.java.additional.7.stripquotes=TRUE
#wrapper.java.additional.8=-Dorg.apache.catalina.loader.WebappClassLoader.ENABLE_CLEAR_REFERENCES=false
#wrapper.java.additional.9=-Xdebug
#wrapper.java.additional.9=-Xrunjdwp:transport=dt_socket,server=y,suspend=n,address=8000

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

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

Do I need to put that
wrapper.java.additional.3=-Xloggc:/var/log/ignition/javagc-%WRAPPER_TIME_YYYYMMDDHHIISS%.log

Line in there too? reindexed of course but as for a Windows equivalent Path in there I’m not sure where to put it?
something like -XLoggc:“D:\Ignition/log/javagc-%WRAPPER_TIME_YYYYMMDDHHIISS%.log” or should I strip the quotes?

as far as the actual failures are concerned though We ended up tacking that down to a hung SQL script

ISDProj · September 4, 2018, 5:04am

Cancel the last question. it’s no quotes
Thanks again for your Help @pturmel Much appreciated.

Regards,

Peter.