Optimize storage (serialization and de-serilization) of very large dictionaries inside MongoDB

.github/workflows/ci.yaml

@@ -40,6 +40,10 @@ jobs:
           - name: 'Unit Tests'
             task: 'ci-unit'
             python-version: '3.6'
+          # This job is slow so we only run in on a daily basis
+          # - name: 'Micro Benchmarks'
+          #   task: 'micro-benchmarks'
+          #   python-version: '3.6'
           # Integration tests are not working yet, still done in Travis
           # - name: 'Integration Tests'
           #   task: 'ci-integration'

CHANGELOG.rst

@@ -12,6 +12,48 @@ Changed
 
   Contributed by @Kami.
 
+* Add new ``-x`` argument to the ``st2 execution get`` command which allows
+  ``result`` field to be excluded from the output. (improvement) #4846
+
+* Underlying database field type and storage format for the ``Execution`` and ``LiveAction``
+  database models has changed.
+
+  Contributed by @Kami.
+
+  This new format is much faster and efficient than the previous one. Users with larger executions
+  (executions with larger results) should see the biggest improvements, but the change also scales
+  down so there should also be improvements when reading and writing executions with small and
+  medium sized results.
+
+  Our micro and end to benchmarks have shown improvements up to 10x for write path (storing model
+  in the database) and up to 6x for the read path.
+
+  To put things into perspective - with previous version, running a Python runner action which
+  returns 8 MB result would take around ~18 seconds total, but with this new storage format, it
+  takes around 2 seconds (in this context, duration means the from the time the execution was
+  scheduled to the time the execution model and result was written and available in the database).
+
+  Overall performance improvement doesn't just mean large decrease in those operation timings, but
+  also large overall reduction of CPU usage - previously serializing large results was a CPU
+  intensive time since it included tons of conversions and transformations back and forth.
+
+  The actual change should be fully opaque and transparent to the end users - it's purely a
+  field storage implementation detail and the code takes care of automatically handling both
+  formats when working with those object.
+
+  Same field data storage optimizations have also been applied to workflow related database models
+  which should result in the same performance improvements for Orquesta workflows which pass larger
+  data sets / execution results around.
+
+  Trigger instance payload field has also been updated to use this new field type which should
+  result in lower CPU utilization and better throughput of rules engine service when working with
+  triggers with larger payloads.
+
+  This should address a long standing issue where StackStorm was reported to be slow and CPU
+  inefficient with handling large executions. (improvement) #4846
+
+  Contributed by @Kami.
+
 3.4.0 - March 02, 2021
 ----------------------
 
@@ -29,8 +71,9 @@ Added
 * Added st2-auth-ldap pip requirements for LDAP auth integartion. (new feature) #5082
   Contributed by @hnanchahal
 
