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. 4 from py_trace_event import trace_time 5 6 7 r"""Instrumentation-based profiling for Python. 8 9 trace_event allows you to hand-instrument your code with areas of interest. 10 When enabled, trace_event logs the start and stop times of these events to a 11 logfile. These resulting logfiles can be viewed with either Chrome's 12 about:tracing UI or with the standalone trace_event_viewer available at 13 http://www.github.com/natduca/trace_event_viewer/ 14 15 To 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 30 trace_event records trace events to an in-memory buffer. If your application is 31 long running and you want to see the results of a trace before it exits, you can 32 call trace_flush to write any in-memory events to disk. 33 34 To help intregrating trace_event into existing codebases that dont want to add 35 trace_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 37 shim, trace_event.py, directly into your including codebase. If the 38 trace_event_impl is not found, the shim will simply noop. 39 40 trace_event is safe with regard to Python threads. Simply trace as you normally 41 would and each thread's timing will show up in the trace file. 42 43 Multiple processes can safely output into a single trace_event logfile. If you 44 fork after enabling tracing, the child process will continue outputting to the 45 logfile. Use of the multiprocessing module will work as well. In both cases, 46 however, note that disabling tracing in the parent process will not stop tracing 47 in the child processes. 48 """ 49 50 try: 51 import trace_event_impl 52 except ImportError: 53 trace_event_impl = None 54 55 56 def 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. 67 TracedMetaClass = type 68 69 if 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 124 else: 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 169 trace_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 190 trace_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 196 trace_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 202 trace_is_enabled.__doc__ = """Returns whether tracing is enabled. 203 """ 204 205 trace_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 235 trace_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 244 trace_set_thread_name.__doc__ = """Sets the trace's name for the current thread. 245 """ 246 247 trace.__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 258 traced.__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 274 clock_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
