BasicExecutionEngine Errors

WillMT10 · December 20, 2018, 7:51pm

Periodically, one of our Gateways will get a “BasicExecutionEngine: Uncaught exception executing self scheduled runnable” error. Sometimes we will get a few in short order, other times they are more spread out. The errors will have one of two different messages, I’ve copied the two different messages below. I made some updates today to the Named Queries to better protect against NULL parameters being passed in. This seems to have reduced the frequency of the errors - and it appears that we now only get the error with the short error message - but they still trigger periodically (sometimes every few minutes, other times, every few seconds).

Lastly, I turned on Trace Logging for the NamedQueries.executor and noticed that the errors seem to only occur during “Next maint interval is X millis. ExpirationMap size is Y, cache size is Y” log messages. Not sure if this points to anything but thought it was interesting. I’ve included a portion of this trace below (last snippit). That is not all of the “maint interval” messages in the log, there were a lot more but didn’t think adding all of them would help anyone. Let me know if there are any other logs that would help.

Ignition 7.9.8 (b2018060714)
Windows 7 PC 64-bit
8 Core 2.4 GHz
32 GB Ram (24 GB allocated to Ignition)
SSD

Error message that appears with a more detailed message:

INFO   | jvm 1    | 2018/12/20 10:34:43 | java.lang.NullPointerException: null
INFO   | jvm 1    | 2018/12/20 10:34:43 | 	at com.inductiveautomation.ignition.gateway.project.NamedQueryExecutor.run(NamedQueryExecutor.java:239)
INFO   | jvm 1    | 2018/12/20 10:34:43 | 	at com.inductiveautomation.ignition.common.execution.impl.BasicExecutionEngine$SelfSchedulingRunner.run(BasicExecutionEngine.java:483)
INFO   | jvm 1    | 2018/12/20 10:34:43 | 	at com.inductiveautomation.ignition.common.execution.impl.BasicExecutionEngine$TrackedTask.run(BasicExecutionEngine.java:565)
INFO   | jvm 1    | 2018/12/20 10:34:43 | 	at java.util.concurrent.Executors$RunnableAdapter.call(Unknown Source)
INFO   | jvm 1    | 2018/12/20 10:34:43 | 	at java.util.concurrent.FutureTask.run(Unknown Source)
INFO   | jvm 1    | 2018/12/20 10:34:43 | 	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(Unknown Source)
INFO   | jvm 1    | 2018/12/20 10:34:43 | 	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(Unknown Source)
INFO   | jvm 1    | 2018/12/20 10:34:43 | 	at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
INFO   | jvm 1    | 2018/12/20 10:34:43 | 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
INFO   | jvm 1    | 2018/12/20 10:34:43 | 	at java.lang.Thread.run(Unknown Source)

Other times this error will appear (since updating the Named Queries this is the only message that has appeared):

INFO   | jvm 1    | 2018/12/20 11:09:43 | E [C.BasicExecutionEngine        ] [19:09:43]: Uncaught exception executing self scheduled runnable. 
INFO   | jvm 1    | 2018/12/20 11:09:43 | java.lang.NullPointerException: null

Log with NamedQueries.executor set to Trace:

