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