Workflows have large performance (latency) overhead

[nmaludy]

Problem

I've been noticing that calling mistral workflows there is a fairly significant latency on the order of several seconds per workflow.

Scenario

In the reproduction we're going to have a "parent" workflow with 3x tasks each calling a "sub" workflow. The sub workflow is going to have a single task that runs a core.local. The command we're going to run core.local is the sleep command.

Reproduction

examples/actions/nick_sub_workflow.yaml

---
description: Run a local linux command
enabled: true
runner_type: mistral-v2
entry_point: workflows/nick_sub_workflow.yaml
name: nick_sub_workflow
pack: examples
parameters:
  cmd:
    required: true
    type: string

examples/actions/workflows/nick_sub_workflow.yaml

version: '2.0'

examples.nick_sub_workflow:
  type: direct
  input:
    - cmd
  output:
    stdout: <% $.stdout %>
    stderr: <% $.stderr %>
    
  tasks:
    task1:
      action: core.local cmd=<% $.cmd %>
      publish:
        stdout: <% task(task1).result.stdout %>
        stderr: <% task(task1).result.stderr %>

examples/actions/nick_parent_workflow.yaml

---
description: Run a local linux command
enabled: true
runner_type: mistral-v2
entry_point: workflows/nick_parent_workflow.yaml
name: nick_parent_workflow
pack: examples
parameters:
  cmd:
    required: true
    type: string

examples/actions/workflows/nick_parent_workflow.yaml

version: '2.0'

examples.nick_parent_workflow:
  type: direct
  input:
    - cmd
  output:
    stdout: <% $.stdout %>
    
  tasks:
    task1:
      action: examples.nick_sub_workflow cmd=<% $.cmd %>
      publish:
        stdout: <% task(task1).result.stdout %>
        stderr: <% task(task1).result.stderr %>
      on-success:
        - task2

    task2:
      action: examples.nick_sub_workflow cmd=<% $.cmd %>
      publish:
        stdout2: <% task(task2).result.stdout %>
        stderr2: <% task(task2).result.stderr %>
      on-success:
        - task3

    task3:
      action: examples.nick_sub_workflow cmd=<% $.cmd %>
      publish:
        stdout3: <% task(task3).result.stdout %>
        stderr3: <% task(task3).result.stderr %>

Results - Parent

# date --utc --iso-8601=seconds; st2 run examples.nick_parent_workflow cmd="sleep 1"; date --utc --iso-8601=seconds
2017-09-02T01:33:14+0000
...........
id: 59aa0a5aa814c007272e4026
action.ref: examples.nick_parent_workflow
parameters: 
  cmd: sleep 1
status: succeeded
result_task: task3
result: 
  extra:
    state: SUCCESS
    state_info: null
  stderr: ''
  stdout: ''
  tasks:
  - created_at: '2017-09-02 01:33:26'
    id: c4a6a3bb-b211-40fe-8053-1b540fa2d59b
    input: null
    name: task1
    published:
      stderr: ''
      stdout: ''
    result:
      failed: false
      return_code: 0
      stderr: ''
      stdout: ''
      succeeded: true
    state: SUCCESS
    state_info: null
    updated_at: '2017-09-02 01:33:27'
    workflow_execution_id: ba31c3d6-f9e8-470c-b72c-44f140718d38
    workflow_name: examples.nick_sub_workflow
start_timestamp: 2017-09-02T01:33:14.510747Z
end_timestamp: 2017-09-02T01:33:35.810724Z
+-----------------------------+------------------------+-------+--------------------+-----------------+
| id                          | status                 | task  | action             | start_timestamp |
+-----------------------------+------------------------+-------+--------------------+-----------------+
| + 59aa0a5aa814c007272e4029  | succeeded (6s elapsed) | task1 | examples.nick_sub_ | Sat, 02 Sep     |
|                             |                        |       | workflow           | 2017 01:33:14   |
|                             |                        |       |                    | UTC             |
|    59aa0a5ba814c007272e402b | succeeded (1s elapsed) | task1 | core.local         | Sat, 02 Sep     |
|                             |                        |       |                    | 2017 01:33:15   |
|                             |                        |       |                    | UTC             |
| + 59aa0a60a814c007272e402d  | succeeded (5s elapsed) | task2 | examples.nick_sub_ | Sat, 02 Sep     |
|                             |                        |       | workflow           | 2017 01:33:20   |
|                             |                        |       |                    | UTC             |
|    59aa0a61a814c007272e402f | succeeded (1s elapsed) | task1 | core.local         | Sat, 02 Sep     |
|                             |                        |       |                    | 2017 01:33:21   |
|                             |                        |       |                    | UTC             |
| + 59aa0a65a814c007272e4031  | succeeded (5s elapsed) | task3 | examples.nick_sub_ | Sat, 02 Sep     |
|                             |                        |       | workflow           | 2017 01:33:25   |
|                             |                        |       |                    | UTC             |
|    59aa0a66a814c007272e4033 | succeeded (1s elapsed) | task1 | core.local         | Sat, 02 Sep     |
|                             |                        |       |                    | 2017 01:33:26   |
|                             |                        |       |                    | UTC             |
+-----------------------------+------------------------+-------+--------------------+-----------------+
2017-09-02T01:33:37+0000

