SERVER-63565 Validate tests runtime in burn-in

6 files changed, 169 insertions, 15 deletions

diff --git a/buildscripts/patch_builds/task_generation.py b/buildscripts/patch_builds/task_generation.py
index 7eb0e3f5bf2..fa2cc0cc5c3 100644
--- a/buildscripts/patch_builds/task_generation.py
+++ b/buildscripts/patch_builds/task_generation.py
@@ -49,6 +49,7 @@ def resmoke_commands(run_tests_fn_name: str, run_tests_vars: Dict[str, Any],
         FunctionCall(CONFIGURE_EVG_CREDENTIALS),
         FunctionCall(DO_MULTIVERSION_SETUP) if require_multiversion_setup else None,
         FunctionCall(run_tests_fn_name, run_tests_vars),
+        FunctionCall("validate resmoke tests runtime"),
     ]
 
     return [cmd for cmd in commands if cmd]
diff --git a/buildscripts/resmoke_tests_runtime_validate.py b/buildscripts/resmoke_tests_runtime_validate.py
new file mode 100644
index 00000000000..cffcbf48e9d
--- /dev/null
+++ b/buildscripts/resmoke_tests_runtime_validate.py
@@ -0,0 +1,123 @@
+#!/usr/bin/env python3
+"""Utility to validate resmoke tests runtime."""
+import json
+import sys
+from collections import namedtuple
+from datetime import datetime, timedelta
+from statistics import mean
+from typing import Dict, List
+
+import click
+import structlog
+
+from buildscripts.resmokelib.testing.report import TestInfo, TestReport
+from buildscripts.resmokelib.utils import get_task_name_without_suffix
+from buildscripts.util.cmdutils import enable_logging
+from evergreen import RetryingEvergreenApi, TestStats
+
+LOGGER = structlog.get_logger("buildscripts.resmoke_tests_runtime_validate")
+
+LOOK_BACK_NUM_DAYS = 20
+BURN_IN_PREFIX = "burn_in:"
+
+HISTORIC_MAX_MULTIPLIER = 1.5
+IGNORE_LESS_THAN_SECS = 15
+
+_TestData = namedtuple("TestData", ["test_file", "duration"])
+
+
+def parse_resmoke_report(report_file: str) -> List[TestInfo]:
+    """Get js tests info from resmoke report json."""
+    with open(report_file, "r") as fh:
+        report_data = json.load(fh)
+    test_report = TestReport.from_dict(report_data)
+    return [test_info for test_info in test_report.test_infos if "jstests" in test_info.test_file]
+
+
+def get_historic_stats(evg_api_config: str, project_id: str, test_files: List[str], task_name: str,
+                       build_variant: str) -> List[TestStats]:
+    """Get historic test stats."""
+    evg_api = RetryingEvergreenApi.get_api(config_file=evg_api_config)
+    before_date = datetime.today()
+    after_date = before_date - timedelta(days=LOOK_BACK_NUM_DAYS)
+    base_task_name = get_task_name_without_suffix(task_name, build_variant).replace(
+        BURN_IN_PREFIX, "")
+    return evg_api.test_stats_by_project(project_id=project_id, after_date=after_date,
+                                         before_date=before_date, tests=test_files,
+                                         tasks=[base_task_name], variants=[build_variant])
+
+
+def make_stats_map(stats: List[_TestData]) -> Dict[str, List[float]]:
+    """Make test stats map."""
+    stats_map = {}
+
+    for stat in stats:
+        if stat.test_file in stats_map:
+            stats_map[stat.test_file].append(stat.duration)
+        else:
+            stats_map[stat.test_file] = [stat.duration]
+
+    return stats_map
+
+
+@click.command()
+@click.option("--resmoke-report-file", type=str, required=True,
+              help="Location of resmoke's report JSON file.")
+@click.option("--evg-api-config", type=str, required=True,
+              help="Location of evergreen api configuration.")
+@click.option("--project-id", type=str, required=True, help="Evergreen project id.")
+@click.option("--build-variant", type=str, required=True, help="Evergreen build variant name.")
+@click.option("--task-name", type=str, required=True, help="Evergreen task name.")
+def main(resmoke_report_file: str, evg_api_config: str, project_id: str, build_variant: str,
+         task_name: str) -> None:
+    """Compare resmoke tests runtime with historic stats."""
+    enable_logging(verbose=False)
+
+    current_test_infos = parse_resmoke_report(resmoke_report_file)
+    current_stats_map = make_stats_map([
+        _TestData(test_info.test_file, test_info.end_time - test_info.start_time)
+        for test_info in current_test_infos
+    ])
+
+    historic_stats = get_historic_stats(evg_api_config, project_id, list(current_stats_map.keys()),
+                                        task_name, build_variant)
+    historic_stats_map = make_stats_map([
+        _TestData(test_stats.test_file, test_stats.avg_duration_pass)
+        for test_stats in historic_stats
+    ])
+
+    failed = False
+
+    for test, stats in current_stats_map.items():
+        current_mean = mean(stats)
+        if current_mean < IGNORE_LESS_THAN_SECS:
+            continue
+
+        historic_test_stats = historic_stats_map.get(test)
+        if historic_test_stats:
+            historic_max = max(historic_test_stats)
+            target = historic_max * HISTORIC_MAX_MULTIPLIER
+            if current_mean > target:
+                LOGGER.error("Found long running test.", test_file=test,
+                             current_mean_time=current_mean, maximum_expected_time=target,
+                             historic_max_time=historic_max)
+                failed = True
+
+    LOGGER.info("Done comparing resmoke tests runtime with historic stats.")
+    if failed:
+        percent = int((HISTORIC_MAX_MULTIPLIER - 1) * 100)
+        LOGGER.error(
+            f"The test failed due to its runtime taking {percent}% more than the recent max"
+            " and can negatively contribute to the future patch build experience."
+            " Consider checking if there is an unexpected regression.")
+        LOGGER.error("If the test is being intentionally expanded, please split it up into separate"
+                     " JS files that run as separate tests.")
+        LOGGER.error(
+            "If you believe the test has inherently large variability, please consider writing"
+            " a new test instead of modifying this one.")
+        LOGGER.error("For any other questions or concerns, please reach out to #server-testing.")
+        sys.exit(1)
+
+
+if __name__ == '__main__':
+    main()  # pylint: disable=no-value-for-parameter
diff --git a/buildscripts/resmokelib/testing/report.py b/buildscripts/resmokelib/testing/report.py
index bb9198bd57c..51804f9d8f8 100644
--- a/buildscripts/resmokelib/testing/report.py
+++ b/buildscripts/resmokelib/testing/report.py
@@ -105,7 +105,7 @@ class TestReport(unittest.TestResult):  # pylint: disable=too-many-instance-attr
 
         unittest.TestResult.startTest(self, test)
 