INFO   | jvm 1    | 2018/12/20 11:09:43 | T [N.executor                    ] [19:09:43]: Next maint interval is 6890553091920 millis. ExpirationMap size is 2, cache size is 2 
INFO   | jvm 1    | 2018/12/20 11:09:43 | E [C.BasicExecutionEngine        ] [19:09:43]: Uncaught exception executing self scheduled runnable. 
INFO   | jvm 1    | 2018/12/20 11:09:43 | java.lang.NullPointerException: null
INFO   | jvm 1    | 2018/12/20 11:09:43 | T [N.executor                    ] [19:09:43]: Next maint interval is 6890553177449 millis. ExpirationMap size is 2, cache size is 2 
INFO   | jvm 1    | 2018/12/20 11:09:43 | T [N.executor                    ] [19:09:43]: Next maint interval is 6890553180015 millis. ExpirationMap size is 2, cache size is 2 
INFO   | jvm 1    | 2018/12/20 11:09:43 | T [N.executor                    ] [19:09:43]: Next maint interval is 6890553248439 millis. ExpirationMap size is 2, cache size is 2 
INFO   | jvm 1    | 2018/12/20 11:09:43 | T [N.executor                    ] [19:09:43]: Next maint interval is 6890553251432 millis. ExpirationMap size is 2, cache size is 2 
INFO   | jvm 1    | 2018/12/20 11:09:43 | T [N.executor                    ] [19:09:43]: Next maint interval is 6890553274525 millis. ExpirationMap size is 2, cache size is 2 
INFO   | jvm 1    | 2018/12/20 11:09:43 | T [N.executor                    ] [19:09:43]: Next maint interval is 6890553265117 millis. ExpirationMap size is 2, cache size is 2 
INFO   | jvm 1    | 2018/12/20 11:09:43 | T [N.executor                    ] [19:09:43]: Next maint interval is 6890553293770 millis. ExpirationMap size is 2, cache size is 2 
INFO   | jvm 1    | 2018/12/20 11:09:43 | T [N.executor                    ] [19:09:43]: Next maint interval is 6890553301040 millis. ExpirationMap size is 2, cache size is 2 
INFO   | jvm 1    | 2018/12/20 11:09:43 | T [N.executor                    ] [19:09:43]: Next maint interval is 6890553343805 millis. ExpirationMap size is 2, cache size is 2 
INFO   | jvm 1    | 2018/12/20 11:09:43 | T [N.executor                    ] [19:09:43]: Next maint interval is 6890553353640 millis. ExpirationMap size is 2, cache size is 2 
INFO   | jvm 1    | 2018/12/20 11:09:43 | T [N.executor                    ] [19:09:43]: Next maint interval is 6890553363476 millis. ExpirationMap size is 2, cache size is 2 
INFO   | jvm 1    | 2018/12/20 11:09:43 | T [N.executor                    ] [19:09:43]: Next maint interval is 6890553350219 millis. ExpirationMap size is 2, cache size is 2 
INFO   | jvm 1    | 2018/12/20 11:09:43 | T [N.executor                    ] [19:09:43]: Next maint interval is 6890553367325 millis. ExpirationMap size is 2, cache size is 2 
INFO   | jvm 1    | 2018/12/20 11:09:43 | T [N.executor                    ] [19:09:43]: Next maint interval is 6890553384003 millis. ExpirationMap size is 2, cache size is 2 
INFO   | jvm 1    | 2018/12/20 11:09:43 | T [N.executor                    ] [19:09:43]: Next maint interval is 6890553383148 millis. ExpirationMap size is 2, cache size is 2 
INFO   | jvm 1    | 2018/12/20 11:09:43 | T [N.executor                    ] [19:09:43]: Next maint interval is 6890553407524 millis. ExpirationMap size is 2, cache size is 2 
INFO   | jvm 1    | 2018/12/20 11:09:43 | T [N.executor                    ] [19:09:43]: Next maint interval is 6890553417360 millis. ExpirationMap size is 2, cache size is 2 
INFO   | jvm 1    | 2018/12/20 11:09:43 | T [N.executor                    ] [19:09:43]: Next maint interval is 6890553421637 millis. ExpirationMap size is 2, cache size is 2 
INFO   | jvm 1    | 2018/12/20 11:09:43 | T [N.executor                    ] [19:09:43]: Next maint interval is 6890553432755 millis. ExpirationMap size is 2, cache size is 2 
INFO   | jvm 1    | 2018/12/20 11:09:43 | T [N.executor                    ] [19:09:43]: Next maint interval is 6890553456276 millis. ExpirationMap size is 2, cache size is 2 
INFO   | jvm 1    | 2018/12/20 11:09:43 | T [N.executor                    ] [19:09:43]: Next maint interval is 6890553466967 millis. ExpirationMap size is 2, cache size is 2 
INFO   | jvm 1    | 2018/12/20 11:09:43 | T [N.executor                    ] [19:09:43]: Next maint interval is 6890553475520 millis. ExpirationMap size is 2, cache size is 2 
... Plus MANY more lines of the same thing

