Issue Summary

Insight Automation rules are not executed in parallel although insight-event is multithreaded.
When there are multiple events to be executed at the same time, the one running at the moment might block the other threads while it hasn't finished.

Steps to Reproduce

1. Install a vanilla instance of Jira Service Management.
   • This was validated on JSM version 4.22.2 (Insight 9.1.11).
2. Create project with sample data; choose Insight IT Service Management project.
3. Create an endpoint to receive requests from Insight Automation.
   • In this example we are using RequestBin.
   • Create a bin with a workflow to delay the request for 15 seconds.
   • For NodeJS you could use the following code.

     export default defineComponent({
       async run({ steps, $ }) {
         const headers = {}
     
         await new Promise(resolve => setTimeout(resolve, 15000));
     
         const body = {
           about: `Pipedream is the fastest way to connects APIs. Build and run workflows with code-level control when you need it — and no code when you don't.`,
           event_id: steps.trigger.context.id,
           workflow_id: steps.trigger.context.workflow_id,
           owner_id: steps.trigger.context.owner_id,
           deployment_id: steps.trigger.context.deployment_id,
           timestamp: steps.trigger.context.ts,
           inspect: `https://pipedream.com/@/${steps.trigger.context.workflow_id}`, 
           quickstart: `https://pipedream.com/quickstart/`,
         }
     
         await $.respond({
           status: 200,
           headers,
           body,
         })
       },
     })
     

4. On Jira, go to Insight > Insight Object Schemas.
5. For the created object schema, go to Cog icong > Configure.
6. Select Automation and create a rule with the following details.
   
   • When: Object updated
   • If: Any objects
   • Then: Http Request action targeting the endpoint configured on a previous step.
7. Access the Hardware > Servers objects from the Insight project.
   
8. Change the Operating System attribute value for 4 of the objects.

Expected Results

Since Insight Automation is multithreaded, carried out by insight-event-X threads, then 4 rules are executed in parallel and they all finish in ~15s (aggregate time).

Actual Results

A running Insight Automation thread blocks the other ones, preventing rules from running in parallel.
All 4 rules finish in ~60s (aggregate time).

Checking the insight_automation.log, you will notice an insight-event thread only starts processing an event after the previous one completed.