# st2 execution get --detail 59aa0a5aa814c007272e4026
+-----------------+--------------------------------------------------------------+
| Property        | Value                                                        |
+-----------------+--------------------------------------------------------------+
| id              | 59aa0a5aa814c007272e4026                                     |
| action.ref      | examples.nick_parent_workflow                                |
| context.user    | st2admin                                                     |
| parameters      | {                                                            |
|                 |     "cmd": "sleep 1"                                         |
|                 | }                                                            |
| status          | succeeded (21s elapsed)                                      |
| start_timestamp | Sat, 02 Sep 2017 01:33:14 UTC                                |
| end_timestamp   | Sat, 02 Sep 2017 01:33:35 UTC                                |
| result          | {                                                            |
|                 |     "tasks": [                                               |
|                 |         {                                                    |
|                 |             "state_info": null,                              |
|                 |             "name": "task1",                                 |
|                 |             "workflow_name":                                 |
|                 | "examples.nick_parent_workflow",                             |
|                 |             "created_at": "2017-09-02 01:33:14",             |
|                 |             "updated_at": "2017-09-02 01:33:20",             |
|                 |             "workflow_execution_id": "58e22641-81a1-4dc7     |
|                 | -998b-fffa14d27e80",                                         |
|                 |             "state": "SUCCESS",                              |
|                 |             "result": {                                      |
|                 |                 "extra": {                                   |
|                 |                     "state_info": null,                      |
|                 |                     "state": "SUCCESS"                       |
|                 |                 },                                           |
|                 |                 "tasks": [                                   |
|                 |                     {                                        |
|                 |                         "state_info": null,                  |
|                 |                         "name": "task1",                     |
|                 |                         "created_at": "2017-09-02 01:33:15", |
|                 |                         "updated_at": "2017-09-02 01:33:16", |
|                 |                         "id": "6d329e1f-464f-4ac1-948c-      |
|                 | 9d851a0e2d27",                                               |
|                 |                         "workflow_execution_id":             |
|                 | "2b7c84e1-0433-46a3-abee-b49fb34755d1",                      |
|                 |                         "state": "SUCCESS",                  |
|                 |                         "result": {                          |
|                 |                             "succeeded": true,               |
|                 |                             "failed": false,                 |
|                 |                             "return_code": 0,                |
|                 |                             "stderr": "",                    |
|                 |                             "stdout": ""                     |
|                 |                         },                                   |
|                 |                         "published": {                       |
|                 |                             "stderr": "",                    |
|                 |                             "stdout": ""                     |
|                 |                         },                                   |
|                 |                         "input": null,                       |
|                 |                         "workflow_name":                     |
|                 | "examples.nick_sub_workflow"                                 |
|                 |                     }                                        |
|                 |                 ],                                           |
|                 |                 "stderr": "",                                |
|                 |                 "stdout": ""                                 |
|                 |             },                                               |
|                 |             "published": {                                   |
|                 |                 "stderr": "",                                |
|                 |                 "stdout": ""                                 |
|                 |             },                                               |
|                 |             "input": null,                                   |
|                 |             "id": "5a5b17f5-74f5-4e17-abf5-c10b2d530ce4"     |
|                 |         },                                                   |
|                 |         {                                                    |
|                 |             "state_info": null,                              |
|                 |             "name": "task2",                                 |
|                 |             "workflow_name":                                 |
|                 | "examples.nick_parent_workflow",                             |
|                 |             "created_at": "2017-09-02 01:33:20",             |
|                 |             "updated_at": "2017-09-02 01:33:25",             |
|                 |             "workflow_execution_id": "58e22641-81a1-4dc7     |
|                 | -998b-fffa14d27e80",                                         |
|                 |             "state": "SUCCESS",                              |
|                 |             "result": {                                      |
|                 |                 "tasks": [                                   |
|                 |                     {                                        |
|                 |                         "state_info": null,                  |
|                 |                         "name": "task1",                     |
|                 |                         "workflow_name":                     |
|                 | "examples.nick_sub_workflow",                                |
|                 |                         "created_at": "2017-09-02 01:33:21", |
|                 |                         "updated_at": "2017-09-02 01:33:22", |
|                 |                         "workflow_execution_id": "fb5d67bb-  |
|                 | f2a6-4bc0-a4ae-c818f905bf1f",                                |
|                 |                         "state": "SUCCESS",                  |
|                 |                         "result": {                          |
|                 |                             "succeeded": true,               |
|                 |                             "failed": false,                 |
|                 |                             "return_code": 0,                |
|                 |                             "stderr": "",                    |
|                 |                             "stdout": ""                     |
|                 |                         },                                   |
|                 |                         "published": {                       |
|                 |                             "stderr": "",                    |
|                 |                             "stdout": ""                     |
|                 |                         },                                   |
|                 |                         "input": null,                       |
|                 |                         "id": "474884cc-de3b-49c1-88ea-      |
|                 | 86d5667e6c2a"                                                |
|                 |                     }                                        |
|                 |                 ],                                           |
|                 |                 "stdout": "",                                |
|                 |                 "stderr": "",                                |
|                 |                 "extra": {                                   |
|                 |                     "state_info": null,                      |
|                 |                     "state": "SUCCESS"                       |
|                 |                 }                                            |
|                 |             },                                               |
|                 |             "published": {                                   |
|                 |                 "stderr2": "",                               |
|                 |                 "stdout2": ""                                |
|                 |             },                                               |
|                 |             "input": null,                                   |
|                 |             "id": "b1246c2d-faee-4b8b-8715-16dca0916457"     |
|                 |         },                                                   |
|                 |         {                                                    |
|                 |             "state_info": null,                              |
|                 |             "name": "task3",                                 |
|                 |             "workflow_name":                                 |
|                 | "examples.nick_parent_workflow",                             |
|                 |             "created_at": "2017-09-02 01:33:25",             |
|                 |             "updated_at": "2017-09-02 01:33:30",             |
|                 |             "workflow_execution_id": "58e22641-81a1-4dc7     |
|                 | -998b-fffa14d27e80",                                         |
|                 |             "state": "SUCCESS",                              |
|                 |             "result": {                                      |
|                 |                 "extra": {                                   |
|                 |                     "state_info": null,                      |
|                 |                     "state": "SUCCESS"                       |
|                 |                 },                                           |
|                 |                 "tasks": [                                   |
|                 |                     {                                        |
|                 |                         "state_info": null,                  |
|                 |                         "name": "task1",                     |
|                 |                         "created_at": "2017-09-02 01:33:26", |
|                 |                         "updated_at": "2017-09-02 01:33:27", |
|                 |                         "id":                                |
|                 | "c4a6a3bb-b211-40fe-8053-1b540fa2d59b",                      |
|                 |                         "workflow_execution_id":             |
|                 | "ba31c3d6-f9e8-470c-b72c-44f140718d38",                      |
|                 |                         "state": "SUCCESS",                  |
|                 |                         "result": {                          |
|                 |                             "succeeded": true,               |
|                 |                             "failed": false,                 |
|                 |                             "return_code": 0,                |
|                 |                             "stderr": "",                    |
|                 |                             "stdout": ""                     |
|                 |                         },                                   |
|                 |                         "published": {                       |
|                 |                             "stderr": "",                    |
|                 |                             "stdout": ""                     |
|                 |                         },                                   |
|                 |                         "input": null,                       |
|                 |                         "workflow_name":                     |
|                 | "examples.nick_sub_workflow"                                 |
|                 |                     }                                        |
|                 |                 ],                                           |
|                 |                 "stderr": "",                                |
|                 |                 "stdout": ""                                 |
|                 |             },                                               |
|                 |             "published": {                                   |
|                 |                 "stderr3": "",                               |
|                 |                 "stdout3": ""                                |
|                 |             },                                               |
|                 |             "input": null,                                   |
|                 |             "id": "06dd7260-4fe3-483f-84dd-9a5c686aabe1"     |
|                 |         }                                                    |
|                 |     ],                                                       |
|                 |     "stdout": "",                                            |
|                 |     "extra": {                                               |
|                 |         "state_info": null,                                  |
|                 |         "state": "SUCCESS"                                   |
|                 |     }                                                        |
|                 | }                                                            |
| liveaction      | {                                                            |
|                 |     "runner_info": {                                         |
|                 |         "hostname": "stackstorm.maludy.home",                |
|                 |         "pid": 1025                                          |
|                 |     },                                                       |
|                 |     "parameters": {                                          |
|                 |         "cmd": "sleep 1"                                     |
|                 |     },                                                       |
|                 |     "action_is_workflow": true,                              |
|                 |     "callback": {},                                          |
|                 |     "action": "examples.nick_parent_workflow",               |
|                 |     "id": "59aa0a5aa814c007272e4025"                         |
|                 | }                                                            |
+-----------------+--------------------------------------------------------------+

