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
64# Default TracedMetaClass to type incase trace_event_impl is not defined.
65# This is to avoid exception during import time since TracedMetaClass typically
66# used in class definition scope.
67TracedMetaClass = type
68
69if trace_event_impl:
70  import time
71
72
73  def trace_is_enabled():
74    return trace_event_impl.trace_is_enabled()
75
76  def trace_enable(logfile):
77    return trace_event_impl.trace_enable(logfile)
78
79  def trace_disable():
80    return trace_event_impl.trace_disable()
81
82  def trace_flush():
83    trace_event_impl.trace_flush()
84
85  def trace_begin(name, **kwargs):
86    args_to_log = {key: repr(value) for key, value in kwargs.iteritems()}
87    trace_event_impl.add_trace_event("B", trace_time.Now(), "python", name,
88                                     args_to_log)
89
90  def trace_end(name):
91    trace_event_impl.add_trace_event("E", trace_time.Now(), "python", name)
92
93  def trace_set_thread_name(thread_name):
94    trace_event_impl.add_trace_event("M", trace_time.Now(), "__metadata",
95                                     "thread_name", {"name": thread_name})
96
97  def trace(name, **kwargs):
98    return trace_event_impl.trace(name, **kwargs)
99
100  TracedMetaClass = trace_event_impl.TracedMetaClass
101
102  def traced(fn):
103    return trace_event_impl.traced(fn)
104
105  def clock_sync(sync_id, issue_ts=None):
106    '''
107    Add a clock sync event to the trace log.
108
109    Args:
110      sync_id: ID of clock sync event.
111      issue_ts: Time at which clock sync was issued, in microseconds.
112    '''
113    time_stamp = trace_time.Now()
114    args_to_log = {'sync_id': sync_id}
115    if issue_ts: # Issuer if issue_ts is set, else reciever.
116      assert issue_ts <= time_stamp
117      args_to_log['issue_ts'] = issue_ts
118    trace_event_impl.add_trace_event(
119        "c", time_stamp, "python", "clock_sync", args_to_log)
120
121  def is_tracing_controllable():
122    return trace_event_impl.is_tracing_controllable()
123
124else:
125  import contextlib
126
127  def trace_enable():
128    raise TraceException(
129        "Cannot enable trace_event. No trace_event_impl module found.")
130
131  def trace_disable():
132    pass
133
134  def trace_is_enabled():
135    return False
136
137  def trace_flush():
138    pass
139
140  def trace_begin(name, **kwargs):
141    del name # unused.
142    del kwargs # unused.
143    pass
144
145  def trace_end(name):
146    del name # unused.
147    pass
148
149  def trace_set_thread_name(thread_name):
150    del thread_name # unused.
151    pass
152
153  @contextlib.contextmanager
154  def trace(name, **kwargs):
155    del name # unused
156    del kwargs # unused
157    yield
158
159  def traced(fn):
160    return fn
161
162  def clock_sync(sync_id, issue_ts=None):
163    del sync_id # unused.
164    pass
165
166  def is_tracing_controllable():
167    return False
168
169trace_enable.__doc__ = """Enables tracing.
170
171  Once enabled, the enabled bit propagates to forked processes and
172  multiprocessing subprocesses. Regular child processes, e.g. those created via
173  os.system/popen, or subprocess.Popen instances, will not get traced. You can,
174  however, enable tracing on those subprocess manually.
175
176  Trace files are multiprocess safe, so you can have multiple processes
177  outputting to the same tracelog at once.
178
179  log_file can be one of three things:
180
181    None: a logfile is opened based on sys[argv], namely
182          "./" + sys.argv[0] + ".json"
183
184    string: a logfile of the given name is opened.
185
186    file-like object: the fileno() is is used. The underlying file descriptor
187                      must support fcntl.lockf() operations.
188  """
189
190trace_disable.__doc__ = """Disables tracing, if enabled.
191
192  Will not disable tracing on any existing child proceses that were forked
193  from this process. You must disable them yourself.
194  """
195
196trace_flush.__doc__ = """Flushes any currently-recorded trace data to disk.
197
198  trace_event records traces into an in-memory buffer for efficiency. Flushing
199  is only done at process exit or when this method is called.
200  """
201
202trace_is_enabled.__doc__ = """Returns whether tracing is enabled.
203  """
204
205trace_begin.__doc__ = """Records the beginning of an event of the given name.
206
207  The building block for performance tracing. A typical example is:
208     from trace_event import *
209     def something_heavy():
210        trace_begin("something_heavy")
211
212        trace_begin("read")
213        try:
214          lines = open().readlines()
215        finally:
216          trace_end("read")
217
218        trace_begin("parse")
219        try:
220          parse(lines)
221        finally:
222          trace_end("parse")
223
224        trace_end("something_heavy")
225
226  Note that a trace_end call must be issued for every trace_begin call. When
227  tracing around blocks that might throw exceptions, you should use the trace
228  function, or a try-finally pattern to ensure that the trace_end method is
229  called.
230
231  See the documentation for the @traced decorator for a simpler way to
232  instrument functions and methods.
233  """
234
235trace_end.__doc__ = """Records the end of an event of the given name.
236
237  See the documentation for trace_begin for more information.
238
239  Make sure to issue a trace_end for every trace_begin issued. Failure to pair
240  these calls will lead to bizarrely tall looking traces in the
241  trace_event_viewer UI.
242  """
243
244trace_set_thread_name.__doc__ = """Sets the trace's name for the current thread.
245  """
246
247trace.__doc__ = """Traces a block of code using a with statement.
248
249  Example usage:
250    from trace_event import *
251    def something_heavy(lines):
252      with trace("parse_lines", lines=lines):
253        parse(lines)
254
255  If tracing an entire function call, prefer the @traced decorator.
256  """
257
258traced.__doc__ = """
259  Traces the provided function, using the function name for the actual generated
260  event.
261
262  Prefer this decorator over the explicit trace_begin and trace_end functions
263  whenever you are tracing the start and stop of a function. It automatically
264  issues trace_begin/end events, even when the wrapped function throws.
265
266  You can also pass the function's argument names to traced, and the argument
267  values will be added to the trace. Example usage:
268    from trace_event import *
269    @traced("url")
270    def send_request(url):
271      urllib2.urlopen(url).read()
272  """
273
274clock_sync.__doc__ = """
275  Issues a clock sync marker event.
276
277  Clock sync markers are used to synchronize the clock domains of different
278  traces so that they can be used together. It takes a sync_id, and if it is
279  the issuer of a clock sync event it will also require an issue_ts. The
280  issue_ts is a timestamp from when the clocksync was first issued. This is used
281  to calculate the time difference between clock domains.
282  """
283