-        test_info = _TestInfo(test.id(), test.test_name, test.dynamic)
+        test_info = TestInfo(test.id(), test.test_name, test.dynamic)
         if _config.SPAWN_USING == "jasper":
             # The group id represents the group of logs this test belongs to in
             # cedar buildlogger. It must be sent to evergreen/cedar in order to
@@ -322,14 +322,15 @@ class TestReport(unittest.TestResult):  # pylint: disable=too-many-instance-attr
         Used when combining reports instances.
         """
 
-        report = cls(logging.loggers.EXECUTOR_LOGGER, _config.SuiteOptions.ALL_INHERITED.resolve())
+        report = cls(logging.loggers.ROOT_EXECUTOR_LOGGER,
+                     _config.SuiteOptions.ALL_INHERITED.resolve())
         for result in report_dict["results"]:
             # By convention, dynamic tests are named "<basename>:<hook name>".
             is_dynamic = ":" in result["test_file"] or ":" in result.get("display_test_name", "")
             test_file = result["test_file"]
             # Using test_file as the test id is ok here since the test id only needs to be unique
             # during suite execution.
-            test_info = _TestInfo(test_file, test_file, is_dynamic)
+            test_info = TestInfo(test_file, test_file, is_dynamic)
             test_info.display_test_name = result.get("display_test_name")
             test_info.group_id = result.get("group_id")
             test_info.url_endpoint = result.get("url")
@@ -377,11 +378,11 @@ class TestReport(unittest.TestResult):  # pylint: disable=too-many-instance-attr
         raise ValueError("Details for %s not found in the report" % (test.basename()))
 
 
-class _TestInfo(object):  # pylint: disable=too-many-instance-attributes
+class TestInfo(object):  # pylint: disable=too-many-instance-attributes
     """Holder for the test status and timing information."""
 
     def __init__(self, test_id, test_file, dynamic):
-        """Initialize the _TestInfo instance."""
+        """Initialize the TestInfo instance."""
 
         self.test_id = test_id
         # If spawned using jasper, we need to set the display_test_name and the
@@ -405,7 +406,7 @@ class _TestInfo(object):  # pylint: disable=too-many-instance-attributes
 
 def test_order(test_name):
     """
