Merge "Add pipeline-based merge op metrics"

6 files changed, 70 insertions, 9 deletions

diff --git a/doc/source/monitoring.rst b/doc/source/monitoring.rst
index 0c2cb4351..1cb61ee01 100644
--- a/doc/source/monitoring.rst
+++ b/doc/source/monitoring.rst
@@ -110,7 +110,27 @@ These metrics are emitted by the Zuul :ref:`scheduler`:
          operation(s).  This will always include a request to a Zuul
          merger to speculatively merge the change, but it may also
          include a second request submitted in parallel to identify
-         the files altered by the change.
+         the files altered by the change.  Includes
+         :stat:`zuul.tenant.<tenant>.pipeline.<pipeline>.merger_merge_op_time`
+         and
+         :stat:`zuul.tenant.<tenant>.pipeline.<pipeline>.merger_files_changes_op_time`.
+
+      .. stat:: merger_merge_op_time
+         :type: timer
+
+         The amount of time the merger spent performing a merge
+         operation.  This does not include any of the round-trip time
+         from the scheduler to the merger, or any other merge
+         operations.
+
+      .. stat:: merger_files_changes_op_time
+         :type: timer
+
+         The amount of time the merger spent performing a files-changes
+         operation to detect changed files (this is sometimes
+         performed if the source does not provide this information).
+         This does not include any of the round-trip time from the
+         scheduler to the merger, or any other merge operations.
 
       .. stat:: layout_generation_time
          :type: timer
@@ -128,7 +148,17 @@ These metrics are emitted by the Zuul :ref:`scheduler`:
 
          The amount of time waiting for a secondary Zuul merger
          operation to collect additional information about the repo
-         state of required projects.
+         state of required projects.  Includes
+         :stat:`zuul.tenant.<tenant>.pipeline.<pipeline>.merger_repo_state_op_time`.
+
+      .. stat:: merger_repo_state_op_time
+         :type: timer
+
+         The amount of time the merger spent performing a repo state
+         operation to collect additional information about the repo
+         state of required projects.  This does not include any of the
+         round-trip time from the scheduler to the merger, or any
+         other merge operations.
 
       .. stat:: node_request_time
          :type: timer
diff --git a/tests/unit/test_scheduler.py b/tests/unit/test_scheduler.py
index d4fa98d1e..5e0385be3 100644
--- a/tests/unit/test_scheduler.py
+++ b/tests/unit/test_scheduler.py
@@ -452,6 +452,7 @@ class TestScheduler(ZuulTestCase):
                 'zuul.tenant.tenant-one.reconfiguration_time',
                 'zuul.tenant.tenant-one.pipeline.gate.event_enqueue_time',
                 'zuul.tenant.tenant-one.pipeline.gate.merge_request_time',
+                'zuul.tenant.tenant-one.pipeline.gate.merger_merge_op_time',
                 'zuul.tenant.tenant-one.pipeline.gate.job_freeze_time',
                 'zuul.tenant.tenant-one.pipeline.gate.node_request_time',
                 'zuul.tenant.tenant-one.pipeline.gate.job_wait_time',
diff --git a/zuul/manager/__init__.py b/zuul/manager/__init__.py
index 7cb96e34b..a66f5ad22 100644
--- a/zuul/manager/__init__.py
+++ b/zuul/manager/__init__.py
@@ -1823,18 +1823,27 @@ class PipelineManager(metaclass=ABCMeta):
             # We're the second of the files/merger pair, report the stat
             self.reportPipelineTiming('merge_request_time',
                                       build_set.configured_time)
+        if event.elapsed_time:
+            self.reportPipelineTiming('merger_files_changes_op_time',
+                                      event.elapsed_time, elapsed=True)
 
     def onMergeCompleted(self, event, build_set):
         if build_set.merge_state == build_set.COMPLETE:
             self._onGlobalRepoStateCompleted(event, build_set)
             self.reportPipelineTiming('repo_state_time',
                                       build_set.repo_state_request_time)
+            if event.elapsed_time:
+                self.reportPipelineTiming('merger_repo_state_op_time',
+                                          event.elapsed_time, elapsed=True)
         else:
             self._onMergeCompleted(event, build_set)
             if build_set.files_state == build_set.COMPLETE:
                 # We're the second of the files/merger pair, report the stat
                 self.reportPipelineTiming('merge_request_time',
                                           build_set.configured_time)
+            if event.elapsed_time:
+                self.reportPipelineTiming('merger_merge_op_time',
+                                          event.elapsed_time, elapsed=True)
 
     def _onMergeCompleted(self, event, build_set):
 
@@ -2126,7 +2135,7 @@ class PipelineManager(metaclass=ABCMeta):
         except Exception:
             self.log.exception("Exception reporting pipeline stats")
 
-    def reportPipelineTiming(self, key, start, end=None):
+    def reportPipelineTiming(self, key, start, end=None, elapsed=False):
         if not self.sched.statsd:
             return
         if not start:
@@ -2136,5 +2145,8 @@ class PipelineManager(metaclass=ABCMeta):
         pipeline = self.pipeline
         tenant = pipeline.tenant
         stats_key = f'zuul.tenant.{tenant.name}.pipeline.{pipeline.name}'
-        dt = (end - start) * 1000
+        if elapsed:
+            dt = start
+        else:
+            dt = (end - start) * 1000
         self.sched.statsd.timing(f'{stats_key}.{key}', dt)
