Automation very bad performance on first execution

[Rachid El Mansouri]

Hello experts,

I am facing a performance issue when executing automation rule.

"The call to the Jira server did not complete within the timeout period. We are unsure of the result of this operation."

The execution is very long = 150s at the first execution and following execution takink only 0.7s.

I don't understand why it is taking so long and how to fix it. 

Following actions didn't fix the problem : 

• Reindex project
• Full Background reindex
• Restart Jira service
• Upgrade plugin Automation from 7.2.1 to 7.4.1
• remove of 
  • <JIRA_HOME>/plugins/.osgi-plugins/
  • <JIRA_HOME>/plugins/.bundled-plugins

Thank you for your support

[Gonchik Tsymzhitov]

Hi @Rash , 

Could you provide more information please? 

i.e. CPU, RAM , latency. and in the logs Lucene index problems

Do you really need an immediate execution?

Cheers,

Gonchik Tsymzhitov

[Rachid El Mansouri]

Hi @Gonchik Tsymzhitov

On  Defect Report issue we need to create immediately a Defect Fix using Automation rule.

This is taking more than 60s on first execution and following execution take 2s.

This morning i worked on this problem and after making some incremental tests i noticed that the root cause is related to some cascading fields that are present on the Defect Fix creation screen.

After removing these field from the screen the execution time is acceptable (less than 5s).

These cascading fields contain hundreds of options.
I don't know why this is taking too long to load on first execution ? Atlassian Developers should know.

Now that we have probably identified the root cause, do you have any workaround
except removing these cascading fields from creation screen ?

Best regards, 

Rachid

[Mykenna Cepek]

Could you share a screenshot of the configuration of your trigger?

[Rachid El Mansouri]

Hello @Mykenna Cepek, 
Please find attached the configuration of the trigger

[Mykenna Cepek]

Have you tried disabling the "Trigger > More options > Execute this rule immediately..." setting? It's pretty clear about performance impact.

[Rachid El Mansouri]

@Mykenna Cepek Yes we have tried disabling with no more success.

[Mykenna Cepek]

Why does your trigger use the same value for "From status" and "To status". That doesn't make sense to me.

Also, can you share a screenshot of the workflow being used by the project you are using for your testing?

[Rachid El Mansouri]

[Rachid El Mansouri]

We want to fire the trigger "Add FR" on the status "in correction".

Do you have another suggestion on how to do this ?

[Rachid El Mansouri]

@Mykenna Cepek 

I just tried changing the trigger from "issue transitioned" to "manual trigger" : Same behavior it's taking too long to execute 

[Mykenna Cepek]

Ok, let's pivot.

You posted your atlassian-jira.log file, which showed a lot of activity. Based on that snippet, I estimate that the activity shown is occurring about 260 times per second. That could be a tremendous load. So what is it?

The log identifies CommentAssignIssue.jspa -- what's that? I found this documentation:

     CommentAssignIssue (Atlassian JIRA 7.6.1 API)

Essentially, it's a horribly named API call for transitioning an issue.

For it to be called hundreds of times per second (for long periods of time), something must be going terribly wrong.

Can you think of anything in your Jira instance that might be causing over 10,000 issue transitions per minute? This could include:

• Other automation rules
• Workflow post functions
• Other Jira apps/add-ins
• External integrations calling the Jira REST API

[Rachid El Mansouri]

Hello @Mykenna Cepek

Thanks for your reply,

This morning i worked on this problem and after making some incremental tests i noticed that the root cause is related to some cascading fields that are present on the Defect Fix creation screen.

These cascading fields contain hundreds of options.
I don't know why this is taking too long to load on first execution ? Atlassian Developers should know why.

Now that we have probably identified the root cause, do you have any workaround
except removing thos cascading fields from creation screen ?

Best regards,
Rash

[Mykenna Cepek]

I haven't encountered this problem before. Hopefully others here can provide some suggestions from their experience. However, I do have some additional thoughts...

If the fields with all the cascading options are not required on the create screens, perhaps remove them. If they are on the edit screens, people will still have access to them. And issue creation will go faster (when those fields are not needed).

Something else that might be worth trying: put these fields with cascading options into a separate Field Tab. If those fields aren't used very often, that this might postpone the loading of that field data until the user navigates to that Field Tab. Not sure, could be worth a try.

Even though we've seen some concerning server load in your logs, I do wonder if slow browser behavior could account for some of this slowness. Does this delay still happen on your newest, fastest computer/browser with the most RAM and few other things running? I'm thinking about older computers and browsers, low memory and swapping, boated javascript for the page, and very chatty messaging to the server to request each menu cascade option. Something like Chrome's Developer Tools > Network would reveal the messaging going on during a page load. It won't differentiate between the computer/browser and Jira server being slow, but it might reveal how chatty the communication is during a page load. Just more clues.

[Rachid El Mansouri]

Hi @Jimmy Petersson and everybody, 

