Add even more pipeline processing stats

This adds some timers that can help operators identify the frequency
and time spent processing individual pipelines.

Change-Id: I927e30268b3c3c08b720174a961259f9670f8c4b

doc/source/monitoring.rst

@@ -150,10 +150,24 @@ These metrics are emitted by the Zuul :ref:`scheduler`:
          The number of items currently being processed by this
          pipeline.
 
+      .. stat:: handling
+         :type: timer
+
+         The total time taken to refresh and process the pipeline.
+         This is emitted every time a scheduler examines a pipeline
+         regardless of whether it takes any actions.
+
+      .. stat:: event_process
+         :type: timer
+
+         The time taken to process the event queues for the pipeline.
+         This is emitted only if there are events to process.
+
       .. stat:: process
          :type: timer
 
-         The time taken to process the pipeline.
+         The time taken to process the pipeline.  This is emitted only
+         if there were events to process.
 
       .. stat:: data_size_compressed
          :type: gauge

releasenotes/notes/pipeline-timing-ea263e6e5939b1aa.yaml

@@ -20,3 +20,5 @@ features:
     * :stat:`zuul.tenant.<tenant>.pipeline.<pipeline>.write_znodes`
     * :stat:`zuul.tenant.<tenant>.pipeline.<pipeline>.read_bytes`
     * :stat:`zuul.tenant.<tenant>.pipeline.<pipeline>.write_bytes`
+    * :stat:`zuul.tenant.<tenant>.pipeline.<pipeline>.event_process`
+    * :stat:`zuul.tenant.<tenant>.pipeline.<pipeline>.handling`

tests/unit/test_scheduler.py

@@ -452,6 +452,10 @@ class TestScheduler(ZuulTestCase):
                 'zuul.tenant.tenant-one.pipeline.gate.resident_time',
                 'zuul.tenant.tenant-one.pipeline.gate.read_time',
                 'zuul.tenant.tenant-one.pipeline.gate.write_time',
+                'zuul.tenant.tenant-one.pipeline.gate.process',
+                'zuul.tenant.tenant-one.pipeline.gate.event_process',
+                'zuul.tenant.tenant-one.pipeline.gate.handling',
+                'zuul.tenant.tenant-one.pipeline.gate.refresh',
         ]:
             val = self.assertReportedStat(key, kind='ms')
             self.assertTrue(0.0 < float(val) < 60000.0)

zuul/scheduler.py

@@ -1922,7 +1922,9 @@ class Scheduler(threading.Thread):
                 ) as lock:
                     ctx = self.createZKContext(lock, self.log)
                     with pipeline.manager.currentContext(ctx):
-                        refreshed = self._process_pipeline(tenant, pipeline)
+                        with self.statsd_timer(f'{stats_key}.handling'):
+                            refreshed = self._process_pipeline(
+                                tenant, pipeline)
                     # Update pipeline summary for zuul-web
                     if refreshed:
                         pipeline.summary.update(ctx, self.globals)
@@ -1984,11 +1986,12 @@ class Scheduler(threading.Thread):
             self._reenqueuePipeline(tenant, pipeline, ctx)
         pipeline.state.cleanup(ctx)
 
-        self.process_pipeline_management_queue(tenant, pipeline)
-        # Give result events priority -- they let us stop builds, whereas
-        # trigger events cause us to execute builds.
-        self.process_pipeline_result_queue(tenant, pipeline)
-        self.process_pipeline_trigger_queue(tenant, pipeline)
+        with self.statsd_timer(f'{stats_key}.event_process'):
+            self.process_pipeline_management_queue(tenant, pipeline)
+            # Give result events priority -- they let us stop builds,
+            # whereas trigger events cause us to execute builds.
+            self.process_pipeline_result_queue(tenant, pipeline)
+            self.process_pipeline_trigger_queue(tenant, pipeline)
         try:
             with self.statsd_timer(f'{stats_key}.process'):
                 while not self._stopped and pipeline.manager.processQueue():