Merge ~twom/launchpad:stats-add-ppa-latency into launchpad:master

[Tom Wardill]

Add PPA build and publishing latency stats

Taken from https://bazaar.launchpad.net/%7Ecanonical-losas/tuolumne-lp-configs/trunk/view/head%3A/hackberry/every_hour.py

[Thiago F. Pappacena (pappacena)]

LGTM

review: Approve

[Otto Co-Pilot (otto-copilot)]

Merging failed
https://jenkins.ols.canonical.com/online-services/job/launchpad/1260/

diff --git a/lib/lp/services/statsd/numbercruncher.py b/lib/lp/services/statsd/numbercruncher.py
index b143927..a90a815 100644
--- a/lib/lp/services/statsd/numbercruncher.py
+++ b/lib/lp/services/statsd/numbercruncher.py
@@ -31,10 +31,12 @@ from lp.buildmaster.interfaces.builder import IBuilderSet
 from lp.buildmaster.manager import PrefetchedBuilderFactory
 from lp.code.enums import CodeImportJobState
 from lp.code.model.codeimportjob import CodeImportJob
+from lp.soyuz.model.archive import Archive
 from lp.services.database.interfaces import IStore
 from lp.services.librarian.model import LibraryFileContent
 from lp.services.statsd.interfaces.statsd_client import IStatsdClient
 
+
 NUMBER_CRUNCHER_LOG_NAME = "number-cruncher"
 
 
@@ -45,6 +47,7 @@ class NumberCruncher(service.Service):
     BUILDER_INTERVAL = 60
     LIBRARIAN_INTERVAL = 3600
     CODE_IMPORT_INTERVAL = 60
+    PPA_LATENCY_INTERVAL = 3600
 
     def __init__(self, clock=None, builder_factory=None):
         if clock is None:
@@ -181,6 +184,50 @@ class NumberCruncher(service.Service):
             self.logger.exception("Failure while updating code import stats.")
         transaction.abort()
 
+    def updatePPABuildLatencyStats(self):
+        """Update stats about build latencies.
+
+        This aborts the current transaction before returning.
+        """
+
+        try:
+            self.logger.debug("Update PPA build latency stats.")
+            query = """
+            SELECT
+                avg(extract(
+                    epoch FROM bpb.date_first_dispatched - bpb.date_created)
+                    )/60,
+                avg(extract(
+                    epoch FROM bpr.datecreated - bpb.date_finished))/60,
+                avg(extract(
+                    epoch FROM bpph.datecreated - bpr.datecreated))/60,
+                avg(extract(
+                    epoch FROM bpph.datepublished - bpph.datecreated))/60
+            FROM
+                archive,
+                binarypackagebuild bpb,
+                binarypackagepublishinghistory bpph,
+                binarypackagerelease bpr
+            WHERE
+                archive.purpose = 2
+                AND bpph.archive = archive.id
+                AND bpph.archive = bpb.archive
+                AND bpr.id = bpph.binarypackagerelease
+                AND bpr.build = bpb.id
+                AND bpb.distro_arch_series = bpph.distroarchseries
+                AND bpph.datepublished >= %s
+            """ % "(NOW() at time zone 'UTC' - interval '1 hour')"
+            results = IStore(Archive).execute(query).get_one()
+            self._sendGauge("ppa.startdelay", results[0])
+            self._sendGauge("ppa.uploaddelay", results[1])
+            self._sendGauge("ppa.processaccepted", results[2])
+            self._sendGauge("ppa.publishdistro", results[3])
+            self.logger.debug("PPA build latency stats update complete.")
+        except Exception:
+            self.logger.exception(
+                "Failure while update PPA build latency stats.")
+        transaction.abort()
+
     def startService(self):
         self.logger.info("Starting number-cruncher service.")
         self.loops = []
@@ -190,6 +237,7 @@ class NumberCruncher(service.Service):
                 (self.BUILDER_INTERVAL, self.updateBuilderStats),
                 (self.LIBRARIAN_INTERVAL, self.updateLibrarianStats),
                 (self.CODE_IMPORT_INTERVAL, self.updateCodeImportStats),
+                (self.PPA_LATENCY_INTERVAL, self.updatePPABuildLatencyStats),
                 ):
             loop, stopping_deferred = self._startLoop(interval, callback)
             self.loops.append(loop)