Thanks for your support. 

Unfortunately, the problem is still there :

The first execution after Jira restart OR after 30-60 min takes almost 60s and the following executions take 2s.

Following actions already done :

• Check the workflow for the transition to 'Add FR' and we don't have other third-party apps post-function configured there.
• Check the Create issue transition after the issue is created from the automation rules. The third-party apps from the validator are disabled and do not have other third-party apps post-functions.
• We can reproduce the problem with some fields removed from the automation.
• The problem is only reproducible once and then the automation rules run fast. We suspect is due to the cache issue that causes the slow on the first try.
• We increased automation.processing.thread.pool.size.per.node to 8 threads
• We enabled Plugin Safe mode (except ScriptRunner and Automation Rules)

If you have any suggestion i would appreciate it.

[Jimmy Petersson]

Hi Rash,

This question is tricky to answer w/o knowing further details about your context.

But there are a few clues in your automation snippet.

1. You are running this as a global rule - this means that any issues being transitioned will be evaluated again the rule. This could be a performance issue if you have lots of projects with lots of issues using these transition states. Advise: Try using a project rule, i e limited to one project, and see if this improves performance

2. Your trigger is transition from In Correction to In Correction - by definition transition should be between different states. I was expecting transition from two separate states, e g New to In Correction. Advise: review to ensure that you are using the correct states, and that these states are not use in other more frequently invoked work-flows

3. Review if you have other project automations or background jobs cannibalising your processing capacity. Project automation is AFAIK executed in a single thread with low(est) priority

Good luck!

//Jimmy

[Rachid El Mansouri]

Hi Jimmy, 

Thank you for your answer.

I applied your suggestions and performance is slightly improved but not fixed.

We still have too long execution times around 60s on first execution.

Do you have another idea ?

[Jimmy Petersson]

Hi Rash,

Usually when a rule has long execution time you end up with it being throttled. This is visible in the project automation audit log. Look for the yellow throttled status and check the entry. It will include the message "This rule execution exceeded allowed service limits for Automation for Jira. View performance insights."

If you select the link for Performance Insights it will show stats of the executed rules, including long avg duration. This could be helpful to understand if you have many rules with long avg duration that potentially is hogging all your resources.

Here is a link to the official documentation on how to optimise rule performance: Link to official documentation. Maybe there are some nuggets there that can lead you further.

If these capacity issues prevails, the next step would be to troubleshoot the server itself and tune it. Luckily, Atlassian has your back here with a really good guide: Link to official documentation.

Good Luck!

//Jimmy

[Rachid El Mansouri]

Hi @Jimmy Petersson 

Thanks for your reply.

Actually, in the audit log the rule status is success and no error message is logged.

On atlassian-jira.log during rule execution i have hundreds lines with follwoing information :

2022-03-30 11:49:27,324+0300 http-nio-8080-exec-9 DEBUG JOEDOE 709x30032x3 zqdss1 X.X.X.X,Y.Y.Y.Y /secure/CommentAssignIssue.jspa [o.objectweb.jotm.jta] Current.getStatus()
2022-03-30 11:49:27,329+0300 http-nio-8080-exec-9 DEBUG JOEDOE 709x30032x3 zqdss1 X.X.X.X,Y.Y.Y.Y /secure/CommentAssignIssue.jspa [o.objectweb.jotm.jta] Current.getStatus()
2022-03-30 11:49:27,334+0300 http-nio-8080-exec-9 DEBUG JOEDOE 709x30032x3 zqdss1 X.X.X.X,Y.Y.Y.Y /secure/CommentAssignIssue.jspa [o.objectweb.jotm.jta] Current.getStatus()
2022-03-30 11:49:27,338+0300 http-nio-8080-exec-9 DEBUG JOEDOE 709x30032x3 zqdss1 X.X.X.X,Y.Y.Y.Y /secure/CommentAssignIssue.jspa [o.objectweb.jotm.jta] Current.getStatus()
2022-03-30 11:49:27,343+0300 http-nio-8080-exec-9 DEBUG JOEDOE 709x30032x3 zqdss1 X.X.X.X,Y.Y.Y.Y /secure/CommentAssignIssue.jspa [o.objectweb.jotm.jta] Current.getStatus()
2022-03-30 11:49:27,347+0300 http-nio-8080-exec-9 DEBUG JOEDOE 709x30032x3 zqdss1 X.X.X.X,Y.Y.Y.Y /secure/CommentAssignIssue.jspa [o.objectweb.jotm.jta] Current.getStatus()

....

Is it normal behavior ?

I remind you that long execution is observed only on after long inactivity on Jira.

Thank you for your support

[Jimmy Petersson]

Hi Rash,

If the issue occurs after a longer period of inactivity in Jira, it could be related to resource limitations. E g other applications on the same server consuming RAM thus pushing idle processes to swap space. 

So the link on server troubleshooting that I shared before could be useful for further investigations.

Best Regards

//Jimmy