Merge "Stats: break out job runtimes and counts by result"

NEWS.rst

@@ -1,4 +1,4 @@
-Since 1.2.0:
+Since 1.3.0:
 
 * The Jenkins launcher is replaced with Gearman launcher.  An internal
   Gearman server is provided, and there is a Gearman plugin for
@@ -17,3 +17,10 @@ Since 1.2.0:
   the old behavior (which would wait until the conflicting change was
   at the head before dequeuing it), see the new "dequeue-on-conflict"
   option.
+
+* Some statsd keys have changed in a backwards incompatible way:
+  * The counters and timers of the form zuul.job.{name} is now split
+    into several keys of the form:
+    zuul.pipeline.{pipeline-name}.job.{job-name}.{result}
+  * Job names in statsd keys now have the '_' character substituted
+    for the '.' character.

tests/test_scheduler.py

@@ -1017,16 +1017,21 @@ class TestScheduler(testtools.TestCase):
                     print 'heads', queue.severed_heads
                 self.assertEqual(len(queue.severed_heads), 0)
 
-    def assertReportedStat(self, key, value=None):
+    def assertReportedStat(self, key, value=None, kind=None):
         start = time.time()
         while time.time() < (start + 5):
             for stat in self.statsd.stats:
+                pprint.pprint(self.statsd.stats)
                 k, v = stat.split(':')
                 if key == k:
-                    if value is None:
-                        return
-                    if value == v:
+                    if value is None and kind is None:
                         return
+                    elif value:
+                        if value == v:
+                            return
+                    elif kind:
+                        if v.endswith('|' + kind):
+                            return
             time.sleep(0.1)
 
         pprint.pprint(self.statsd.stats)
@@ -1048,15 +1053,20 @@ class TestScheduler(testtools.TestCase):
         self.assertEqual(A.data['status'], 'MERGED')
         self.assertEqual(A.reported, 2)
 
-        self.assertReportedStat('gerrit.event.comment-added', '1|c')
-        self.assertReportedStat('zuul.pipeline.gate.current_changes', '1|g')
-        self.assertReportedStat('zuul.job.project-merge')
-        self.assertReportedStat('zuul.pipeline.gate.resident_time')
-        self.assertReportedStat('zuul.pipeline.gate.total_changes', '1|c')
+        self.assertReportedStat('gerrit.event.comment-added', value='1|c')
+        self.assertReportedStat('zuul.pipeline.gate.current_changes',
+                                value='1|g')
+        self.assertReportedStat('zuul.pipeline.gate.job.project-merge.SUCCESS',
+                                kind='ms')
+        self.assertReportedStat('zuul.pipeline.gate.job.project-merge.SUCCESS',
+                                value='1|c')
+        self.assertReportedStat('zuul.pipeline.gate.resident_time', kind='ms')
+        self.assertReportedStat('zuul.pipeline.gate.total_changes',
+                                value='1|c')
         self.assertReportedStat(
-            'zuul.pipeline.gate.org.project.resident_time')
+            'zuul.pipeline.gate.org.project.resident_time', kind='ms')
         self.assertReportedStat(
-            'zuul.pipeline.gate.org.project.total_changes', '1|c')
+            'zuul.pipeline.gate.org.project.total_changes', value='1|c')
 
     def test_duplicate_pipelines(self):
         "Test that a change matching multiple pipelines works"

zuul/model.py

@@ -534,6 +534,7 @@ class Build(object):
         self.start_time = None
         self.end_time = None
         self.estimated_time = None
+        self.pipeline = None
         self.parameters = {}
 
     def __repr__(self):
@@ -604,6 +605,7 @@ class QueueItem(object):
 
     def addBuild(self, build):
         self.current_build_set.addBuild(build)
+        build.pipeline = self.pipeline
 
     def setReportedResult(self, result):
         self.current_build_set.result = result

zuul/scheduler.py

@@ -315,8 +315,10 @@ class Scheduler(threading.Thread):
         self.log.debug("Adding complete event for build: %s" % build)
         build.end_time = time.time()
         try:
-            if statsd:
-                key = 'zuul.job.%s' % build.job.name
+            if statsd and build.pipeline:
+                jobname = build.job.name.replace('.', '_')
+                key = 'zuul.pipeline.%s.job.%s.%s' % (build.pipeline.name,
+                                                      jobname, build.result)
                 if build.result in ['SUCCESS', 'FAILURE'] and build.start_time:
                     dt = int((build.end_time - build.start_time) * 1000)
                     statsd.timing(key, dt)