buildbucket: add monitoring using ts_mon

appengine/cr-buildbucket/metrics.py

 # Copyright 2015 The Chromium Authors. All rights reserved.
 # Use of this source code is governed by a BSD-style license that can be
 # found in the LICENSE file.
 
 import logging
+
+from google.appengine.api import app_identity
 from google.appengine.ext import ndb
 
 from components import metrics
 from components import utils
+import gae_ts_mon
 
 import config
 import model
 
+# TODO(nodir): remove Cloud Monitoring and refactor
+# when gae_ts_mon is stabilized
+
 LABEL_BUCKET = 'buildbucket/bucket'
 COMMON_LABELS = {
   LABEL_BUCKET: 'Bucket'
 }
 METRIC_PENDING_BUILDS = metrics.Descriptor(
   name='buildbucket/builds/pending',
   description='Number of pending builds',
   labels=COMMON_LABELS,
 )
 METRIC_RUNNING_BUILDS = metrics.Descriptor(
@@ skipping 12 matching lines @@
 METRIC_SCHEDULING_LATENCY = metrics.Descriptor(
   name='buildbucket/builds/scheduling_latency',
   description=(
     'Average number of seconds for a scheduled build '
     'to remain in SCHEDULED leased state'
   ),
   value_type='double',
   labels=COMMON_LABELS,
 )
 
+# gae_ts_mon
+FIELD_BUCKET = 'bucket'
+COMMON_FIELDS = {
+  'buildbucket_hostname': app_identity.get_default_version_hostname(),
+}
+
+
+def _def_metric(metric_type, name, description):
+  return metric_type(
+    '/buildbucket/%s' % name,

[Sergey Berezin, 2015/12/17 00:08:01]

Remove the leading slash: just 'buildbucket/%s'.

[nodir, 2015/12/17 01:28:54]

Done.

+    fields=COMMON_FIELDS,
+    description=description)
+
+
+CREATE_COUNT = _def_metric(
+  gae_ts_mon.CounterMetric,
+  'created',

[Sergey Berezin, 2015/12/17 00:08:01]

nit: I'd make the metric name more descriptive, e.g. 'builds/created'. Similarly
below.

[nodir, 2015/12/17 01:28:54]

Done

+  'Build creation',
+)
+START_COUNT = _def_metric(
+  gae_ts_mon.CounterMetric,
+  'started',
+  'Build start',
+)
+COMPLETE_COUNT = _def_metric(
+  gae_ts_mon.CounterMetric,
+  'completed',
+  'Build completion, including success, failure and cancellation'
+)
+HEARTBEAT_FAILURE_COUNT = _def_metric(
+  gae_ts_mon.CounterMetric,
+  'heartbeat_failures',
+  'Failures to extend a build lease'
+)
+LEASE_COUNT = _def_metric(
+  gae_ts_mon.CounterMetric,
+  'leases',
+  'Successful build lease extension',
+)
+LEASE_EXPIRATION_COUNT = _def_metric(
+  gae_ts_mon.CounterMetric,
+  'lease_expired',
+  'Build lease expirations'
+)
+CURRENTLY_PENDING = _def_metric(
+  gae_ts_mon.GaugeMetric,
+  'pending',
+  'Number of pending builds',
+)
+CURRENTLY_RUNNING = _def_metric(
+  gae_ts_mon.GaugeMetric,
+  'running',
+  'Number of running builds'
+)
+LEASE_LATENCY = _def_metric(
+  gae_ts_mon.NonCumulativeDistributionMetric,

[Sergey Berezin, 2015/12/17 00:08:01]

I think this should be CumulativeDistributionMetric, since you want to measure
it at the moment the build is leased, so it becomes an event.

[nodir, 2015/12/17 01:28:54]

FWIU, you are suggesting to do

LEASE_LATENCY.add(now - created, {'bucket': 'master.x'})

the moment a build is leased.

However, imagine that something happened with buildbot and it stopped leasing
entirely. Events don't fire and thus graphs do not indicate a problem, until the
moment buildbot is back again. The moment leasing resumes we notice that it is
huge, but we want to notice it the moment leasing stopped.

[Sergey Berezin, 2015/12/17 02:30:18]

It's a valid point; e.g. CQ measures both completed attempt times (cumulative)
and time currently in CQ (non-cumulative), just for that reason.

In this case, the name and description of the metric suggests it's an actual
latency (time delta between two events), which is a cumulative measurement taken
at lease time. I'd add both builds/lease_latency (cumulative) and
builds/pending_time (or something like that - non-cumulative).

Similarly for builds/scheduling_latency - the word "latency" implies something
completed, not still waiting. The description also doesn't make it clear.

In CQ, these metrics are named pending_attempts/durations and
completed_attempts/durations, making it less ambiguous. 

[nodir, 2015/12/17 03:19:56]

Renamed to never_leased_duration and scheduling_duration

+  'lease_latency',
+  'Duration between a build is created and it is leased for the first time',
+)
+SCHEDULING_LATENCY = _def_metric(
+  gae_ts_mon.NonCumulativeDistributionMetric,
+  'scheduling_latency',
+  'Duration of a build being in SCHEDULED state',
+)
+
+
+GAUGE_OF_CLOUD_METRIC = {
+  METRIC_PENDING_BUILDS: CURRENTLY_PENDING,
+  METRIC_RUNNING_BUILDS: CURRENTLY_RUNNING,
+}
+DISTRIBUTION_OF_CLOUD_METRIC = {
+  METRIC_LEASE_BUILD_LATENCY: LEASE_LATENCY,
+  METRIC_SCHEDULING_LATENCY: SCHEDULING_LATENCY,
+}
+
+
+def increment(metric, build, **fields):
+  fields = {
+    k: str(v)
+    for k, v in fields.iteritems()
+    if v is not None

[Sergey Berezin, 2015/12/17 00:08:01]

Don't skip fields dynamically. ts_mon requires all fields to be present in the
metric for all points, globally. Otherwise inconsistent metrics will be
rejected. If needed, assign None, empty string or 0 to the field as appropriate.

[nodir, 2015/12/17 01:28:54]

Done.

+  }
+  fields.setdefault(FIELD_BUCKET, build.bucket if build else '<no bucket>')
+  if build:
+    for t in build.tags:
+      k, v = t.split(':', 1)
+      fields.setdefault('tag_%s' % k, v)

[Sergey Berezin, 2015/12/17 00:08:01]

How many different tags are there? Just checking that they are not dynamically
generated. If they are, we can't have them as a field, since they'll create too
many streams per metric.

[nodir, 2015/12/17 01:28:54]

made them static

+  metric.increment(fields)
+
 
 def set_gauge(buf, bucket, metric, value):
   logging.info('Bucket %s: %s = %d', bucket, metric.name, value)
   buf.set_gauge(metric, value, {LABEL_BUCKET: bucket})
+  gae_ts_mon_metric = GAUGE_OF_CLOUD_METRIC.get(metric)
+  if gae_ts_mon_metric:
+    gae_ts_mon_metric.set(value, {FIELD_BUCKET: bucket})
 
 
 @ndb.tasklet
 def send_build_status_metric(buf, bucket, metric, status):
   q = model.Build.query(
     model.Build.bucket == bucket,
     model.Build.status == status)
   value = yield q.count_async()
   set_gauge(buf, bucket, metric, value)
 
 
 @ndb.tasklet
 def send_build_latency(buf, metric, bucket, must_be_never_leased):
   q = model.Build.query(
     model.Build.bucket == bucket,
     model.Build.status == model.BuildStatus.SCHEDULED,
   )
   if must_be_never_leased:
     q = q.filter(model.Build.never_leased == True)
   else:
     # Reuse the index that has never_leased
     q = q.filter(model.Build.never_leased.IN((True, False)))
 
   now = utils.utcnow()
   avg_latency = 0.0
   count = 0
+  dist = gae_ts_mon.Distribution(gae_ts_mon.GeometricBucketer())
   for e in q.iter(projection=[model.Build.create_time]):
-    avg_latency += (now - e.create_time).total_seconds()
+    latency = (now - e.create_time).total_seconds()
+    dist.add(latency)
+    avg_latency += latency
     count += 1
   if count > 0:
     avg_latency /= count
   set_gauge(buf, bucket, metric, avg_latency)
+  DISTRIBUTION_OF_CLOUD_METRIC[metric].set(dist, {FIELD_BUCKET: bucket})
 
 
 def send_all_metrics():
   buf = metrics.Buffer()
   futures = []
   for b in config.get_buckets_async().get_result():
     futures.extend([
       send_build_status_metric(
         buf, b.name, METRIC_PENDING_BUILDS, model.BuildStatus.SCHEDULED),
       send_build_status_metric(
         buf, b.name, METRIC_RUNNING_BUILDS, model.BuildStatus.STARTED),
       send_build_latency(buf, METRIC_LEASE_BUILD_LATENCY, b.name, True),
       send_build_latency(buf, METRIC_SCHEDULING_LATENCY, b.name, False),
     ])
   ndb.Future.wait_all(futures)
   buf.flush()
   for f in futures:
     f.check_success()