diff --git a/lib/lp/services/statsd/tests/test_numbercruncher.py b/lib/lp/services/statsd/tests/test_numbercruncher.py
index f2ea44e..3433282 100644
--- a/lib/lp/services/statsd/tests/test_numbercruncher.py
+++ b/lib/lp/services/statsd/tests/test_numbercruncher.py
@@ -7,6 +7,9 @@ from __future__ import absolute_import, print_function, unicode_literals
 
 __metaclass__ = type
 
+from datetime import datetime
+
+import pytz
 from storm.store import Store
 from testtools.matchers import (
     Equals,
@@ -19,7 +22,10 @@ from twisted.internet import task
 from zope.component import getUtility
 from zope.security.proxy import removeSecurityProxy
 
-from lp.buildmaster.enums import BuilderCleanStatus
+from lp.buildmaster.enums import (
+    BuilderCleanStatus,
+    BuildStatus,
+    )
 from lp.buildmaster.interactor import BuilderSlave
 from lp.buildmaster.interfaces.processor import IProcessorSet
 from lp.buildmaster.model.buildqueue import BuildQueue
@@ -30,6 +36,7 @@ from lp.services.database.policy import DatabaseBlockedPolicy
 from lp.services.log.logger import BufferLogger
 from lp.services.statsd.numbercruncher import NumberCruncher
 from lp.services.statsd.tests import StatsMixin
+from lp.soyuz.enums import PackagePublishingStatus
 from lp.testing import TestCaseWithFactory
 from lp.testing.fakemethod import FakeMethod
 from lp.testing.layers import ZopelessDatabaseLayer
@@ -284,6 +291,42 @@ class TestNumberCruncher(StatsMixin, TestCaseWithFactory):
         self.assertIn(
             "Failure while updating code import stats.",
             cruncher.logger.getLogBuffer())
+        self.assertFalse(is_transaction_in_progress())
+
+    def test_updatePPABuildLatencyStats(self):
+        archive = self.factory.makeArchive()
+        bpph = self.factory.makeBinaryPackagePublishingHistory(
+            archive=archive, status=PackagePublishingStatus.PUBLISHED)
+        bpph.binarypackagerelease.build.updateStatus(
+            BuildStatus.BUILDING, date_started=datetime.now(pytz.UTC))
+        bpph.binarypackagerelease.build.updateStatus(BuildStatus.FULLYBUILT)
+        clock = task.Clock()
+        cruncher = NumberCruncher(clock=clock)
+        cruncher.updatePPABuildLatencyStats()
+        self.assertEqual(4, self.stats_client.gauge.call_count)
+        # The raw values here are non-deterministic and affected
+        # by the test data, so just check that the gauges exist
+        keys = [x[0][0] for x in self.stats_client.gauge.call_args_list]
+        gauges = [
+            "ppa.startdelay,env=test",
+            "ppa.uploaddelay,env=test",
+            "ppa.processaccepted,env=test",
+            "ppa.publishdistro,env=test"]
+        for gauge in gauges:
+            self.assertIn(gauge, keys)
+
+    def test_updatePPABuildLatencyStats_error(self):
+        clock = task.Clock()
+        cruncher = NumberCruncher(clock=clock)
+        cruncher.logger = BufferLogger()
+        with DatabaseBlockedPolicy():
+            cruncher.updatePPABuildLatencyStats()
+
+        self.assertFalse(is_transaction_in_progress())
+        self.assertIn(
+            "Failure while update PPA build latency stats.",
+            cruncher.logger.getLogBuffer())
+        self.assertFalse(is_transaction_in_progress())
 
     def test_startService_starts_update_queues_loop(self):
         clock = task.Clock()
@@ -328,3 +371,14 @@ class TestNumberCruncher(StatsMixin, TestCaseWithFactory):
         advance = NumberCruncher.CODE_IMPORT_INTERVAL + 1
         clock.advance(advance)
         self.assertNotEqual(0, cruncher.updateCodeImportStats.call_count)
+
+    def test_startService_starts_update_ppa_build_latency_loop(self):
+        clock = task.Clock()
+        cruncher = NumberCruncher(clock=clock)
+
+        cruncher.updatePPABuildLatencyStats = FakeMethod()
+
+        cruncher.startService()
+        advance = NumberCruncher.PPA_LATENCY_INTERVAL + 1
+        clock.advance(advance)
+        self.assertNotEqual(0, cruncher.updatePPABuildLatencyStats.call_count)