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