Results - Sub Workflow 1

# st2 execution get 59aa0a5aa814c007272e4029
id: 59aa0a5aa814c007272e4029
action.ref: examples.nick_sub_workflow
parameters: 
  cmd: sleep 1
status: succeeded (6s elapsed)
result_task: task1
result: 
  failed: false
  return_code: 0
  stderr: ''
  stdout: ''
  succeeded: true
start_timestamp: 2017-09-02T01:33:14.846564Z
end_timestamp: 2017-09-02T01:33:20.524351Z
+--------------------------+------------------------+-------+------------+-----------------+
| id                       | status                 | task  | action     | start_timestamp |
+--------------------------+------------------------+-------+------------+-----------------+
| 59aa0a5ba814c007272e402b | succeeded (1s elapsed) | task1 | core.local | Sat, 02 Sep     |
|                          |                        |       |            | 2017 01:33:15   |
|                          |                        |       |            | UTC             |
+--------------------------+------------------------+-------+------------+-----------------+

# st2 execution get --detail 59aa0a5aa814c007272e4029
+-----------------+--------------------------------------------------------------+
| Property        | Value                                                        |
+-----------------+--------------------------------------------------------------+
| id              | 59aa0a5aa814c007272e4029                                     |
| action.ref      | examples.nick_sub_workflow                                   |
| context.user    | st2admin                                                     |
| parameters      | {                                                            |
|                 |     "cmd": "sleep 1"                                         |
|                 | }                                                            |
| status          | succeeded (6s elapsed)                                       |
| start_timestamp | Sat, 02 Sep 2017 01:33:14 UTC                                |
| end_timestamp   | Sat, 02 Sep 2017 01:33:20 UTC                                |
| result          | {                                                            |
|                 |     "tasks": [                                               |
|                 |         {                                                    |
|                 |             "state_info": null,                              |
|                 |             "name": "task1",                                 |
|                 |             "workflow_name": "examples.nick_sub_workflow",   |
|                 |             "created_at": "2017-09-02 01:33:15",             |
|                 |             "updated_at": "2017-09-02 01:33:16",             |
|                 |             "workflow_execution_id": "2b7c84e1-0433-46a3     |
|                 | -abee-b49fb34755d1",                                         |
|                 |             "state": "SUCCESS",                              |
|                 |             "result": {                                      |
|                 |                 "failed": false,                             |
|                 |                 "stderr": "",                                |
|                 |                 "return_code": 0,                            |
|                 |                 "succeeded": true,                           |
|                 |                 "stdout": ""                                 |
|                 |             },                                               |
|                 |             "published": {                                   |
|                 |                 "stderr": "",                                |
|                 |                 "stdout": ""                                 |
|                 |             },                                               |
|                 |             "input": null,                                   |
|                 |             "id": "6d329e1f-464f-4ac1-948c-9d851a0e2d27"     |
|                 |         }                                                    |
|                 |     ],                                                       |
|                 |     "stdout": "",                                            |
|                 |     "stderr": "",                                            |
|                 |     "extra": {                                               |
|                 |         "state_info": null,                                  |
|                 |         "state": "SUCCESS"                                   |
|                 |     }                                                        |
|                 | }                                                            |
| liveaction      | {                                                            |
|                 |     "runner_info": {                                         |
|                 |         "hostname": "stackstorm.maludy.home",                |
|                 |         "pid": 1060                                          |
|                 |     },                                                       |
|                 |     "parameters": {                                          |
|                 |         "cmd": "sleep 1"                                     |
|                 |     },                                                       |
|                 |     "action_is_workflow": true,                              |
|                 |     "callback": {                                            |
|                 |         "url": "http://0.0.0.0:8989/v2/action_executions     |
|                 | /1d6779dd-ff5b-437b-a900-03485ed17e74",                      |
|                 |         "source": "mistral_v2"                               |
|                 |     },                                                       |
|                 |     "action": "examples.nick_sub_workflow",                  |
|                 |     "id": "59aa0a5aa814c007272e4028"                         |
|                 | }                                                            |
+-----------------+--------------------------------------------------------------+

