| # Copyright 2016 The Emscripten Authors. All rights reserved. |
| # Emscripten is available under two separate licenses, the MIT license and the |
| # University of Illinois/NCSA Open Source License. Both these licenses can be |
| # found in the LICENSE file. |
| |
| import atexit |
| import logging |
| import os |
| import sys |
| import subprocess |
| import tempfile |
| import time |
| from contextlib import ContextDecorator |
| |
| sys.path.insert(1, os.path.dirname(os.path.dirname(os.path.abspath(__file__)))) |
| logger = logging.getLogger('profiler') |
| |
| from tools import response_file |
| |
| EMPROFILE = int(os.getenv('EMPROFILE', '0')) |
| |
| |
| class Logger(ContextDecorator): |
| def __init__(self, name): |
| self.name = name |
| |
| def __enter__(self): |
| self.start = time.time() |
| |
| def __exit__(self, type, value, traceback): |
| # When a block ends debug log the total duration. |
| now = time.time() |
| logger.debug('block "%s" took %.2f seconds', self.name, now - self.start) |
| |
| |
| if EMPROFILE: |
| original_sys_exit = sys.exit |
| original_subprocess_call = subprocess.call |
| original_subprocess_check_call = subprocess.check_call |
| original_subprocess_check_output = subprocess.check_output |
| original_Popen = subprocess.Popen |
| process_returncode = None |
| |
| def profiled_sys_exit(returncode): |
| # Stack the returncode which then gets used in the atexit handler |
| global process_returncode |
| process_returncode = returncode |
| original_sys_exit(returncode) |
| |
| def profiled_call(cmd, *args, **kw): |
| pid = ToolchainProfiler.imaginary_pid() |
| ToolchainProfiler.record_subprocess_spawn(pid, cmd) |
| try: |
| returncode = original_subprocess_call(cmd, *args, **kw) |
| except Exception: |
| ToolchainProfiler.record_subprocess_finish(pid, 1) |
| raise |
| ToolchainProfiler.record_subprocess_finish(pid, returncode) |
| return returncode |
| |
| def profiled_check_call(cmd, *args, **kw): |
| pid = ToolchainProfiler.imaginary_pid() |
| ToolchainProfiler.record_subprocess_spawn(pid, cmd) |
| try: |
| ret = original_subprocess_check_call(cmd, *args, **kw) |
| except Exception as e: |
| ToolchainProfiler.record_subprocess_finish(pid, e.returncode) |
| raise |
| ToolchainProfiler.record_subprocess_finish(pid, 0) |
| return ret |
| |
| def profiled_check_output(cmd, *args, **kw): |
| pid = ToolchainProfiler.imaginary_pid() |
| ToolchainProfiler.record_subprocess_spawn(pid, cmd) |
| try: |
| ret = original_subprocess_check_output(cmd, *args, **kw) |
| except Exception as e: |
| ToolchainProfiler.record_subprocess_finish(pid, e.returncode) |
| raise |
| ToolchainProfiler.record_subprocess_finish(pid, 0) |
| return ret |
| |
| class ProfiledPopen(original_Popen): |
| def __init__(self, args, *otherargs, **kwargs): |
| super().__init__(args, *otherargs, **kwargs) |
| ToolchainProfiler.record_subprocess_spawn(self.pid, args) |
| |
| def communicate(self, *args, **kwargs): |
| ToolchainProfiler.record_subprocess_wait(self.pid) |
| output = super().communicate(*args, **kwargs) |
| ToolchainProfiler.record_subprocess_finish(self.pid, self.returncode) |
| return output |
| |
| sys.exit = profiled_sys_exit |
| subprocess.call = profiled_call |
| subprocess.check_call = profiled_check_call |
| subprocess.check_output = profiled_check_output |
| subprocess.Popen = ProfiledPopen |
| |
| class ToolchainProfiler: |
| # Provide a running counter towards negative numbers for PIDs for which we |
| # don't know what the actual process ID is |
| imaginary_pid_ = 0 |
| profiler_logs_path = None # Log file not opened yet |
| |
| block_stack = [] |
| |
| # Track if record_process_exit and record_process_start have been called |
| # so we can assert they are only ever called once. |
| process_start_recorded = False |
| process_exit_recorded = False |
| |
| @staticmethod |
| def timestamp(): |
| return '{0:.3f}'.format(time.time()) |
| |
| @staticmethod |
| def log_access(): |
| # Note: This function is called in two importantly different contexts: in |
| # "main" process and in python subprocesses invoked via |
| # subprocessing.Pool.map(). The subprocesses have their own PIDs, and |
| # hence record their own data JSON files, but since the process pool is |
| # maintained internally by python, the toolchain profiler does not track |
| # the parent->child process spawns for the subprocessing pools. Therefore |
| # any profiling events that the subprocess children generate are virtually |
| # treated as if they were performed by the parent PID. |
| return open(os.path.join(ToolchainProfiler.profiler_logs_path, 'toolchain_profiler.pid_' + str(os.getpid()) + '.json'), 'a') |
| |
| @staticmethod |
| def escape_string(arg): |
| return arg.replace('\\', '\\\\').replace('"', '\\"') |
| |
| @staticmethod |
| def escape_args(args): |
| return map(lambda arg: ToolchainProfiler.escape_string(arg), args) |
| |
| @staticmethod |
| def record_process_start(write_log_entry=True): |
| assert not ToolchainProfiler.process_start_recorded |
| ToolchainProfiler.process_start_recorded = True |
| atexit.register(ToolchainProfiler.record_process_exit) |
| |
| # For subprocessing.Pool.map() child processes, this points to the PID of |
| # the parent process that spawned the subprocesses. This makes the |
| # subprocesses look as if the parent had called the functions. |
| ToolchainProfiler.mypid_str = str(os.getpid()) |
| ToolchainProfiler.profiler_logs_path = os.path.join(tempfile.gettempdir(), 'emscripten_toolchain_profiler_logs') |
| os.makedirs(ToolchainProfiler.profiler_logs_path, exist_ok=True) |
| |
| ToolchainProfiler.block_stack = [] |
| |
| if write_log_entry: |
| with ToolchainProfiler.log_access() as f: |
| f.write('[\n{"pid":' + ToolchainProfiler.mypid_str + ',"subprocessPid":' + str(os.getpid()) + ',"op":"start","time":' + ToolchainProfiler.timestamp() + ',"cmdLine":["' + '","'.join(ToolchainProfiler.escape_args(sys.argv)) + '"]}') |
| |
| @staticmethod |
| def record_process_exit(): |
| assert not ToolchainProfiler.process_exit_recorded |
| assert ToolchainProfiler.process_start_recorded |
| ToolchainProfiler.process_exit_recorded = True |
| |
| ToolchainProfiler.exit_all_blocks() |
| with ToolchainProfiler.log_access() as f: |
| returncode = process_returncode |
| if returncode is None: |
| returncode = '"MISSING EXIT CODE"' |
| f.write(',\n{"pid":' + ToolchainProfiler.mypid_str + ',"subprocessPid":' + str(os.getpid()) + ',"op":"exit","time":' + ToolchainProfiler.timestamp() + ',"returncode":' + str(returncode) + '}\n]\n') |
| |
| @staticmethod |
| def record_subprocess_spawn(process_pid, process_cmdline): |
| expanded_cmdline = [] |
| for item in process_cmdline: |
| if item.startswith('@'): |
| expanded_cmdline += response_file.read_response_file(item) |
| else: |
| expanded_cmdline.append(item) |
| |
| with ToolchainProfiler.log_access() as f: |
| 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(expanded_cmdline)) + '"]}') |
| |
| @staticmethod |
| def record_subprocess_wait(process_pid): |
| with ToolchainProfiler.log_access() as f: |
| f.write(',\n{"pid":' + ToolchainProfiler.mypid_str + ',"subprocessPid":' + str(os.getpid()) + ',"op":"wait","targetPid":' + str(process_pid) + ',"time":' + ToolchainProfiler.timestamp() + '}') |
| |
| @staticmethod |
| def record_subprocess_finish(process_pid, returncode): |
| with ToolchainProfiler.log_access() as f: |
| f.write(',\n{"pid":' + ToolchainProfiler.mypid_str + ',"subprocessPid":' + str(os.getpid()) + ',"op":"finish","targetPid":' + str(process_pid) + ',"time":' + ToolchainProfiler.timestamp() + ',"returncode":' + str(returncode) + '}') |
| |
| @staticmethod |
| def enter_block(block_name): |
| with ToolchainProfiler.log_access() as f: |
| f.write(',\n{"pid":' + ToolchainProfiler.mypid_str + ',"subprocessPid":' + str(os.getpid()) + ',"op":"enterBlock","name":"' + block_name + '","time":' + ToolchainProfiler.timestamp() + '}') |
| |
| ToolchainProfiler.block_stack.append(block_name) |
| |
| @staticmethod |
| def remove_last_occurrence_if_exists(lst, item): |
| for i in range(len(lst)): |
| if lst[i] == item: |
| lst.pop(i) |
| return True |
| return False |
| |
| @staticmethod |
| def exit_block(block_name): |
| if ToolchainProfiler.remove_last_occurrence_if_exists(ToolchainProfiler.block_stack, block_name): |
| with ToolchainProfiler.log_access() as f: |
| f.write(',\n{"pid":' + ToolchainProfiler.mypid_str + ',"subprocessPid":' + str(os.getpid()) + ',"op":"exitBlock","name":"' + block_name + '","time":' + ToolchainProfiler.timestamp() + '}') |
| |
| @staticmethod |
| def exit_all_blocks(): |
| for b in ToolchainProfiler.block_stack[::-1]: |
| ToolchainProfiler.exit_block(b) |
| |
| class ProfileBlock(Logger): |
| def __init__(self, block_name): |
| super().__init__(block_name) |
| self.block_name = block_name |
| |
| def __enter__(self): |
| ToolchainProfiler.enter_block(self.block_name) |
| |
| def __exit__(self, type, value, traceback): |
| ToolchainProfiler.exit_block(self.block_name) |
| |
| @staticmethod |
| def profile_block(block_name): |
| return ToolchainProfiler.ProfileBlock(ToolchainProfiler.escape_string(block_name)) |
| |
| @staticmethod |
| def imaginary_pid(): |
| ToolchainProfiler.imaginary_pid_ -= 1 |
| return ToolchainProfiler.imaginary_pid_ |
| |
| ToolchainProfiler.record_process_start() |
| else: |
| class ToolchainProfiler: |
| @staticmethod |
| def enter_block(block_name): |
| pass |
| |
| @staticmethod |
| def exit_block(block_name): |
| pass |
| |
| @staticmethod |
| def profile_block(block_name): |
| return Logger(block_name) |