WillMT10 · December 20, 2018, 8:11pm

Last 5 minutes or so:

BasicExecutionEngine	20Dec2018 15:10:49	Uncaught exception executing self scheduled runnable.
BasicExecutionEngine	20Dec2018 15:10:40	Uncaught exception executing self scheduled runnable.
BasicExecutionEngine	20Dec2018 15:10:31	Uncaught exception executing self scheduled runnable.
BasicExecutionEngine	20Dec2018 15:10:27	Uncaught exception executing self scheduled runnable.
BasicExecutionEngine	20Dec2018 15:10:26	Uncaught exception executing self scheduled runnable.
BasicExecutionEngine	20Dec2018 15:10:19	Tried to unregister non existant unit [namedquery cache maintenance scanning_scada].
BasicExecutionEngine	20Dec2018 15:10:19	Unregistering unit [namedquery cache maintenance scanning_scada], allow interrupt: true
BasicExecutionEngine	20Dec2018 15:10:19	Unregistering unit [namedquery cache maintenance scanning_scada], allow interrupt: true
BasicExecutionEngine	20Dec2018 15:10:19	Unregistering unit [namedquery cache maintenance scanning_scada], allow interrupt: true
BasicExecutionEngine	20Dec2018 15:10:19	Unregistering unit [namedquery cache maintenance scanning_scada], allow interrupt: true
BasicExecutionEngine	20Dec2018 15:10:19	Unregistering unit [namedquery cache maintenance scanning_scada], allow interrupt: true
BasicExecutionEngine	20Dec2018 15:10:19	Uncaught exception executing self scheduled runnable.
BasicExecutionEngine	20Dec2018 15:10:01	Uncaught exception executing self scheduled runnable.
BasicExecutionEngine	20Dec2018 15:09:54	Uncaught exception executing self scheduled runnable.
BasicExecutionEngine	20Dec2018 15:09:52	Uncaught exception executing self scheduled runnable.
BasicExecutionEngine	20Dec2018 15:09:39	Uncaught exception executing self scheduled runnable.
BasicExecutionEngine	20Dec2018 15:09:33	Uncaught exception executing self scheduled runnable.
BasicExecutionEngine	20Dec2018 15:09:31	Uncaught exception executing self scheduled runnable.
BasicExecutionEngine	20Dec2018 15:09:23	Uncaught exception executing self scheduled runnable.
BasicExecutionEngine	20Dec2018 15:09:19	Uncaught exception executing self scheduled runnable.
BasicExecutionEngine	20Dec2018 15:09:00	Uncaught exception executing self scheduled runnable.
BasicExecutionEngine	20Dec2018 15:08:56	Uncaught exception executing self scheduled runnable.
BasicExecutionEngine	20Dec2018 15:08:50	Uncaught exception executing self scheduled runnable.
BasicExecutionEngine	20Dec2018 15:08:48	Tried to unregister non existant unit [namedquery cache maintenance scanning_scada].
BasicExecutionEngine	20Dec2018 15:08:48	Tried to unregister non existant unit [namedquery cache maintenance scanning_scada].
BasicExecutionEngine	20Dec2018 15:08:48	Unregistering unit [namedquery cache maintenance scanning_scada], allow interrupt: true
BasicExecutionEngine	20Dec2018 15:08:48	Unregistering unit [namedquery cache maintenance scanning_scada], allow interrupt: true
BasicExecutionEngine	20Dec2018 15:08:48	Unregistering unit [namedquery cache maintenance scanning_scada], allow interrupt: true
BasicExecutionEngine	20Dec2018 15:08:48	Unregistering unit [namedquery cache maintenance scanning_scada], allow interrupt: true
BasicExecutionEngine	20Dec2018 15:08:46	Tried to unregister non existant unit [namedquery cache maintenance scanning_scada].
BasicExecutionEngine	20Dec2018 15:08:46	Unregistering unit [namedquery cache maintenance scanning_scada], allow interrupt: true
BasicExecutionEngine	20Dec2018 15:08:46	Unregistering unit [namedquery cache maintenance scanning_scada], allow interrupt: true
BasicExecutionEngine	20Dec2018 15:08:46	Unregistering unit [namedquery cache maintenance scanning_scada], allow interrupt: true
BasicExecutionEngine	20Dec2018 15:08:46	Unregistering unit [namedquery cache maintenance scanning_scada], allow interrupt: true
BasicExecutionEngine	20Dec2018 15:08:46	Unregistering unit [namedquery cache maintenance scanning_scada], allow interrupt: true
BasicExecutionEngine	20Dec2018 15:08:46	Unregistering unit [namedquery cache maintenance scanning_scada], allow interrupt: true
BasicExecutionEngine	20Dec2018 15:08:46	Unregistering unit [namedquery cache maintenance scanning_scada], allow interrupt: true
BasicExecutionEngine	20Dec2018 15:08:43	Uncaught exception executing self scheduled runnable.
BasicExecutionEngine	20Dec2018 15:08:33	Uncaught exception executing self scheduled runnable.
BasicExecutionEngine	20Dec2018 15:08:22	Uncaught exception executing self scheduled runnable.
BasicExecutionEngine	20Dec2018 15:08:19	Uncaught exception executing self scheduled runnable.
BasicExecutionEngine	20Dec2018 15:08:08	Uncaught exception executing self scheduled runnable.
BasicExecutionEngine	20Dec2018 15:08:04	Uncaught exception executing self scheduled runnable.
BasicExecutionEngine	20Dec2018 15:07:56	Uncaught exception executing self scheduled runnable.
BasicExecutionEngine	20Dec2018 15:07:32	Uncaught exception executing self scheduled runnable.
BasicExecutionEngine	20Dec2018 15:07:19	Uncaught exception executing self scheduled runnable.
BasicExecutionEngine	20Dec2018 15:07:15	Uncaught exception executing self scheduled runnable.
BasicExecutionEngine	20Dec2018 15:07:05	Uncaught exception executing self scheduled runnable.
BasicExecutionEngine	20Dec2018 15:06:53	Uncaught exception executing self scheduled runnable.
BasicExecutionEngine	20Dec2018 15:06:50	Uncaught exception executing self scheduled runnable.
BasicExecutionEngine	20Dec2018 15:06:35	Uncaught exception executing self scheduled runnable.
BasicExecutionEngine	20Dec2018 15:06:21	Uncaught exception executing self scheduled runnable.
BasicExecutionEngine	20Dec2018 15:06:08	Uncaught exception executing self scheduled runnable.
BasicExecutionEngine	20Dec2018 15:06:06	Uncaught exception executing self scheduled runnable.
BasicExecutionEngine	20Dec2018 15:06:02	Uncaught exception executing self scheduled runnable.
BasicExecutionEngine	20Dec2018 15:05:57	Uncaught exception executing self scheduled runnable.
BasicExecutionEngine	20Dec2018 15:05:56	Uncaught exception executing self scheduled runnable.
BasicExecutionEngine	20Dec2018 15:05:34	Uncaught exception executing self scheduled runnable.
BasicExecutionEngine	20Dec2018 15:05:32	Uncaught exception executing self scheduled runnable.
BasicExecutionEngine	20Dec2018 15:05:30	Uncaught exception executing self scheduled runnable.
BasicExecutionEngine	20Dec2018 15:05:03	Uncaught exception executing self scheduled runnable.
BasicExecutionEngine	20Dec2018 15:04:45	Uncaught exception executing self scheduled runnable.
BasicExecutionEngine	20Dec2018 15:04:21	Uncaught exception executing self scheduled runnable.

PGriffith · December 20, 2018, 8:55pm

I would upgrade your system - there were a few changes made to the named query cache system in 7.9.9 that should resolve this.

WillMT10 · December 20, 2018, 8:57pm

Ok, good to hear. Will do and thank you.