Results - Sub Workflow 2

# st2 execution get 59aa0a60a814c007272e402d
id: 59aa0a60a814c007272e402d
action.ref: examples.nick_sub_workflow
parameters: 
  cmd: sleep 1
status: succeeded (5s elapsed)
result_task: task1
result: 
  failed: false
  return_code: 0
  stderr: ''
  stdout: ''
  succeeded: true
start_timestamp: 2017-09-02T01:33:20.796377Z
end_timestamp: 2017-09-02T01:33:25.647713Z
+--------------------------+------------------------+-------+------------+-----------------+
| id                       | status                 | task  | action     | start_timestamp |
+--------------------------+------------------------+-------+------------+-----------------+
| 59aa0a61a814c007272e402f | succeeded (1s elapsed) | task1 | core.local | Sat, 02 Sep     |
|                          |                        |       |            | 2017 01:33:21   |
|                          |                        |       |            | UTC             |
+--------------------------+------------------------+-------+------------+-----------------+

# st2 execution get --detail 59aa0a60a814c007272e402d
+-----------------+--------------------------------------------------------------+
| Property        | Value                                                        |
+-----------------+--------------------------------------------------------------+
| id              | 59aa0a60a814c007272e402d                                     |
| action.ref      | examples.nick_sub_workflow                                   |
| context.user    | st2admin                                                     |
| parameters      | {                                                            |
|                 |     "cmd": "sleep 1"                                         |
|                 | }                                                            |
| status          | succeeded (5s elapsed)                                       |
| start_timestamp | Sat, 02 Sep 2017 01:33:20 UTC                                |
| end_timestamp   | Sat, 02 Sep 2017 01:33:25 UTC                                |
| result          | {                                                            |
|                 |     "tasks": [                                               |
|                 |         {                                                    |
|                 |             "state_info": null,                              |
|                 |             "name": "task1",                                 |
|                 |             "workflow_name": "examples.nick_sub_workflow",   |
|                 |             "created_at": "2017-09-02 01:33:21",             |
|                 |             "updated_at": "2017-09-02 01:33:22",             |
|                 |             "workflow_execution_id": "fb5d67bb-f2a6-4bc0     |
|                 | -a4ae-c818f905bf1f",                                         |
|                 |             "state": "SUCCESS",                              |
|                 |             "result": {                                      |
|                 |                 "failed": false,                             |
|                 |                 "stderr": "",                                |
|                 |                 "return_code": 0,                            |
|                 |                 "succeeded": true,                           |
|                 |                 "stdout": ""                                 |
|                 |             },                                               |
|                 |             "published": {                                   |
|                 |                 "stderr": "",                                |
|                 |                 "stdout": ""                                 |
|                 |             },                                               |
|                 |             "input": null,                                   |
|                 |             "id": "474884cc-de3b-49c1-88ea-86d5667e6c2a"     |
|                 |         }                                                    |
|                 |     ],                                                       |
|                 |     "stdout": "",                                            |
|                 |     "stderr": "",                                            |
|                 |     "extra": {                                               |
|                 |         "state_info": null,                                  |
|                 |         "state": "SUCCESS"                                   |
|                 |     }                                                        |
|                 | }                                                            |
| liveaction      | {                                                            |
|                 |     "runner_info": {                                         |
|                 |         "hostname": "stackstorm.maludy.home",                |
|                 |         "pid": 1056                                          |
|                 |     },                                                       |
|                 |     "parameters": {                                          |
|                 |         "cmd": "sleep 1"                                     |
|                 |     },                                                       |
|                 |     "action_is_workflow": true,                              |
|                 |     "callback": {                                            |
|                 |         "url":                                               |
|                 | "http://0.0.0.0:8989/v2/action_executions/af5ead6e-c157-47b5 |
|                 | -b6ce-df4e94448253",                                         |
|                 |         "source": "mistral_v2"                               |
|                 |     },                                                       |
|                 |     "action": "examples.nick_sub_workflow",                  |
|                 |     "id": "59aa0a60a814c007272e402c"                         |
|                 | }                                                            |
+-----------------+--------------------------------------------------------------+

Results - Sub Workflow 3

# st2 execution get 59aa0a60a814c007272e402d
id: 59aa0a60a814c007272e402d
action.ref: examples.nick_sub_workflow
parameters: 
  cmd: sleep 1
status: succeeded (5s elapsed)
result_task: task1
result: 
  failed: false
  return_code: 0
  stderr: ''
  stdout: ''
  succeeded: true
