OLD | NEW |
(Empty) | |
| 1 # Copyright 2016 The Chromium Authors. All rights reserved. |
| 2 # Use of this source code is govered by a BSD-style |
| 3 # license that can be found in the LICENSE file or at |
| 4 # https://developers.google.com/open-source/licenses/bsd |
| 5 |
| 6 """A simple profiler object to track how time is spent on a request. |
| 7 |
| 8 The profiler is called from application code at the begining and |
| 9 end of each major phase and subphase of processing. The profiler |
| 10 object keeps track of how much time was spent on each phase or subphase. |
| 11 |
| 12 This class is useful when developers need to understand where |
| 13 server-side time is being spent. It includes durations in |
| 14 milliseconds, and a simple bar chart on the HTML page. |
| 15 |
| 16 On-page debugging and performance info is useful because it makes it easier |
| 17 to explore performance interactively. |
| 18 """ |
| 19 |
| 20 import logging |
| 21 import time |
| 22 |
| 23 from contextlib import contextmanager |
| 24 |
| 25 |
| 26 class Profiler(object): |
| 27 """Object to record and help display request processing profiling info. |
| 28 |
| 29 The Profiler class holds a list of phase objects, which can hold additional |
| 30 phase objects (which are subphases). Each phase or subphase represents some |
| 31 meaningful part of this application's HTTP request processing. |
| 32 """ |
| 33 |
| 34 _COLORS = ['900', '090', '009', '360', '306', '036', |
| 35 '630', '630', '063', '333'] |
| 36 |
| 37 def __init__(self): |
| 38 """Each request processing profile begins with an empty list of phases.""" |
| 39 self.top_phase = _Phase('overall profile', -1, None) |
| 40 self.current_phase = self.top_phase |
| 41 self.next_color = 0 |
| 42 |
| 43 @contextmanager |
| 44 def Phase(self, name='unspecified phase'): |
| 45 """Context manager to automatically begin and end (sub)phases.""" |
| 46 color = self._COLORS[self.next_color % len(self._COLORS)] |
| 47 self.next_color += 1 |
| 48 self.current_phase = _Phase(name, color, self.current_phase) |
| 49 try: |
| 50 yield |
| 51 finally: |
| 52 self.current_phase = self.current_phase.End() |
| 53 |
| 54 def LogStats(self): |
| 55 """Log sufficiently-long phases and subphases, for debugging purposes.""" |
| 56 self.top_phase.LogStats() |
| 57 |
| 58 |
| 59 class _Phase(object): |
| 60 """A _Phase instance represents a period of time during request processing.""" |
| 61 |
| 62 def __init__(self, name, color, parent): |
| 63 """Initialize a (sub)phase with the given name and current system clock.""" |
| 64 self.start = time.time() |
| 65 self.name = name |
| 66 self.color = color |
| 67 self.subphases = [] |
| 68 self.elapsed_seconds = None |
| 69 self.ms = 'in_progress' # shown if the phase never records a finish. |
| 70 self.uncategorized_ms = None |
| 71 self.parent = parent |
| 72 if self.parent is not None: |
| 73 self.parent._RegisterSubphase(self) |
| 74 |
| 75 def _RegisterSubphase(self, subphase): |
| 76 """Add a subphase to this phase.""" |
| 77 self.subphases.append(subphase) |
| 78 |
| 79 def End(self): |
| 80 """Record the time between the start and end of this (sub)phase.""" |
| 81 self.elapsed_seconds = time.time() - self.start |
| 82 self.ms = str(int(self.elapsed_seconds * 1000)) |
| 83 categorized = sum(sub.elapsed_seconds for sub in self.subphases) |
| 84 self.uncategorized_ms = int((self.elapsed_seconds - categorized) * 1000) |
| 85 return self.parent |
| 86 |
| 87 def LogStats(self): |
| 88 # Phases that took longer than 30ms are interesting. |
| 89 if self.elapsed_seconds > 0.03: |
| 90 logging.info('%5s: %s', self.ms, self.name) |
| 91 for subphase in self.subphases: |
| 92 subphase.LogStats() |
OLD | NEW |