-* Added --register-recreate-virtualenvs flag to st2ctl reload to recreate virtualenvs from scratch.
-  (part of upgrade instructions) [#5167]
+* Added --register-recreate-virtualenvs flag to st2ctl reload to recreate virtualenvs from
+  scratch. (part of upgrade instructions) #5167
+
   Contributed by @winem and @blag
 
 Changed
@@ -55,6 +98,39 @@ Changed
 
 * Updated cryptography dependency to version 3.3.2 to avoid CVE-2020-36242 (security) #5151
 
+* Update ``st2 execution get <id>`` command to also display execution ``log`` attribute which
+  includes execution state transition information.
+
+  By default ``end_timestamp`` attribute and ``duration`` attribute displayed in the command
+  output only include the time it took action runner to finish running actual action, but it
+  doesn't include the time it it takes action runner container to fully finish running the
+  execution - this includes persisting execution result in the database.
+
+  For actions which return large results, there could be a substantial discrepancy - e.g.
+  action itself could finish in 0.5 seconds, but writing data to the database could take
+  additional 5 seconds after the action code itself was executed.
+
+  For all purposes until the execution result is  persisted to the database, execution is
+  not considered as finished.
+
+  While writing result to the database action runner is also consuming CPU cycles since
+  serialization of large results is a CPU intensive task.
+
+  This means that "elapsed" attribute and start_timestamp + end_timestamp will make it look
+  like actual action completed in 0.5 seconds, but in reality it took 5.5 seconds (0.5 + 5 seconds).
+
+  Log attribute can be used to determine actual duration of the execution (from
+  start to finish). (improvement) #4846
+
+  Contributed by @Kami.
+
+* Various internal improvements (reducing number of DB queries, speeding up YAML
+  parsing, using DB object cache, etc.) which should speed up pack action
+  registration between 15-30%. This is especially pronounced with packs which
+  have a lot of actions (e.g. aws one). (improvement) #4846
+
+  Contributed by @Kami.
+
 Fixed
 ~~~~~
 
@@ -143,6 +219,7 @@ Added
 
 Changed
 ~~~~~~~
+
 * Switch to MongoDB ``4.0`` as the default version starting with all supported OS's in st2
   ``v3.3.0`` (improvement) #4972
 
@@ -165,6 +242,7 @@ Changed
 
 Fixed
 ~~~~~
+
 * Fixed a bug where `type` attribute was missing for netstat action in linux pack. Fixes #4946
 
   Reported by @scguoi and contributed by Sheshagiri (@sheshagiri)

Makefile

@@ -62,14 +62,17 @@ ifndef PYLINT_CONCURRENCY
 	PYLINT_CONCURRENCY := 1
 endif
 
-NOSE_OPTS := --rednose --immediate --with-parallel --nocapture
+# NOTE: We exclude resourceregistrar DEBUG level log messages since those are very noisy (we
+# loaded resources for every tests) which makes tests hard to troubleshoot on failure due to
+# pages and pages and pages of noise.
+NOSE_OPTS := --rednose --immediate --with-parallel --nocapture --logging-filter=-st2.st2common.bootstrap
 
 ifndef NOSE_TIME
 	NOSE_TIME := yes
 endif
 
 ifeq ($(NOSE_TIME),yes)
-	NOSE_OPTS := --rednose --immediate --with-parallel --with-timer --nocapture
+	NOSE_OPTS := --rednose --immediate --with-parallel --with-timer --nocapture --logging-filter=-st2.st2common.bootstrap
 	NOSE_WITH_TIMER := 1
 endif
 
@@ -261,7 +264,7 @@ check-python-packages-nightly:
 	done
 
 .PHONY: ci-checks-nightly
-ci-checks-nightly: check-python-packages-nightly
+ci-checks-nightly: check-python-packages-nightly micro-benchmarks
 
 .PHONY: checklogs
 checklogs:
@@ -516,6 +519,19 @@ compilepy3:
 	find ${ROOT_DIR}/st2common/st2common/ \( -name \*.py ! -name router\.py -name \*.py \) -type f -print0 | xargs -0 cat | grep st2stream; test $$? -eq 1
 	find ${ROOT_DIR}/st2common/st2common/ -name \*.py -type f -print0 | xargs -0 cat | grep st2exporter; test $$? -eq 1
 
+.PHONY: micro-benchmarks
+micro-benchmarks: requirements .micro-benchmarks
+
+.PHONY: .micro-benchmarks
+.micro-benchmarks:
+	@echo
+	@echo "==================== micro-benchmarks ===================="
+	@echo
+	. $(VIRTUALENV_DIR)/bin/activate; pytest --benchmark-only --benchmark-name=short --benchmark-columns=min,max,mean,stddev,median,ops,rounds --benchmark-group-by=group,param:fixture_file -s -v st2common/benchmarks/micro/test_mongo_field_types.py -k "test_save_large_execution"
+	. $(VIRTUALENV_DIR)/bin/activate; pytest --benchmark-only --benchmark-name=short --benchmark-columns=min,max,mean,stddev,median,ops,rounds --benchmark-group-by=group,param:fixture_file -s -v st2common/benchmarks/micro/test_mongo_field_types.py -k "test_read_large_execution"
+	. $(VIRTUALENV_DIR)/bin/activate; pytest --benchmark-only --benchmark-name=short --benchmark-columns=min,max,mean,stddev,median,ops,rounds --benchmark-group-by=group,param:fixture_file -s -v st2common/benchmarks/micro/test_mongo_field_types.py -k "test_save_multiple_fields"
+
+
 .PHONY: .cleanmongodb
 .cleanmongodb:
 	@echo "==================== cleanmongodb ===================="

conf/st2.dev.conf

@@ -1,6 +1,8 @@
 # Config used by local development environment (tools/launch.dev.sh)
 [database]
 host = 127.0.0.1
+use_json_dict_field = True
+json_dict_field_backend = ujson
 
 [api]
 # Host and port to bind the API server.

contrib/core/requirements-tests.txt

@@ -1 +1 @@
-mail-parser>=3.9.1,<3.10.0
+mail-parser==3.15.0

contrib/core/tests/test_action_sendmail.py

@@ -20,7 +20,6 @@
 import tempfile
 import socket
 
-import six
 import mock
 import mailparser
 
@@ -126,20 +125,12 @@ def test_sendmail_utf8_subject_and_body(self):
             "attachments": "",
         }
 
