Use the logging framework instead of print, to be consistent and as the logging framework prints out messages unbuffered which is more responsive on Windows.

Add debug logging facility to track waits on external processes when EM_BUILD_VERBOSE >= 3. This helps pinpointing if the build hangs on some tool dying/live/deadlocking, and where it might occur.

Implement process.pid on WindowsPopen replacement so that EM_BUILD_VERBOSE=3 works on it as well.

2 files changed, 14 insertions, 5 deletions

diff --git a/tools/jsrun.py b/tools/jsrun.py
index 6f77ce51..7acfc978 100644
--- a/tools/jsrun.py
+++ b/tools/jsrun.py
@@ -1,6 +1,8 @@
-import time
+import time, os, sys, logging
 from subprocess import Popen, PIPE, STDOUT
 
+TRACK_PROCESS_SPAWNS = True if (os.getenv('EM_BUILD_VERBOSE') and int(os.getenv('EM_BUILD_VERBOSE')) >= 3) else False
+
 def timeout_run(proc, timeout, note='unnamed process', full_output=False):
   start = time.time()
   if timeout is not None:
@@ -11,19 +13,25 @@ def timeout_run(proc, timeout, note='unnamed process', full_output=False):
       raise Exception("Timed out: " + note)
   out = proc.communicate()
   out = map(lambda o: '' if o is None else o, out)
+  if TRACK_PROCESS_SPAWNS:
+    logging.info('Process ' + str(proc.pid) + ' finished after ' + str(time.time() - start) + ' seconds.')
   return '\n'.join(out) if full_output else out[0]
 
 def run_js(filename, engine=None, args=[], check_timeout=False, stdin=None, stdout=PIPE, stderr=None, cwd=None, full_output=False):
   if type(engine) is not list:
     engine = [engine]
   command = engine + [filename] + (['--'] if 'd8' in engine[0] or 'jsc' in engine[0] else []) + args
-  return timeout_run(
-    Popen(
+  proc = Popen(
       command,
       stdin=stdin,
       stdout=stdout,
       stderr=stderr,
-      cwd=cwd),
-    15*60 if check_timeout else None,
+      cwd=cwd)
+  timeout = 15*60 if check_timeout else None
+  if TRACK_PROCESS_SPAWNS:
+    logging.info('Blocking on process ' + str(proc.pid) + ': ' + str(command) + (' for ' + str(timeout) + ' seconds' if timeout else ' until it finishes.'))
+  return timeout_run(
+    proc, 
+    timeout,
     'Execution',
     full_output=full_output)
diff --git a/tools/shared.py b/tools/shared.py
index 2b933d1f..c0c5313f 100644
--- a/tools/shared.py
+++ b/tools/shared.py
@@ -47,6 +47,7 @@ class WindowsPopen:
     try:
       # Call the process with fixed streams.
       self.process = subprocess.Popen(args, bufsize, executable, self.stdin_, self.stdout_, self.stderr_, preexec_fn, close_fds, shell, cwd, env, universal_newlines, startupinfo, creationflags)
+      self.pid = self.process.pid
     except Exception, e:
       logging.error('\nsubprocess.Popen(args=%s) failed! Exception %s\n' % (' '.join(args), str(e)))
       raise e