St2: Large query to /executions fails in mongodb

[JohnWelborn]

The indexes added in 2.1 helped with a similar error but now I'm getting the following using production data that did not reproduce using 2k test executions.

My use case is that I need to query all the parent executions (status, action name, arguments, start/stop time) in the past 24 hours where the action name matches a substring. This allows me to throttle/deny additional requests from users based on a set of policies.

2016-12-13 22:03:54,425 140362311938768 INFO hooks [-] e02fb208-4202-4fee-bd77-1e4d7fe356d8 -  GET /executions with filters={u'limit': u'2000', u'exclude_attributes': u'result,trigger_instance', u'timestamp_gt': u'2016-12-12T22:03:54.403458Z', u'parent': u'null'} (remote_addr='127.0.0.1',method='GET',filters={u'exclude_attributes': u'result,trigger_instance', u'limit': u'2000', u'parent': u'null', u'timestamp_gt': u'2016-12-12T22:03:54.403458Z'},request_id='e02fb208-4202-4fee-bd77-1e4d7fe356d8',path='/executions')
[..]
2016-12-13 22:03:54,430 140362311938768 INFO resource [-] GET all /executions with filters={'start_timestamp__gt': datetime.datetime(2016, 12, 12, 22, 3, 54, 403458, tzinfo=tzutc()), 'order_by': ['+start_timestamp', 'action.ref'], 'parent': u'null'} (offset=0,limit=2000,filters={'start_timestamp__gt': datetime.datetime(2016, 12, 12, 22, 3, 54, 403458, tzinfo=tzutc()), 'order_by': ['+start_timestamp', 'action.ref'], 'parent': u'null'},sort=[])
2016-12-13 22:03:54,578 140362311938768 ERROR hooks [-] API call failed: errmsg: "Sort operation used more than the maximum 33554432 bytes of RAM. Add an index, or specify a smaller limit."
Traceback (most recent call last):
  File "/opt/stackstorm/st2/local/lib/python2.7/site-packages/pecan/core.py", line 631, in __call__
    self.invoke_controller(controller, args, kwargs, state)
  File "/opt/stackstorm/st2/local/lib/python2.7/site-packages/pecan/core.py", line 531, in invoke_controller
    result = controller(*args, **kwargs)
  File "/opt/stackstorm/st2/local/lib/python2.7/site-packages/st2common/rbac/decorators.py", line 61, in func_wrapper
    return func(*args, **kwargs)
  File "/opt/stackstorm/st2/local/lib/python2.7/site-packages/st2common/models/api/base.py", line 284, in callfunction
    raise e
OperationFailure: errmsg: "Sort operation used more than the maximum 33554432 bytes of RAM. Add an index, or specify a smaller limit." (_exception_data={'_OperationFailure__code': 96, '_OperationFailure__details': {u'ok': 0.0, u'code': 96, u'waitedMS': 0L, u'errmsg': u'errmsg: "Sort operation used more than the maximum 33554432 bytes of RAM. Add an index, or specify a smaller limit."'}},_exception_class='OperationFailure',_exception_message='errmsg: "Sort operation used more than the maximum 33554432 bytes of RAM. Add an index, or specify a smaller limit."')

Is it worth increasing internalQueryExecMaxBlockingStortBytes or is there a missing index that would help here? Or is there an index that is not being updated often enough?

Thanks!

[JohnWelborn]

I set it to 128mb and it is working. But if this error could come back... I'm curious if there is a solution with indexes, or if this points out the need for an index.

[Kami]

Thanks for reporting this.

It does look like it's related to a missing index.

Can you please manually run st2api service with --profile and --debug flag and gist the logs? This way we can see exactly which query is executed and which indexes are used - https://docs.stackstorm.com/troubleshooting/database.html#troubleshooting-performance-and-missing-index-related-issues.

You should see something like this - https://gist.github.com/Kami/3123c5c6ab50831eab853a0ef8a88afc

[JohnWelborn]

@Kami https://gist.github.com/JohnWelborn/1e3e93a0d67ca6dc34c269e7da830923

[JohnWelborn]

We hit this error again while using:
db.adminCommand({"setParameter": 1, "internalQueryExecMaxBlockingSortBytes" : 134217728})

Currently there are some executions that have a very large result/stderr output but I'm not sure if that should matter with this sorting limit. That should be resolved soon.

Temporarily can/should we increase this limit? mongo is using 12g out of 24g memory. 7 gig still in cached. We are purging executions older than 24 hours every 6 hours.

[Kami]

@JohnWelborn can you please again follow the steps described above (https://github.com/StackStorm/st2/issues/3111#issuecomment-266981949) and gist the log and the output?

This way we can check if it's a missing index and sorting related issue or something else. Ideally we could prevent this issue without you needing to change internalQueryExecMaxBlockingSortBytes, but we first need to see what is going on.

[JohnWelborn]

@Kami
failure: https://gist.github.com/JohnWelborn/b04f558a3a516075d0bc0f318be86e8f
success: https://gist.github.com/JohnWelborn/fd7dc1ce3e081695003f163887c50262

[estee-tew]

https://stackstorm.slack.com/archives/community/p1492028690236579

[stale[bot]]

Thanks for contributing to this issue. As it has been 90 days since the last activity, we are automatically marking is as stale. If this issue is not relevant or applicable anymore (problem has been fixed in a new version or similar), please close the issue or let us know so we can close it. On the contrary, if the issue is still relevant, there is nothing you need to do, but if you have any additional details or context which would help us when working on this issue, please include it as a comment to this issue.