2022-05-13 14:29:37,926 [insight-event-10] | Got rule and event for insightObjectAsyncEvent: null, id: 1 - InsightObjectEvent eventType: OBJECT_UPDATED, rule id: 1, name: Test Insight Automation Rule, isActive true, objectRuleEvent id: 1 and object: exchange.prod.app1 (IITSMITSM-17)
2022-05-13 14:29:37,938 [insight-event-10] | doAction(), called for event class: InsightObjectUpdatedEvent
2022-05-13 14:29:37,938 [insight-event-10] | Object name: exchange.prod.app1, id: 17
2022-05-13 14:29:37,938 [insight-event-10] | Execute Rule action (AutomationRuleHttpRequestAction): Start, id: 1, event [id: 1, iql: No iql], condition: None
2022-05-13 14:29:58,013 [insight-event-10] | Execute Rule action (AutomationRuleHttpRequestAction), Result: POST executed. Url: https://planetexpress.m.pipedream.net data: { "test": "event" }
2022-05-13 14:29:58,013 [insight-event-10] | Execute Rule action (AutomationRuleHttpRequestAction): Done, id:1, event [id: 1, iql: No iql, condition: None
2022-05-13 14:29:58,038 [insight-event-5] | Got rule and event for insightObjectAsyncEvent: null, id: 1 - InsightObjectEvent eventType: OBJECT_UPDATED, rule id: 1, name: Test Insight Automation Rule, isActive true, objectRuleEvent id: 1 and object: Oracle-E-Business-Server (IITSMITSM-20)
2022-05-13 14:29:58,042 [insight-event-5] | doAction(), called for event class: InsightObjectUpdatedEvent
2022-05-13 14:29:58,042 [insight-event-5] | Object name: Oracle-E-Business-Server, id: 20
2022-05-13 14:29:58,042 [insight-event-5] | Execute Rule action (AutomationRuleHttpRequestAction): Start, id: 1, event [id: 1, iql: No iql], condition: None
2022-05-13 14:30:13,321 [insight-event-5] | Execute Rule action (AutomationRuleHttpRequestAction), Result: POST executed. Url: https://planetexpress.m.pipedream.net data: { "test": "event" }
2022-05-13 14:30:13,322 [insight-event-5] | Execute Rule action (AutomationRuleHttpRequestAction): Done, id:1, event [id: 1, iql: No iql, condition: None
2022-05-13 14:30:13,342 [insight-event-11] | Got rule and event for insightObjectAsyncEvent: null, id: 1 - InsightObjectEvent eventType: OBJECT_UPDATED, rule id: 1, name: Test Insight Automation Rule, isActive true, objectRuleEvent id: 1 and object: mysql-prod-app7 (IITSMITSM-19)
2022-05-13 14:30:13,343 [insight-event-11] | doAction(), called for event class: InsightObjectUpdatedEvent
2022-05-13 14:30:13,343 [insight-event-11] | Object name: mysql-prod-app7, id: 19
2022-05-13 14:30:13,343 [insight-event-11] | Execute Rule action (AutomationRuleHttpRequestAction): Start, id: 1, event [id: 1, iql: No iql], condition: None
2022-05-13 14:30:28,591 [insight-event-11] | Execute Rule action (AutomationRuleHttpRequestAction), Result: POST executed. Url: https://planetexpress.m.pipedream.net data: { "test": "event" }
2022-05-13 14:30:28,592 [insight-event-11] | Execute Rule action (AutomationRuleHttpRequestAction): Done, id:1, event [id: 1, iql: No iql, condition: None
2022-05-13 14:30:28,599 [insight-event-8] | Got rule and event for insightObjectAsyncEvent: null, id: 1 - InsightObjectEvent eventType: OBJECT_UPDATED, rule id: 1, name: Test Insight Automation Rule, isActive true, objectRuleEvent id: 1 and object: exchange2016-prod-db1 (IITSMITSM-18)
2022-05-13 14:30:28,600 [insight-event-8] | doAction(), called for event class: InsightObjectUpdatedEvent
2022-05-13 14:30:28,600 [insight-event-8] | Object name: exchange2016-prod-db1, id: 18
2022-05-13 14:30:28,600 [insight-event-8] | Execute Rule action (AutomationRuleHttpRequestAction): Start, id: 1, event [id: 1, iql: No iql], condition: None
2022-05-13 14:30:43,940 [insight-event-8] | Execute Rule action (AutomationRuleHttpRequestAction), Result: POST executed. Url: https://planetexpress.m.pipedream.net data: { "test": "event" }
2022-05-13 14:30:43,940 [insight-event-8] | Execute Rule action (AutomationRuleHttpRequestAction): Done, id:1, event [id: 1, iql: No iql, condition: None

If thread dumps are collected while the above is occurring, then we have the following scenario.

• A runnable insight-event thread holding a lock to com.google.common.eventbus.Subscriber$SynchronizedSubscriber similar to the below.

  "insight-event-10" #836 prio=5 os_prio=31 tid=0x00007ff6db76f800 nid=0x1f623 runnable [0x00007000180bc000]
     java.lang.Thread.State: RUNNABLE
  	at java.net.SocketInputStream.socketRead0(Native Method)
  	at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
  	at java.net.SocketInputStream.read(SocketInputStream.java:171)
  	at java.net.SocketInputStream.read(SocketInputStream.java:141)
  	at sun.security.ssl.SSLSocketInputRecord.read(SSLSocketInputRecord.java:464)
  	at sun.security.ssl.SSLSocketInputRecord.bytesInCompletePacket(SSLSocketInputRecord.java:68)
  	at sun.security.ssl.SSLSocketImpl.readApplicationRecord(SSLSocketImpl.java:1341)
  	at sun.security.ssl.SSLSocketImpl.access$300(SSLSocketImpl.java:73)
  	at sun.security.ssl.SSLSocketImpl$AppInputStream.read(SSLSocketImpl.java:957)
  	at java.io.BufferedInputStream.fill(BufferedInputStream.java:246)
  	at java.io.BufferedInputStream.read1(BufferedInputStream.java:286)
  	at java.io.BufferedInputStream.read(BufferedInputStream.java:345)
  	- locked <0x00000007a15d5f78> (a java.io.BufferedInputStream)
  	at sun.net.www.http.HttpClient.parseHTTPHeader(HttpClient.java:735)
  	at sun.net.www.http.HttpClient.parseHTTP(HttpClient.java:678)
  	at sun.net.www.protocol.http.HttpURLConnection.getInputStream0(HttpURLConnection.java:1590)
  	- locked <0x00000007a0ecee68> (a sun.net.www.protocol.https.DelegateHttpsURLConnection)
  	at sun.net.www.protocol.http.HttpURLConnection.getInputStream(HttpURLConnection.java:1495)
  	- locked <0x00000007a0ecee68> (a sun.net.www.protocol.https.DelegateHttpsURLConnection)
  	at sun.net.www.protocol.https.HttpsURLConnectionImpl.getInputStream(HttpsURLConnectionImpl.java:268)
  	- locked <0x00000007a0ec6140> (a sun.net.www.protocol.https.HttpsURLConnectionImpl)
  	at com.riadalabs.jira.plugins.insight.services.util.InsightHttpRequester.doRequest(InsightHttpRequester.java:82)
  	at com.riadalabs.jira.plugins.insight.services.automation.action.AutomationRuleHttpRequestAction.doActionSafe(AutomationRuleHttpRequestAction.java:56)
  	at com.riadalabs.jira.plugins.insight.services.automation.action.AbstractInsightAutomationAction.doAction(AbstractInsightAutomationAction.java:107)
  	at com.riadalabs.jira.plugins.insight.services.automation.rule.impl.AutomationRuleEngineImpl.executeAction(AutomationRuleEngineImpl.java:675)
  	at com.riadalabs.jira.plugins.insight.services.automation.rule.impl.AutomationRuleEngineImpl.executeActions(AutomationRuleEngineImpl.java:660)
  	at com.riadalabs.jira.plugins.insight.services.automation.rule.impl.AutomationRuleEngineImpl.matchConditionAndExecuteActions(AutomationRuleEngineImpl.java:453)
  	at com.riadalabs.jira.plugins.insight.services.automation.rule.impl.AutomationRuleEngineImpl.executeAsConfiguredUser(AutomationRuleEngineImpl.java:261)
  	at com.riadalabs.jira.plugins.insight.services.automation.rule.impl.AutomationRuleEngineImpl.handleAsyncEvent(AutomationRuleEngineImpl.java:214)
  	at com.riadalabs.jira.plugins.insight.services.automation.event.AutomationRuleEventListener.onAsyncEvent(AutomationRuleEventListener.java:94)
  	at sun.reflect.GeneratedMethodAccessor1499.invoke(Unknown Source)
  	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
  	at java.lang.reflect.Method.invoke(Method.java:498)
  	at com.google.common.eventbus.Subscriber.invokeSubscriberMethod(Subscriber.java:87)
  	at com.google.common.eventbus.Subscriber$SynchronizedSubscriber.invokeSubscriberMethod(Subscriber.java:144)
  	- locked <0x000000075fd41a80> (a com.google.common.eventbus.Subscriber$SynchronizedSubscriber)
  	at com.google.common.eventbus.Subscriber$1.run(Subscriber.java:72)
  	at com.atlassian.sal.core.executor.ThreadLocalDelegateRunnable.run(ThreadLocalDelegateRunnable.java:34)
  	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
  	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
  	at java.lang.Thread.run(Thread.java:748)
  

• A number of blocked insight-event threads similar to the below.

  "insight-event-8" #834 prio=5 os_prio=31 tid=0x00007ff6afcda800 nid=0x1fd1f waiting for monitor entry [0x0000700011682000]
     java.lang.Thread.State: BLOCKED (on object monitor)
  	at com.google.common.eventbus.Subscriber$SynchronizedSubscriber.invokeSubscriberMethod(Subscriber.java:143)
  	- waiting to lock <0x000000075fd41a80> (a com.google.common.eventbus.Subscriber$SynchronizedSubscriber)
  	at com.google.common.eventbus.Subscriber$1.run(Subscriber.java:72)
  	at com.atlassian.sal.core.executor.ThreadLocalDelegateRunnable.run(ThreadLocalDelegateRunnable.java:34)
  	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
  	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
  	at java.lang.Thread.run(Thread.java:748)
  

Notes
The above describes an edge scenario on which an automation is forcefully delayed, which might not be the case on a production environment.
On a production system this problem might appear when there are thousands of automation events to be processed and they are not executed in parallel.

Workaround

Currently there is no known workaround for this behavior. A workaround will be added here when available.