start_timestamp: 2017-09-02T01:33:20.796377Z
end_timestamp: 2017-09-02T01:33:25.647713Z
+--------------------------+------------------------+-------+------------+-----------------+
| id                       | status                 | task  | action     | start_timestamp |
+--------------------------+------------------------+-------+------------+-----------------+
| 59aa0a61a814c007272e402f | succeeded (1s elapsed) | task1 | core.local | Sat, 02 Sep     |
|                          |                        |       |            | 2017 01:33:21   |
|                          |                        |       |            | UTC             |
+--------------------------+------------------------+-------+------------+-----------------+

# st2 execution get --detail 59aa0a60a814c007272e402d
+-----------------+--------------------------------------------------------------+
| Property        | Value                                                        |
+-----------------+--------------------------------------------------------------+
| id              | 59aa0a60a814c007272e402d                                     |
| action.ref      | examples.nick_sub_workflow                                   |
| context.user    | st2admin                                                     |
| parameters      | {                                                            |
|                 |     "cmd": "sleep 1"                                         |
|                 | }                                                            |
| status          | succeeded (5s elapsed)                                       |
| start_timestamp | Sat, 02 Sep 2017 01:33:20 UTC                                |
| end_timestamp   | Sat, 02 Sep 2017 01:33:25 UTC                                |
| result          | {                                                            |
|                 |     "tasks": [                                               |
|                 |         {                                                    |
|                 |             "state_info": null,                              |
|                 |             "name": "task1",                                 |
|                 |             "workflow_name": "examples.nick_sub_workflow",   |
|                 |             "created_at": "2017-09-02 01:33:21",             |
|                 |             "updated_at": "2017-09-02 01:33:22",             |
|                 |             "workflow_execution_id": "fb5d67bb-f2a6-4bc0     |
|                 | -a4ae-c818f905bf1f",                                         |
|                 |             "state": "SUCCESS",                              |
|                 |             "result": {                                      |
|                 |                 "failed": false,                             |
|                 |                 "stderr": "",                                |
|                 |                 "return_code": 0,                            |
|                 |                 "succeeded": true,                           |
|                 |                 "stdout": ""                                 |
|                 |             },                                               |
|                 |             "published": {                                   |
|                 |                 "stderr": "",                                |
|                 |                 "stdout": ""                                 |
|                 |             },                                               |
|                 |             "input": null,                                   |
|                 |             "id": "474884cc-de3b-49c1-88ea-86d5667e6c2a"     |
|                 |         }                                                    |
|                 |     ],                                                       |
|                 |     "stdout": "",                                            |
|                 |     "stderr": "",                                            |
|                 |     "extra": {                                               |
|                 |         "state_info": null,                                  |
|                 |         "state": "SUCCESS"                                   |
|                 |     }                                                        |
|                 | }                                                            |
| liveaction      | {                                                            |
|                 |     "runner_info": {                                         |
|                 |         "hostname": "stackstorm.maludy.home",                |
|                 |         "pid": 1056                                          |
|                 |     },                                                       |
|                 |     "parameters": {                                          |
|                 |         "cmd": "sleep 1"                                     |
|                 |     },                                                       |
|                 |     "action_is_workflow": true,                              |
|                 |     "callback": {                                            |
|                 |         "url":                                               |
|                 | "http://0.0.0.0:8989/v2/action_executions/af5ead6e-c157-47b5 |
|                 | -b6ce-df4e94448253",                                         |
|                 |         "source": "mistral_v2"                               |
|                 |     },                                                       |
|                 |     "action": "examples.nick_sub_workflow",                  |
|                 |     "id": "59aa0a60a814c007272e402c"                         |
|                 | }                                                            |
+-----------------+--------------------------------------------------------------+

Observations

As you can see, each "sub" workflow takes 5s to run, even though the single task only takes 1s to run.

These runs are using the following settings in /etc/st2/st2.conf

[resultstracker]
logging = /etc/st2/logging.resultstracker.conf
query_interval = 0.1
thread_pool_size = 20

[mistral]
jitter_interval = 0

[nmaludy]

Did a little more debugging by enabling debug in all sections in /etc/st2/st2.conf, then ran the example workflow(s) and saved off the logs.

Parent workflow

# date --utc --iso-8601=seconds; st2 run examples.nick_parent_workflow cmd="sleep 1"; date --utc --iso-8601=seconds; st2ctl stop
2017-09-02T02:02:20+0000
...........
id: 59aa112ca814c01d4f7f293f
action.ref: examples.nick_parent_workflow
parameters: 
  cmd: sleep 1
status: succeeded
result_task: task3
result: 
  extra:
    state: SUCCESS
    state_info: null
  stderr: ''
  stdout: ''
  tasks:
  - created_at: '2017-09-02 02:02:32'
    id: 4efaf8d3-ade0-4dab-9a2f-aa7b7dfbe890
    input: null
    name: task1
    published:
      stderr: ''
      stdout: ''
    result:
      failed: false
      return_code: 0
      stderr: ''
      stdout: ''
      succeeded: true
    state: SUCCESS
    state_info: null
    updated_at: '2017-09-02 02:02:34'
    workflow_execution_id: a81a18d9-5aff-4f11-8a92-2409123dfb8b
    workflow_name: examples.nick_sub_workflow