-        if six.PY2:
-            expected_body = (
-                "Hello there 😃😃.\n"
-                "<br><br>\n"
-                "This message was generated by StackStorm action "
-                "send_mail running on %s" % (HOSTNAME)
-            )
-        else:
-            expected_body = (
-                "Hello there \\U0001f603\\U0001f603.\n"
-                "<br><br>\n"
-                "This message was generated by StackStorm action "
-                "send_mail running on %s" % (HOSTNAME)
-            )
+        expected_body = (
+            "Hello there 😃😃.\n"
+            "<br><br>\n"
+            "This message was generated by StackStorm action "
+            "send_mail running on %s" % (HOSTNAME)
+        )
 
         status, _, email_data, message = self._run_action(
             action_parameters=action_parameters
@@ -167,18 +158,11 @@ def test_sendmail_utf8_subject_and_body(self):
             "attachments": "",
         }
 
-        if six.PY2:
-            expected_body = (
-                "Hello there 😃😃.\n\n"
-                "This message was generated by StackStorm action "
-                "send_mail running on %s" % (HOSTNAME)
-            )
-        else:
-            expected_body = (
-                "Hello there \\U0001f603\\U0001f603.\n\n"
-                "This message was generated by StackStorm action "
-                "send_mail running on %s" % (HOSTNAME)
-            )
+        expected_body = (
+            "Hello there 😃😃.\n\n"
+            "This message was generated by StackStorm action "
+            "send_mail running on %s" % (HOSTNAME)
+        )
 
         status, _, email_data, message = self._run_action(
             action_parameters=action_parameters
@@ -271,10 +255,6 @@ def _run_action(self, action_parameters):
             email_data = result["stdout"]
             email_data = email_data.split("\n")[:-2]
             email_data = "\n".join(email_data)
-
-            if six.PY2 and isinstance(email_data, six.text_type):
-                email_data = email_data.encode("utf-8")
-
             message = mailparser.parse_from_string(email_data)
         else:
             email_data = None

contrib/examples/actions/orquesta-data-flow-large-data.yaml

@@ -0,0 +1,11 @@
+---
+name: orquesta-data-flow-large-data
+description: A basic workflow which passes large JSON data around.
+runner_type: orquesta
+entry_point: workflows/orquesta-data-flow-large-data.yaml
+enabled: true
+parameters:
+  file_path:
+    type: string
+    required: true
+    description: "Path to the JSON fixture file to use."

contrib/examples/actions/python_runner_load_and_print_fixture.meta.yaml

@@ -0,0 +1,11 @@
+---
+name: python_runner_load_and_print_fixture
+description: Action which loads provided JSON fixture file, parses it and returns it as an action result. Useful when testing and benchmarking execution save timing.
+runner_type: "python-script"
+enabled: true
+entry_point: pythonactions/load_and_print_fixture.py
+parameters:
+    file_path:
+        type: "string"
+        required: true
+        description: "Path to the JSON fixture file to use."

contrib/examples/actions/pythonactions/load_and_print_fixture.py

@@ -0,0 +1,12 @@
+import orjson
+
+from st2common.runners.base_action import Action
+
+
+class LoadAndPrintFixtureAction(Action):
+    def run(self, file_path: str):
+        with open(file_path, "r") as fp:
+            content = fp.read()
+
+        data = orjson.loads(content)
+        return data

contrib/examples/actions/workflows/orquesta-data-flow-large-data.yaml

@@ -0,0 +1,37 @@
+version: 1.0
+
+description: A basic workflow which passes large data around.
+
+input:
+  - file_path
+  - b1: <% ctx().file_path %>
+
+vars:
+  - a2: <% ctx().b1 %>
+  - b2: <% ctx().a2 %>
+
+output:
+  - a5: <% ctx().b4 %>
+  - b5: <% ctx().a5 %>
+
+tasks:
+  task1:
+    action: core.echo
+    input:
+      message: <% ctx().b2 %>
+    next:
+      - when: <% succeeded() %>
+        publish:
+          - a3: <% result().stdout %>
+          - b3: <% ctx().a3 %>
+        do: task2
+  task2:
+    action: examples.load_and_print_fixture
+    input:
+      file_path: <% ctx().file_path %>
+    next:
+      - when: <% succeeded() %>
+        publish: a4=<% result().result %> b4=<% ctx().a4 %>
+        do: task3
+  task3:
+    action: core.noop

fixed-requirements.txt

@@ -63,4 +63,5 @@ python-dateutil==2.8.0
 python-statsd==2.1.0
 prometheus_client==0.1.1
 ujson==1.35
+orjson==3.4.8
 zipp>=0.5,<=1.0.0

requirements.txt

@@ -36,6 +36,7 @@ networkx==1.11
 nose
 nose-parallel==0.3.1
 nose-timer==0.7.5
+orjson==3.4.8
 oslo.config<1.13,>=1.12.1
 oslo.utils<5.0,>=4.0.0
 paramiko==2.7.1