xref: /aosp_15_r20/external/autotest/utils/frozen_chromite/lib/metrics.py (revision 9c5db1993ded3edbeafc8092d69fe5de2ee02df7)
1*9c5db199SXin Li# -*- coding: utf-8 -*-
2*9c5db199SXin Li# Copyright 2016 The Chromium OS Authors. All rights reserved.
3*9c5db199SXin Li# Use of this source code is governed by a BSD-style license that can be
4*9c5db199SXin Li# found in the LICENSE file.
5*9c5db199SXin Li
6*9c5db199SXin Li"""Wrapper library around ts_mon.
7*9c5db199SXin Li
8*9c5db199SXin LiThis library provides some wrapper functionality around ts_mon, to make it more
9*9c5db199SXin Lifriendly to developers. It also provides import safety, in case ts_mon is not
10*9c5db199SXin Lideployed with your code.
11*9c5db199SXin Li"""
12*9c5db199SXin Li
13*9c5db199SXin Lifrom __future__ import division
14*9c5db199SXin Lifrom __future__ import print_function
15*9c5db199SXin Li
16*9c5db199SXin Liimport collections
17*9c5db199SXin Liimport contextlib
18*9c5db199SXin Liimport ssl
19*9c5db199SXin Liimport time
20*9c5db199SXin Lifrom functools import wraps
21*9c5db199SXin Li
22*9c5db199SXin Liimport six
23*9c5db199SXin Lifrom six.moves import queue as Queue
24*9c5db199SXin Li
25*9c5db199SXin Lifrom autotest_lib.utils.frozen_chromite.lib import cros_logging as logging
26*9c5db199SXin Li
27*9c5db199SXin Litry:
28*9c5db199SXin Li  from infra_libs import ts_mon
29*9c5db199SXin Liexcept (ImportError, RuntimeError):
30*9c5db199SXin Li  ts_mon = None
31*9c5db199SXin Li
32*9c5db199SXin Li
33*9c5db199SXin Li# This number is chosen because 1.16^100 seconds is about
34*9c5db199SXin Li# 32 days. This is a good compromise between bucket size
35*9c5db199SXin Li# and dynamic range.
36*9c5db199SXin Li_SECONDS_BUCKET_FACTOR = 1.16
37*9c5db199SXin Li
38*9c5db199SXin Li# If none, we create metrics in this process. Otherwise, we send metrics via
39*9c5db199SXin Li# this Queue to a dedicated flushing processes.
40*9c5db199SXin Li# These attributes are set by chromite.lib.ts_mon_config.SetupTsMonGlobalState.
41*9c5db199SXin LiFLUSHING_PROCESS = None
42*9c5db199SXin LiMESSAGE_QUEUE = None
43*9c5db199SXin Li
44*9c5db199SXin Li_MISSING = object()
45*9c5db199SXin Li
46*9c5db199SXin LiMetricCall = collections.namedtuple('MetricCall', [
47*9c5db199SXin Li    'metric_name', 'metric_args', 'metric_kwargs',
48*9c5db199SXin Li    'method', 'method_args', 'method_kwargs',
49*9c5db199SXin Li    'reset_after'
50*9c5db199SXin Li])
51*9c5db199SXin Li
52*9c5db199SXin Li
53*9c5db199SXin Lidef _FlushingProcessClosed():
54*9c5db199SXin Li  """Returns whether the metrics flushing process has been closed."""
55*9c5db199SXin Li  return (FLUSHING_PROCESS is not None and
56*9c5db199SXin Li          FLUSHING_PROCESS.exitcode is not None)
57*9c5db199SXin Li
58*9c5db199SXin Li
59*9c5db199SXin Liclass ProxyMetric(object):
60*9c5db199SXin Li  """Redirects any method calls to the message queue."""
61*9c5db199SXin Li  def __init__(self, metric, metric_args, metric_kwargs):
62*9c5db199SXin Li    self.metric = metric
63*9c5db199SXin Li    self.metric_args = metric_args
64*9c5db199SXin Li    self.reset_after = metric_kwargs.pop('reset_after', False)
65*9c5db199SXin Li    self.metric_kwargs = metric_kwargs
66*9c5db199SXin Li
67*9c5db199SXin Li  def __getattr__(self, method_name):
68*9c5db199SXin Li    """Redirects all method calls to the MESSAGE_QUEUE."""
69*9c5db199SXin Li    def enqueue(*args, **kwargs):
70*9c5db199SXin Li      if not _FlushingProcessClosed():
71*9c5db199SXin Li        try:
72*9c5db199SXin Li          MESSAGE_QUEUE.put_nowait(
73*9c5db199SXin Li              MetricCall(
74*9c5db199SXin Li                  metric_name=self.metric,
75*9c5db199SXin Li                  metric_args=self.metric_args,
76*9c5db199SXin Li                  metric_kwargs=self.metric_kwargs,
77*9c5db199SXin Li                  method=method_name,
78*9c5db199SXin Li                  method_args=args,
79*9c5db199SXin Li                  method_kwargs=kwargs,
80*9c5db199SXin Li                  reset_after=self.reset_after))
81*9c5db199SXin Li        except Queue.Full:
82*9c5db199SXin Li          logging.warning(
83*9c5db199SXin Li              "Metrics queue is full; skipped sending metric '%s'",
84*9c5db199SXin Li              self.metric)
85*9c5db199SXin Li      else:
86*9c5db199SXin Li        try:
87*9c5db199SXin Li          exit_code = FLUSHING_PROCESS.exitcode
88*9c5db199SXin Li        except AttributeError:
89*9c5db199SXin Li          exit_code = None
90*9c5db199SXin Li        logging.warning(
91*9c5db199SXin Li            'Flushing process has been closed (exit code %s),'
92*9c5db199SXin Li            " skipped sending metric '%s'",
93*9c5db199SXin Li            exit_code,
94*9c5db199SXin Li            self.metric)
95*9c5db199SXin Li
96*9c5db199SXin Li    return enqueue
97*9c5db199SXin Li
98*9c5db199SXin Li
99*9c5db199SXin Lidef _Indirect(fn):
100*9c5db199SXin Li  """Decorates a function to be indirect If MESSAGE_QUEUE is set.
101*9c5db199SXin Li
102*9c5db199SXin Li  If MESSAGE_QUEUE is set, the indirect function will return a proxy metrics
103*9c5db199SXin Li  object; otherwise, it behaves normally.
104*9c5db199SXin Li  """
105*9c5db199SXin Li  @wraps(fn)
106*9c5db199SXin Li  def AddToQueueIfPresent(*args, **kwargs):
107*9c5db199SXin Li    if MESSAGE_QUEUE:
108*9c5db199SXin Li      return ProxyMetric(fn.__name__, args, kwargs)
109*9c5db199SXin Li    else:
110*9c5db199SXin Li      # Whether to reset the metric after the flush; this is only used by
111*9c5db199SXin Li      # |ProxyMetric|, so remove this from the kwargs.
112*9c5db199SXin Li      kwargs.pop('reset_after', None)
113*9c5db199SXin Li      return fn(*args, **kwargs)
114*9c5db199SXin Li  return AddToQueueIfPresent
115*9c5db199SXin Li
116*9c5db199SXin Li
117*9c5db199SXin Liclass MockMetric(object):
118*9c5db199SXin Li  """Mock metric object, to be returned if ts_mon is not set up."""
119*9c5db199SXin Li
120*9c5db199SXin Li  def _mock_method(self, *args, **kwargs):
121*9c5db199SXin Li    pass
122*9c5db199SXin Li
123*9c5db199SXin Li  def __getattr__(self, _):
124*9c5db199SXin Li    return self._mock_method
125*9c5db199SXin Li
126*9c5db199SXin Li
127*9c5db199SXin Lidef _ImportSafe(fn):
128*9c5db199SXin Li  """Decorator which causes |fn| to return MockMetric if ts_mon not imported."""
129*9c5db199SXin Li  @wraps(fn)
130*9c5db199SXin Li  def wrapper(*args, **kwargs):
131*9c5db199SXin Li    if ts_mon:
132*9c5db199SXin Li      return fn(*args, **kwargs)
133*9c5db199SXin Li    else:
134*9c5db199SXin Li      return MockMetric()
135*9c5db199SXin Li
136*9c5db199SXin Li  return wrapper
137*9c5db199SXin Li
138*9c5db199SXin Li
139*9c5db199SXin Liclass FieldSpecAdapter(object):
140*9c5db199SXin Li  """Infers the types of fields values to work around field_spec requirement.
141*9c5db199SXin Li
142*9c5db199SXin Li  See: https://chromium-review.googlesource.com/c/432120/ for the change
143*9c5db199SXin Li  which added a required field_spec argument. This class is a temporary
144*9c5db199SXin Li  workaround to allow inferring the field_spec if is not provided.
145*9c5db199SXin Li  """
146*9c5db199SXin Li  FIELD_CLASSES = {} if ts_mon is None else {
147*9c5db199SXin Li      bool: ts_mon.BooleanField,
148*9c5db199SXin Li      int: ts_mon.IntegerField,
149*9c5db199SXin Li      str: ts_mon.StringField,
150*9c5db199SXin Li      six.text_type: ts_mon.StringField,
151*9c5db199SXin Li  }
152*9c5db199SXin Li
153*9c5db199SXin Li  def __init__(self, metric_cls, *args, **kwargs):
154*9c5db199SXin Li    self._metric_cls = metric_cls
155*9c5db199SXin Li    self._args = args
156*9c5db199SXin Li    self._kwargs = kwargs
157*9c5db199SXin Li    self._instance = _MISSING
158*9c5db199SXin Li
159*9c5db199SXin Li  def __getattr__(self, prop):
160*9c5db199SXin Li    """Return a wrapper which constructs the metric object on demand.
161*9c5db199SXin Li
162*9c5db199SXin Li    Args:
163*9c5db199SXin Li      prop: The property name
164*9c5db199SXin Li
165*9c5db199SXin Li    Returns:
166*9c5db199SXin Li      If self._instance has been created, the instance's .|prop| property,
167*9c5db199SXin Li      otherwise, a wrapper function which creates the ._instance and then
168*9c5db199SXin Li      calls the |prop| method on the instance.
169*9c5db199SXin Li    """
170*9c5db199SXin Li    if self._instance is not _MISSING:
171*9c5db199SXin Li      return getattr(self._instance, prop)
172*9c5db199SXin Li
173*9c5db199SXin Li    def func(*args, **kwargs):
174*9c5db199SXin Li      if self._instance is not _MISSING:
175*9c5db199SXin Li        return getattr(self._instance, prop)(*args, **kwargs)
176*9c5db199SXin Li      fields = FieldSpecAdapter._InferFields(prop, args, kwargs)
177*9c5db199SXin Li      self._kwargs['field_spec'] = FieldSpecAdapter._InferFieldSpec(fields)
178*9c5db199SXin Li      self._instance = self._metric_cls(*self._args, **self._kwargs)
179*9c5db199SXin Li      return getattr(self._instance, prop)(*args, **kwargs)
180*9c5db199SXin Li
181*9c5db199SXin Li    func.__name__ = prop
182*9c5db199SXin Li    return func
183*9c5db199SXin Li
184*9c5db199SXin Li  @staticmethod
185*9c5db199SXin Li  def _InferFields(method_name, args, kwargs):
186*9c5db199SXin Li    """Infers the fields argument.
187*9c5db199SXin Li
188*9c5db199SXin Li    Args:
189*9c5db199SXin Li      method_name: The method called.
190*9c5db199SXin Li      args: The args list
191*9c5db199SXin Li      kwargs: The keyword args
192*9c5db199SXin Li    """
193*9c5db199SXin Li    if 'fields' in kwargs:
194*9c5db199SXin Li      return kwargs['fields']
195*9c5db199SXin Li
196*9c5db199SXin Li    if method_name == 'increment' and args:
197*9c5db199SXin Li      return args[0]
198*9c5db199SXin Li
199*9c5db199SXin Li    if len(args) >= 2:
200*9c5db199SXin Li      return args[1]
201*9c5db199SXin Li
202*9c5db199SXin Li  @staticmethod
203*9c5db199SXin Li  def _InferFieldSpec(fields):
204*9c5db199SXin Li    """Infers the fields types from the given fields.
205*9c5db199SXin Li
206*9c5db199SXin Li    Args:
207*9c5db199SXin Li      fields: A dictionary with metric fields.
208*9c5db199SXin Li    """
209*9c5db199SXin Li    if not fields or not ts_mon:
210*9c5db199SXin Li      return None
211*9c5db199SXin Li
212*9c5db199SXin Li    return [FieldSpecAdapter.FIELD_CLASSES[type(v)](field)
213*9c5db199SXin Li            for (field, v) in sorted(fields.items())]
214*9c5db199SXin Li
215*9c5db199SXin Li
216*9c5db199SXin Lidef _OptionalFieldSpec(fn):
217*9c5db199SXin Li  """Decorates a function to allow an optional description and field_spec."""
218*9c5db199SXin Li  @wraps(fn)
219*9c5db199SXin Li  def wrapper(*args, **kwargs):
220*9c5db199SXin Li    kwargs = dict(**kwargs)  # It's bad practice to mutate **kwargs
221*9c5db199SXin Li    # Slightly different than .setdefault, this line sets a default even when
222*9c5db199SXin Li    # the key is present (as long as the value is not truthy). Empty or None is
223*9c5db199SXin Li    # not allowed for descriptions.
224*9c5db199SXin Li    kwargs['description'] = kwargs.get('description') or 'No description.'
225*9c5db199SXin Li    if 'field_spec' in kwargs and kwargs['field_spec'] is not _MISSING:
226*9c5db199SXin Li      return fn(*args, **kwargs)
227*9c5db199SXin Li    else:
228*9c5db199SXin Li      return FieldSpecAdapter(fn, *args, **kwargs)
229*9c5db199SXin Li  return wrapper
230*9c5db199SXin Li
231*9c5db199SXin Li
232*9c5db199SXin Lidef _Metric(fn):
233*9c5db199SXin Li  """A pipeline of decorators to apply to our metric constructors."""
234*9c5db199SXin Li  return _OptionalFieldSpec(_ImportSafe(_Indirect(fn)))
235*9c5db199SXin Li
236*9c5db199SXin Li
237*9c5db199SXin Li# This is needed for the reset_after flag used by @Indirect.
238*9c5db199SXin Li# pylint: disable=unused-argument
239*9c5db199SXin Li
240*9c5db199SXin Li@_Metric
241*9c5db199SXin Lidef CounterMetric(name, reset_after=False, description=None,
242*9c5db199SXin Li                  field_spec=_MISSING, start_time=None):
243*9c5db199SXin Li  """Returns a metric handle for a counter named |name|."""
244*9c5db199SXin Li  return ts_mon.CounterMetric(name,
245*9c5db199SXin Li                              description=description, field_spec=field_spec,
246*9c5db199SXin Li                              start_time=start_time)
247*9c5db199SXin LiCounter = CounterMetric
248*9c5db199SXin Li
249*9c5db199SXin Li
250*9c5db199SXin Li@_Metric
251*9c5db199SXin Lidef GaugeMetric(name, reset_after=False, description=None, field_spec=_MISSING):
252*9c5db199SXin Li  """Returns a metric handle for a gauge named |name|."""
253*9c5db199SXin Li  return ts_mon.GaugeMetric(name, description=description,
254*9c5db199SXin Li                            field_spec=field_spec)
255*9c5db199SXin LiGauge = GaugeMetric
256*9c5db199SXin Li
257*9c5db199SXin Li
258*9c5db199SXin Li@_Metric
259*9c5db199SXin Lidef CumulativeMetric(name, reset_after=False, description=None,
260*9c5db199SXin Li                     field_spec=_MISSING):
261*9c5db199SXin Li  """Returns a metric handle for a cumulative float named |name|."""
262*9c5db199SXin Li  return ts_mon.CumulativeMetric(name, description=description,
263*9c5db199SXin Li                                 field_spec=field_spec)
264*9c5db199SXin Li
265*9c5db199SXin Li
266*9c5db199SXin Li@_Metric
267*9c5db199SXin Lidef StringMetric(name, reset_after=False, description=None,
268*9c5db199SXin Li                 field_spec=_MISSING):
269*9c5db199SXin Li  """Returns a metric handle for a string named |name|."""
270*9c5db199SXin Li  return ts_mon.StringMetric(name, description=description,
271*9c5db199SXin Li                             field_spec=field_spec)
272*9c5db199SXin LiString = StringMetric
273*9c5db199SXin Li
274*9c5db199SXin Li
275*9c5db199SXin Li@_Metric
276*9c5db199SXin Lidef BooleanMetric(name, reset_after=False, description=None,
277*9c5db199SXin Li                  field_spec=_MISSING):
278*9c5db199SXin Li  """Returns a metric handle for a boolean named |name|."""
279*9c5db199SXin Li  return ts_mon.BooleanMetric(name, description=description,
280*9c5db199SXin Li                              field_spec=field_spec)
281*9c5db199SXin LiBoolean = BooleanMetric
282*9c5db199SXin Li
283*9c5db199SXin Li
284*9c5db199SXin Li@_Metric
285*9c5db199SXin Lidef FloatMetric(name, reset_after=False, description=None, field_spec=_MISSING):
286*9c5db199SXin Li  """Returns a metric handle for a float named |name|."""
287*9c5db199SXin Li  return ts_mon.FloatMetric(name, description=description,
288*9c5db199SXin Li                            field_spec=field_spec)
289*9c5db199SXin LiFloat = FloatMetric
290*9c5db199SXin Li
291*9c5db199SXin Li
292*9c5db199SXin Li@_Metric
293*9c5db199SXin Lidef CumulativeDistributionMetric(name, reset_after=False, description=None,
294*9c5db199SXin Li                                 bucketer=None, field_spec=_MISSING):
295*9c5db199SXin Li  """Returns a metric handle for a cumulative distribution named |name|."""
296*9c5db199SXin Li  return ts_mon.CumulativeDistributionMetric(
297*9c5db199SXin Li      name, description=description, bucketer=bucketer, field_spec=field_spec)
298*9c5db199SXin LiCumulativeDistribution = CumulativeDistributionMetric
299*9c5db199SXin Li
300*9c5db199SXin Li
301*9c5db199SXin Li@_Metric
302*9c5db199SXin Lidef DistributionMetric(name, reset_after=False, description=None,
303*9c5db199SXin Li                       bucketer=None, field_spec=_MISSING):
304*9c5db199SXin Li  """Returns a metric handle for a distribution named |name|."""
305*9c5db199SXin Li  return ts_mon.NonCumulativeDistributionMetric(
306*9c5db199SXin Li      name, description=description, bucketer=bucketer, field_spec=field_spec)
307*9c5db199SXin LiDistribution = DistributionMetric
308*9c5db199SXin Li
309*9c5db199SXin Li
310*9c5db199SXin Li@_Metric
311*9c5db199SXin Lidef CumulativeSmallIntegerDistribution(name, reset_after=False,
312*9c5db199SXin Li                                       description=None, field_spec=_MISSING):
313*9c5db199SXin Li  """Returns a metric handle for a cumulative distribution named |name|.
314*9c5db199SXin Li
315*9c5db199SXin Li  This differs slightly from CumulativeDistribution, in that the underlying
316*9c5db199SXin Li  metric uses a uniform bucketer rather than a geometric one.
317*9c5db199SXin Li
318*9c5db199SXin Li  This metric type is suitable for holding a distribution of numbers that are
319*9c5db199SXin Li  nonnegative integers in the range of 0 to 100.
320*9c5db199SXin Li  """
321*9c5db199SXin Li  return ts_mon.CumulativeDistributionMetric(
322*9c5db199SXin Li      name,
323*9c5db199SXin Li      bucketer=ts_mon.FixedWidthBucketer(1),
324*9c5db199SXin Li      description=description,
325*9c5db199SXin Li      field_spec=field_spec)
326*9c5db199SXin Li
327*9c5db199SXin Li
328*9c5db199SXin Li@_Metric
329*9c5db199SXin Lidef CumulativeSecondsDistribution(name, scale=1, reset_after=False,
330*9c5db199SXin Li                                  description=None, field_spec=_MISSING):
331*9c5db199SXin Li  """Returns a metric handle for a cumulative distribution named |name|.
332*9c5db199SXin Li
333*9c5db199SXin Li  The distribution handle returned by this method is better suited than the
334*9c5db199SXin Li  default one for recording handling times, in seconds.
335*9c5db199SXin Li
336*9c5db199SXin Li  This metric handle has bucketing that is optimized for time intervals
337*9c5db199SXin Li  (in seconds) in the range of 1 second to 32 days. Use |scale| to adjust this
338*9c5db199SXin Li  (e.g. scale=0.1 covers a range from .1 seconds to 3.2 days).
339*9c5db199SXin Li
340*9c5db199SXin Li  Args:
341*9c5db199SXin Li    name: string name of metric
342*9c5db199SXin Li    scale: scaling factor of buckets, and size of the first bucket. default: 1
343*9c5db199SXin Li    reset_after: Should the metric be reset after reporting.
344*9c5db199SXin Li    description: A string description of the metric.
345*9c5db199SXin Li    field_spec: A sequence of ts_mon.Field objects to specify the field schema.
346*9c5db199SXin Li  """
347*9c5db199SXin Li  b = ts_mon.GeometricBucketer(growth_factor=_SECONDS_BUCKET_FACTOR,
348*9c5db199SXin Li                               scale=scale)
349*9c5db199SXin Li  return ts_mon.CumulativeDistributionMetric(
350*9c5db199SXin Li      name, bucketer=b, units=ts_mon.MetricsDataUnits.SECONDS,
351*9c5db199SXin Li      description=description, field_spec=field_spec)
352*9c5db199SXin Li
353*9c5db199SXin LiSecondsDistribution = CumulativeSecondsDistribution
354*9c5db199SXin Li
355*9c5db199SXin Li
356*9c5db199SXin Li@_Metric
357*9c5db199SXin Lidef PercentageDistribution(
358*9c5db199SXin Li    name, num_buckets=1000, reset_after=False,
359*9c5db199SXin Li    description=None, field_spec=_MISSING):
360*9c5db199SXin Li  """Returns a metric handle for a cumulative distribution for percentage.
361*9c5db199SXin Li
362*9c5db199SXin Li  The distribution handle returned by this method is better suited for reporting
363*9c5db199SXin Li  percentage values than the default one. The bucketing is optimized for values
364*9c5db199SXin Li  in [0,100].
365*9c5db199SXin Li
366*9c5db199SXin Li  Args:
367*9c5db199SXin Li    name: The name of this metric.
368*9c5db199SXin Li    num_buckets: This metric buckets the percentage values before
369*9c5db199SXin Li        reporting. This argument controls the number of the bucket the range
370*9c5db199SXin Li        [0,100] is divided in. The default gives you 0.1% resolution.
371*9c5db199SXin Li    reset_after: Should the metric be reset after reporting.
372*9c5db199SXin Li    description: A string description of the metric.
373*9c5db199SXin Li    field_spec: A sequence of ts_mon.Field objects to specify the field schema.
374*9c5db199SXin Li  """
375*9c5db199SXin Li  # The last bucket actually covers [100, 100 + 1.0/num_buckets), so it
376*9c5db199SXin Li  # corresponds to values that exactly match 100%.
377*9c5db199SXin Li  bucket_width = 100 / num_buckets
378*9c5db199SXin Li  b = ts_mon.FixedWidthBucketer(bucket_width, num_buckets)
379*9c5db199SXin Li  return ts_mon.CumulativeDistributionMetric(
380*9c5db199SXin Li      name, bucketer=b,
381*9c5db199SXin Li      description=description, field_spec=field_spec)
382*9c5db199SXin Li
383*9c5db199SXin Li
384*9c5db199SXin Li@contextlib.contextmanager
385*9c5db199SXin Lidef SecondsTimer(name, fields=None, description=None, field_spec=_MISSING,
386*9c5db199SXin Li                 scale=1, record_on_exception=True, add_exception_field=False):
387*9c5db199SXin Li  """Record the time of an operation to a CumulativeSecondsDistributionMetric.
388*9c5db199SXin Li
389*9c5db199SXin Li  Records the time taken inside of the context block, to the
390*9c5db199SXin Li  CumulativeSecondsDistribution named |name|, with the given fields.
391*9c5db199SXin Li
392*9c5db199SXin Li  Examples:
393*9c5db199SXin Li    # Time the doSomething() call, with field values that are independent of the
394*9c5db199SXin Li    # results of the operation.
395*9c5db199SXin Li    with SecondsTimer('timer/name', fields={'foo': 'bar'},
396*9c5db199SXin Li                      description='My timer',
397*9c5db199SXin Li                      field_spec=[ts_mon.StringField('foo'),
398*9c5db199SXin Li                                  ts_mon.BooleanField('success')]):
399*9c5db199SXin Li      doSomething()
400*9c5db199SXin Li
401*9c5db199SXin Li    # Time the doSomethingElse call, with field values that depend on the
402*9c5db199SXin Li    # results of that operation. Note that it is important that a default value
403*9c5db199SXin Li    # is specified for these fields, in case an exception is thrown by
404*9c5db199SXin Li    # doSomethingElse()
405*9c5db199SXin Li    f = {'success': False, 'foo': 'bar'}
406*9c5db199SXin Li    with SecondsTimer('timer/name', fields=f, description='My timer',
407*9c5db199SXin Li                      field_spec=[ts_mon.StringField('foo')]) as c:
408*9c5db199SXin Li      doSomethingElse()
409*9c5db199SXin Li      c['success'] = True
410*9c5db199SXin Li
411*9c5db199SXin Li    # Incorrect Usage!
412*9c5db199SXin Li    with SecondsTimer('timer/name', description='My timer') as c:
413*9c5db199SXin Li      doSomething()
414*9c5db199SXin Li      c['foo'] = bar # 'foo' is not a valid field, because no default
415*9c5db199SXin Li                     # value for it was specified in the context constructor.
416*9c5db199SXin Li                     # It will be silently ignored.
417*9c5db199SXin Li
418*9c5db199SXin Li  Args:
419*9c5db199SXin Li    name: The name of the metric to create
420*9c5db199SXin Li    fields: The fields of the metric to create.
421*9c5db199SXin Li    description: A string description of the metric.
422*9c5db199SXin Li    field_spec: A sequence of ts_mon.Field objects to specify the field schema.
423*9c5db199SXin Li    scale: A float to scale the CumulativeSecondsDistribution buckets by.
424*9c5db199SXin Li    record_on_exception: Whether to record metrics if an exception is raised.
425*9c5db199SXin Li    add_exception_field: Whether to add a BooleanField('encountered_exception')
426*9c5db199SXin Li        to the FieldSpec provided, and set its value to True iff an exception
427*9c5db199SXin Li        was raised in the context.
428*9c5db199SXin Li  """
429*9c5db199SXin Li  if field_spec is not None and field_spec is not _MISSING:
430*9c5db199SXin Li    field_spec.append(ts_mon.BooleanField('encountered_exception'))
431*9c5db199SXin Li
432*9c5db199SXin Li  m = CumulativeSecondsDistribution(
433*9c5db199SXin Li      name, scale=scale, description=description, field_spec=field_spec)
434*9c5db199SXin Li  f = fields or {}
435*9c5db199SXin Li  f = dict(f)
436*9c5db199SXin Li  keys = list(f)
437*9c5db199SXin Li  t0 = _GetSystemClock()
438*9c5db199SXin Li
439*9c5db199SXin Li  error = True
440*9c5db199SXin Li  try:
441*9c5db199SXin Li    yield f
442*9c5db199SXin Li    error = False
443*9c5db199SXin Li  finally:
444*9c5db199SXin Li    if record_on_exception and add_exception_field:
445*9c5db199SXin Li      keys.append('encountered_exception')
446*9c5db199SXin Li      f.setdefault('encountered_exception', error)
447*9c5db199SXin Li    # Filter out keys that were not part of the initial key set. This is to
448*9c5db199SXin Li    # avoid inconsistent fields.
449*9c5db199SXin Li    # TODO(akeshet): Doing this filtering isn't super efficient. Would be better
450*9c5db199SXin Li    # to implement some key-restricted subclass or wrapper around dict, and just
451*9c5db199SXin Li    # yield that above rather than yielding a regular dict.
452*9c5db199SXin Li    if record_on_exception or not error:
453*9c5db199SXin Li      dt = _GetSystemClock() - t0
454*9c5db199SXin Li      # TODO(ayatane): Handle backward clock jumps.  See _GetSystemClock.
455*9c5db199SXin Li      if dt >= 0:
456*9c5db199SXin Li        m.add(dt, fields={k: f[k] for k in keys})
457*9c5db199SXin Li
458*9c5db199SXin Li
459*9c5db199SXin Lidef SecondsTimerDecorator(name, fields=None, description=None,
460*9c5db199SXin Li                          field_spec=_MISSING, scale=1,
461*9c5db199SXin Li                          record_on_exception=True, add_exception_field=False):
462*9c5db199SXin Li  """Decorator to time the duration of function calls.
463*9c5db199SXin Li
464*9c5db199SXin Li  Examples:
465*9c5db199SXin Li    @SecondsTimerDecorator('timer/name', fields={'foo': 'bar'},
466*9c5db199SXin Li                           description='My timer',
467*9c5db199SXin Li                           field_spec=[ts_mon.StringField('foo')])
468*9c5db199SXin Li    def Foo(bar):
469*9c5db199SXin Li      return doStuff()
470*9c5db199SXin Li
471*9c5db199SXin Li    is equivalent to
472*9c5db199SXin Li
473*9c5db199SXin Li    def Foo(bar):
474*9c5db199SXin Li      with SecondsTimer('timer/name', fields={'foo': 'bar'},
475*9c5db199SXin Li                        description='My timer',
476*9c5db199SXin Li                        field_spec=[ts_mon.StringField('foo')])
477*9c5db199SXin Li        return doStuff()
478*9c5db199SXin Li
479*9c5db199SXin Li  Args:
480*9c5db199SXin Li    name: The name of the metric to create
481*9c5db199SXin Li    fields: The fields of the metric to create
482*9c5db199SXin Li    description: A string description of the metric.
483*9c5db199SXin Li    field_spec: A sequence of ts_mon.Field objects to specify the field schema.
484*9c5db199SXin Li    scale: A float to scale the distrubtion by
485*9c5db199SXin Li    record_on_exception: Whether to record metrics if an exception is raised.
486*9c5db199SXin Li    add_exception_field: Whether to add a BooleanField('encountered_exception')
487*9c5db199SXin Li        to the FieldSpec provided, and set its value to True iff an exception
488*9c5db199SXin Li        was raised in the context.
489*9c5db199SXin Li  """
490*9c5db199SXin Li  def decorator(fn):
491*9c5db199SXin Li    @wraps(fn)
492*9c5db199SXin Li    def wrapper(*args, **kwargs):
493*9c5db199SXin Li      with SecondsTimer(name, fields=fields, description=description,
494*9c5db199SXin Li                        field_spec=field_spec, scale=scale,
495*9c5db199SXin Li                        record_on_exception=record_on_exception,
496*9c5db199SXin Li                        add_exception_field=add_exception_field):
497*9c5db199SXin Li        return fn(*args, **kwargs)
498*9c5db199SXin Li
499*9c5db199SXin Li    return wrapper
500*9c5db199SXin Li
501*9c5db199SXin Li  return decorator
502*9c5db199SXin Li
503*9c5db199SXin Li
504*9c5db199SXin Li@contextlib.contextmanager
505*9c5db199SXin Lidef SecondsInstanceTimer(name, fields=None, description=None,
506*9c5db199SXin Li                         field_spec=_MISSING, record_on_exception=True,
507*9c5db199SXin Li                         add_exception_field=False):
508*9c5db199SXin Li  """Record the time of an operation to a FloatMetric.
509*9c5db199SXin Li
510*9c5db199SXin Li  Records the time taken inside of the context block, to the
511*9c5db199SXin Li  Float metric named |name|, with the given fields.  This is
512*9c5db199SXin Li  a non-cumulative metric; this represents the absolute time
513*9c5db199SXin Li  taken for a specific block.  The duration is stored in a float
514*9c5db199SXin Li  to provide flexibility in the future for higher accuracy.
515*9c5db199SXin Li
516*9c5db199SXin Li  Examples:
517*9c5db199SXin Li    # Time the doSomething() call, with field values that are independent of the
518*9c5db199SXin Li    # results of the operation.
519*9c5db199SXin Li    with SecondsInstanceTimer('timer/name', fields={'foo': 'bar'},
520*9c5db199SXin Li                              description='My timer',
521*9c5db199SXin Li                              field_spec=[ts_mon.StringField('foo'),
522*9c5db199SXin Li                                          ts_mon.BooleanField('success')]):
523*9c5db199SXin Li      doSomething()
524*9c5db199SXin Li
525*9c5db199SXin Li    # Time the doSomethingElse call, with field values that depend on the
526*9c5db199SXin Li    # results of that operation. Note that it is important that a default value
527*9c5db199SXin Li    # is specified for these fields, in case an exception is thrown by
528*9c5db199SXin Li    # doSomethingElse()
529*9c5db199SXin Li    f = {'success': False, 'foo': 'bar'}
530*9c5db199SXin Li    with SecondsInstanceTimer('timer/name', fields=f, description='My timer',
531*9c5db199SXin Li                              field_spec=[ts_mon.StringField('foo')]) as c:
532*9c5db199SXin Li      doSomethingElse()
533*9c5db199SXin Li      c['success'] = True
534*9c5db199SXin Li
535*9c5db199SXin Li    # Incorrect Usage!
536*9c5db199SXin Li    with SecondsInstanceTimer('timer/name', description='My timer') as c:
537*9c5db199SXin Li      doSomething()
538*9c5db199SXin Li      c['foo'] = bar # 'foo' is not a valid field, because no default
539*9c5db199SXin Li                     # value for it was specified in the context constructor.
540*9c5db199SXin Li                     # It will be silently ignored.
541*9c5db199SXin Li
542*9c5db199SXin Li  Args:
543*9c5db199SXin Li    name: The name of the metric to create
544*9c5db199SXin Li    fields: The fields of the metric to create.
545*9c5db199SXin Li    description: A string description of the metric.
546*9c5db199SXin Li    field_spec: A sequence of ts_mon.Field objects to specify the field schema.
547*9c5db199SXin Li    record_on_exception: Whether to record metrics if an exception is raised.
548*9c5db199SXin Li    add_exception_field: Whether to add a BooleanField('encountered_exception')
549*9c5db199SXin Li        to the FieldSpec provided, and set its value to True iff an exception
550*9c5db199SXin Li        was raised in the context.
551*9c5db199SXin Li
552*9c5db199SXin Li  Yields:
553*9c5db199SXin Li    Float based metric measing the duration of execution.
554*9c5db199SXin Li  """
555*9c5db199SXin Li  if field_spec is not None and field_spec is not _MISSING:
556*9c5db199SXin Li    field_spec.append(ts_mon.BooleanField('encountered_exception'))
557*9c5db199SXin Li
558*9c5db199SXin Li  m = FloatMetric(name, description=description, field_spec=field_spec)
559*9c5db199SXin Li  f = dict(fields or {})
560*9c5db199SXin Li  keys = list(f)
561*9c5db199SXin Li  t0 = _GetSystemClock()
562*9c5db199SXin Li
563*9c5db199SXin Li  error = True
564*9c5db199SXin Li  try:
565*9c5db199SXin Li    yield f
566*9c5db199SXin Li    error = False
567*9c5db199SXin Li  finally:
568*9c5db199SXin Li    if record_on_exception and add_exception_field:
569*9c5db199SXin Li      keys.append('encountered_exception')
570*9c5db199SXin Li      f.setdefault('encountered_exception', error)
571*9c5db199SXin Li    # Filter out keys that were not part of the initial key set. This is to
572*9c5db199SXin Li    # avoid inconsistent fields.
573*9c5db199SXin Li    # TODO(akeshet): Doing this filtering isn't super efficient. Would be better
574*9c5db199SXin Li    # to implement some key-restricted subclass or wrapper around dict, and just
575*9c5db199SXin Li    # yield that above rather than yielding a regular dict.
576*9c5db199SXin Li    if record_on_exception or not error:
577*9c5db199SXin Li      dt = _GetSystemClock() - t0
578*9c5db199SXin Li      m.set(dt, fields={k: f[k] for k in keys})
579*9c5db199SXin Li
580*9c5db199SXin Li
581*9c5db199SXin Lidef SecondsInstanceTimerDecorator(name, fields=None, description=None,
582*9c5db199SXin Li                                  field_spec=_MISSING,
583*9c5db199SXin Li                                  record_on_exception=True,
584*9c5db199SXin Li                                  add_exception_field=False):
585*9c5db199SXin Li  """Decorator to time the gauge duration of function calls.
586*9c5db199SXin Li
587*9c5db199SXin Li  Examples:
588*9c5db199SXin Li    @SecondsInstanceTimerDecorator('timer/name', fields={'foo': 'bar'},
589*9c5db199SXin Li                                   description='My timer',
590*9c5db199SXin Li                                   field_spec=[ts_mon.StringField('foo'),
591*9c5db199SXin Li                                               ts_mon.BooleanField('success')]):
592*9c5db199SXin Li
593*9c5db199SXin Li    def Foo(bar):
594*9c5db199SXin Li      return doStuff()
595*9c5db199SXin Li
596*9c5db199SXin Li    is equivalent to
597*9c5db199SXin Li
598*9c5db199SXin Li    def Foo(bar):
599*9c5db199SXin Li      with SecondsInstanceTimer('timer/name', fields={'foo': 'bar'},
600*9c5db199SXin Li                                description='My timer',
601*9c5db199SXin Li                                field_spec=[ts_mon.StringField('foo'),
602*9c5db199SXin Li                                            ts_mon.BooleanField('success')]):
603*9c5db199SXin Li        return doStuff()
604*9c5db199SXin Li
605*9c5db199SXin Li  Args:
606*9c5db199SXin Li    name: The name of the metric to create
607*9c5db199SXin Li    fields: The fields of the metric to create
608*9c5db199SXin Li    description: A string description of the metric.
609*9c5db199SXin Li    field_spec: A sequence of ts_mon.Field objects to specify the field schema.
610*9c5db199SXin Li    record_on_exception: Whether to record metrics if an exception is raised.
611*9c5db199SXin Li    add_exception_field: Whether to add a BooleanField('encountered_exception')
612*9c5db199SXin Li        to the FieldSpec provided, and set its value to True iff an exception
613*9c5db199SXin Li        was raised in the context.
614*9c5db199SXin Li
615*9c5db199SXin Li  Returns:
616*9c5db199SXin Li    A SecondsInstanceTimer metric decorator.
617*9c5db199SXin Li  """
618*9c5db199SXin Li  def decorator(fn):
619*9c5db199SXin Li    @wraps(fn)
620*9c5db199SXin Li    def wrapper(*args, **kwargs):
621*9c5db199SXin Li      with SecondsInstanceTimer(name, fields=fields, description=description,
622*9c5db199SXin Li                                field_spec=field_spec,
623*9c5db199SXin Li                                record_on_exception=record_on_exception,
624*9c5db199SXin Li                                add_exception_field=add_exception_field):
625*9c5db199SXin Li        return fn(*args, **kwargs)
626*9c5db199SXin Li
627*9c5db199SXin Li    return wrapper
628*9c5db199SXin Li
629*9c5db199SXin Li  return decorator
630*9c5db199SXin Li
631*9c5db199SXin Li
632*9c5db199SXin Li@contextlib.contextmanager
633*9c5db199SXin Lidef SuccessCounter(name, fields=None, description=None, field_spec=_MISSING):
634*9c5db199SXin Li  """Create a counter that tracks if something succeeds.
635*9c5db199SXin Li
636*9c5db199SXin Li  Args:
637*9c5db199SXin Li    name: The name of the metric to create
638*9c5db199SXin Li    fields: The fields of the metric
639*9c5db199SXin Li    description: A string description of the metric.
640*9c5db199SXin Li    field_spec: A sequence of ts_mon.Field objects to specify the field schema.
641*9c5db199SXin Li  """
642*9c5db199SXin Li  c = Counter(name)
643*9c5db199SXin Li  f = fields or {}
644*9c5db199SXin Li  f = f.copy()
645*9c5db199SXin Li  # We add in the additional field success.
646*9c5db199SXin Li  keys = list(f) + ['success']
647*9c5db199SXin Li  success = False
648*9c5db199SXin Li  try:
649*9c5db199SXin Li    yield f
650*9c5db199SXin Li    success = True
651*9c5db199SXin Li  finally:
652*9c5db199SXin Li    f.setdefault('success', success)
653*9c5db199SXin Li    f = {k: f[k] for k in keys}
654*9c5db199SXin Li    c.increment(fields=f)
655*9c5db199SXin Li
656*9c5db199SXin Li
657*9c5db199SXin Li@contextlib.contextmanager
658*9c5db199SXin Lidef Presence(name, fields=None, description=None, field_spec=_MISSING):
659*9c5db199SXin Li  """A counter of 'active' things.
660*9c5db199SXin Li
661*9c5db199SXin Li  This keeps track of how many name's are active at any given time. However,
662*9c5db199SXin Li  it's only suitable for long running tasks, since the initial true value may
663*9c5db199SXin Li  never be written out if the task doesn't run for at least a minute.
664*9c5db199SXin Li  """
665*9c5db199SXin Li  b = Boolean(name, description=None, field_spec=field_spec)
666*9c5db199SXin Li  b.set(True, fields=fields)
667*9c5db199SXin Li  try:
668*9c5db199SXin Li    yield
669*9c5db199SXin Li  finally:
670*9c5db199SXin Li    b.set(False, fields=fields)
671*9c5db199SXin Li
672*9c5db199SXin Li
673*9c5db199SXin Liclass RuntimeBreakdownTimer(object):
674*9c5db199SXin Li  """Record the time of an operation and the breakdown into sub-steps.
675*9c5db199SXin Li
676*9c5db199SXin Li  Examples:
677*9c5db199SXin Li    with RuntimeBreakdownTimer('timer/name', fields={'foo':'bar'},
678*9c5db199SXin Li                               description='My timer',
679*9c5db199SXin Li                               field_spec=[ts_mon.StringField('foo')]) as timer:
680*9c5db199SXin Li      with timer.Step('first_step'):
681*9c5db199SXin Li        doFirstStep()
682*9c5db199SXin Li      with timer.Step('second_step'):
683*9c5db199SXin Li        doSecondStep()
684*9c5db199SXin Li      # The time spent next will show up under .../timer/name/breakdown_no_step
685*9c5db199SXin Li      doSomeNonStepWork()
686*9c5db199SXin Li
687*9c5db199SXin Li  This will emit the following metrics:
688*9c5db199SXin Li  - .../timer/name/total_duration - A CumulativeSecondsDistribution metric for
689*9c5db199SXin Li        the time spent inside the outer with block.
690*9c5db199SXin Li  - .../timer/name/breakdown/first_step and
691*9c5db199SXin Li    .../timer/name/breakdown/second_step - PercentageDistribution metrics for
692*9c5db199SXin Li        the fraction of time devoted to each substep.
693*9c5db199SXin Li  - .../timer/name/breakdown_unaccounted - PercentageDistribution metric for the
694*9c5db199SXin Li        fraction of time that is not accounted for in any of the substeps.
695*9c5db199SXin Li  - .../timer/name/bucketing_loss - PercentageDistribution metric buckets values
696*9c5db199SXin Li        before reporting them as distributions. This causes small errors in the
697*9c5db199SXin Li        reported values because they are rounded to the reported buckets lower
698*9c5db199SXin Li        bound. This is a CumulativeMetric measuring the total rounding error
699*9c5db199SXin Li        accrued in reporting all the percentages. The worst case bucketing loss
700*9c5db199SXin Li        for x steps is (x+1)/10. So, if you time across 9 steps, you should
701*9c5db199SXin Li        expect no more than 1% rounding error.
702*9c5db199SXin Li  [experimental]
703*9c5db199SXin Li  - .../timer/name/duration_breakdown - A Float metric, with one stream per Step
704*9c5db199SXin Li        indicating the ratio of time spent in that step. The different steps are
705*9c5db199SXin Li        differentiated via a field with key 'step_name'. Since some of the time
706*9c5db199SXin Li        can be spent outside any steps, these ratios will sum to <= 1.
707*9c5db199SXin Li
708*9c5db199SXin Li  NB: This helper can only be used if the field values are known at the
709*9c5db199SXin Li  beginning of the outer context and do not change as a result of any of the
710*9c5db199SXin Li  operations timed.
711*9c5db199SXin Li  """
712*9c5db199SXin Li
713*9c5db199SXin Li  PERCENT_BUCKET_COUNT = 1000
714*9c5db199SXin Li
715*9c5db199SXin Li  _StepMetrics = collections.namedtuple('_StepMetrics', ['name', 'time_s'])
716*9c5db199SXin Li
717*9c5db199SXin Li  def __init__(self, name, fields=None, description=None, field_spec=_MISSING):
718*9c5db199SXin Li    self._name = name
719*9c5db199SXin Li    self._fields = fields
720*9c5db199SXin Li    self._field_spec = field_spec
721*9c5db199SXin Li    self._description = description
722*9c5db199SXin Li    self._outer_t0 = None
723*9c5db199SXin Li    self._total_time_s = 0
724*9c5db199SXin Li    self._inside_step = False
725*9c5db199SXin Li    self._step_metrics = []
726*9c5db199SXin Li
727*9c5db199SXin Li  def __enter__(self):
728*9c5db199SXin Li    self._outer_t0 = _GetSystemClock()
729*9c5db199SXin Li    return self
730*9c5db199SXin Li
731*9c5db199SXin Li  def __exit__(self, _type, _value, _traceback):
732*9c5db199SXin Li    self._RecordTotalTime()
733*9c5db199SXin Li
734*9c5db199SXin Li    outer_timer = CumulativeSecondsDistribution(
735*9c5db199SXin Li        '%s/total_duration' % (self._name,),
736*9c5db199SXin Li        field_spec=self._field_spec,
737*9c5db199SXin Li        description=self._description)
738*9c5db199SXin Li    outer_timer.add(self._total_time_s, fields=self._fields)
739*9c5db199SXin Li
740*9c5db199SXin Li    for name, percent in self._GetStepBreakdowns().items():
741*9c5db199SXin Li      step_metric = PercentageDistribution(
742*9c5db199SXin Li          '%s/breakdown/%s' % (self._name, name),
743*9c5db199SXin Li          num_buckets=self.PERCENT_BUCKET_COUNT,
744*9c5db199SXin Li          field_spec=self._field_spec,
745*9c5db199SXin Li          description=self._description)
746*9c5db199SXin Li      step_metric.add(percent, fields=self._fields)
747*9c5db199SXin Li
748*9c5db199SXin Li      fields = dict(self._fields) if self._fields is not None else dict()
749*9c5db199SXin Li      fields['step_name'] = name
750*9c5db199SXin Li      # TODO(pprabhu): Convert _GetStepBreakdowns() to return ratios instead of
751*9c5db199SXin Li      # percentage when the old PercentageDistribution reporting is deleted.
752*9c5db199SXin Li      Float('%s/duration_breakdown' % self._name).set(percent / 100,
753*9c5db199SXin Li                                                      fields=fields)
754*9c5db199SXin Li
755*9c5db199SXin Li    unaccounted_metric = PercentageDistribution(
756*9c5db199SXin Li        '%s/breakdown_unaccounted' % self._name,
757*9c5db199SXin Li        num_buckets=self.PERCENT_BUCKET_COUNT,
758*9c5db199SXin Li        field_spec=self._field_spec,
759*9c5db199SXin Li        description=self._description)
760*9c5db199SXin Li    unaccounted_metric.add(self._GetUnaccountedBreakdown(), fields=self._fields)
761*9c5db199SXin Li
762*9c5db199SXin Li    bucketing_loss_metric = CumulativeMetric(
763*9c5db199SXin Li        '%s/bucketing_loss' % self._name,
764*9c5db199SXin Li        field_spec=self._field_spec,
765*9c5db199SXin Li        description=self._description)
766*9c5db199SXin Li    bucketing_loss_metric.increment_by(self._GetBucketingLoss(),
767*9c5db199SXin Li                                       fields=self._fields)
768*9c5db199SXin Li
769*9c5db199SXin Li  @contextlib.contextmanager
770*9c5db199SXin Li  def Step(self, step_name):
771*9c5db199SXin Li    """Start a new step named step_name in the timed operation.
772*9c5db199SXin Li
773*9c5db199SXin Li    Note that it is not possible to start a step inside a step. i.e.,
774*9c5db199SXin Li
775*9c5db199SXin Li    with RuntimeBreakdownTimer('timer') as timer:
776*9c5db199SXin Li      with timer.Step('outer_step'):
777*9c5db199SXin Li        with timer.Step('inner_step'):
778*9c5db199SXin Li          # will by design raise an exception.
779*9c5db199SXin Li
780*9c5db199SXin Li    Args:
781*9c5db199SXin Li      step_name: The name of the step being timed.
782*9c5db199SXin Li    """
783*9c5db199SXin Li    if self._inside_step:
784*9c5db199SXin Li      logging.error('RuntimeBreakdownTimer.Step is not reentrant. '
785*9c5db199SXin Li                    'Dropping step: %s', step_name)
786*9c5db199SXin Li      yield
787*9c5db199SXin Li      return
788*9c5db199SXin Li
789*9c5db199SXin Li    self._inside_step = True
790*9c5db199SXin Li    t0 = _GetSystemClock()
791*9c5db199SXin Li    try:
792*9c5db199SXin Li      yield
793*9c5db199SXin Li    finally:
794*9c5db199SXin Li      self._inside_step = False
795*9c5db199SXin Li      step_time_s = _GetSystemClock() - t0
796*9c5db199SXin Li      # TODO(ayatane): Handle backward clock jumps.  See _GetSystemClock.
797*9c5db199SXin Li      step_time_s = max(0, step_time_s)
798*9c5db199SXin Li      self._step_metrics.append(self._StepMetrics(step_name, step_time_s))
799*9c5db199SXin Li
800*9c5db199SXin Li  def _GetStepBreakdowns(self):
801*9c5db199SXin Li    """Returns percentage of time spent in each step.
802*9c5db199SXin Li
803*9c5db199SXin Li    Must be called after |_RecordTotalTime|.
804*9c5db199SXin Li    """
805*9c5db199SXin Li    if not self._total_time_s:
806*9c5db199SXin Li      return {}
807*9c5db199SXin Li    return {x.name: (x.time_s * 100) / self._total_time_s
808*9c5db199SXin Li            for x in self._step_metrics}
809*9c5db199SXin Li
810*9c5db199SXin Li  def _GetUnaccountedBreakdown(self):
811*9c5db199SXin Li    """Returns the percentage time spent outside of all steps.
812*9c5db199SXin Li
813*9c5db199SXin Li    Must be called after |_RecordTotalTime|.
814*9c5db199SXin Li    """
815*9c5db199SXin Li    breakdown_percentages = sum(self._GetStepBreakdowns().values())
816*9c5db199SXin Li    return max(0, 100 - breakdown_percentages)
817*9c5db199SXin Li
818*9c5db199SXin Li  def _GetBucketingLoss(self):
819*9c5db199SXin Li    """Compute the actual loss in reported percentages due to bucketing.
820*9c5db199SXin Li
821*9c5db199SXin Li    Must be called after |_RecordTotalTime|.
822*9c5db199SXin Li    """
823*9c5db199SXin Li    reported = list(self._GetStepBreakdowns().values())
824*9c5db199SXin Li    reported.append(self._GetUnaccountedBreakdown())
825*9c5db199SXin Li    bucket_width = 100 / self.PERCENT_BUCKET_COUNT
826*9c5db199SXin Li    return sum(x % bucket_width for x in reported)
827*9c5db199SXin Li
828*9c5db199SXin Li  def _RecordTotalTime(self):
829*9c5db199SXin Li    self._total_time_s = _GetSystemClock() - self._outer_t0
830*9c5db199SXin Li    # TODO(ayatane): Handle backward clock jumps.  See _GetSystemClock.
831*9c5db199SXin Li    self._total_time_s = max(0, self._total_time_s)
832*9c5db199SXin Li
833*9c5db199SXin Li
834*9c5db199SXin Lidef _GetSystemClock():
835*9c5db199SXin Li  """Return a clock time.
836*9c5db199SXin Li
837*9c5db199SXin Li  The only thing that the return value can be used for is to subtract from
838*9c5db199SXin Li  other instances to determine time elapsed.
839*9c5db199SXin Li  """
840*9c5db199SXin Li  # TODO(ayatane): We should use a monotonic clock to measure this,
841*9c5db199SXin Li  # but Python 2 does not have one.
842*9c5db199SXin Li  return time.time()
843*9c5db199SXin Li
844*9c5db199SXin Li
845*9c5db199SXin Lidef Flush(reset_after=()):
846*9c5db199SXin Li  """Flushes metrics, but warns on transient errors.
847*9c5db199SXin Li
848*9c5db199SXin Li  Args:
849*9c5db199SXin Li    reset_after: A list of metrics to reset after flushing.
850*9c5db199SXin Li  """
851*9c5db199SXin Li  if not ts_mon:
852*9c5db199SXin Li    return
853*9c5db199SXin Li
854*9c5db199SXin Li  try:
855*9c5db199SXin Li    ts_mon.flush()
856*9c5db199SXin Li    while reset_after:
857*9c5db199SXin Li      reset_after.pop().reset()
858*9c5db199SXin Li  except ssl.SSLError as e:
859*9c5db199SXin Li    logging.warning('Caught transient network error while flushing: %s', e)
860*9c5db199SXin Li  except Exception as e:
861*9c5db199SXin Li    logging.error('Caught exception while flushing: %s', e)
862