start_timestamp: 2017-09-02T02:02:20.689680Z
end_timestamp: 2017-09-02T02:02:41.999915Z
+-----------------------------+------------------------+-------+--------------------+-----------------+
| id                          | status                 | task  | action             | start_timestamp |
+-----------------------------+------------------------+-------+--------------------+-----------------+
| + 59aa112da814c01d4f7f2942  | succeeded (5s elapsed) | task1 | examples.nick_sub_ | Sat, 02 Sep     |
|                             |                        |       | workflow           | 2017 02:02:21   |
|                             |                        |       |                    | UTC             |
|    59aa112ea814c01d4f7f2944 | succeeded (1s elapsed) | task1 | core.local         | Sat, 02 Sep     |
|                             |                        |       |                    | 2017 02:02:22   |
|                             |                        |       |                    | UTC             |
| + 59aa1133a814c01d4f7f2946  | succeeded (4s elapsed) | task2 | examples.nick_sub_ | Sat, 02 Sep     |
|                             |                        |       | workflow           | 2017 02:02:27   |
|                             |                        |       |                    | UTC             |
|    59aa1133a814c01d4f7f2948 | succeeded (2s elapsed) | task1 | core.local         | Sat, 02 Sep     |
|                             |                        |       |                    | 2017 02:02:27   |
|                             |                        |       |                    | UTC             |
| + 59aa1138a814c01d4f7f294a  | succeeded (4s elapsed) | task3 | examples.nick_sub_ | Sat, 02 Sep     |
|                             |                        |       | workflow           | 2017 02:02:32   |
|                             |                        |       |                    | UTC             |
|    59aa1138a814c01d4f7f294c | succeeded (2s elapsed) | task1 | core.local         | Sat, 02 Sep     |
|                             |                        |       |                    | 2017 02:02:32   |
|                             |                        |       |                    | UTC             |
+-----------------------------+------------------------+-------+--------------------+-----------------+

Sub workflow 1

# st2 execution get 59aa112da814c01d4f7f2942
id: 59aa112da814c01d4f7f2942
action.ref: examples.nick_sub_workflow
parameters: 
  cmd: sleep 1
status: succeeded (5s elapsed)
result_task: task1
result: 
  failed: false
  return_code: 0
  stderr: ''
  stdout: ''
  succeeded: true
start_timestamp: 2017-09-02T02:02:21.326771Z
end_timestamp: 2017-09-02T02:02:26.767052Z
+--------------------------+------------------------+-------+------------+-----------------+
| id                       | status                 | task  | action     | start_timestamp |
+--------------------------+------------------------+-------+------------+-----------------+
| 59aa112ea814c01d4f7f2944 | succeeded (1s elapsed) | task1 | core.local | Sat, 02 Sep     |
|                          |                        |       |            | 2017 02:02:22   |
|                          |                        |       |            | UTC             |
+--------------------------+------------------------+-------+------------+-----------------+

Logs

So i started checking logs between start_timestamp: 2017-09-02T02:02:21.326771Z and end_timestamp: 2017-09-02T02:02:26.767052Z. The key logs i found were in st2resultstracker.log

