Uploaded image for project: 'Jira Data Center'
  1. Jira Data Center
  2. JRASERVER-68174

Issue Create/Update action is slow when WebHooks are configured

XMLWordPrintable

      Summary

      Create Issue takes longer when there are configured WebHooks with Create Issue event.

      The WebHooks are fired asynchronously, but the logic that evaluates whether a WebHook should be called is synchronous and executes one JQL query per each configured WebHook.

      On instances that have problems with slow JQLs or with overly complicated WebHook filters configured, this can increase the time it takes to perform actions in Jira.

      Environment

      An environment where there are WebHooks with Create Issue event and with complex JQL queries.

      Expected Results

      When a customer creates an issue, they should swiftly see it's created on the UI. Slow JQLs configured for the WebHooks shouldn't impact the issue creation time.

      Actual Results

      The customer clicks on Create Issue, Issue is created and the logic determining which WebHooks to call is executed. After all JQL filters are executed, user sees the new issue in the UI and the actual WebHooks are called in separate background threads.

      Jira log:

      2018-10-26 05:15:47,287 http-nio-8090-exec-298 INFO XXXXXXXXX 315x2689003x27 cxcxcxccx XXXXXXXXXXXXX /secure/CreateIssueDetails.jspa [c.a.j.p.webhooks.matcher.JqlEventMatcher_SLOW] JQL query '{project =
 "XXXXXXX"} AND {filter = 98453} AND {key in ("TEST-123")}' produced lucene query and took '59' ms to run.
2018-10-26 05:15:47,373 http-nio-8090-exec-298 INFO XXXXXXXXX 315x2689003x27 cxcxcxccx XXXXXXXXXXXXX /secure/CreateIssueDetails.jspa [c.a.j.p.webhooks.matcher.JqlEventMatcher_SLOW] JQL query '{project =
 "XXXXXXX"} AND {filter = 98465} AND {key in ("TEST-123")}' produced lucene query and took '54' ms to run.
2018-10-26 05:15:48,491 http-nio-8090-exec-298 INFO XXXXXXXXX 315x2689003x27 cxcxcxccx XXXXXXXXXXXXX /secure/CreateIssueDetails.jspa [c.a.j.p.webhooks.matcher.JqlEventMatcher_SLOW] JQL query '{project =
 "XXXXXX"} AND {filter = 89511} AND {key in ("TEST-123")}' produced lucene query and took '955' ms to run.
2018-10-26 05:15:49,541 http-nio-8090-exec-298 INFO XXXXXXXXX 315x2689003x27 cxcxcxccx XXXXXXXXXXXXX /secure/CreateIssueDetails.jspa [c.a.j.p.webhooks.matcher.JqlEventMatcher_SLOW] JQL query '{project =
 "RGHT"} AND {filter = 89511} AND {key in ("TEST-123")}' produced lucene query and took '1050' ms to run.
2018-10-26 05:15:50,507 http-nio-8090-exec-298 INFO XXXXXXXXX 315x2689003x27 cxcxcxccx XXXXXXXXXXXXX /secure/CreateIssueDetails.jspa [c.a.j.p.webhooks.matcher.JqlEventMatcher_SLOW] JQL query '{project =
 "XXXXXXX"} AND {filter = 89511} AND {key in ("TEST-123")}' produced lucene query and took '959' ms to run.
2018-10-26 05:15:51,630 http-nio-8090-exec-298 INFO XXXXXXXXX 315x2689003x27 cxcxcxccx XXXXXXXXXXXXX /secure/CreateIssueDetails.jspa [c.a.j.p.webhooks.matcher.JqlEventMatcher_SLOW] JQL query '{project =
 "XXXXXX"} AND {filter = 89511} AND {key in ("TEST-123")}' produced lucene query and took '1123' ms to run.
2018-10-26 05:15:52,739 http-nio-8090-exec-298 INFO XXXXXXXXX 315x2689003x27 cxcxcxccx XXXXXXXXXXXXX /secure/CreateIssueDetails.jspa [c.a.j.p.webhooks.matcher.JqlEventMatcher_SLOW] JQL query '{project =
 "XXXXXX"} AND {filter = 89511} AND {key in ("TEST-123")}' produced lucene query and took '1040' ms to run.
2018-10-26 05:15:53,773 http-nio-8090-exec-298 INFO XXXXXXXXX 315x2689003x27 cxcxcxccx XXXXXXXXXXXXX /secure/CreateIssueDetails.jspa [c.a.j.p.webhooks.matcher.JqlEventMatcher_SLOW] JQL query '{project =
 "XXXXX"} AND {filter = 89511} AND {key in ("TEST-123")}' produced lucene query and took '1019' ms to run.
2018-10-26 05:15:54,812 http-nio-8090-exec-298 INFO XXXXXXXXX 315x2689003x27 cxcxcxccx XXXXXXXXXXXXX /secure/CreateIssueDetails.jspa [c.a.j.p.webhooks.matcher.JqlEventMatcher_SLOW] JQL query '{project =
 "XXXXX"} AND {filter = 89511} AND {key in ("TEST-123")}' produced lucene query and took '927' ms to run.
2018-10-26 05:15:55,752 http-nio-8090-exec-298 INFO XXXXXXXXX 315x2689003x27 cxcxcxccx XXXXXXXXXXXXX /secure/CreateIssueDetails.jspa [c.a.j.p.webhooks.matcher.JqlEventMatcher_SLOW] JQL query '{project =
 "GRSD"} AND {FILTER = 89511} AND {key in ("TEST-123")}' produced lucene query and took '940' ms to run.
