diff --git a/em++ b/em++ index 85236ebbcbe07..4aa8100e235da 100755 --- a/em++ +++ b/em++ @@ -3,6 +3,8 @@ # This script should work in python 2 *or* 3. It loads emcc.py, which needs python 2. # It also tells emcc.py that we want C++ and not C by default +from tools.toolchain_profiler import ToolchainProfiler + import sys sys.argv += ['--emscripten-cxx'] @@ -10,7 +12,9 @@ sys.argv += ['--emscripten-cxx'] if sys.version_info.major == 2: import emcc if __name__ == '__main__': + ToolchainProfiler.record_process_start() emcc.run() + sys.exit(0) else: import os, subprocess if __name__ == '__main__': diff --git a/emar b/emar index cd86e9e382cbc..4064f4dc19af5 100755 --- a/emar +++ b/emar @@ -2,15 +2,16 @@ # This script should work in python 2 *or* 3. It loads emar.py, which needs python 2. +from tools.toolchain_profiler import ToolchainProfiler import sys - - if sys.version_info.major == 2: import emar if __name__ == '__main__': + ToolchainProfiler.record_process_start() emar.run() + sys.exit(0) else: import os, subprocess if __name__ == '__main__': diff --git a/emar.py b/emar.py index 5f5e548dac623..b09cc6148d761 100755 --- a/emar.py +++ b/emar.py @@ -7,6 +7,8 @@ This script acts as a frontend replacement for ar. See emcc. ''' +from tools.toolchain_profiler import ToolchainProfiler + import os, subprocess, sys from tools import shared @@ -59,4 +61,6 @@ def run(): shared.try_delete(d) if __name__ == '__main__': + ToolchainProfiler.record_process_start() run() + sys.exit(0) diff --git a/emcc b/emcc index 0ea18a2d08715..6d6b241f33297 100755 --- a/emcc +++ b/emcc @@ -2,15 +2,16 @@ # This script should work in python 2 *or* 3. It loads emcc.py, which needs python 2. +from tools.toolchain_profiler import ToolchainProfiler import sys - - if sys.version_info.major == 2: import emcc if __name__ == '__main__': + ToolchainProfiler.record_process_start() emcc.run() + sys.exit(0) else: import os, subprocess if __name__ == '__main__': diff --git a/emcc.py b/emcc.py index 36f2ffed74c33..16a42a6056d3b 100755 --- a/emcc.py +++ b/emcc.py @@ -23,6 +23,10 @@ EMMAKEN_COMPILER - The compiler to be used, if you don't want the default clang. ''' +from tools.toolchain_profiler import ToolchainProfiler +if __name__ == '__main__': + ToolchainProfiler.record_process_start() + import os, sys, shutil, tempfile, subprocess, shlex, time, re, logging from subprocess import PIPE from tools import shared, jsrun, system_libs @@ -2103,3 +2107,4 @@ def un_src(): # use this if you want to modify the script and need it to be inli if __name__ == '__main__': run() + sys.exit(0) diff --git a/emprofile.bat b/emprofile.bat new file mode 100644 index 0000000000000..f9d8033274278 --- /dev/null +++ b/emprofile.bat @@ -0,0 +1,2 @@ +@echo off +python "%~dp0\emprofile.py" %* \ No newline at end of file diff --git a/emprofile.py b/emprofile.py new file mode 100755 index 0000000000000..d84444edab913 --- /dev/null +++ b/emprofile.py @@ -0,0 +1,92 @@ +#!/usr/bin/env python + +import sys, shutil, os, json, tempfile, time + +profiler_logs_path = os.path.join(tempfile.gettempdir(), 'emscripten_toolchain_profiler_logs') + +# If set to 1, always generates the output file under the same filename and doesn't delete the temp data. +DEBUG_EMPROFILE_PY = 0 + +OUTFILE = 'toolchain_profiler.results_' + time.strftime('%Y%m%d_%H%M') +for arg in sys.argv: + if arg.startswith('--outfile='): + OUTFILE = arg.split('=')[1].strip().replace('.html', '') + +# Deletes all previously captured log files to make room for a new clean run. +def delete_profiler_logs(): + try: + shutil.rmtree(profiler_logs_path) + except: + pass + +def list_files_in_directory(d): + files = [] + try: + items = os.listdir(d) + for i in items: + f = os.path.join(d, i) + if os.path.isfile(f): + files += [f] + return files + except: + return [] + +def create_profiling_graph(): + log_files = [f for f in list_files_in_directory(profiler_logs_path) if 'toolchain_profiler.pid_' in f] + + all_results = [] + if len(log_files) > 0: + print 'Processing ' + str(len(log_files)) + ' profile log files in "' + profiler_logs_path + '"...' + for f in log_files: + try: + json_data = open(f, 'r').read() + lines = json_data.split('\n') + lines = filter(lambda x: x != '[' and x != ']' and x != ',' and len(x.strip()) > 0, lines) + lines = map(lambda x: (x + ',') if not x.endswith(',') else x, lines) + lines[-1] = lines[-1][:-1] + json_data = '[' + '\n'.join(lines) + ']' + all_results += json.loads(json_data) + except Exception, e: + print >> sys.stderr, str(e) + print >> sys.stderr, 'Failed to parse JSON file "' + f + '"!' + sys.exit(1) + if len(all_results) == 0: + print 'No profiler logs were found in path "' + profiler_logs_path + '". Try setting the environment variable EM_PROFILE_TOOLCHAIN=1 and run some emcc commands, and then rerun "python emprofile.py --graph" again.' + return + + all_results.sort(key=lambda x: x['time']) + + json_file = OUTFILE + '.json' + open(json_file, 'w').write(json.dumps(all_results, indent=2)) + print 'Wrote "' + json_file + '"' + + html_file = OUTFILE + '.html' + html_contents = open(os.path.join(os.path.dirname(os.path.realpath(__file__)), 'tools', 'toolchain_profiler.results_template.html'), 'r').read().replace('{{{results_log_file}}}', '"' + json_file + '"') + open(html_file, 'w').write(html_contents) + print 'Wrote "' + html_file + '"' + + if not DEBUG_EMPROFILE_PY: + delete_profiler_logs() + +if len(sys.argv) < 2: + print '''Usage: + emprofile.py --reset + Deletes all previously recorded profiling log files. + + emprofile.py --graph + Draws a graph from all recorded profiling log files. + +Optional parameters: + + --outfile=x.html + Specifies the name of the results file to generate. +''' + sys.exit(1) + +if '--reset' in sys.argv: + delete_profiler_logs() +elif '--graph' in sys.argv: + create_profiling_graph() +else: + print 'Unknown command "' + sys.argv[1] + '"!' + sys.exit(1) diff --git a/emscripten.py b/emscripten.py index 265cc9eeea36d..6fab043c11170 100755 --- a/emscripten.py +++ b/emscripten.py @@ -9,6 +9,10 @@ headers, for the libc implementation in JS). ''' +from tools.toolchain_profiler import ToolchainProfiler +if __name__ == '__main__': + ToolchainProfiler.record_process_start() + import os, sys, json, optparse, subprocess, re, time, logging from tools import shared @@ -1729,3 +1733,4 @@ def _main(args=None): if __name__ == '__main__': _main() + sys.exit(0) diff --git a/tools/js_optimizer.py b/tools/js_optimizer.py index f6f5c8073a5a7..86c1a673081e9 100644 --- a/tools/js_optimizer.py +++ b/tools/js_optimizer.py @@ -1,4 +1,8 @@ +from toolchain_profiler import ToolchainProfiler +if __name__ == '__main__': + ToolchainProfiler.record_process_start() + import os, sys, subprocess, multiprocessing, re, string, json, shutil, logging import shared @@ -559,4 +563,5 @@ def run(filename, passes, js_engine=shared.NODE_JS, source_map=False, extra_info extra_info = None out = run(sys.argv[1], sys.argv[2:], extra_info=extra_info) shutil.copyfile(out, sys.argv[1] + '.jsopt.js') + sys.exit(0) diff --git a/tools/jsrun.py b/tools/jsrun.py index 0f315e6d288d0..7f18418ecd1b5 100644 --- a/tools/jsrun.py +++ b/tools/jsrun.py @@ -1,3 +1,4 @@ +from toolchain_profiler import ToolchainProfiler import time, os, sys, logging from subprocess import Popen, PIPE, STDOUT diff --git a/tools/shared.py b/tools/shared.py index 2b22fd05bf05e..89592974b450b 100644 --- a/tools/shared.py +++ b/tools/shared.py @@ -1,3 +1,4 @@ +from toolchain_profiler import ToolchainProfiler import shutil, time, os, sys, json, tempfile, copy, shlex, atexit, subprocess, hashlib, cPickle, re, errno from subprocess import Popen, PIPE, STDOUT from tempfile import mkstemp diff --git a/tools/toolchain_profiler.py b/tools/toolchain_profiler.py new file mode 100644 index 0000000000000..f2f99e7b253c7 --- /dev/null +++ b/tools/toolchain_profiler.py @@ -0,0 +1,220 @@ +import subprocess, os, time, sys, tempfile + +EM_PROFILE_TOOLCHAIN = int(os.getenv('EM_PROFILE_TOOLCHAIN')) if os.getenv('EM_PROFILE_TOOLCHAIN') != None else 0 + +if EM_PROFILE_TOOLCHAIN: + 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 + + def profiled_sys_exit(returncode): + ToolchainProfiler.record_process_exit(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 as e: + ToolchainProfiler.record_subprocess_finish(pid, 1) + raise e + 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 e + 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 e + ToolchainProfiler.record_subprocess_finish(pid, 0) + return ret + + class ProfiledPopen: + def __init__(self, args, bufsize=0, executable=None, stdin=None, stdout=None, stderr=None, preexec_fn=None, close_fds=False, + shell=False, cwd=None, env=None, universal_newlines=False, startupinfo=None, creationflags=0): + self.process = original_Popen(args, bufsize, executable, stdin, stdout, stderr, preexec_fn, close_fds, shell, cwd, env, universal_newlines, startupinfo, creationflags) + self.pid = self.process.pid + ToolchainProfiler.record_subprocess_spawn(self.pid, args) + + def communicate(self, input=None): + ToolchainProfiler.record_subprocess_wait(self.pid) + output = self.process.communicate(input) + self.returncode = self.process.returncode + ToolchainProfiler.record_subprocess_finish(self.pid, self.returncode) + return output + + def wait(self): + return self.process.wait() + + def poll(self): + return self.process.poll() + + def kill(self): + return self.process.kill() + + 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 + + @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 record_process_start(write_log_entry=True): + ToolchainProfiler.block_stack = [] + # 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') + try: + os.makedirs(ToolchainProfiler.profiler_logs_path) + except: + pass + if write_log_entry: + with ToolchainProfiler.log_access() as f: + f.write('[\n') + f.write('{"pid":' + ToolchainProfiler.mypid_str + ',"subprocessPid":' + str(os.getpid()) + ',"op":"start","time":' + ToolchainProfiler.timestamp() + ',"cmdLine":["' + '","'.join(sys.argv).replace('\\', '\\\\') + '"]}') + + @staticmethod + def record_process_exit(returncode): + ToolchainProfiler.exit_all_blocks() + with ToolchainProfiler.log_access() as f: + f.write(',\n{"pid":' + ToolchainProfiler.mypid_str + ',"subprocessPid":' + str(os.getpid()) + ',"op":"exit","time":' + ToolchainProfiler.timestamp() + ',"returncode":' + str(returncode) + '}') + f.write('\n]\n') + + @staticmethod + def record_subprocess_spawn(process_pid, process_cmdline): + 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(process_cmdline).replace('\\', '\\\\') + '"]}') + + @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) + '}') + + block_stack = [] + + @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 xrange(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: + def __init__(self, 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(block_name) + + @staticmethod + def imaginary_pid(): + ToolchainProfiler.imaginary_pid_ -= 1 + return ToolchainProfiler.imaginary_pid_ + +else: + class ToolchainProfiler: + @staticmethod + def record_process_start(): + pass + + @staticmethod + def record_process_exit(returncode): + pass + + @staticmethod + def record_subprocess_spawn(process_pid, process_cmdline): + pass + + @staticmethod + def record_subprocess_wait(process_pid): + pass + + @staticmethod + def record_subprocess_finish(process_pid, returncode): + pass + + @staticmethod + def enter_block(block_name): + pass + + @staticmethod + def exit_block(block_name): + pass + + class ProfileBlock: + def __init__(self, block_name): + pass + def __enter__(self): + pass + def __exit__(self, type, value, traceback): + pass + + @staticmethod + def profile_block(block_name): + return ToolchainProfiler.ProfileBlock(block_name) diff --git a/tools/toolchain_profiler.results_template.html b/tools/toolchain_profiler.results_template.html new file mode 100644 index 0000000000000..1094f831a0018 --- /dev/null +++ b/tools/toolchain_profiler.results_template.html @@ -0,0 +1,601 @@ + + + + +
+ +Show only blocks that took at least msecs (0=show all). + + + +