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