• Home
  • Line#
  • Scopes#
  • Navigate#
  • Raw
  • Download
1# Copyright 2016 The Chromium Authors. All rights reserved.
2# Use of this source code is governed by a BSD-style license that can be
3# found in the LICENSE file.
4from py_trace_event import trace_time
5
6
7r"""Instrumentation-based profiling for Python.
8
9trace_event allows you to hand-instrument your code with areas of interest.
10When enabled, trace_event logs the start and stop times of these events to a
11logfile. These resulting logfiles can be viewed with either Chrome's
12about:tracing UI or with the standalone trace_event_viewer available at
13  http://www.github.com/natduca/trace_event_viewer/
14
15To use trace event, call trace_event_enable and start instrumenting your code:
16   from trace_event import *
17
18   if "--trace" in sys.argv:
19     trace_enable("myfile.trace")
20
21   @traced
22   def foo():
23     ...
24
25   class MyFoo(object):
26     @traced
27     def bar(self):
28       ...
29
30trace_event records trace events to an in-memory buffer. If your application is
31long running and you want to see the results of a trace before it exits, you can
32call trace_flush to write any in-memory events to disk.
33
34To help intregrating trace_event into existing codebases that dont want to add
35trace_event as a dependancy, trace_event is split into an import shim
36(trace_event.py) and an implementaiton (trace_event_impl/*). You can copy the
37shim, trace_event.py, directly into your including codebase. If the
38trace_event_impl is not found, the shim will simply noop.
39
40trace_event is safe with regard to Python threads. Simply trace as you normally
41would and each thread's timing will show up in the trace file.
42
43Multiple processes can safely output into a single trace_event logfile. If you
44fork after enabling tracing, the child process will continue outputting to the
45logfile. Use of the multiprocessing module will work as well. In both cases,
46however, note that disabling tracing in the parent process will not stop tracing
47in the child processes.
48"""
49
50try:
51  import trace_event_impl
52except ImportError:
53  trace_event_impl = None
54
55
56def trace_can_enable():
57  """
58  Returns True if a trace_event_impl was found. If false,
59  trace_enable will fail. Regular tracing methods, including
60  trace_begin and trace_end, will simply be no-ops.
61  """
62  return trace_event_impl != None
63
64if trace_event_impl:
65  import time
66
67
68  def trace_is_enabled():
69    return trace_event_impl.trace_is_enabled()
70
71  def trace_enable(logfile):
72    return trace_event_impl.trace_enable(logfile)
73
74  def trace_disable():
75    return trace_event_impl.trace_disable()
76
77  def trace_flush():
78    trace_event_impl.trace_flush()
79
80  def trace_begin(name, **kwargs):
81    args_to_log = {key: repr(value) for key, value in kwargs.iteritems()}
82    trace_event_impl.add_trace_event("B", trace_time.Now(), "python", name,
83                                     args_to_log)
84
85  def trace_end(name):
86    trace_event_impl.add_trace_event("E", trace_time.Now(), "python", name)
87
88  def trace(name, **kwargs):
89    return trace_event_impl.trace(name, **kwargs)
90
91  TracedMetaClass = trace_event_impl.TracedMetaClass
92
93  def traced(fn):
94    return trace_event_impl.traced(fn)
95
96  def clock_sync(sync_id, issue_ts=None):
97    '''
98    Add a clock sync event to the trace log.
99
100    Args:
101      sync_id: ID of clock sync event.
102      issue_ts: Time at which clock sync was issued, in microseconds.
103    '''
104    time_stamp = trace_time.Now()
105    args_to_log = {'sync_id': sync_id}
106    if issue_ts: # Issuer if issue_ts is set, else reciever.
107      assert issue_ts <= time_stamp
108      args_to_log['issue_ts'] = issue_ts
109    trace_event_impl.add_trace_event(
110        "c", time_stamp, "python", "clock_sync", args_to_log)
111
112  def is_tracing_controllable():
113    return trace_event_impl.is_tracing_controllable()
114
115else:
116  import contextlib
117
118  def trace_enable():
119    raise TraceException(
120        "Cannot enable trace_event. No trace_event_impl module found.")
121
122  def trace_disable():
123    pass
124
125  def trace_is_enabled():
126    return False
127
128  def trace_flush():
129    pass
130
131  def trace_begin(name, **kwargs):
132    del name # unused.
133    del kwargs # unused.
134    pass
135
136  def trace_end(name):
137    del name # unused.
138    pass
139
140  @contextlib.contextmanager
141  def trace(name, **kwargs):
142    del name # unused
143    del kwargs # unused
144    yield
145
146  def traced(fn):
147    return fn
148
149  def clock_sync(sync_id, issue_ts=None):
150    del sync_id # unused.
151    pass
152
153  def is_tracing_controllable():
154    return False
155
156trace_enable.__doc__ = """Enables tracing.
157
158  Once enabled, the enabled bit propagates to forked processes and
159  multiprocessing subprocesses. Regular child processes, e.g. those created via
160  os.system/popen, or subprocess.Popen instances, will not get traced. You can,
161  however, enable tracing on those subprocess manually.
162
163  Trace files are multiprocess safe, so you can have multiple processes
164  outputting to the same tracelog at once.
165
166  log_file can be one of three things:
167
168    None: a logfile is opened based on sys[argv], namely
169          "./" + sys.argv[0] + ".json"
170
171    string: a logfile of the given name is opened.
172
173    file-like object: the fileno() is is used. The underlying file descriptor
174                      must support fcntl.lockf() operations.
175  """
176
177trace_disable.__doc__ = """Disables tracing, if enabled.
178
179  Will not disable tracing on any existing child proceses that were forked
180  from this process. You must disable them yourself.
181  """
182
183trace_flush.__doc__ = """Flushes any currently-recorded trace data to disk.
184
185  trace_event records traces into an in-memory buffer for efficiency. Flushing
186  is only done at process exit or when this method is called.
187  """
188
189trace_is_enabled.__doc__ = """Returns whether tracing is enabled.
190  """
191
192trace_begin.__doc__ = """Records the beginning of an event of the given name.
193
194  The building block for performance tracing. A typical example is:
195     from trace_event import *
196     def something_heavy():
197        trace_begin("something_heavy")
198
199        trace_begin("read")
200        try:
201          lines = open().readlines()
202        finally:
203          trace_end("read")
204
205        trace_begin("parse")
206        try:
207          parse(lines)
208        finally:
209          trace_end("parse")
210
211        trace_end("something_heavy")
212
213  Note that a trace_end call must be issued for every trace_begin call. When
214  tracing around blocks that might throw exceptions, you should use the trace
215  function, or a try-finally pattern to ensure that the trace_end method is
216  called.
217
218  See the documentation for the @traced decorator for a simpler way to
219  instrument functions and methods.
220  """
221
222trace_end.__doc__ = """Records the end of an event of the given name.
223
224  See the documentation for trace_begin for more information.
225
226  Make sure to issue a trace_end for every trace_begin issued. Failure to pair
227  these calls will lead to bizarrely tall looking traces in the
228  trace_event_viewer UI.
229  """
230
231trace.__doc__ = """Traces a block of code using a with statement.
232
233  Example usage:
234    from trace_event import *
235    def something_heavy(lines):
236      with trace("parse_lines", lines=lines):
237        parse(lines)
238
239  If tracing an entire function call, prefer the @traced decorator.
240  """
241
242traced.__doc__ = """
243  Traces the provided function, using the function name for the actual generated
244  event.
245
246  Prefer this decorator over the explicit trace_begin and trace_end functions
247  whenever you are tracing the start and stop of a function. It automatically
248  issues trace_begin/end events, even when the wrapped function throws.
249
250  You can also pass the function's argument names to traced, and the argument
251  values will be added to the trace. Example usage:
252    from trace_event import *
253    @traced("url")
254    def send_request(url):
255      urllib2.urlopen(url).read()
256  """
257
258clock_sync.__doc__ = """
259  Issues a clock sync marker event.
260
261  Clock sync markers are used to synchronize the clock domains of different
262  traces so that they can be used together. It takes a sync_id, and if it is
263  the issuer of a clock sync event it will also require an issue_ts. The
264  issue_ts is a timestamp from when the clocksync was first issued. This is used
265  to calculate the time difference between clock domains.
266  """
267