Merge pull request #4846 from StackStorm/optimize_escaped_dict_fields

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

Author: Kami

.github/workflows/ci.yaml

@@ -40,6 +40,7 @@ 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'

CHANGELOG.rst

@@ -17,11 +17,10 @@ Added
 
   Contributed by @anirudhbagri.
 
-Fixed
-~~~~~
+* Various additional metrics have been added to the action runner service to provide for better
+  operational visibility. (improvement) #4846
 
-* Refactor spec_loader util to use yaml.load with SafeLoader. (security)
-  Contributed by @ashwini-orchestral
+  Contributed by @Kami.
 
 Changed
 ~~~~~~~
@@ -37,12 +36,142 @@ Changed
 
   Contributed by @Kami and @shital.
 
+* Add new ``-x`` argument to the ``st2 execution get`` command which allows
+  ``result`` field to be excluded from the output. (improvement) #4846
+
+* 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.
+
+* Underlying database field type and storage format for the ``Execution``, ``LiveAction``,
+  ``WorkflowExecutionDB``, ``TaskExecutionDB`` and ``TriggerInstanceDB`` database models has
+  changed.
+
+  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 15-20x for write path (storing
+  model in the database) and up to 10x 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).
+
+  The difference is even larger when working with Orquesta workflows.
+
+  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 new format is also around 10-20% more storage efficient which means that it should allows
+  for larger model values (MongoDB document size limit is 16 MB).
+
+  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.
+
+* Add new ``result_size`` field to the ``ActionExecutionDB`` model. This field will only be
+  populated for executions which utilize new field storage format.
+
+  It holds the size of serialzed execution result field in bytes. This field will allow us to
+  implement more efficient execution result retrieval and provide better UX since we will be
+  able to avoid loading execution results in the WebUI for executions with very large results
+  (which cause browser to freeze). (improvement) #4846
+
+  Contributed by @Kami.
+
+* Add new ``/v1/executions/<id>/result[?download=1&compress=1&pretty_format=1]`` API endpoint
+  which can be used used to retrieve or download raw execution result as (compressed) JSON file.
+
+  This endpoint will primarily be used by st2web when executions produce very large results so
+  we can avoid loading, parsing and formatting those very large results as JSON in the browser
+  which freezes the browser window / tab. (improvement) #4846
+
+  Contributed by @Kami.
+
+Improvements
+~~~~~~~~~~~~
+
+* CLI has been updated to use or ``orjson`` when parsing API response and C version of the YAML
+  safe dumper when formatting execution result for display. This should result in speed up when
+  displaying execution result (``st2 execution get``, etc.) for executions with large results.
+
+  When testing it locally, the difference for execution with 8 MB result was 18 seconds vs ~6
+  seconds. (improvement) #4846
+
+  Contributed by @Kami.
+
+* Update various Jinja functiona to utilize C version of YAML ``safe_{load,dump}`` functions and
+  orjson for better performance. (improvement) #4846
+
+  Contributed by @Kami.
+
+* For performance reasons, use ``udatetime`` library for parsing ISO8601 / RFC3339 date strings
+  where possible. (improvement) #4846
+
+  Contributed by @Kami.
+
+Fixed
+~~~~~
+
+* Refactor spec_loader util to use yaml.load with SafeLoader. (security)
+  Contributed by @ashwini-orchestral
+
 * Import ABC from collections.abc for Python 3.10 compatibility. (#5007)
   Contributed by @tirkarthi
 
 * Updated to use virtualenv 20.4.0/PIP20.3.3 and fixate-requirements to work with PIP 20.3.3 #512
   Contributed by Amanda McGuinness (@amanda11 Ammeon Solutions)
 
+* Fix ``st2 execution get --with-schema`` flag.  (bug fix) #4846
+
+  Contributed by @Kami.
+
 3.4.0 - March 02, 2021
 ----------------------
 
@@ -60,8 +189,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
@@ -186,6 +316,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
 
@@ -208,6 +339,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

@@ -63,14 +63,19 @@ 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.
+# The minus in front of st2.st2common.bootstrap filters out logging statements from that module.
+# See https://nose.readthedocs.io/en/latest/usage.html#cmdoption-logging-filter
+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
 
@@ -262,7 +267,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:
@@ -522,6 +527,11 @@ micro-benchmarks: requirements .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"
+	. $(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_string_value"
+	. $(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_string_value"
 	. $(VIRTUALENV_DIR)/bin/activate; pytest --benchmark-only --benchmark-name=short --benchmark-columns=min,max,mean,stddev,median,ops,rounds --benchmark-group-by=group,param:dict_keys_count_and_depth -s -v st2common/benchmarks/micro/test_fast_deepcopy.py -k "test_fast_deepcopy_with_dict_values"
 	. $(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_fast_deepcopy.py -k "test_fast_deepcopy_with_json_fixture_file"
 	. $(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,param:indent_sort_keys_tuple -s -v st2common/benchmarks/micro/test_json_serialization_and_deserialization.py  -k "test_json_dumps"

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 json
+
+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 = json.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