-    A key function used for sorting _TestInfo objects by recommended order of investigation.
+    A key function used for sorting TestInfo objects by recommended order of investigation.
 
     Investigate setup/teardown errors, then hooks, then test files.
     """
diff --git a/buildscripts/tests/patch_builds/test_task_generation.py b/buildscripts/tests/patch_builds/test_task_generation.py
index defd2540b00..fea15ee9269 100644
--- a/buildscripts/tests/patch_builds/test_task_generation.py
+++ b/buildscripts/tests/patch_builds/test_task_generation.py
@@ -14,8 +14,9 @@ class TestResmokeCommand(unittest.TestCase):
 
         commands = under_test.resmoke_commands(run_tests, test_vars, timeout_info)
 
-        # 3 expected command = 1 for setup + 1 for evergreen credentials + 1 for running tests.
-        self.assertEqual(3, len(commands))
+        # 4 expected command = 1 for setup + 1 for evergreen credentials + 1 for running tests +
+        # 1 for validate resmoke tests runtime.
+        self.assertEqual(4, len(commands))
 
     def test_with_multiversion(self):
         run_tests = "run tests"
@@ -25,8 +26,9 @@ class TestResmokeCommand(unittest.TestCase):
         commands = under_test.resmoke_commands(run_tests, test_vars, timeout_info,
                                                require_multiversion_setup=True)
 
-        # 4 expected command = 1 for setup + 1 for running tests + 3 for multiversion setup.
-        self.assertEqual(6, len(commands))
+        # 7 expected command = 1 for setup + 1 for evergreen credentials + 3 for multiversion setup +
+        # 1 for running tests + 1 for validate resmoke tests runtime.
+        self.assertEqual(7, len(commands))
 
     def test_with_timeout(self):
         run_tests = "run tests"
@@ -35,8 +37,9 @@ class TestResmokeCommand(unittest.TestCase):
 
         commands = under_test.resmoke_commands(run_tests, test_vars, timeout_info)
 
-        # 4 expected command = 1 for setup + 1 for evergreen credentials + 1 for running tests + 1 for timeout.
-        self.assertEqual(4, len(commands))
+        # 5 expected command = 1 for setup + 1 for evergreen credentials + 1 for running tests +
+        # 1 for timeout + 1 for validate resmoke tests runtime.
+        self.assertEqual(5, len(commands))
 
     def test_with_everything(self):
         run_tests = "run tests"
@@ -46,9 +49,9 @@ class TestResmokeCommand(unittest.TestCase):
         commands = under_test.resmoke_commands(run_tests, test_vars, timeout_info,
                                                require_multiversion_setup=True)
 
-        # 5 expected command = 1 for setup + 1 for running tests + 3 for multiversion setup +
-        # 1 for timeout.
-        self.assertEqual(7, len(commands))
+        # 8 expected command = 1 for setup + 1 for evergreen credentials + 3 for multiversion setup +
+        # 1 for running tests + 1 for timeout + 1 for validate resmoke tests runtime.
+        self.assertEqual(8, len(commands))
 
 
 class TestTimeoutInfo(unittest.TestCase):
diff --git a/etc/evergreen.yml b/etc/evergreen.yml
index 7e32967c849..eb487f27bab 100644
--- a/etc/evergreen.yml
+++ b/etc/evergreen.yml
@@ -1186,6 +1186,17 @@ functions:
           - "./src/evergreen/gen_tasks_activate.sh"
 
   # Used by generator
+  "validate resmoke tests runtime":
+    - *f_expansions_write
+    - *configure_evergreen_api_credentials
+    - command: subprocess.exec
+      type: test
+      params:
+        binary: bash
+        args:
+          - "./src/evergreen/resmoke_tests_runtime_validate.sh"
+
+  # Used by generator
   "run generated tests":
   - *f_expansions_write
   - *retrieve_generated_test_configuration
diff --git a/evergreen/resmoke_tests_runtime_validate.sh b/evergreen/resmoke_tests_runtime_validate.sh
new file mode 100644
index 00000000000..1ccfc71c225
--- /dev/null
+++ b/evergreen/resmoke_tests_runtime_validate.sh
@@ -0,0 +1,15 @@
+DIR="$(cd "$(dirname "${BASH_SOURCE[0]}")" > /dev/null 2>&1 && pwd)"
+. "$DIR/prelude.sh"
+
+cd src
+
+set -o verbose
+set -o errexit
+
+activate_venv
+$python buildscripts/resmoke_tests_runtime_validate.py \
+  --resmoke-report-file ./report.json \
+  --evg-api-config ./.evergreen.yml \
+  --project-id ${project_id} \
+  --build-variant ${build_variant} \
+  --task-name ${task_name}