Sporadic delayed rule starting: Thread pool too small?

When changing the runtime.cfg based on this info… Cron based rules suddenly stop executing - #14 by 5iver, I see an immediate change using the Karaf command in that post. I’ve used these settings for about a year, and my server has never had an issue with load…

openhab> config:list "(service.pid=org.eclipse.smarthome.threadpool)"
----------------------------------------------------------------
Pid:            org.eclipse.smarthome.threadpool
BundleLocation: null
Properties:
   discovery = 55
   ruleEngine = 55
   safeCall = 55
   service.pid = org.eclipse.smarthome.threadpool
   thingHandler = 55

But no matter how many threads I added to the pool, I always only saw 5 threads.

Before running rules:

openhab> shell:threads --list |grep "RuleEngine"
82224 │ pipe-grep "RuleEngine"                                                                         │ RUNNABLE      │ 56       │ 40

After running rules:

openhab> shell:threads --list |grep "RuleEngine"
82223 │ pipe-grep "RuleEngine"                                                                         │ TIMED_WAITING │ 59       │ 40
82249 │ ESH-RuleEngine-26                                                                              │ TIMED_WAITING │ 1        │ 0
82250 │ ESH-RuleEngine-27                                                                              │ TIMED_WAITING │ 1        │ 0
82251 │ ESH-RuleEngine-28                                                                              │ TIMED_WAITING │ 1        │ 0
82252 │ ESH-RuleEngine-29                                                                              │ TIMED_WAITING │ 1        │ 0
82253 │ ESH-RuleEngine-30                                                                              │ TIMED_WAITING │ 1        │ 0

Rules (repeated 10 times)

rule "Test1"
when
    Item Virtual_Switch_1 received command
then
    logDebug("Rules","Test1: Start")
    Thread::sleep(10000)
    logDebug("Rules","Test1: End")
end

Log:

2018-09-27 23:00:49.340 [DEBUG] [org.eclipse.smarthome.model.script.Rules] - Test2: Start
2018-09-27 23:00:49.343 [DEBUG] [org.eclipse.smarthome.model.script.Rules] - Test3: Start
2018-09-27 23:00:49.345 [DEBUG] [org.eclipse.smarthome.model.script.Rules] - Test6: Start
2018-09-27 23:00:49.346 [DEBUG] [org.eclipse.smarthome.model.script.Rules] - Test10: Start
2018-09-27 23:00:49.348 [DEBUG] [org.eclipse.smarthome.model.script.Rules] - Test9: Start
2018-09-27 23:00:59.342 [DEBUG] [org.eclipse.smarthome.model.script.Rules] - Test2: End
2018-09-27 23:00:59.346 [DEBUG] [org.eclipse.smarthome.model.script.Rules] - Test3: End
2018-09-27 23:00:59.352 [DEBUG] [org.eclipse.smarthome.model.script.Rules] - Test4: Start
2018-09-27 23:00:59.349 [DEBUG] [org.eclipse.smarthome.model.script.Rules] - Test9: End
2018-09-27 23:00:59.348 [DEBUG] [org.eclipse.smarthome.model.script.Rules] - Test6: End
2018-09-27 23:00:59.347 [DEBUG] [org.eclipse.smarthome.model.script.Rules] - Test10: End
2018-09-27 23:00:59.359 [DEBUG] [org.eclipse.smarthome.model.script.Rules] - Test5: Start
2018-09-27 23:00:59.346 [DEBUG] [org.eclipse.smarthome.model.script.Rules] - Test8: Start
2018-09-27 23:00:59.360 [DEBUG] [org.eclipse.smarthome.model.script.Rules] - Test7: Start
2018-09-27 23:00:59.361 [DEBUG] [org.eclipse.smarthome.model.script.Rules] - Test1: Start
2018-09-27 23:01:09.359 [DEBUG] [org.eclipse.smarthome.model.script.Rules] - Test4: End
2018-09-27 23:01:09.361 [DEBUG] [org.eclipse.smarthome.model.script.Rules] - Test8: End
2018-09-27 23:01:09.362 [DEBUG] [org.eclipse.smarthome.model.script.Rules] - Test1: End
2018-09-27 23:01:09.361 [DEBUG] [org.eclipse.smarthome.model.script.Rules] - Test5: End
2018-09-27 23:01:09.362 [DEBUG] [org.eclipse.smarthome.model.script.Rules] - Test7: End