2018-10-26 05:15:55,807 http-nio-8090-exec-298 INFO XXXXXXXXX 315x2689003x27 cxcxcxccx XXXXXXXXXXXXX /secure/CreateIssueDetails.jspa [c.a.j.p.webhooks.matcher.JqlEventMatcher_SLOW] JQL query '{project =
 "XXXXXXX"} AND {filter = 98454} AND {key in ("TEST-123")}' produced lucene query and took '55' ms to run.
2018-10-26 05:15:55,862 http-nio-8090-exec-298 INFO XXXXXXXXX 315x2689003x27 cxcxcxccx XXXXXXXXXXXXX /secure/CreateIssueDetails.jspa [c.a.j.p.webhooks.matcher.JqlEventMatcher_SLOW] JQL query '{project =
 "XXXXXXX"} AND {filter = 98452} AND {key in ("TEST-123")}' produced lucene query and took '54' ms to run.
2018-10-26 05:15:56,978 http-nio-8090-exec-298 INFO XXXXXXXXX 315x2689003x27 cxcxcxccx XXXXXXXXXXXXX /secure/CreateIssueDetails.jspa [c.a.j.p.webhooks.matcher.JqlEventMatcher_SLOW] JQL query '{project =
 "XXXXX"} AND {filter = 89511} AND {key in ("TEST-123")}' produced lucene query and took '1062' ms to run.
2018-10-26 05:15:58,400 http-nio-8090-exec-298 INFO XXXXXXXXX 315x2689003x27 cxcxcxccx XXXXXXXXXXXXX /secure/CreateIssueDetails.jspa [c.a.j.p.webhooks.matcher.JqlEventMatcher_SLOW] JQL query '{project =
 "XXXXX"} AND {filter = 89511} AND {key in ("TEST-123")}' produced lucene query and took '1313' ms to run.
2018-10-26 05:15:58,535 http-nio-8090-exec-298 INFO XXXXXXXXX 315x2689003x27 cxcxcxccx XXXXXXXXXXXXX /secure/CreateIssueDetails.jspa [c.a.j.p.webhooks.matcher.JqlEventMatcher_SLOW] JQL query '{project =
 "XXXXXXX"} AND {filter = 98459} AND {key in ("TEST-123")}' produced lucene query and took '65' ms to run.
2018-10-26 05:15:59,709 http-nio-8090-exec-298 INFO XXXXXXXXX 315x2689003x27 cxcxcxccx XXXXXXXXXXXXX /secure/CreateIssueDetails.jspa [c.a.j.p.webhooks.matcher.JqlEventMatcher_SLOW] JQL query '{project =
 "XXXX"} AND {filter = 89511} AND {key in ("TEST-123")}' produced lucene query and took '1075' ms to run.
2018-10-26 05:16:00,760 http-nio-8090-exec-298 INFO XXXXXXXXX 315x2689003x27 cxcxcxccx XXXXXXXXXXXXX /secure/CreateIssueDetails.jspa [c.a.j.p.webhooks.matcher.JqlEventMatcher_SLOW] JQL query '{project =
 "XXXXX"} AND {filter = 89511} AND {key in ("TEST-123")}' produced lucene query and took '1051' ms to run.
2018-10-26 05:16:01,841 http-nio-8090-exec-298 INFO XXXXXXXXX 315x2689003x27 cxcxcxccx XXXXXXXXXXXXX /secure/CreateIssueDetails.jspa [c.a.j.p.webhooks.matcher.JqlEventMatcher_SLOW] JQL query '{project =
 "XXXXX"} AND {filter = 89511} AND {key in ("TEST-123")}' produced lucene query and took '1080' ms to run.
2018-10-26 05:16:03,013 http-nio-8090-exec-298 INFO XXXXXXXXX 315x2689003x27 cxcxcxccx XXXXXXXXXXXXX /secure/CreateIssueDetails.jspa [c.a.j.p.webhooks.matcher.JqlEventMatcher_SLOW] JQL query '{project =
 "XXXXXX"} AND {filter = 89511} AND {key in ("TEST-123")}' produced lucene query and took '1123' ms to run.
2018-10-26 05:16:12,856 http-nio-8090-exec-298 INFO XXXXXXXXX 315x2689003x27 cxcxcxccx XXXXXXXXXXXXX /secure/CreateIssueDetails.jspa [c.a.j.p.webhooks.matcher.JqlEventMatcher_SLOW] JQL query '{project =
 "XXXXXXX"} AND {filter = 98453} AND {key in ("TEST-123")}' produced lucene query and took '65' ms to run.
2018-10-26 05:16:12,955 http-nio-8090-exec-298 INFO XXXXXXXXX 315x2689003x27 cxcxcxccx XXXXXXXXXXXXX /secure/CreateIssueDetails.jspa [c.a.j.p.webhooks.matcher.JqlEventMatcher_SLOW] JQL query '{project =
 "XXXXXXX"} AND {filter = 98465} AND {key in ("TEST-123")}' produced lucene query and took '68' ms to run.
2018-10-26 05:16:14,022 http-nio-8090-exec-298 INFO XXXXXXXXX 315x2689003x27 cxcxcxccx XXXXXXXXXXXXX /secure/CreateIssueDetails.jspa [c.a.j.p.webhooks.matcher.JqlEventMatcher_SLOW] JQL query '{project =
 "XXXXXX"} AND {filter = 89511} AND {key in ("TEST-123")}' produced lucene query and took '938' ms to run.
 2018-10-26 05:16:14,919 http-nio-8090-exec-298 INFO XXXXXXXXX 315x2689003x27 cxcxcxccx XXXXXXXXXXXXX /secure/CreateIssueDetails.jspa [c.a.j.p.webhooks.matcher.JqlEventMatcher_SLOW] JQL query '{project =
 "XXXXX"} AND {filter = 89511} AND {key in ("TEST-123")}' produced lucene query and took '896' ms to run.
