Tracking down slow (and strange!) lucene queries

[Katie McGovern]

In our atlassian-jira.log file there are many many INFO warnings about slow lucene queries that frankly don't make much sense. I'm trying to track down where they're coming from, and would appreciate any pointers on how to most effectively track down the offending plugin/dashboard/whatever.

They don't make sense in that the INFO warning statements all take a form similar to this...

JQL query '{project = "foo"} AND {component = "bar"} AND {key in ("baz-123")}' produced lucene query and took '389' ms to run.

... where the key is for a different project than is listed in the first term. They appear never able to positively return any results! Sometimes there are additional terms adede in specifying issuetype, or reporter. But they always specify a key and a project in conflict w each other.

In the atlassian-JIRA.log, these slow queries are attributed to users all across the company, who confirm they're not triggering these via the search interface. Interestingly, the atlassian-jira-slow-queries.log shows a different set of slow queries and none of these ones. 

If it matters, we're on JIRA server 6.4.14, and we have a handful of big plugins installed... Zephyr 2.6.1, ScriptRunner 4.1.3, BigPicture 5.4.2, Agile 6.7.16, Structure 3.3.0.

Thank you for any suggestions! 

[Damian Rosochacki · Accepted solution]

Hi Katie,

Did you ever figure this out?

I'm a little late, but I'm dealing with the same problem right now. I isolated the cause to one of the Slack webhooks I have setup - disabling it stops the INFO statements. Still haven't figured out what's causing it, but at least I've found the culprit. 

[Jan Scherks]

Damian, thanks for this. I had a lot of entries in my log with strange queries that didn't make any sense. I was able to track it down to one rogue webhook. Webhook is disabled and log much cleaner :)

[Katie McGovern]

Somehow missed the notifications for your response last year! But yes, this appears to be it for me as well! 

[Willis Towers Watson Atlassian Team · Accepted solution]

Damian is absolutely correct.  From what I can tell, every event (Issue: created, updated) for EVERY ticket in JIRA is compared to the JQL in the webhook.  If it takes more than 50ms to run, then it puts the INFO into the log.

I've tried simplifying my JQL by adding "updated >= -1m", but that seems to have had little or no effect.  The only thing I can think to do now is to break up my web hooks into multiple simple JQL queries.

[Ganga Bopaiah]

Hey Willis Towers Watson Atlassian Team

Any suggestion on how to breakdown the JQL into simple queries? We have a project called COBALT and the webhook JQL is as simple as project = COBALT and this is configured to trigger for every event create, update and delete in the project.

This Webhook JQL is getting triggered for every issue update that happens in jira, and is slowing down the UI experience that we have end users complain about the lag.

If I disable this webhook, another one is triggered from the list of webhooks and this goes on until all webhooks are disabled and that isn't an option right now.

Is there anything that I can do as a work around?

Thanks

Ganga

[Radek Janata]

I found hundreds of these records in our log, too. JQL searches took from 50 up to 500ms.

You can use various shell commands to retrieve valuable statistics.

Overview of all such records:

grep 'JqlEventMatcher_SLOW' atlassian-jira.log

Total time spent by JQL searches in webhooks in certain period:

grep 'JqlEventMatcher_SLOW' atlassian-jira.log | sed -re "s/.*took '([0-9]+).*/\1/" | awk '{s+=$1} END {print s}'

As we use webhooks quite a lot and they are triggered almost on every Jira issue and many events (comments, edit, created, ...) we decided to move all JQL conditions into ScriptRunner script listeners (as we already use this addon).

The conditions based on project and issues types are easy to rewrite into Groovy. If the condition passes, webhook is called. Conditions in Groovy takes 1-3 ms each.

This way we got rid of inefficient JQL search conditions and optimized webhook calls using Groovy.

[Larry Lowe]

@Radek Janata do you have any examples of migrating webhooks to groovy? What does the webhook look like, and what does the Groovy look like when it calls the webhook?

[Willis Towers Watson Atlassian Team]

Help us, Radek Janata. You're our only hope!

Seriously though, I'm still waiting with baited breath to hear how you use a script listener to call the webhook.  I would be very grateful if you would provide that for us.

[Radek Janata]

My post above was written just after we did some PoC investigation in this area and founding that JQL condition rewritten to ScriptRunner takes significantly less time than JQL condition used in webhooks.

Later we wanted to add calling existing webhooks from the ScriptRunner but found it's a quite a problem. None of the solutions we tried was fully satisfying.

First, we've found out that we are unable to call an existing webhook via Java API. Probably, there's a class/method to do it but we were unable to find it. If anyone know, please let me know.

So we tried two other ways.

1. Calling an existing webhook via REST API

You can trigger a webhook via {{PUT /rest/webhooks/1.0/webhook/{id}}} where {{id}} is the webhook ID per {{AO_4AEACD_WEBHOOK_DAO}} DB table. The problem with this is that the webhook needs some context (what user, what issue, what event, changed fields etc.) and we were not able to pass this data to the webhook. Probably it's possible via the request body but we didn't know the correct syntax.

So, you can trigger a webhook but without context data -> useless.

2. Calling POST request directly from ScriptRunner

Also tried to create custom POST request to our remote server using {{HTTPBuilder}} (find some articles on this topic here in the community). The downside of this solution is that you need to define every single item sent to remote server (current issue ID, username etc.). And there are so many data that you need to pass that it would take us a lot of time to define them all.

So after further investigation we've quit this idea and returned back to using JQL conditions in webhooks.