Thread [drivers-request-cycle-[device]] high CPU usage? Soft Logix

I have had a pretty persistent problem. Where Ignition seems to pick out one of my Soft Logix machines and exhibits the below behavior. Or they pick ignition. I know that Soft Logix isn’t officially supported. I am using Allen-Bradley ControlLogix (Legacy), driver. The affected machines seem to be the ones I have that run ver 16.xx and not the ones that are ver 19.xx although I couldn’t swear it.

The new IA drivers(21+) seem to work with my versions of Soft Logix as well. But, if I recall there were problems getting string datatypes. I am thinking about looking into trying that again. When I initially tried it I was super new to ignition. But, can you add the same device twice? With two different drivers? I can’t lose the one that is in production lol. This is so intermittent as well it would not a very good test. And who is to say when the problem would resurface. Restarting the gateway solves the problem or simply “re-saving” the device in the gateway web app. And returns my gateway back to its nice and stable sub 10%CPU. MySQL, as I have it, is already really CPU intensive on this machine. Which is a whole other problem I have… :roll_eyes:

Do real systems integrators implement logic of some sort or another to recognize this and reset? is that possible?

Everything seems normal with the device. Scan times and transaction groups all seem to be fine with the device. It’s just eating CPU?

As always I really appreciate any help or guidance!

Thread [drivers-controllogixdriver-D06-2] id=166, (RUNNABLE)
  java.base@11.0.4/java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(Unknown Source)
  java.base@11.0.4/java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(Unknown Source)
  java.base@11.0.4/java.util.concurrent.ThreadPoolExecutor.getTask(Unknown Source)
  java.base@11.0.4/java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
  java.base@11.0.4/java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
  java.base@11.0.4/java.lang.Thread.run(Unknown Source)
Thread [drivers-controllogixdriver-D06-1] id=164, (WAITING for java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject@23f9258c)
  java.base@11.0.4/jdk.internal.misc.Unsafe.park(Native Method)
  java.base@11.0.4/java.util.concurrent.locks.LockSupport.park(Unknown Source)
  java.base@11.0.4/java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(Unknown Source)
  java.base@11.0.4/java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(Unknown Source)
  java.base@11.0.4/java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(Unknown Source)
  java.base@11.0.4/java.util.concurrent.ThreadPoolExecutor.getTask(Unknown Source)
  java.base@11.0.4/java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
  java.base@11.0.4/java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
  java.base@11.0.4/java.lang.Thread.run(Unknown Source)
Thread [drivers-request-cycle-D06] id=136475, (WAITING for java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject@2e135dc6)
  java.base@11.0.4/jdk.internal.misc.Unsafe.park(Native Method)
  java.base@11.0.4/java.util.concurrent.locks.LockSupport.park(Unknown Source)
  java.base@11.0.4/java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(Unknown Source)
  com.inductiveautomation.xopc.driver.api.BlockingRequestQueue.waitForNext(BlockingRequestQueue.java:126)
 com.inductiveautomation.xopc.driver.api.BlockingRequestQueue.take(BlockingRequestQueue.java:114)
  com.inductiveautomation.xopc.driver.api.BasicRequestCycle.run(BasicRequestCycle.java:127)
  java.base@11.0.4/java.lang.Thread.run(Unknown Source)


After re-saving device connection:

Can you try getting a few thread dumps next time it happens? Just spaced out a few seconds apart.

For sure

Ignition-IS-DP-IGNITION_thread_dump20200303-094727.txt (337.1 KB)
Ignition-IS-DP-IGNITION_thread_dump20200303-094652.txt (338.0 KB)
Ignition-IS-DP-IGNITION_thread_dump20200303-094632.txt (309.3 KB)
Ignition-IS-DP-IGNITION_thread_dump20200303-094609.txt (288.3 KB)
Ignition-IS-DP-IGNITION_thread_dump20200303-094604.txt (297.1 KB)

Here is an instance where a couple of devices are showing this behavior. Running an avg CPU of 75%. Usually its sub 5%. I appreciate any time you spend looking at it man.

The devices that are like D01 & D21 are softlogixs

INFO   | jvm 1    | 2020/03/02 21:20:16 | W [c.i.x.d.a.ScheduledRequest    ] [03:20:16]: Uncaught Throwable invoking class com.inductiveautomation.xopc.drivers.allenbradley.requests.ABControlLogixReadRequest#receiveMessage: java.lang.NullPointerException 
INFO   | jvm 1    | 2020/03/02 21:36:43 | E [d.T.TCPConnection[9761]       ] [03:36:43]: Connection lost. 
INFO   | jvm 1    | 2020/03/02 21:36:43 | java.net.SocketException: Connection reset
INFO   | jvm 1    | 2020/03/02 21:36:43 | 	at java.base/java.net.SocketInputStream.read(Unknown Source)
INFO   | jvm 1    | 2020/03/02 21:36:43 | 	at java.base/java.net.SocketInputStream.read(Unknown Source)
INFO   | jvm 1    | 2020/03/02 21:36:43 | 	at java.base/java.net.SocketInputStream.read(Unknown Source)
INFO   | jvm 1    | 2020/03/02 21:36:43 | 	at com.inductiveautomation.iosession.socket.AsyncSocketIOSession.run(AsyncSocketIOSession.java:71)
INFO   | jvm 1    | 2020/03/02 21:36:43 | 	at java.base/java.lang.Thread.run(Unknown Source)
INFO   | jvm 1    | 2020/03/02 21:38:43 | W [c.i.x.d.a.ScheduledRequest    ] [03:38:43]: Uncaught Throwable invoking class com.inductiveautomation.xopc.drivers.allenbradley.requests.ABControlLogixReadRequest#receiveMessage: java.lang.NullPointerException 
INFO   | jvm 1    | 2020/03/02 21:48:55 | 0

This was in the log when the behavior started.

Hmm. Maybe related. There’s nothing wrong in the thread dumps so I’m not really sure what’s going on here.

Maybe once this starts happening turn loggers for ControlLogixDriver and ABControlLogixReadRequest to DEBUG level and see if anything is going crazy in the logs. Maybe after that error something enters into a really tight loop somewhere. Haven’t seen anything like this before.

Will do. Thanks!

Read Request error. Status code: ABResponseStatus{code=15}, First item: CHIP_CONV.TEMPURATURE, Transaction: 798

Might be another Clue. I’ll get dozens of these every second on start-up. Everything does have external access enabled.

VER: 19.11 SoftLogix

1789-L60/A R19.11