Report Resource Usage Statistics When a dbt Command Finishes (#8671)

* Add performance metrics to the CommandCompleted event.

* Add changelog entry.

* Add flag for controling the log level of ResourceReport.

* Update changelog entry to reflect changes

* Remove outdated attributes

* Work around missing resource module on windows

* Fix corner case where flags are not set

.changes/unreleased/Features-20230919-102148.yaml

@@ -0,0 +1,6 @@
+kind: Features
+body: Add new ResourceReport event to record memory/cpu/io metrics
+time: 2023-09-19T10:21:48.772635-04:00
+custom:
+  Author: peterallenwebb
+  Issue: "8342"

core/dbt/cli/main.py

@@ -169,6 +169,7 @@ def wrapper(*args, **kwargs):
 @p.warn_error
 @p.warn_error_options
 @p.log_format
+@p.show_resource_report
 def cli(ctx, **kwargs):
     """An ELT tool for managing your SQL transformations and data models.
     For more documentation on these commands, visit: docs.getdbt.com

core/dbt/cli/params.py

@@ -614,3 +614,10 @@ def _version_callback(ctx, _param, value):
     help="Whether or not to write the manifest.json and run_results.json files to the target directory",
     default=True,
 )
+
+show_resource_report = click.option(
+    "--show-resource-report/--no-show-resource-report",
+    default=False,
+    envvar="DBT_SHOW_RESOURCE_REPORT",
+    hidden=True,
+)

core/dbt/cli/requires.py

@@ -9,12 +9,14 @@
 from dbt.cli.flags import Flags
 from dbt.config import RuntimeConfig
 from dbt.config.runtime import load_project, load_profile, UnsetProfile
+from dbt.events.base_types import EventLevel
 from dbt.events.functions import fire_event, LOG_VERSION, set_invocation_id, setup_event_logger
 from dbt.events.types import (
     CommandCompleted,
     MainReportVersion,
     MainReportArgs,
     MainTrackingUserState,
+    ResourceReport,
 )
 from dbt.events.helpers import get_json_string_utcnow
 from dbt.events.types import MainEncounteredError, MainStackTrace
@@ -27,6 +29,7 @@
 
 from click import Context
 from functools import update_wrapper
+import importlib.util
 import time
 import traceback
 
@@ -96,6 +99,28 @@ def wrapper(*args, **kwargs):
             fire_event(MainStackTrace(stack_trace=traceback.format_exc()))
             raise ExceptionExit(e)
         finally:
+            # Fire ResourceReport, but only on systems which support the resource
+            # module. (Skip it on Windows).
+            if importlib.util.find_spec("resource") is not None:
+                import resource
+
+                rusage = resource.getrusage(resource.RUSAGE_SELF)
+                fire_event(
+                    ResourceReport(
+                        command_name=ctx.command.name,
+                        command_success=success,
+                        command_wall_clock_time=time.perf_counter() - start_func,
+                        process_user_time=rusage.ru_utime,
+                        process_kernel_time=rusage.ru_stime,
+                        process_mem_max_rss=rusage.ru_maxrss,
+                        process_in_blocks=rusage.ru_inblock,
+                        process_out_blocks=rusage.ru_oublock,
+                    ),
+                    EventLevel.INFO
+                    if "flags" in ctx.obj and ctx.obj["flags"].SHOW_RESOURCE_REPORT
+                    else None,
+                )
+
             fire_event(
                 CommandCompleted(
                     command=ctx.command_path,

core/dbt/events/base_types.py

@@ -102,7 +102,10 @@ def to_dict(self):
 
     def to_json(self) -> str:
         return MessageToJson(
-            self.pb_msg, preserving_proto_field_name=True, including_default_value_fields=True
+            self.pb_msg,
+            preserving_proto_field_name=True,
+            including_default_value_fields=True,
+            indent=None,
         )
 
     def level_tag(self) -> EventLevel:

core/dbt/events/types.proto

@@ -2457,3 +2457,24 @@ message NoteMsg {
     EventInfo info = 1;
     Note data = 2;
 }
+
+// Z051
+message ResourceReport {
+    string command_name = 2;
+    bool command_success = 3;
+    float command_wall_clock_time = 4;
+    // The process_* metrics reflect the resource consumption of the process as
+    // a whole when the command completes. When dbt is being used as a library,
+    // these will reflect the resource consumption of the host process as a whole,
+    // rather than the resources used exclusively by the command.
+    float process_user_time = 5;
+    float process_kernel_time = 6;
+    int64 process_mem_max_rss = 7;
+    int64 process_in_blocks = 8;
+    int64 process_out_blocks = 9;
+}
+
+message ResourceReportMsg {
+    EventInfo info = 1;
+    ResourceReport data = 2;
+}

core/dbt/events/types.py

@@ -2349,13 +2349,21 @@ def message(self) -> str:
         return self.msg
 
 
-# The Note event provides a way to log messages which aren't likely to be useful as more structured events.
-# For console formatting text like empty lines and separator bars, use the Formatting event instead.
-
-
 class Note(InfoLevel):
+    """The Note event provides a way to log messages which aren't likely to be
+    useful as more structured events. For console formatting text like empty
+    lines and separator bars, use the Formatting event instead."""
+
     def code(self) -> str:
         return "Z050"
 
     def message(self) -> str:
         return self.msg
+
+
+class ResourceReport(DebugLevel):
+    def code(self) -> str:
+        return "Z051"
+
+    def message(self) -> str:
+        return f"Resource report: {self.to_json()}"

tests/functional/events/events.py

@@ -0,0 +1,33 @@
+import os
+
+from dbt.cli.main import dbtRunner
+from dbt.events.base_types import EventLevel
+
+
+def test_performance_report(project):
+
+    resource_report_level = None
+
+    def check_for_report(e):
+        # If we see a ResourceReport event, record its level
+        if e.info.name == "ResourceReport":
+            nonlocal resource_report_level
+            resource_report_level = e.info.level
+
+    runner = dbtRunner(callbacks=[check_for_report])
+
+    runner.invoke(["run"])
+
+    # With not cli flag or env var set, ResourceReport should be debug level.
+    assert resource_report_level == EventLevel.DEBUG
+
+    try:
+        os.environ["DBT_SHOW_RESOURCE_REPORT"] = "1"
+        runner.invoke(["run"])
+
+        # With the appropriate env var set, ResourceReport should be info level.
+        # This allows this fairly technical log line to be omitted by default
+        # but still available in production scenarios.
+        assert resource_report_level == EventLevel.INFO
+    finally:
+        del os.environ["DBT_SHOW_RESOURCE_REPORT"]

tests/unit/test_events.py

@@ -378,7 +378,10 @@ def test_event_codes(self):
     types.DepsUnpinned(revision="", git=""),
     types.NoNodesForSelectionCriteria(spec_raw=""),
     types.CommandCompleted(
-        command="", success=True, elapsed=0.1, completed_at=get_json_string_utcnow()
+        command="",
+        success=True,
+        elapsed=0.1,
+        completed_at=get_json_string_utcnow(),
     ),
     types.ShowNode(node_name="", preview="", is_inline=True, unique_id="model.test.my_model"),
     types.CompiledNode(node_name="", compiled="", is_inline=True, unique_id="model.test.my_model"),
@@ -428,6 +431,7 @@ def test_event_codes(self):
     types.DebugCmdResult(),
     types.ListCmdOut(),
     types.Note(msg="This is a note."),
+    types.ResourceReport(),
 ]