st2api being bogged down by MongoEngine

Working recently with a bunch of large workflows and seeing the st2api service using 100% CPU.

I turned on a wsgi profiler (https://medium.com/@maxmaxmaxmax/measuring-performance-of-python-based-apps-using-gunicorn-and-cprofile-ee4027b2be41) and am seeing profile stacktraces like so:

2018-03-08 19:59:43,333 100167760 ERROR wsgi_profiler [-] 
[4525] [INFO] [POST] URI /v1/actionexecutions
2018-03-08 19:59:43,333 100167760 ERROR wsgi_profiler [-] [4525] [INFO]          21554881 function calls (20361663 primitive calls) in 60.828 seconds

   Ordered by: internal time, cumulative time
   List reduced from 1272 to 30 due to restriction <30>

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
  3888837    4.593    0.000    4.651    0.000 {isinstance}
    45770    3.272    0.000   25.510    0.001 /opt/stackstorm/st2/lib/python2.7/site-packages/mongoengine/base/document.py:36(__init__)
   374817    2.745    0.000    8.031    0.000 /opt/stackstorm/st2/lib/python2.7/site-packages/mongoengine/base/fields.py:123(__set__)
874662/830081    2.720    0.000   12.477    0.000 /opt/stackstorm/st2/lib/python2.7/site-packages/mongoengine/base/document.py:144(__setattr__)
53587/1799    2.446    0.000   11.942    0.007 /opt/stackstorm/st2/lib/python2.7/site-packages/mongoengine/dereference.py:163(_attach_objects)
1452191/1255348    2.137    0.000    6.932    0.000 {getattr}
  1052620    2.072    0.000    4.654    0.000 /opt/stackstorm/st2/lib/python2.7/site-packages/mongoengine/base/datastructures.py:382(__getitem__)
   874913    1.789    0.000    2.500    0.000 /opt/stackstorm/st2/lib/python2.7/site-packages/mongoengine/common.py:5(_import_class)
879819/506309    1.747    0.000   12.198    0.000 {setattr}
   640806    1.711    0.000    5.291    0.000 /opt/stackstorm/st2/lib/python2.7/site-packages/mongoengine/base/datastructures.py:396(get)
  1901626    1.603    0.000    1.603    0.000 {method 'get' of 'dict' objects}
   466160    1.531    0.000    4.158    0.000 /opt/stackstorm/st2/lib/python2.7/site-packages/mongoengine/base/datastructures.py:410(iteritems)
45637/1056    1.477    0.000   48.524    0.046 /opt/stackstorm/st2/lib/python2.7/site-packages/mongoengine/base/document.py:672(_from_son)
53587/1799    1.432    0.000    4.081    0.002 /opt/stackstorm/st2/lib/python2.7/site-packages/mongoengine/dereference.py:80(_find_references)
     59/0    1.337    0.023    0.000          /opt/stackstorm/st2/lib/python2.7/site-packages/pymongo/auth.py:482(authenticate)
   187230    1.191    0.000    1.191    0.000 /opt/stackstorm/st2/lib/python2.7/site-packages/mongoengine/base/datastructures.py:454(__getattr__)
    45770    1.177    0.000    1.417    0.000 /opt/stackstorm/st2/lib/python2.7/site-packages/mongoengine/base/datastructures.py:435(create)
155175/1491    1.032    0.000   30.454    0.020 /opt/stackstorm/st2/lib/python2.7/site-packages/mongoengine/base/fields.py:299(to_python)
   878632    1.032    0.000    1.032    0.000 {hasattr}
   421229    0.874    0.000    0.874    0.000 /opt/stackstorm/st2/lib/python2.7/site-packages/mongoengine/base/datastructures.py:463(__setattr__)
   421229    0.863    0.000    2.633    0.000 /opt/stackstorm/st2/lib/python2.7/site-packages/mongoengine/base/datastructures.py:389(__setitem__)
   281293    0.810    0.000    4.409    0.000 /opt/stackstorm/st2/lib/python2.7/site-packages/mongoengine/base/fields.py:113(__get__)
    88774    0.808    0.000    1.567    0.000 /opt/stackstorm/st2/lib/python2.7/site-packages/mongoengine/base/datastructures.py:113(__getitem__)
    55696    0.711    0.000    4.900    0.000 /opt/stackstorm/st2/lib/python2.7/site-packages/mongoengine/base/datastructures.py:426(__len__)
   222834    0.693    0.000    0.693    0.000 {method 'replace' of 'datetime.datetime' objects}
   466160    0.668    0.000    1.014    0.000 /opt/stackstorm/st2/lib/python2.7/site-packages/mongoengine/base/datastructures.py:424(<genexpr>)
    47312    0.647    0.000   18.743    0.000 /opt/stackstorm/st2/lib/python2.7/site-packages/mongoengine/base/fields.py:252(__get__)
114474/82442    0.637    0.000    1.464    0.000 /usr/lib64/python2.7/copy.py:145(deepcopy)
    44602    0.622    0.000    1.341    0.000 /opt/stackstorm/st2/lib/python2.7/site-packages/st2common/fields.py:67(_datetime_to_microseconds_since_epoch)
    89078    0.610    0.000    1.621    0.000 /opt/stackstorm/st2/lib/python2.7/site-packages/st2common/fields.py:52(_microseconds_since_epoch_to_datetime)

And general times reaching 100+ seconds as i let it go for longer and longer

[6397] [INFO] [POST] URI /v1/actionexecutions Total time: 100.877137899

This is reproduced using the following action workflow:

---
description: Run a local linux command
enabled: true
runner_type: mistral-v2
entry_point: workflows/mistral-nested.yaml
name: mistral-nested
pack: examples
parameters:
  cmd:
    required: true
    type: string
    default: "ls"
  timeout:
    type: integer
    default: 60

version: '2.0'

examples.mistral-nested:
    description: A basic workflow that runs an arbitrary linux command.
    type: direct
    input:
        - cmd
        - timeout
        - task_names:
            - 'snmp'
            
    output:
      stdout: "{{ _.stdout }}"
        
    tasks:
      main:
        action: core.local
        input:
          cmd: "{{ _.cmd }}"
        publish:
          stdout: "main {{ task('main').result.stdout }}"
        on-complete:
          - nested_workflow_1

      nested_workflow_1:
        with-items: "x in {{ range(0, 250, 1) }}"
        action: examples.mistral-jinja-workbook-complex
        input:
          vm_name: "{{ _.cmd }}_{{ _.x }}"
        publish:
          stdout: "{{ task('nested_workflow_1').result }}"

Start at the st2api POST /v1/actionexecutions entry point and reproduce the profiler trace with the supplied nested Mistral workflow. Compare the MongoEngine and PyMongo-heavy paths involved in processing the large workflow, then verify that the reproduction no longer drives st2api to 100% CPU and that request time improves.