1# Copyright 2016 The Emscripten Authors. All rights reserved. 2# Emscripten is available under two separate licenses, the MIT license and the 3# University of Illinois/NCSA Open Source License. Both these licenses can be 4# found in the LICENSE file. 5 6import subprocess 7import os 8import time 9import sys 10import tempfile 11 12sys.path.insert(1, os.path.dirname(os.path.dirname(os.path.abspath(__file__)))) 13 14from tools import response_file 15 16EM_PROFILE_TOOLCHAIN = int(os.getenv('EM_PROFILE_TOOLCHAIN', '0')) 17 18if EM_PROFILE_TOOLCHAIN: 19 original_sys_exit = sys.exit 20 original_subprocess_call = subprocess.call 21 original_subprocess_check_call = subprocess.check_call 22 original_subprocess_check_output = subprocess.check_output 23 original_Popen = subprocess.Popen 24 25 def profiled_sys_exit(returncode): 26 ToolchainProfiler.record_process_exit(returncode) 27 original_sys_exit(returncode) 28 29 def profiled_call(cmd, *args, **kw): 30 pid = ToolchainProfiler.imaginary_pid() 31 ToolchainProfiler.record_subprocess_spawn(pid, cmd) 32 try: 33 returncode = original_subprocess_call(cmd, *args, **kw) 34 except Exception: 35 ToolchainProfiler.record_subprocess_finish(pid, 1) 36 raise 37 ToolchainProfiler.record_subprocess_finish(pid, returncode) 38 return returncode 39 40 def profiled_check_call(cmd, *args, **kw): 41 pid = ToolchainProfiler.imaginary_pid() 42 ToolchainProfiler.record_subprocess_spawn(pid, cmd) 43 try: 44 ret = original_subprocess_check_call(cmd, *args, **kw) 45 except Exception as e: 46 ToolchainProfiler.record_subprocess_finish(pid, e.returncode) 47 raise 48 ToolchainProfiler.record_subprocess_finish(pid, 0) 49 return ret 50 51 def profiled_check_output(cmd, *args, **kw): 52 pid = ToolchainProfiler.imaginary_pid() 53 ToolchainProfiler.record_subprocess_spawn(pid, cmd) 54 try: 55 ret = original_subprocess_check_output(cmd, *args, **kw) 56 except Exception as e: 57 ToolchainProfiler.record_subprocess_finish(pid, e.returncode) 58 raise 59 ToolchainProfiler.record_subprocess_finish(pid, 0) 60 return ret 61 62 class ProfiledPopen(original_Popen): 63 def __init__(self, args, *otherargs, **kwargs): 64 super(ProfiledPopen, self).__init__(args, *otherargs, **kwargs) 65 ToolchainProfiler.record_subprocess_spawn(self.pid, args) 66 67 def communicate(self, *args, **kwargs): 68 ToolchainProfiler.record_subprocess_wait(self.pid) 69 output = super(ProfiledPopen, self).communicate(*args, **kwargs) 70 ToolchainProfiler.record_subprocess_finish(self.pid, self.returncode) 71 return output 72 73 sys.exit = profiled_sys_exit 74 subprocess.call = profiled_call 75 subprocess.check_call = profiled_check_call 76 subprocess.check_output = profiled_check_output 77 subprocess.Popen = ProfiledPopen 78 79 class ToolchainProfiler(object): 80 # Provide a running counter towards negative numbers for PIDs for which we don't know what the actual process ID is 81 imaginary_pid_ = 0 82 profiler_logs_path = None # Log file not opened yet 83 84 block_stack = [] 85 86 # Because process spawns are tracked from multiple entry points, it is possible that record_process_start() and/or record_process_exit() 87 # are called multiple times. Prevent recording multiple entries to the logs to keep them clean. 88 process_start_recorded = False 89 process_exit_recorded = False 90 91 @staticmethod 92 def timestamp(): 93 return '{0:.3f}'.format(time.time()) 94 95 @staticmethod 96 def log_access(): 97 # If somehow the process escaped opening the log at startup, do so now. (this biases the startup time of the process, but best effort) 98 if not ToolchainProfiler.profiler_logs_path: 99 ToolchainProfiler.record_process_start() 100 101 # Note: This function is called in two importantly different contexts: in "main" process and in python subprocesses 102 # invoked via subprocessing.Pool.map(). The subprocesses have their own PIDs, and hence record their own data JSON 103 # files, but since the process pool is maintained internally by python, the toolchain profiler does not track the 104 # parent->child process spawns for the subprocessing pools. Therefore any profiling events that the subprocess 105 # children generate are virtually treated as if they were performed by the parent PID. 106 return open(os.path.join(ToolchainProfiler.profiler_logs_path, 'toolchain_profiler.pid_' + str(os.getpid()) + '.json'), 'a') 107 108 @staticmethod 109 def escape_args(args): 110 return map(lambda arg: arg.replace('\\', '\\\\').replace('"', '\\"'), args) 111 112 @staticmethod 113 def record_process_start(write_log_entry=True): 114 # For subprocessing.Pool.map() child processes, this points to the PID of the parent process that spawned 115 # the subprocesses. This makes the subprocesses look as if the parent had called the functions. 116 ToolchainProfiler.mypid_str = str(os.getpid()) 117 ToolchainProfiler.profiler_logs_path = os.path.join(tempfile.gettempdir(), 'emscripten_toolchain_profiler_logs') 118 try: 119 os.makedirs(ToolchainProfiler.profiler_logs_path) 120 except OSError: 121 pass 122 123 if ToolchainProfiler.process_start_recorded: 124 return 125 ToolchainProfiler.process_start_recorded = True 126 ToolchainProfiler.block_stack = [] 127 128 if write_log_entry: 129 with ToolchainProfiler.log_access() as f: 130 f.write('[\n{"pid":' + ToolchainProfiler.mypid_str + ',"subprocessPid":' + str(os.getpid()) + ',"op":"start","time":' + ToolchainProfiler.timestamp() + ',"cmdLine":["' + '","'.join(ToolchainProfiler.escape_args(sys.argv)) + '"]}') 131 132 @staticmethod 133 def record_process_exit(returncode): 134 if ToolchainProfiler.process_exit_recorded: 135 return 136 ToolchainProfiler.process_exit_recorded = True 137 138 ToolchainProfiler.exit_all_blocks() 139 with ToolchainProfiler.log_access() as f: 140 f.write(',\n{"pid":' + ToolchainProfiler.mypid_str + ',"subprocessPid":' + str(os.getpid()) + ',"op":"exit","time":' + ToolchainProfiler.timestamp() + ',"returncode":' + str(returncode) + '}\n]\n') 141 142 @staticmethod 143 def record_subprocess_spawn(process_pid, process_cmdline): 144 response_cmdline = [] 145 for item in process_cmdline: 146 if item.startswith('@'): 147 response_cmdline += response_file.read_response_file(item) 148 149 with ToolchainProfiler.log_access() as f: 150 f.write(',\n{"pid":' + ToolchainProfiler.mypid_str + ',"subprocessPid":' + str(os.getpid()) + ',"op":"spawn","targetPid":' + str(process_pid) + ',"time":' + ToolchainProfiler.timestamp() + ',"cmdLine":["' + '","'.join(ToolchainProfiler.escape_args(process_cmdline + response_cmdline)) + '"]}') 151 152 @staticmethod 153 def record_subprocess_wait(process_pid): 154 with ToolchainProfiler.log_access() as f: 155 f.write(',\n{"pid":' + ToolchainProfiler.mypid_str + ',"subprocessPid":' + str(os.getpid()) + ',"op":"wait","targetPid":' + str(process_pid) + ',"time":' + ToolchainProfiler.timestamp() + '}') 156 157 @staticmethod 158 def record_subprocess_finish(process_pid, returncode): 159 with ToolchainProfiler.log_access() as f: 160 f.write(',\n{"pid":' + ToolchainProfiler.mypid_str + ',"subprocessPid":' + str(os.getpid()) + ',"op":"finish","targetPid":' + str(process_pid) + ',"time":' + ToolchainProfiler.timestamp() + ',"returncode":' + str(returncode) + '}') 161 162 @staticmethod 163 def enter_block(block_name): 164 with ToolchainProfiler.log_access() as f: 165 f.write(',\n{"pid":' + ToolchainProfiler.mypid_str + ',"subprocessPid":' + str(os.getpid()) + ',"op":"enterBlock","name":"' + block_name + '","time":' + ToolchainProfiler.timestamp() + '}') 166 167 ToolchainProfiler.block_stack.append(block_name) 168 169 @staticmethod 170 def remove_last_occurrence_if_exists(lst, item): 171 for i in range(len(lst)): 172 if lst[i] == item: 173 lst.pop(i) 174 return True 175 return False 176 177 @staticmethod 178 def exit_block(block_name): 179 if ToolchainProfiler.remove_last_occurrence_if_exists(ToolchainProfiler.block_stack, block_name): 180 with ToolchainProfiler.log_access() as f: 181 f.write(',\n{"pid":' + ToolchainProfiler.mypid_str + ',"subprocessPid":' + str(os.getpid()) + ',"op":"exitBlock","name":"' + block_name + '","time":' + ToolchainProfiler.timestamp() + '}') 182 183 @staticmethod 184 def exit_all_blocks(): 185 for b in ToolchainProfiler.block_stack[::-1]: 186 ToolchainProfiler.exit_block(b) 187 188 class ProfileBlock(object): 189 def __init__(self, block_name): 190 self.block_name = block_name 191 192 def __enter__(self): 193 ToolchainProfiler.enter_block(self.block_name) 194 195 def __exit__(self, type, value, traceback): 196 ToolchainProfiler.exit_block(self.block_name) 197 198 @staticmethod 199 def profile_block(block_name): 200 return ToolchainProfiler.ProfileBlock(block_name) 201 202 @staticmethod 203 def imaginary_pid(): 204 ToolchainProfiler.imaginary_pid_ -= 1 205 return ToolchainProfiler.imaginary_pid_ 206 207else: 208 class ToolchainProfiler(object): 209 @staticmethod 210 def record_process_start(): 211 pass 212 213 @staticmethod 214 def record_process_exit(returncode): 215 pass 216 217 @staticmethod 218 def record_subprocess_spawn(process_pid, process_cmdline): 219 pass 220 221 @staticmethod 222 def record_subprocess_wait(process_pid): 223 pass 224 225 @staticmethod 226 def record_subprocess_finish(process_pid, returncode): 227 pass 228 229 @staticmethod 230 def enter_block(block_name): 231 pass 232 233 @staticmethod 234 def exit_block(block_name): 235 pass 236 237 class ProfileBlock(object): 238 def __init__(self, block_name): 239 pass 240 241 def __enter__(self): 242 pass 243 244 def __exit__(self, type, value, traceback): 245 pass 246 247 @staticmethod 248 def profile_block(block_name): 249 return ToolchainProfiler.ProfileBlock(block_name) 250