Troubleshooting slow rule executions in Automation for Jira

Still need help?

The Atlassian Community is here for you.

Ask the community


  

Platform Notice: Cloud, Server, and Data Center - This article applies equally to all platforms.

Support for Server* products ended on February 15th 2024. If you are running a Server product, you can visit the Atlassian Server end of support announcement to review your migration options.

*Except Fisheye and Crucible

  

Summary

Using the audit log, we might eventually find that some rules are taking a longer time to execute than expected.

The first step is to check the Optimize rules page to view general rule best practices.

Starting in Automation for Jira 7.4.0, we can export the log to JSON and find more details about the rule execution.

Diagnosis

After exporting the log, format the JSON data to make it readable. Editors such as Sublime and VS Code have tools for that, but there are several online pages that can do the job too.

Let's take one example to start our analysis:

{
    "items": [
        {
            "id": 741068,
            "summary": "Create issue on transition",
            "authorKey": "jiraadmin",
            "created": 1643673518072,
            "startExecution": 1643673518072,
            "endExecution": 1643673595145,
            "category": "SUCCESS",
            "eventSource": "jira.issue.event.trigger:transitioned",
            "objectItem": {
                "id": 1229,
                "name": "Create issue on transition",
                "typeName": "jira.issue.event.trigger:transitioned"
            },
            "globalAssociatedItems": [],
            "globalMessages": [],
            "componentChanges": [
                {
                    "id": 1706137,
                    "componentId": 60056,
                    "component": "ACTION",
                    "componentNameKey": "Create issue",
                    "startTime": 1643673589202,
                    "duration": 11882,
                    "associatedItems": {
                        "limit": 9223372036854775807,
                        "offset": 0,
                        "total": 0,
                        "results": []
                    },
                    "changeItems": {
                        "limit": 9223372036854775807,
                        "offset": 0,
                        "total": 1,
                        "results": [
                            {
                                "fieldName": "Issues created successfully",
                                "changeTo": "SD-123"
                            }
                        ]
                    }
                },
                {
                    "id": 1706136,
                    "componentId": 60054,
                    "component": "CONDITION_BLOCK",
                    "componentNameKey": "If block",
                    "startTime": 1643673539852,
                    "duration": 98700,
                    "associatedItems": {
                        "limit": 9223372036854775807,
                        "offset": 0,
                        "total": 0,
                        "results": []
                    },
                    "changeItems": {
                        "limit": 9223372036854775807,
                        "offset": 0,
                        "total": 1,
                        "results": [
                            {
                                "fieldName": "The following issues passed:",
                                "changeTo": "SD-122"
                            }
                        ]
                    }
                },
                {
                    "id": 1706135,
                    "componentId": 60052,
                    "component": "TRIGGER",
                    "componentNameKey": "Issue event",
                    "startTime": 1643673518085,
                    "duration": 43534,
                    "associatedItems": {
                        "limit": 9223372036854775807,
                        "offset": 0,
                        "total": 1,
                        "results": [
                            {
                                "id": "154644",
                                "name": "SD-122",
                                "typeName": "ISSUE",
                                "parentId": "10001",
                                "parentName": "SD"
                            }
                        ]
                    },
                    "changeItems": {
                        "limit": 9223372036854775807,
                        "offset": 0,
                        "total": 0,
                        "results": []
                    }
                }
            ],
            "projectIds": [
                "10001"
            ],
            "duration": 77071
        },
        {
            "id":...

Each one of the items is a rule execution.

At the beginning of the data, there are data that is more of an overview, and is generally available in the UI. The most important fields for the troubleshooting are:

  • summary - rule name
  • created - rule trigger time
  • startExecution - the execution start date
  • endExecution - the execution end date
  • category - the item status
(info) All dates are in epoch times, in milliseconds. To convert to actual dates, use a command or an online tool such as https://www.epochconverter.com/.
To find the rule execution duration, just subtract the startExecution from the endExecution times.

The most interesting reason to export the log is to inspect details about each component, which are under componentChanges.

  • The components are ordered from bottom to top, so we see the trigger at the bottom.
  • Each component has its duration in milliseconds and its startTime. This helps us understand which component is the main offender, or if there is a general slowness.
  • Under results, we can see the results from that component. This will tell us the actions effectively performed by each component and might help understand longer execution times.

Solution

While there is not a standard solution for all situations, here are some of the most common ones below.

  • Check the Optimize rules page for rule best practices.
  • If using JQL in a component, try to use smart values. If not possible, check Factors contributing to JQL performance in Jira Server and Data Center.
  • If there's a considerable difference between the created and startExecution dates. This could mean that rules are being queued - that is, rule creation rate was higher than the server's capacity to process.
    • Try to optimize other rules.
    • Verify database performance.
    • If the server CPU is not high, consider increasing the number of threads for Automation for Jira in its configured Service Limits (automation.processing.thread.pool.size.per.node property)
      (info) To avoid general performance issues, perform this increase in small steps.
  • If all items are taking long times, without an apparent reason:
    • Configure audit log expiration, as it might have grown too large: Expire audit log items
    • Check the database performance.

Last modified on Dec 26, 2023

Was this helpful?

Yes
No
Provide feedback about this article
Powered by Confluence and Scroll Viewport.