2017-09-01 22:02:21,464 69134128 DEBUG base [-] Querying external service for results. Context: {'mistral': {'workflow_name': u'examples.nick_parent_workflow', 'execution_id': 'c76a612d-3d26-43d8-8ed4-391a45b88039'}}
2017-09-01 22:02:21,465 69134448 DEBUG base [-] Querying external service for results. Context: {u'mistral': {u'workflow_name': u'encore.wait_for_vm', u'execution_id': u'6a288df1-9407-4697-b7ff-43c014462f80'}}
2017-09-01 22:02:21,468 69134128 INFO mistral_v2 [-] [59aa112ca814c01d4f7f293e] Querying mistral execution c76a612d-3d26-43d8-8ed4-391a45b88039...
2017-09-01 22:02:21,488 69134128 DEBUG httpclient [-] HTTP GET http://127.0.0.1:8989/v2/executions/c76a612d-3d26-43d8-8ed4-391a45b88039 200
2017-09-01 22:02:21,489 69134128 INFO mistral_v2 [-] [59aa112ca814c01d4f7f293e] Query returned status "RUNNING" for mistral execution c76a612d-3d26-43d8-8ed4-391a45b88039.
2017-09-01 22:02:21,508 69134128 DEBUG httpclient [-] HTTP GET http://127.0.0.1:8989/v2/executions/c76a612d-3d26-43d8-8ed4-391a45b88039/tasks 200
2017-09-01 22:02:21,509 69134128 INFO mistral_v2 [-] [59aa112ca814c01d4f7f293e] Querying the following tasks for mistral execution c76a612d-3d26-43d8-8ed4-391a45b88039: task1
2017-09-01 22:02:21,531 69134448 INFO mistral_v2 [-] [59a89cf3a814c00a1bee6bb0] Querying mistral execution 6a288df1-9407-4697-b7ff-43c014462f80...
2017-09-01 22:02:21,544 69134448 DEBUG httpclient [-] HTTP GET http://127.0.0.1:8989/v2/executions/6a288df1-9407-4697-b7ff-43c014462f80 200
2017-09-01 22:02:21,544 69134448 INFO mistral_v2 [-] [59a89cf3a814c00a1bee6bb0] Query returned status "RUNNING" for mistral execution 6a288df1-9407-4697-b7ff-43c014462f80.
2017-09-01 22:02:21,555 69134448 DEBUG httpclient [-] HTTP GET http://127.0.0.1:8989/v2/executions/6a288df1-9407-4697-b7ff-43c014462f80/tasks 200
2017-09-01 22:02:21,555 69134448 INFO mistral_v2 [-] [59a89cf3a814c00a1bee6bb0] Querying the following tasks for mistral execution 6a288df1-9407-4697-b7ff-43c014462f80: wait_for_vm_windows
2017-09-01 22:02:21,586 69134448 DEBUG httpclient [-] HTTP GET http://127.0.0.1:8989/v2/tasks/b495033b-0cec-4795-b590-032a070b9b79 200
2017-09-01 22:02:21,596 69134128 DEBUG httpclient [-] HTTP GET http://127.0.0.1:8989/v2/tasks/c58f862f-441c-4ef1-9f94-ee8258164633 200
2017-09-01 22:02:21,624 69134448 INFO mistral_v2 [-] There are active mistral tasks for 59a89cf3a814c00a1bee6bb0.
2017-09-01 22:02:21,625 69134448 INFO mistral_v2 [-] There are active st2 tasks for 59a89cf3a814c00a1bee6bb0.
2017-09-01 22:02:21,625 69134448 INFO mistral_v2 [-] [59a89cf3a814c00a1bee6bb0] Determined execution status: running
2017-09-01 22:02:21,625 69134448 DEBUG mistral_v2 [-] [59a89cf3a814c00a1bee6bb0] Combined execution result: {'tasks': [{u'state_info': None, u'name': u'wait_for_vm_main', u'created_at': u'2017-08-31 23:34:11', u'updated_at': u'2017-08-31 23:34:11', u'id': u'ed230262-f089-4a4a-a8f8-066f27527a83', u'workflow_execution_id': u'6a288df1-9407-4697-b7ff-43c014462f80', u'state': u'SUCCESS', u'result': None, u'published': {}, u'input': None, u'workflow_name': u'encore.wait_for_vm'}, {'workflow_name': u'encore.wait_for_vm', 'updated_at': None, 'workflow_execution_id': u'6a288df1-9407-4697-b7ff-43c014462f80', 'result': [], 'id': u'b495033b-0cec-4795-b590-032a070b9b79', 'state_info': None, 'name': u'wait_for_vm_windows', 'created_at': u'2017-08-31 23:34:11', 'state': u'RUNNING', 'published': {}, 'input': None}], 'extra': {'state_info': None, 'state': u'RUNNING'}}
2017-09-01 22:02:21,686 69134128 INFO mistral_v2 [-] There are active mistral tasks for 59aa112ca814c01d4f7f293e.
2017-09-01 22:02:21,686 69134128 INFO mistral_v2 [-] There are active st2 tasks for 59aa112ca814c01d4f7f293e.
2017-09-01 22:02:21,686 69134128 INFO mistral_v2 [-] [59aa112ca814c01d4f7f293e] Determined execution status: running
2017-09-01 22:02:21,687 69134128 DEBUG mistral_v2 [-] [59aa112ca814c01d4f7f293e] Combined execution result: {'tasks': [{'workflow_name': u'examples.nick_parent_workflow', 'updated_at': None, 'workflow_execution_id': u'c76a612d-3d26-43d8-8ed4-391a45b88039', 'result': [], 'id': u'c58f862f-441c-4ef1-9f94-ee8258164633', 'state_info': None, 'name': u'task1', 'created_at': u'2017-09-02 02:02:21', 'state': u'RUNNING', 'published': {}, 'input': None}], 'extra': {'state_info': None, 'state': u'RUNNING'}}
2017-09-01 22:02:21,713 69134448 DEBUG channel [-] using channel_id: 1
2017-09-01 22:02:21,730 69134448 DEBUG channel [-] Channel open
2017-09-01 22:02:21,747 69134448 DEBUG channel [-] Closed channel #1
2017-09-01 22:02:21,748 69134448 DEBUG channel [-] using channel_id: 1
2017-09-01 22:02:21,749 69134448 DEBUG channel [-] Channel open
2017-09-01 22:02:21,751 69134448 DEBUG channel [-] Closed channel #1
2017-09-01 22:02:21,764 69134128 DEBUG connection [-] Start from server, version: 0.9, properties: {'information': 'Licensed under the MPL.  See http://www.rabbitmq.com/', 'product': 'RabbitMQ', 'copyright': 'Copyright (C) 2007-2014 GoPivotal, Inc.', 'capabilities': {'exchange_exchange_bindings': True, 'connection.blocked': True, 'authentication_failure_close': True, 'basic.nack': True, 'per_consumer_qos': True, 'consumer_priorities': True, 'consumer_cancel_notify': True, 'publisher_confirms': True}, 'cluster_name': 'rabbit@stackstorm.maludy.home', 'platform': 'Erlang/OTP', 'version': '3.3.5'}, mechanisms: ['AMQPLAIN', 'PLAIN'], locales: [u'en_US']
2017-09-01 22:02:21,768 69134128 DEBUG channel [-] using channel_id: 1
2017-09-01 22:02:21,772 69134128 DEBUG channel [-] Channel open
2017-09-01 22:02:21,777 69134128 DEBUG channel [-] Closed channel #1
2017-09-01 22:02:21,777 69134128 DEBUG channel [-] using channel_id: 1
2017-09-01 22:02:21,779 69134128 DEBUG channel [-] Channel open
2017-09-01 22:02:21,787 69134128 DEBUG channel [-] Closed channel #1
2017-09-01 22:02:22,142 69134128 DEBUG base [-] Adding queries to querier: [<QueryContext id=59aa112ea814c01c7f3b775d,execution_id=59aa112da814c01d4f7f2941,query_context={'mistral': {u'action_execution_id': u'08ddc506-6bab-497c-9dba-732cb8262c39', 'parent': {'workflow_execution_id': u'c76a612d-3d26-43d8-8ed4-391a45b88039', 'workflow_name': u'examples.nick_parent_workflow'}, u'task_id': u'c58f862f-441c-4ef1-9f94-ee8258164633', 'workflow_name': u'examples.nick_sub_workflow', u'task_tags': None, u'task_name': u'task1', u'callback_url': u'/v2/action_executions/08ddc506-6bab-497c-9dba-732cb8262c39', 'execution_id': '72bc9ccb-df10-421a-8e1c-5a21e2cc9f78'}}>]
2017-09-01 22:02:26,564 69134128 DEBUG base [-] Querying external service for results. Context: {u'mistral': {u'workflow_name': u'encore.wait_for_vm', u'execution_id': u'6a288df1-9407-4697-b7ff-43c014462f80'}}
2017-09-01 22:02:26,567 69134448 DEBUG base [-] Querying external service for results. Context: {'mistral': {'workflow_name': u'examples.nick_parent_workflow', 'execution_id': 'c76a612d-3d26-43d8-8ed4-391a45b88039'}}
2017-09-01 22:02:26,570 69134768 DEBUG base [-] Querying external service for results. Context: {'mistral': {u'action_execution_id': u'08ddc506-6bab-497c-9dba-732cb8262c39', 'parent': {'workflow_execution_id': u'c76a612d-3d26-43d8-8ed4-391a45b88039', 'workflow_name': u'examples.nick_parent_workflow'}, u'task_id': u'c58f862f-441c-4ef1-9f94-ee8258164633', 'workflow_name': u'examples.nick_sub_workflow', u'task_tags': None, u'task_name': u'task1', u'callback_url': u'/v2/action_executions/08ddc506-6bab-497c-9dba-732cb8262c39', 'execution_id': '72bc9ccb-df10-421a-8e1c-5a21e2cc9f78'}}
2017-09-01 22:02:26,585 69134128 INFO mistral_v2 [-] [59a89cf3a814c00a1bee6bb0] Querying mistral execution 6a288df1-9407-4697-b7ff-43c014462f80...
2017-09-01 22:02:26,590 69134448 INFO mistral_v2 [-] [59aa112ca814c01d4f7f293e] Querying mistral execution c76a612d-3d26-43d8-8ed4-391a45b88039...
2017-09-01 22:02:26,604 69134448 DEBUG httpclient [-] HTTP GET http://127.0.0.1:8989/v2/executions/c76a612d-3d26-43d8-8ed4-391a45b88039 200
2017-09-01 22:02:26,604 69134448 INFO mistral_v2 [-] [59aa112ca814c01d4f7f293e] Query returned status "RUNNING" for mistral execution c76a612d-3d26-43d8-8ed4-391a45b88039.
2017-09-01 22:02:26,606 69134128 DEBUG httpclient [-] HTTP GET http://127.0.0.1:8989/v2/executions/6a288df1-9407-4697-b7ff-43c014462f80 200
2017-09-01 22:02:26,607 69134128 INFO mistral_v2 [-] [59a89cf3a814c00a1bee6bb0] Query returned status "RUNNING" for mistral execution 6a288df1-9407-4697-b7ff-43c014462f80.
2017-09-01 22:02:26,625 69134128 DEBUG httpclient [-] HTTP GET http://127.0.0.1:8989/v2/executions/6a288df1-9407-4697-b7ff-43c014462f80/tasks 200