So, for some reason OH is not using the configured number of thread pools. Looks like a bug to me, so I opened an issue. I’m using snapshot 1372.

In case anyone is curious, JSR223-Jython does not have the same thread pool limitations, I setup 10 of these rules in JSR223-Jython (note the cool new decorators)…

@rule("Test: Test 1")
@when("Item Virtual_Switch_1 received command")
def threadTest1(event):
    log.debug("JSR223: Test 1: start")
    sleep(10)
    log.debug("JSR223: Test 1: end")

And here is the log:

2018-09-27 22:48:58.129 [DEBUG] [org.eclipse.smarthome.model.script.Rules] - JSR223: Test 2: start
2018-09-27 22:48:58.130 [DEBUG] [org.eclipse.smarthome.model.script.Rules] - JSR223: Test 9: start
2018-09-27 22:48:58.132 [DEBUG] [org.eclipse.smarthome.model.script.Rules] - JSR223: Test 4: start
2018-09-27 22:48:58.134 [DEBUG] [org.eclipse.smarthome.model.script.Rules] - JSR223: Test 8: start
2018-09-27 22:48:58.134 [DEBUG] [org.eclipse.smarthome.model.script.Rules] - JSR223: Test 1: start
2018-09-27 22:48:58.135 [DEBUG] [org.eclipse.smarthome.model.script.Rules] - JSR223: Test 10: start
2018-09-27 22:48:58.136 [DEBUG] [org.eclipse.smarthome.model.script.Rules] - JSR223: Test 6: start
2018-09-27 22:48:58.137 [DEBUG] [org.eclipse.smarthome.model.script.Rules] - JSR223: Test 7: start
2018-09-27 22:48:58.140 [DEBUG] [org.eclipse.smarthome.model.script.Rules] - JSR223: Test 5: start
2018-09-27 22:48:58.141 [DEBUG] [org.eclipse.smarthome.model.script.Rules] - JSR223: Test 3: start
2018-09-27 22:49:08.131 [DEBUG] [org.eclipse.smarthome.model.script.Rules] - JSR223: Test 9: end
2018-09-27 22:49:08.132 [DEBUG] [org.eclipse.smarthome.model.script.Rules] - JSR223: Test 2: end
2018-09-27 22:49:08.133 [DEBUG] [org.eclipse.smarthome.model.script.Rules] - JSR223: Test 4: end
2018-09-27 22:49:08.134 [DEBUG] [org.eclipse.smarthome.model.script.Rules] - JSR223: Test 8: end
2018-09-27 22:49:08.135 [DEBUG] [org.eclipse.smarthome.model.script.Rules] - JSR223: Test 1: end
2018-09-27 22:49:08.135 [DEBUG] [org.eclipse.smarthome.model.script.Rules] - JSR223: Test 10: end
2018-09-27 22:49:08.137 [DEBUG] [org.eclipse.smarthome.model.script.Rules] - JSR223: Test 6: end
2018-09-27 22:49:08.137 [DEBUG] [org.eclipse.smarthome.model.script.Rules] - JSR223: Test 7: end
2018-09-27 22:49:08.141 [DEBUG] [org.eclipse.smarthome.model.script.Rules] - JSR223: Test 5: end
2018-09-27 22:49:08.141 [DEBUG] [org.eclipse.smarthome.model.script.Rules] - JSR223: Test 3: end
2 Likes