diff --git a/zuul/merger/client.py b/zuul/merger/client.py
index 362644b98..29fa39aaf 100644
--- a/zuul/merger/client.py
+++ b/zuul/merger/client.py
@@ -159,7 +159,9 @@ class MergeClient(object):
                 "via result event for %s", merge_request)
             if merge_request.job_type == MergeRequest.FILES_CHANGES:
                 event = FilesChangesCompletedEvent(
-                    merge_request.build_set_uuid, files=None
+                    merge_request.build_set_uuid,
+                    files=None,
+                    elapsed_time=None,
                 )
             else:
                 event = MergeCompletedEvent(
@@ -172,6 +174,7 @@ class MergeClient(object):
                     repo_state=None,
                     item_in_branches=None,
                     errors=None,
+                    elapsed_time=None,
                 )
             try:
                 self.result_events[merge_request.tenant_name][
diff --git a/zuul/merger/server.py b/zuul/merger/server.py
index 91597714f..fe5b938a1 100644
--- a/zuul/merger/server.py
+++ b/zuul/merger/server.py
@@ -256,6 +256,7 @@ class BaseMergeServer(metaclass=ABCMeta):
 
     def executeMergeJob(self, merge_request, params):
         result = None
+        start = time.monotonic()
         if merge_request.job_type == MergeRequest.MERGE:
             result = self.merge(merge_request, params)
         elif merge_request.job_type == MergeRequest.CAT:
@@ -264,6 +265,8 @@ class BaseMergeServer(metaclass=ABCMeta):
             result = self.refstate(merge_request, params)
         elif merge_request.job_type == MergeRequest.FILES_CHANGES:
             result = self.fileschanges(merge_request, params)
+        end = time.monotonic()
+        result['elapsed_time'] = end - start
         return result
 
     def cat(self, merge_request, args):
@@ -376,6 +379,7 @@ class BaseMergeServer(metaclass=ABCMeta):
         item_in_branches = result.get("item_in_branches", [])
         files = result.get("files", {})
         errors = result.get("errors", [])
+        elapsed_time = result.get("elapsed_time")
 
         log.info(
             "Merge %s complete, merged: %s, updated: %s, commit: %s, "
@@ -407,7 +411,9 @@ class BaseMergeServer(metaclass=ABCMeta):
             )
             if merge_request.job_type == MergeRequest.FILES_CHANGES:
                 event = FilesChangesCompletedEvent(
-                    merge_request.build_set_uuid, files
+                    merge_request.build_set_uuid,
+                    files,
+                    elapsed_time,
                 )
             else:
                 event = MergeCompletedEvent(
@@ -420,6 +426,7 @@ class BaseMergeServer(metaclass=ABCMeta):
                     repo_state,
                     item_in_branches,
                     errors,
+                    elapsed_time,
                 )
 
             def put_complete_event(log, merge_request, event):
diff --git a/zuul/model.py b/zuul/model.py
index 14f10deb9..963332826 100644
--- a/zuul/model.py
+++ b/zuul/model.py
@@ -6253,12 +6253,13 @@ class MergeCompletedEvent(ResultEvent):
     :arg dict repo_state: The starting repo state before the merge.
     :arg list item_in_branches: A list of branches in which the final
         commit in the merge list appears (changes without refs).
-    :arg list errors: A list of error message strings
+    :arg list errors: A list of error message strings.
+    :arg float elapsed_time: Elapsed time of merge op in seconds.
     """
 
     def __init__(self, request_uuid, build_set_uuid, merged, updated,
                  commit, files, repo_state, item_in_branches,
-                 errors):
+                 errors, elapsed_time):
         self.request_uuid = request_uuid
         self.build_set_uuid = build_set_uuid
         self.merged = merged
@@ -6268,6 +6269,7 @@ class MergeCompletedEvent(ResultEvent):
         self.repo_state = repo_state or {}
         self.item_in_branches = item_in_branches or []
         self.errors = errors or []
+        self.elapsed_time = elapsed_time
 
     def __repr__(self):
         return ('<MergeCompletedEvent job: %s buildset: %s merged: %s '
@@ -6287,6 +6289,7 @@ class MergeCompletedEvent(ResultEvent):
             "repo_state": dict(self.repo_state),
             "item_in_branches": list(self.item_in_branches),
             "errors": list(self.errors),
+            "elapsed_time": self.elapsed_time,
         }
 
     @classmethod
@@ -6301,6 +6304,7 @@ class MergeCompletedEvent(ResultEvent):
             dict(data.get("repo_state", {})),
             list(data.get("item_in_branches", [])),
             list(data.get("errors", [])),
+            data.get("elapsed_time"),
         )
 
 
@@ -6309,16 +6313,19 @@ class FilesChangesCompletedEvent(ResultEvent):
 
     :arg BuildSet build_set: The build_set which is ready.
     :arg list files: List of files changed.
+    :arg float elapsed_time: Elapsed time of merge op in seconds.
     """
 
-    def __init__(self, build_set_uuid, files):
+    def __init__(self, build_set_uuid, files, elapsed_time):
         self.build_set_uuid = build_set_uuid
         self.files = files or []
+        self.elapsed_time = elapsed_time
 
     def toDict(self):
         return {
             "build_set_uuid": self.build_set_uuid,
             "files": list(self.files),
+            "elapsed_time": self.elapsed_time,
         }
 
     @classmethod
@@ -6326,6 +6333,7 @@ class FilesChangesCompletedEvent(ResultEvent):
         return cls(
             data.get("build_set_uuid"),
             list(data.get("files", [])),
+            data.get("elapsed_time"),
         )