If you notice there is a large gap (5s) from 22:02:21 to 22:02:26.

Investigation in code

It looks like this 5s pause is coming from the Query class here:
https://github.com/StackStorm/st2/blob/master/st2common/st2common/query/base.py#L45-L46
https://github.com/StackStorm/st2/blob/master/st2common/st2common/query/base.py#L79-L87

It appears to be a second sleep that's why query_interval does not affect it.

[nmaludy]

This will probably be solved by the notes here: https://docs.stackstorm.com/troubleshooting/mistral.html

We are reworking the design to use HTTP callbacks from Mistral to StackStorm. Until then, these tunable knobs should help.

[humblearner]

@nmaludy : Can you please verify if #3756 improves latency for you ?

[nmaludy]

@humblearner So, using the config shown in that patch (even without the updated code to tweak the queue sleep times) i was able to reduce our workflow executions by a large amount:

old

| + 59dcdb1d032fb689b1ffe5ff | encore.preprovi | st2admin     | succeeded (102s elapsed) | Tue, 10 Oct     | Tue, 10 Oct   |
|                            | sion            |              |                          | 2017 14:37:17   | 2017 14:38:59 |
|                            |                 |              |                          | UTC             | UTC           |
| + 59dd1a54032fb689b1ffe612 | encore.preprovi | st2admin     | succeeded (86s elapsed)  | Tue, 10 Oct     | Tue, 10 Oct   |
|                            | sion            |              |                          | 2017 19:07:00   | 2017 19:08:26 |
|                            |                 |              |                          | UTC             | UTC           |
| + 59dd1e7f032fb689b1ffe625 | encore.preprovi | st2admin     | succeeded (85s elapsed)  | Tue, 10 Oct     | Tue, 10 Oct   |
|                            | sion            |              |                          | 2017 19:24:47   | 2017 19:26:12 |
|                            |                 |              |                          | UTC             | UTC   

new

| + 59dd218a032fb661f8ba80d9 | encore.preprovi | st2admin     | succeeded (35s elapsed)  | Tue, 10 Oct     | Tue, 10 Oct   |
|                            | sion            |              |                          | 2017 19:37:46   | 2017 19:38:21 |
|                            |                 |              |                          | UTC             | UTC           |

I'm closing this an calling it a success!

Thanks @m4dcoder !

[arm4b]

@nmaludy Since you're affected, just FYI #3776 we're going to fine-tune the resultstracker.query_interval st2.conf value to more balanced 5s, which is somewhere between the 2 evils: 1s (new value, good mistral lantency, but big CPU overhead) and 20s (old value, slow mistral, no CPU overhead).

You still can adjust the settings in your st2.conf, but the defaults will be more or less in between.

See #3776 and #3756 (comment) and would like to know if you have any comments there.