2018-10-26 05:16:15,788 http-nio-8090-exec-298 INFO XXXXXXXXX 315x2689003x27 cxcxcxccx XXXXXXXXXXXXX /secure/CreateIssueDetails.jspa [c.a.j.p.webhooks.matcher.JqlEventMatcher_SLOW] JQL query '{project = "XXXXX"} AND {filter = 89511} AND {key in ("TEST-123")}' produced lucene query and took '862' ms to run.
2018-10-26 05:16:16,721 http-nio-8090-exec-298 INFO XXXXXXXXX 315x2689003x27 cxcxcxccx XXXXXXXXXXXXX /secure/CreateIssueDetails.jspa [c.a.j.p.webhooks.matcher.JqlEventMatcher_SLOW] JQL query '{project = "xxxxx"} AND {filter = 89511} AND {key in ("TEST-123")}' produced lucene query and took '932' ms to run.
2018-10-26 05:16:17,667 http-nio-8090-exec-298 INFO XXXXXXXXX 315x2689003x27 cxcxcxccx XXXXXXXXXXXXX /secure/CreateIssueDetails.jspa [c.a.j.p.webhooks.matcher.JqlEventMatcher_SLOW] JQL query '{project = "xxxxx"} AND {filter = 89511} AND {key in ("TEST-123")}' produced lucene query and took '879' ms to run.
2018-10-26 05:16:18,564 http-nio-8090-exec-298 INFO XXXXXXXXX 315x2689003x27 cxcxcxccx XXXXXXXXXXXXX /secure/CreateIssueDetails.jspa [c.a.j.p.webhooks.matcher.JqlEventMatcher_SLOW] JQL query '{project = "xxxxx"} AND {filter = 89511} AND {key in ("TEST-123")}' produced lucene query and took '884' ms to run.
2018-10-26 05:16:19,542 http-nio-8090-exec-298 INFO XXXXXXXXX 315x2689003x27 cxcxcxccx XXXXXXXXXXXXX /secure/CreateIssueDetails.jspa [c.a.j.p.webhooks.matcher.JqlEventMatcher_SLOW] JQL query '{project = "xxxxx"} AND {filter = 89511} AND {key in ("TEST-123")}' produced lucene query and took '868' ms to run.
2018-10-26 05:16:20,451 http-nio-8090-exec-298 INFO XXXXXXXXX 315x2689003x27 cxcxcxccx XXXXXXXXXXXXX /secure/CreateIssueDetails.jspa [c.a.j.p.webhooks.matcher.JqlEventMatcher_SLOW] JQL query '{project = "xxxx"} AND {FILTER = 89511} AND {key in ("TEST-123")}' produced lucene query and took '890' ms to run.
2018-10-26 05:16:20,573 http-nio-8090-exec-298 INFO XXXXXXXXX 315x2689003x27 cxcxcxccx XXXXXXXXXXXXX /secure/CreateIssueDetails.jspa [c.a.j.p.webhooks.matcher.JqlEventMatcher_SLOW] JQL query '{project = "XXXXX"} AND {filter = 98452} AND {key in ("TEST-123")}' produced lucene query and took '72' ms to run.
2018-10-26 05:16:20,628 http-nio-8090-exec-298 INFO XXXXXXXXX 315x2689003x27 cxcxcxccx XXXXXXXXXXXXX /secure/CreateIssueDetails.jspa [c.a.j.p.webhooks.matcher.JqlEventMatcher_SLOW] JQL query '{project = "XXXXX"} AND {filter = 98455} AND {key in ("TEST-123")}' produced lucene query and took '54' ms to run.
2018-10-26 05:16:21,569 http-nio-8090-exec-298 INFO XXXXXXXXX 315x2689003x27 cxcxcxccx XXXXXXXXXXXXX /secure/CreateIssueDetails.jspa [c.a.j.p.webhooks.matcher.JqlEventMatcher_SLOW] JQL query '{project = "xxxxx"} AND {filter = 89511} AND {key in ("TEST-123")}' produced lucene query and took '932' ms to run.
2018-10-26 05:16:22,589 http-nio-8090-exec-298 INFO XXXXXXXXX 315x2689003x27 cxcxcxccx XXXXXXXXXXXXX /secure/CreateIssueDetails.jspa [c.a.j.p.webhooks.matcher.JqlEventMatcher_SLOW] JQL query '{project = "xxxxx"} AND {filter = 89511} AND {key in ("TEST-123")}' produced lucene query and took '918' ms to run.
2018-10-26 05:16:23,752 http-nio-8090-exec-298 INFO XXXXXXXXX 315x2689003x27 cxcxcxccx XXXXXXXXXXXXX /secure/CreateIssueDetails.jspa [c.a.j.p.webhooks.matcher.JqlEventMatcher_SLOW] JQL query '{project = "xxxx"} AND {filter = 89511} AND {key in ("TEST-123")}' produced lucene query and took '940' ms to run.
2018-10-26 05:16:24,699 http-nio-8090-exec-298 INFO XXXXXXXXX 315x2689003x27 cxcxcxccx XXXXXXXXXXXXX /secure/CreateIssueDetails.jspa [c.a.j.p.webhooks.matcher.JqlEventMatcher_SLOW] JQL query '{project = "xxxxx"} AND {filter = 89511} AND {key in ("TEST-123")}' produced lucene query and took '946' ms to run.
2018-10-26 05:16:25,632 http-nio-8090-exec-298 INFO XXXXXXXXX 315x2689003x27 cxcxcxccx XXXXXXXXXXXXX /secure/CreateIssueDetails.jspa [c.a.j.p.webhooks.matcher.JqlEventMatcher_SLOW] JQL query '{project = "xxxx"} AND {filter = 89511} AND {key in ("TEST-123")}' produced lucene query and took '932' ms to run.
2018-10-26 05:16:26,553 http-nio-8090-exec-298 INFO XXXXXXXXX 315x2689003x27 cxcxcxccx XXXXXXXXXXXXX /secure/CreateIssueDetails.jspa [c.a.j.p.webhooks.matcher.JqlEventMatcher_SLOW] JQL query '{project = "xxxxx"} AND {filter = 89511} AND {key in ("TEST-123")}' produced lucene query and took '881' ms to run.
2018-10-26 05:16:26,670 http-nio-8090-exec-298 INFO XXXXXXXXX 315x2689003x27 cxcxcxccx XXXXXXXXXXXXX /secure/CreateIssueDetails.jspa [c.a.j.p.h.s.task.impl.SendNotificationTask] Found 1 messages to send to HipChat
2018-10-26 05:16:26,721 http-nio-8090-exec-298 WARN UMercEu 315x2689003x27 cxcxcxccx XXXXXXXXXXXXX /secure/CreateIssueDetails.jspa [c.o.scriptrunner.runner.ScriptRunnerImpl] EH3: Current PCF Status is null. New value is also the same, so not updating PCF Status field and its time aggregator.
2018-10-26 05:16:29,035 http-nio-8090-exec-298 INFO XXXXXXXXX 315x2689003x27 cxcxcxccx XXXXXXXXXXXXX /secure/CreateIssueDetails.jspa [c.a.j.p.webhooks.matcher.JqlEventMatcher_SLOW] JQL query '{project = "XXXXX"} AND {filter = 98453} AND {key in ("TEST-123")}' produced lucene query and took '286' ms to run.
2018-10-26 05:16:29,091 http-nio-8090-exec-298 INFO XXXXXXXXX 315x2689003x27 cxcxcxccx XXXXXXXXXXXXX /secure/CreateIssueDetails.jspa [c.a.j.p.webhooks.matcher.JqlEventMatcher_SLOW] JQL query '{project in ("xxxxx", "xxxxxx")} AND {project = "xxxxx"} AND {status not in ("closed", "cancelled", "archived", "Done")} AND {component in ("xxxx", "xxxxx")} AND {key in ("TEST-123")}' produced lucene query and took '56' ms to run.
2018-10-26 05:16:29,153 http-nio-8090-exec-298 INFO XXXXXXXXX 315x2689003x27 cxcxcxccx XXXXXXXXXXXXX /secure/CreateIssueDetails.jspa [c.a.j.p.webhooks.matcher.JqlEventMatcher_SLOW] JQL query '{project = "XXXXX"} AND {filter = 98465} AND {key in ("TEST-123")}' produced lucene query and took '60' ms to run.
2018-10-26 05:16:30,388 http-nio-8090-exec-298 INFO XXXXXXXXX 315x2689003x27 cxcxcxccx XXXXXXXXXXXXX /secure/CreateIssueDetails.jspa [c.a.j.p.webhooks.matcher.JqlEventMatcher_SLOW] JQL query '{project = "xxxxx"} AND {filter = 89511} AND {key in ("TEST-123")}' produced lucene query and took '1100' ms to run.
2018-10-26 05:16:31,383 http-nio-8090-exec-298 INFO XXXXXXXXX 315x2689003x27 cxcxcxccx XXXXXXXXXXXXX /secure/CreateIssueDetails.jspa [c.a.j.p.webhooks.matcher.JqlEventMatcher_SLOW] JQL query '{project = "xxxxx"} AND {filter = 89511} AND {key in ("TEST-123")}' produced lucene query and took '994' ms to run.
2018-10-26 05:16:33,627 http-nio-8090-exec-298 INFO XXXXXXXXX 315x2689003x27 cxcxcxccx XXXXXXXXXXXXX /secure/CreateIssueDetails.jspa [c.a.j.p.webhooks.matcher.JqlEventMatcher_SLOW] JQL query '{project = "xxxxx"} AND {filter = 89511} AND {key in ("TEST-123")}' produced lucene query and took '1181' ms to run.
2018-10-26 05:16:34,785 http-nio-8090-exec-298 INFO XXXXXXXXX 315x2689003x27 cxcxcxccx XXXXXXXXXXXXX /secure/CreateIssueDetails.jspa [c.a.j.p.webhooks.matcher.JqlEventMatcher_SLOW] JQL query '{project = "xxxxx"} AND {filter = 89511} AND {key in ("TEST-123")}' produced lucene query and took '1096' ms to run.
2018-10-26 05:16:35,801 http-nio-8090-exec-298 INFO XXXXXXXXX 315x2689003x27 cxcxcxccx XXXXXXXXXXXXX /secure/CreateIssueDetails.jspa [c.a.j.p.webhooks.matcher.JqlEventMatcher_SLOW] JQL query '{project = "xxxxxx"} AND {filter = 89511} AND {key in ("TEST-123")}' produced lucene query and took '1002' ms to run.
2018-10-26 05:16:36,946 http-nio-8090-exec-298 INFO XXXXXXXXX 315x2689003x27 cxcxcxccx XXXXXXXXXXXXX /secure/CreateIssueDetails.jspa [c.a.j.p.webhooks.matcher.JqlEventMatcher_SLOW] JQL query '{project = "xxxxx"} AND {filter = 89511} AND {key in ("TEST-123")}' produced lucene query and took '1023' ms to run.
2018-10-26 05:16:37,957 http-nio-8090-exec-298 INFO XXXXXXXXX 315x2689003x27 cxcxcxccx XXXXXXXXXXXXX /secure/CreateIssueDetails.jspa [c.a.j.p.webhooks.matcher.JqlEventMatcher_SLOW] JQL query '{project = "xxxx"} AND {FILTER = 89511} AND {key in ("TEST-123")}' produced lucene query and took '1011' ms to run.
2018-10-26 05:16:38,011 http-nio-8090-exec-298 INFO XXXXXXXXX 315x2689003x27 cxcxcxccx XXXXXXXXXXXXX /secure/CreateIssueDetails.jspa [c.a.j.p.webhooks.matcher.JqlEventMatcher_SLOW] JQL query '{project = "XXXXX"} AND {filter = 98454} AND {key in ("TEST-123")}' produced lucene query and took '53' ms to run.
2018-10-26 05:16:38,076 http-nio-8090-exec-298 INFO XXXXXXXXX 315x2689003x27 cxcxcxccx XXXXXXXXXXXXX /secure/CreateIssueDetails.jspa [c.a.j.p.webhooks.matcher.JqlEventMatcher_SLOW] JQL query '{project = "XXXXX"} AND {filter = 98452} AND {key in ("TEST-123")}' produced lucene query and took '64' ms to run.
2018-10-26 05:16:39,049 http-nio-8090-exec-298 INFO XXXXXXXXX 315x2689003x27 cxcxcxccx XXXXXXXXXXXXX /secure/CreateIssueDetails.jspa [c.a.j.p.webhooks.matcher.JqlEventMatcher_SLOW] JQL query '{project = "xxxx"} AND {filter = 89511} AND {key in ("TEST-123")}' produced lucene query and took '917' ms to run.
2018-10-26 05:16:40,044 http-nio-8090-exec-298 INFO XXXXXXXXX 315x2689003x27 cxcxcxccx XXXXXXXXXXXXX /secure/CreateIssueDetails.jspa [c.a.j.p.webhooks.matcher.JqlEventMatcher_SLOW] JQL query '{project = "xxxx"} AND {filter = 89511} AND {key in ("TEST-123")}' produced lucene query and took '878' ms to run.
2018-10-26 05:16:41,026 http-nio-8090-exec-298 INFO XXXXXXXXX 315x2689003x27 cxcxcxccx XXXXXXXXXXXXX /secure/CreateIssueDetails.jspa [c.a.j.p.webhooks.matcher.JqlEventMatcher_SLOW] JQL query '{project = "xxxx"} AND {filter = 89511} AND {key in ("TEST-123")}' produced lucene query and took '828' ms to run.
2018-10-26 05:16:41,854 http-nio-8090-exec-298 INFO XXXXXXXXX 315x2689003x27 cxcxcxccx XXXXXXXXXXXXX /secure/CreateIssueDetails.jspa [c.a.j.p.webhooks.matcher.JqlEventMatcher_SLOW] JQL query '{project = "xxxx"} AND {filter = 89511} AND {key in ("TEST-123")}' produced lucene query and took '827' ms to run.
2018-10-26 05:16:42,706 http-nio-8090-exec-298 INFO XXXXXXXXX 315x2689003x27 cxcxcxccx XXXXXXXXXXXXX /secure/CreateIssueDetails.jspa [c.a.j.p.webhooks.matcher.JqlEventMatcher_SLOW] JQL query '{project = "xxxx"} AND {filter = 89511} AND {key in ("TEST-123")}' produced lucene query and took '851' ms to run.
2018-10-26 05:16:43,622 http-nio-8090-exec-298 INFO XXXXXXXXX 315x2689003x27 cxcxcxccx XXXXXXXXXXXXX /secure/CreateIssueDetails.jspa [c.a.j.p.webhooks.matcher.JqlEventMatcher_SLOW] JQL query '{project = "xxxx"} AND {filter = 89511} AND {key in ("TEST-123")}' produced lucene query and took '881' ms to run.

      Workaround

      No workaround if Webhooks will be used. But if the aim is to increase the performance of creating issue, then Webhooks should be disabled or JQLs should be tuned.

      Fix

      Asynchronous Webhooks were introduced in version 8.19.1, although it has some minor side effects (e.g. Jira shutdown may be delayed). We recommend using versions listed in "Fix Version/s" or newer. They should significantly improve the performance of Webhooks with complex JQL queries. To enable them:

      1. manually enable the "com.atlassian.jira.webhookEventsAsyncProcessing.enabled" feature flag with following instruction.
      2. restart your Jira instance (or each node in case of DC) 

        1. oie_G6x2BRf0mTm8.png
          oie_G6x2BRf0mTm8.png
          275 kB

            [JRASERVER-68174] Issue Create/Update action is slow when WebHooks are configured

            Roberto Martignano added a comment -

            Hello,

            on Jira 8.20.14 we still have a lot of the following logs:

            2023-07-26 12:23:05,028+0200 http-nio-8080-exec-43 INFO 742x4913511x13 1v5hypn /secure/CreateIssueDetails.jspa [c.a.j.p.webhooks.matcher.JqlEventMatcher_SLOW] JQL query ' produced lucene query and took '103' ms to run.

            • When adding the fix should those logs disappear?

            We are not experiencing critical delays on issue create/update at the moment, so I was just wondering if it is helpful to activate the fix, and what happens after activating it.

            Thank you!

            Roberto Martignano added a comment - Hello, on Jira 8.20.14 we still have a lot of the following logs: 2023-07-26 12:23:05,028+0200 http-nio-8080-exec-43 INFO 742x4913511x13 1v5hypn /secure/CreateIssueDetails.jspa [c.a.j.p.webhooks.matcher.JqlEventMatcher_SLOW] JQL query ' produced lucene query and took '103' ms to run. When adding the fix should those logs disappear? We are not experiencing critical delays on issue create/update at the moment, so I was just wondering if it is helpful to activate the fix, and what happens after activating it. Thank you!

            Chand Chandrasegaram added a comment -

            Hi Team, This bug is affecting the performance of a large Jira DC (25k user base) of a UK bank. We would like to see this bug getting fixed and ported to 8.20.x version ASAP.  

            Chand Chandrasegaram added a comment - Hi Team, This bug is affecting the performance of a large Jira DC (25k user base) of a UK bank. We would like to see this bug getting fixed and ported to 8.20.x version ASAP.  

            Patryk Latkowski added a comment -

            Hi!
            We noted some unexpected behavior of asynchronous webhooks. For this reason, as of version 8.20.7, most events are set to synchronous processing, and the feature flag has been disabled by default. Even manually enabling the flag, asynchronous webhooks may not work as expected, so we decided to reopen this ticket. We are currently working on this issue and will try to solve it as soon as possible.

            Best regards,
            Patryk Latkowski
            Jira Server Developer 

            Patryk Latkowski added a comment - Hi! We noted some unexpected behavior of asynchronous webhooks. For this reason, as of version 8.20.7, most events are set to synchronous processing, and the feature flag has been disabled by default. Even manually enabling the flag, asynchronous webhooks may not work as expected, so we decided to reopen this ticket. We are currently working on this issue and will try to solve it as soon as possible. Best regards, Patryk Latkowski Jira Server Developer 

            David Yu added a comment -

            I got around to testing this on 8.20.X today (I didn't realize a feature flag + restart was required) and I still saw delays when I enabled a slow webhook query. Was this the reason it got re-opened again today?

            David Yu added a comment - I got around to testing this on 8.20.X today (I didn't realize a feature flag + restart was required) and I still saw delays when I enabled a slow webhook query. Was this the reason it got re-opened again today?

            Filipi Lima added a comment -

            https://getsupport.atlassian.com/browse/PS-83825

            Filipi Lima added a comment - https://getsupport.atlassian.com/browse/PS-83825

            Pablo added a comment -

            Hi

            I'm using post/get Rest API calls quite often for other integrations

            (based on events/post-functions/jobs in SR)

            and IMHO the performance impact is insensible

            Unfortunately In my case i need exactly same webhook (which looks exactly the same as webhook created via Jira) for integration with third party app

            and my biggest issue it to create it in the easiest way

            (https://community.atlassian.com/t5/Jira-Core-Server-questions/Webhooks-send-via-SR/qaq-p/1779672)

             

            At this moment I'm working at workaraund (which works for me) but I'm still verifying it's stability and performance

            Pablo added a comment - Hi I'm using post/get Rest API calls quite often for other integrations (based on events/post-functions/jobs in SR) and IMHO the performance impact is insensible Unfortunately In my case i need exactly same webhook (which looks exactly the same as webhook created via Jira) for integration with third party app and my biggest issue it to create it in the easiest way ( https://community.atlassian.com/t5/Jira-Core-Server-questions/Webhooks-send-via-SR/qaq-p/1779672)   At this moment I'm working at workaraund (which works for me) but I'm still verifying it's stability and performance

            Ganga Bopaiah added a comment -

            Hey pawel.gryzewski1 

            Do you have any samples of how to use scriptrunner to create JSON call instead of webhooks?

            This issue is getting on my nerves now.

            Would this issue impact Jira's performance in a long run? I don't want my system crashing owing to this issue.

            Ganga Bopaiah added a comment - Hey  pawel.gryzewski1   Do you have any samples of how to use scriptrunner to create JSON call instead of webhooks? This issue is getting on my nerves now. Would this issue impact Jira's performance in a long run? I don't want my system crashing owing to this issue.

            Pablo added a comment - - edited

            Few more info - maybe it'll help to investigate and more

             

            adding webhooks (with body) on updated event increeses time of sprint closing. For ex when you'll add few different webhooks on this event and you'll try to close sprint - closing time can even myltiply;/

             

            WORKARAOUD:

            User scriptrunner to create JSON call instead of webhooks (IMHO works without slowing down updating/creating issues)

             

            Pablo added a comment - - edited Few more info - maybe it'll help to investigate and more   adding webhooks (with body) on updated event increeses time of sprint closing. For ex when you'll add few different webhooks on this event and you'll try to close sprint - closing time can even myltiply;/   WORKARAOUD: User scriptrunner to create JSON call instead of webhooks (IMHO works without slowing down updating/creating issues)  

            Ganga Bopaiah added a comment -

            We nowhave end users complain about this, we are 8.5.5 and its still not fixed

            Ganga Bopaiah added a comment - We nowhave end users complain about this, we are 8.5.5 and its still not fixed

            Lady Glencora added a comment -

            Please fix this. It’s not a “feature.”

            Lady Glencora added a comment - Please fix this. It’s not a “feature.”

            Stanton Stevens added a comment -

            Please increase the priority and emphasis on fixing this bug. This is a serious problem. Webhooks should not show down other operations, or at least have as little impact as possible. This problem is having a significant impact on our large Jira instance. 

            Stanton Stevens added a comment - Please increase the priority and emphasis on fixing this bug. This is a serious problem. Webhooks should not show down other operations, or at least have as little impact as possible. This problem is having a significant impact on our large Jira instance. 

            Molamma Xavier added a comment -

            The issue is affected in our system also and facing slowness for issue creation via post function and Cloning . When we can expect the fix.

            Molamma Xavier added a comment - The issue is affected in our system also and facing slowness for issue creation via post function and Cloning . When we can expect the fix.

            Karen Waters added a comment -

            This issue needs fixing

            Karen Waters added a comment - This issue needs fixing

            Boris Berenberg - Atlas Authority added a comment -

            If you happen to already have Notification Assistant for Jira we support REST endpoints as destination in our core functionality. Events are processed off the main thread and while we won't reduce the JQL search impact, we will not block the main UI thread.

            Boris Berenberg - Atlas Authority added a comment - If you happen to already have Notification Assistant for Jira we support REST endpoints as destination in our core functionality. Events are processed off the main thread and while we won't reduce the JQL search impact, we will not block the main UI thread.

            Daniel Holmes added a comment -

            This should be more than a suggestion.  This is just smart coding practice that is not being followed.  Don't delay user action and response for background processing not required for the user action to be determined to be validated and completed.

            Daniel Holmes added a comment - This should be more than a suggestion.  This is just smart coding practice that is not being followed.  Don't delay user action and response for background processing not required for the user action to be determined to be validated and completed.

            Balint Zsolt added a comment -

            I suggest to add two new parameters to the webhook configuration:  project(s) selection and issuetype(s) selection possibility additionally to the JQL query.

            It does not have to be mandatory.

            The webhook first should check for those two parameters and if those match an additional JQL query can be executed if so configured. Checking for project ID and issuetype is a very quick process (nanoseconds) as those parameters are already loaded with the issue and the webhook configs could be cached.

            On a busy site Executing a single JQL query takes in best case scenario several miliseconds. In our logs I see often >100 and sometimes >1000 milisecond warnings for webhook queries.

            Executing a JQL query  (or multiple if we have more than one webhook) every time an issue is created or updated can significantly affect the performance of the whole instance even if it's run in the background.

            This is not a huge change to the Jira code which could lead to significant performance improvement!

            Balint Zsolt added a comment - I suggest to add two new parameters to the webhook configuration:  project(s) selection and issuetype(s) selection possibility additionally to the JQL query. It does not have to be mandatory. The webhook first should check for those two parameters and if those match an additional JQL query can be executed if so configured. Checking for project ID and issuetype is a very quick process (nanoseconds) as those parameters are already loaded with the issue and the webhook configs could be cached. On a busy site Executing a single JQL query takes in best case scenario several miliseconds. In our logs I see often >100 and sometimes >1000 milisecond warnings for webhook queries. Executing a JQL query  (or multiple if we have more than one webhook) every time an issue is created or updated can significantly affect the performance of the whole instance even if it's run in the background. This is not a huge change to the Jira code which could lead to significant performance improvement!

            Nicole Shepherd added a comment -

            Support tells me it is com.atlassian.jira.plugins.webhooks.matcher.JqlEventMatcher_SLOW

            Hope that helps!

             

            Nicole Shepherd added a comment - Support tells me it is  com.atlassian.jira.plugins.webhooks.matcher.JqlEventMatcher_SLOW Hope that helps!  

            Khai Shaun Ng added a comment -

            Hi Nicole, do you mind to share the correct logger Package name for this log? Would like to turn off logging for this as well.

            Khai Shaun Ng added a comment - Hi Nicole, do you mind to share the correct logger Package name for this log? Would like to turn off logging for this as well.

            Nicole Shepherd added a comment -

            I noticed the same behavior and basically what I got from support was to turn off logging for that. It makes the log unreadable otherwise.

            Nicole Shepherd added a comment - I noticed the same behavior and basically what I got from support was to turn off logging for that. It makes the log unreadable otherwise.

            Paul Stallworth added a comment -

            We have a webhook setup for our MS Teams integration and this webhook (and info log line) constantly fire even though the JQL doesn't match. The JQL configured in the Webhook is

            JQL:(project = "HIT Help Desk" or project = JIRA) AND priority > Low

            My atlassian-jira.log is littered with lines like this:

            2020-01-06 11:33:47,300 http-nio-8080-exec-12 INFO almc7987 693x333146x2 inf5fy 172.21.152.195,192.168.25.71 /secure/QuickCreateIssue.jspa [c.a.j.p.webhooks.matcher.JqlEventMatcher_SLOW] JQL query '( {project = "HIT Help Desk"} OR {project = "JIRA"} ) AND {priority > "Low"} AND {key in ("MARCOMM-8668")}' produced lucene query and took '93' ms to run.

            Alex's thought above about being able to set a project scope for webhooks sounds like a good way to address this for many users.

            Paul Stallworth added a comment - We have a webhook setup for our MS Teams integration and this webhook (and info log line) constantly fire even though the JQL doesn't match. The JQL configured in the Webhook is JQL:(project = "HIT Help Desk" or project = JIRA) AND priority > Low My atlassian-jira.log is littered with lines like this: 2020-01-06 11:33:47,300 http-nio-8080-exec-12 INFO almc7987 693x333146x2 inf5fy 172.21.152.195,192.168.25.71 /secure/QuickCreateIssue.jspa [c.a.j.p.webhooks.matcher.JqlEventMatcher_SLOW] JQL query '( {project = "HIT Help Desk" } OR {project = "JIRA" } ) AND {priority > "Low" } AND {key in ( "MARCOMM-8668" )}' produced lucene query and took '93' ms to run. Alex's thought above about being able to set a project scope for webhooks sounds like a good way to address this for many users.

            Alex Gallien added a comment -

            I feel like the ability to limit the scope of what projects a webhook should fire for (outside of the  JQL that runs every time) would be huge here.

            Alex Gallien added a comment - I feel like the ability to limit the scope of what projects a webhook should fire for (outside of the  JQL that runs every time) would be huge here.

            Willis Towers Watson Atlassian Team added a comment -

            There may be a possible work around on this.  These JqlEventMatcher_SLOW entries seem to be triggered by webhooks, so user "Radek Janata" has used a scripted listener (through ScriptRunner) to listen for the specific JQL and call the webhook by that means.  We can't seem to get the details on [the thread where I found this|https://community.atlassian.com/t5/Jira-questions/Tracking-down-slow-and-strange-lucene-queries/qaq-p/250077], but if someone could find that and put it in the workaround here, that would be nice.

            Willis Towers Watson Atlassian Team added a comment - There may be a possible work around on this.  These JqlEventMatcher_SLOW entries seem to be triggered by webhooks, so user "Radek Janata" has used a scripted listener (through ScriptRunner) to listen for the specific JQL and call the webhook by that means.  We can't seem to get the details on [the thread where I found this| https://community.atlassian.com/t5/Jira-questions/Tracking-down-slow-and-strange-lucene-queries/qaq-p/250077 ], but if someone could find that and put it in the workaround here, that would be nice.

            Ronnie Volkmar added a comment - - edited

            This can also affect comments:

            2019-04-19 09:29:50,430 https-jsse-nio-443-exec-33 url:xxx/comment  INFO I304405 569x530511x3 xxx xxx/rest/api/2/issue/xxx/comment [c.a.j.p.webhooks.matcher.JqlEventMatcher_SLOW] JQL query '{issuetype in ("Defect", "Feature", "Customer Issue", "Task")} AND {status changed} AND {assignee in ("xx", "xx", "xx", "xx", "xx", "xx", "xx", "xx", "xx", "xx", "xx", "xx", "xx", "xx", "xx")} AND {key in ("xx")}' produced lucene query and took '5273' ms to run.

            Ronnie Volkmar added a comment - - edited This can also affect comments: 2019-04-19 09:29:50,430 https-jsse-nio-443-exec-33 url:xxx/comment INFO I304405 569x530511x3 xxx xxx/ rest /api/2/issue/xxx/comment [c.a.j.p.webhooks.matcher.JqlEventMatcher_SLOW] JQL query '{issuetype in ( "Defect" , "Feature" , "Customer Issue" , "Task" )} AND {status changed} AND {assignee in ( "xx" , "xx" , "xx" , "xx" , "xx" , "xx" , "xx" , "xx" , "xx" , "xx" , "xx" , "xx" , "xx" , "xx" , "xx" )} AND {key in ( "xx" )}' produced lucene query and took '5273' ms to run.

            Larry Lowe added a comment -

            I'm seeing the exact same issue. Specifically when the webhook has a filter referenced within its JQL.

            Larry Lowe added a comment - I'm seeing the exact same issue. Specifically when the webhook has a filter referenced within its JQL.

            Gaj Umapathy added a comment -

            I guess the same problem is there when editing and updating a ticket is 'Issue Updated' event is used in a webhook? 

            Gaj Umapathy added a comment - I guess the same problem is there when editing and updating a ticket is 'Issue Updated' event is used in a webhook? 

            Chand Chandrasegaram added a comment - - edited

            Alp Yanar (@reporter) Is there any ETA for the fix ? We are affected by this bug too. 

            Chand Chandrasegaram added a comment - - edited Alp Yanar (@reporter) Is there any ETA for the fix ? We are affected by this bug too. 

            David Yu added a comment -

            Also want to illustrate a similar issue in Cloud JRACLOUD-67507 was deemed high enough priority to get fixed. I suspect more users are affected in Server but they just don't realize it. Just the use of Slack integration alone for example requires one webhook per channel. 

            David Yu added a comment - Also want to illustrate a similar issue in Cloud JRACLOUD-67507 was deemed high enough priority to get fixed. I suspect more users are affected in Server but they just don't realize it. Just the use of Slack integration alone for example requires one webhook per channel. 

            Gonchik Tsymzhitov added a comment -

            Hi, team!

            We have affected also.
            Our affected versions are 7.6.3, 7.6.10/

            Thanks
            It will be awesome if you provide bugfix as New year's present

            Cheers,
            Gonchik Tsymzhitov

            Gonchik Tsymzhitov added a comment - Hi, team! We have affected also. Our affected versions are 7.6.3, 7.6.10/ Thanks It will be awesome if you provide bugfix as New year's present Cheers, Gonchik Tsymzhitov

            David Yu added a comment - - edited

            I thought webhooks were ran in the background--but if it's holding up the UI experience, that's not good. I imagine this extends beyond just Create and includes Edit issue actions as well...basically anything the Webhook will compare against.

            David Yu added a comment - - edited I thought webhooks were ran in the background--but if it's holding up the UI experience, that's not good. I imagine this extends beyond just Create and includes Edit issue actions as well...basically anything the Webhook will compare against.

            Suresh Kumar added a comment - - edited

            @here,

            We were affected by this issue and it tremendously affecting our delivery.

            Could you please increase this priority to high and expecting some workaround to retain the application performance immediately.

            Thanks,

            Suresh Kumar G

            Pearson

            Suresh Kumar added a comment - - edited @here, We were affected by this issue and it tremendously affecting our delivery. Could you please increase this priority to high and expecting some workaround to retain the application performance immediately. Thanks, Suresh Kumar G Pearson

            Ignat (Inactive) added a comment - - edited

            Hey,

            I agree with mwarkocz it could be just an improvement request, unless the delay causing issue create dialog to fail.

             

            ayanar, can you please elaborate more in time units on how long the action processing can be delayed because of the webhook? At which threshold we can start observing the dialog is failing? Thanks for the clarification.

            Cheers,
            Ignat Alexeyenko
            Jira Bugmaster.

            Ignat (Inactive) added a comment - - edited Hey, I agree with mwarkocz it could be just an improvement request, unless the delay causing issue create dialog to fail.   ayanar , can you please elaborate more in time units on how long the action processing can be delayed because of the webhook? At which threshold we can start observing the dialog is failing? Thanks for the clarification. Cheers, Ignat Alexeyenko Jira Bugmaster.

              3e387befff2c Patryk Latkowski
              ayanar Alp
              Affected customers:
              141 This affects my team
              Watchers:
              125 Start watching this issue

                Created:
                Updated:
                Resolved: