launchpad-reviewers team mailing list archive

[Colin Watson <cjwatson@xxxxxxxxxxxxx>]

Colin Watson has proposed merging ~cjwatson/turnip:more-git-metrics into turnip:master.

Commit message:
Add more metrics for git subprocesses

Requested reviews:
  Launchpad code reviewers (launchpad-reviewers)

For more details, see:
https://code.launchpad.net/~cjwatson/turnip/+git/turnip/+merge/406004

Measure the wallclock time as well as system/user time, and send metrics to the log as well as to statsd so that we don't have to laboriously mine them out of Prometheus if we need to look them up for a particular request.

Inspired by an inconclusive debugging session for Andy Whitcroft.
-- 
Your team Launchpad code reviewers is requested to review the proposed merge of ~cjwatson/turnip:more-git-metrics into turnip:master.

diff --git a/turnip/pack/git.py b/turnip/pack/git.py
index 2123bfd..7c43143 100644
--- a/turnip/pack/git.py
+++ b/turnip/pack/git.py
@@ -348,6 +348,12 @@ class GitProcessProtocol(protocol.ProcessProtocol, object):
             except ValueError:
                 pass
             else:
+                self.peer.log.info(
+                    'git exited: clock time {clock_time}, '
+                    'system time {system_time}, user time {user_time}, '
+                    'max RSS {max_rss}',
+                    **resource_usage)
+
                 # remove characters from repository name that
                 # can't be used in statsd
                 repository = re.sub(
@@ -355,23 +361,12 @@ class GitProcessProtocol(protocol.ProcessProtocol, object):
                     six.ensure_text(self.peer.raw_pathname))
                 command = six.ensure_text(self.peer.command)
                 environment = config.get("statsd_environment")
-                gauge_name = (
-                    "git,operation={},repo={},env={},metric=max_rss"
-                    .format(command, repository, environment))
-
-                self.statsd_client.gauge(gauge_name, resource_usage['max_rss'])
-
-                gauge_name = (
-                    "git,operation={},repo={},env={},metric=system_time"
-                    .format(command, repository, environment))
-                self.statsd_client.gauge(gauge_name,
-                                         resource_usage['system_time'])
-
-                gauge_name = (
-                    "git,operation={},repo={},env={},metric=user_time"
-                    .format(command, repository, environment))
-                self.statsd_client.gauge(gauge_name,
-                                         resource_usage['user_time'])
+
+                for metric_name, value in resource_usage.items():
+                    gauge_name = (
+                        "git,operation={},repo={},env={},metric={}"
+                        .format(command, repository, environment, metric_name))
+                    self.statsd_client.gauge(gauge_name, value)
 
     def pauseProducing(self):
         self.transport.pauseProducing()
diff --git a/turnip/pack/git_helper.py b/turnip/pack/git_helper.py
index 9d2756e..72290cc 100755
--- a/turnip/pack/git_helper.py
+++ b/turnip/pack/git_helper.py
@@ -11,6 +11,7 @@ import os
 import resource
 import subprocess
 import sys
+import time
 
 
 if __name__ == '__main__':
@@ -21,12 +22,15 @@ if __name__ == '__main__':
     fcntl.fcntl(3, fcntl.F_SETFD, flags | fcntl.FD_CLOEXEC)
 
     # Call git and wait for it to finish.
+    start_time = time.clock_gettime(time.CLOCK_MONOTONIC)
     ret = subprocess.call(['git'] + sys.argv[1:])
+    end_time = time.clock_gettime(time.CLOCK_MONOTONIC)
 
     # Dump resource usage information to FD 3.
     resource_fd = os.fdopen(3, 'w')
     rusage = resource.getrusage(resource.RUSAGE_CHILDREN)
     resource_fd.write(json.dumps({
+        "clock_time": end_time - start_time,
         "user_time": rusage.ru_utime,
         "system_time": rusage.ru_stime,
         "max_rss": rusage.ru_maxrss,
diff --git a/turnip/pack/tests/test_functional.py b/turnip/pack/tests/test_functional.py
index 6fcb7ec..1ef2125 100644
--- a/turnip/pack/tests/test_functional.py
+++ b/turnip/pack/tests/test_functional.py
@@ -176,7 +176,7 @@ class FunctionalTestMixin(WithScenarios):
         defer.returnValue((out, err))
 
     def assertStatsdSuccess(self, repo, command):
-        metrics = ['max_rss', 'system_time', 'user_time']
+        metrics = ['clock_time', 'user_time', 'system_time', 'max_rss']
         repository = re.sub('[^0-9a-zA-Z]+', '-', six.ensure_str(repo))
         self.assertThat(self.statsd_client.vals, MatchesDict({
             u'git,operation={},repo={},env={},metric={}'