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.

3 files changed, 43 insertions, 34 deletions

diff --git a/emscripten.py b/emscripten.py
index b95e03a7..abff6b1d 100755
--- a/emscripten.py
+++ b/emscripten.py
@@ -9,7 +9,7 @@ header files (so that the JS compiler can see the constants in those
 headers, for the libc implementation in JS).
 '''
 
-import os, sys, json, optparse, subprocess, re, time, multiprocessing, string
+import os, sys, json, optparse, subprocess, re, time, multiprocessing, string, logging
 
 from tools import jsrun, cache as cache_module, tempfiles
 from tools.response_file import read_response_file
@@ -46,7 +46,7 @@ MAX_CHUNK_SIZE = float(os.environ.get('EMSCRIPT_MAX_CHUNK_SIZE') or 'inf') # con
 STDERR_FILE = os.environ.get('EMCC_STDERR_FILE')
 if STDERR_FILE:
   STDERR_FILE = os.path.abspath(STDERR_FILE)
-  print >> sys.stderr, 'logging stderr in js compiler phase into %s' % STDERR_FILE
+  logging.info('logging stderr in js compiler phase into %s' % STDERR_FILE)
   STDERR_FILE = open(STDERR_FILE, 'w')
 
 def process_funcs((i, funcs, meta, settings_file, compiler, forwarded_file, libraries, compiler_engine, temp_files, DEBUG)):
@@ -70,7 +70,7 @@ def process_funcs((i, funcs, meta, settings_file, compiler, forwarded_file, libr
   except KeyboardInterrupt:
     # Python 2.7 seems to lock up when a child process throws KeyboardInterrupt
     raise Exception()
-  if DEBUG: print >> sys.stderr, '.'
+  if DEBUG: logging.debug('.')
   return out
 
 def emscript(infile, settings, outfile, libraries=[], compiler_engine=None,
@@ -91,7 +91,7 @@ def emscript(infile, settings, outfile, libraries=[], compiler_engine=None,
   #   2 aka 'funcs': Process functions. We can parallelize this, working on each function independently.
   #   3 aka 'post' : Process globals, generate postamble and finishing touches.
 
-  if DEBUG: print >> sys.stderr, 'emscript: ll=>js'
+  if DEBUG: logging.debug('emscript: ll=>js')
 
   if jcache: jcache.ensure()
 
@@ -101,7 +101,7 @@ def emscript(infile, settings, outfile, libraries=[], compiler_engine=None,
   scan(ll, settings)
   total_ll_size = len(ll)
   ll = None # allow collection
-  if DEBUG: print >> sys.stderr, '  emscript: scan took %s seconds' % (time.time() - t)
+  if DEBUG: logging.debug('  emscript: scan took %s seconds' % (time.time() - t))
 
   # Split input into the relevant parts for each phase
   pre = []
@@ -136,19 +136,19 @@ def emscript(infile, settings, outfile, libraries=[], compiler_engine=None,
         pre.append(line) # pre needs it so we know about globals in pre and funcs. So emit globals there
   ll_lines = None
   meta = ''.join(meta)
-  if DEBUG and len(meta) > 1024*1024: print >> sys.stderr, 'emscript warning: large amounts of metadata, will slow things down'
-  if DEBUG: print >> sys.stderr, '  emscript: split took %s seconds' % (time.time() - t)
+  if DEBUG and len(meta) > 1024*1024: logging.debug('emscript warning: large amounts of metadata, will slow things down')
+  if DEBUG: logging.debug('  emscript: split took %s seconds' % (time.time() - t))
 
   if len(funcs) == 0:
-    print >> sys.stderr, 'No functions to process. Make sure you prevented LLVM from eliminating them as dead (use EXPORTED_FUNCTIONS if necessary, see the FAQ)'
+    logging.error('No functions to process. Make sure you prevented LLVM from eliminating them as dead (use EXPORTED_FUNCTIONS if necessary, see the FAQ)')
 
   #if DEBUG:
-  #  print >> sys.stderr, '========= pre ================\n'
-  #  print >> sys.stderr, ''.join(pre)
-  #  print >> sys.stderr, '========== funcs ===============\n'
+  #  logging.debug('========= pre ================\n')
+  #  logging.debug(''.join(pre))
+  #  logging.debug('========== funcs ===============\n')
   #  for func in funcs:
-  #    print >> sys.stderr, '\n// ===\n\n', ''.join(func)
-  #  print >> sys.stderr, '=========================\n'
+  #    logging.debug('\n// ===\n\n', ''.join(func))
+  #  logging.debug('=========================\n')
 
   # Save settings to a file to work around v8 issue 1579
   settings_file = temp_files.get('.txt').name
@@ -168,7 +168,7 @@ def emscript(infile, settings, outfile, libraries=[], compiler_engine=None,
   if jcache:
     keys = [pre_input, settings_text, ','.join(libraries)]
     shortkey = jcache.get_shortkey(keys)
-    if DEBUG_CACHE: print >>sys.stderr, 'shortkey', shortkey
+    if DEBUG_CACHE: logging.debug('shortkey', shortkey)
 
     out = jcache.get(shortkey, keys)
 
@@ -181,21 +181,21 @@ def emscript(infile, settings, outfile, libraries=[], compiler_engine=None,
       dfp.write("\n\n========================== libraries\n\n")
       dfp.write("\n".join(libraries))
       dfp.close()
-      print >>sys.stderr, '  cache miss, key data dumped to %s' % dfpath
+      logging.debug('  cache miss, key data dumped to %s' % dfpath)
 
-    if out and DEBUG: print >> sys.stderr, '  loading pre from jcache'
+    if out and DEBUG: logging.debug('  loading pre from jcache')
   if not out:
     open(pre_file, 'w').write(pre_input)
     out = jsrun.run_js(compiler, compiler_engine, [settings_file, pre_file, 'pre'] + libraries, stdout=subprocess.PIPE, stderr=STDERR_FILE,
                        cwd=path_from_root('src'))
     assert '//FORWARDED_DATA:' in out, 'Did not receive forwarded data in pre output - process failed?'
     if jcache:
-      if DEBUG: print >> sys.stderr, '  saving pre to jcache'
+      if DEBUG: logging.debug('  saving pre to jcache')
       jcache.set(shortkey, keys, out)
   pre, forwarded_data = out.split('//FORWARDED_DATA:')
   forwarded_file = temp_files.get('.json').name
   open(forwarded_file, 'w').write(forwarded_data)
-  if DEBUG: print >> sys.stderr, '  emscript: phase 1 took %s seconds' % (time.time() - t)
+  if DEBUG: logging.debug('  emscript: phase 1 took %s seconds' % (time.time() - t))
 
   indexed_functions = set()
   forwarded_json = json.loads(forwarded_data)
@@ -240,7 +240,7 @@ def emscript(infile, settings, outfile, libraries=[], compiler_engine=None,
       return True
     chunks = filter(load_from_cache, chunks)
     if len(cached_outputs) > 0:
-      if out and DEBUG: print >> sys.stderr, '  loading %d funcchunks from jcache' % len(cached_outputs)
+      if out and DEBUG: logging.debug('  loading %d funcchunks from jcache' % len(cached_outputs))
     else:
       cached_outputs = []
 
@@ -250,7 +250,7 @@ def emscript(infile, settings, outfile, libraries=[], compiler_engine=None,
     if cores == 1 and total_ll_size < MAX_CHUNK_SIZE:
       assert len(chunks) == 1, 'no point in splitting up without multiple cores'
 
-    if DEBUG: print >> sys.stderr, '  emscript: phase 2 working on %d chunks %s (intended chunk size: %.2f MB, meta: %.2f MB, forwarded: %.2f MB, total: %.2f MB)' % (len(chunks), ('using %d cores' % cores) if len(chunks) > 1 else '', chunk_size/(1024*1024.), len(meta)/(1024*1024.), len(forwarded_data)/(1024*1024.), total_ll_size/(1024*1024.))
+    if DEBUG: logging.debug('  emscript: phase 2 working on %d chunks %s (intended chunk size: %.2f MB, meta: %.2f MB, forwarded: %.2f MB, total: %.2f MB)' % (len(chunks), ('using %d cores' % cores) if len(chunks) > 1 else '', chunk_size/(1024*1024.), len(meta)/(1024*1024.), len(forwarded_data)/(1024*1024.), total_ll_size/(1024*1024.)))
 
     commands = [
       (i, chunk, meta, settings_file, compiler, forwarded_file, libraries, compiler_engine,# + ['--prof'],
@@ -276,7 +276,7 @@ def emscript(infile, settings, outfile, libraries=[], compiler_engine=None,
       keys = [settings_text, forwarded_data, chunk]
       shortkey = jcache.get_shortkey(keys)
       jcache.set(shortkey, keys, outputs[i])
-    if out and DEBUG and len(chunks) > 0: print >> sys.stderr, '  saving %d funcchunks to jcache' % len(chunks)
+    if out and DEBUG and len(chunks) > 0: logging.debug('  saving %d funcchunks to jcache' % len(chunks))
 
   chunks = None
 
@@ -286,7 +286,7 @@ def emscript(infile, settings, outfile, libraries=[], compiler_engine=None,
   for output in outputs:
     assert len(output) == 2, 'Did not receive forwarded data in an output - process failed? We only got: ' + output[0][-3000:]
 
-  if DEBUG: print >> sys.stderr, '  emscript: phase 2 took %s seconds' % (time.time() - t)
+  if DEBUG: logging.debug('  emscript: phase 2 took %s seconds' % (time.time() - t))
   if DEBUG: t = time.time()
 
   # merge forwarded data
@@ -322,7 +322,7 @@ def emscript(infile, settings, outfile, libraries=[], compiler_engine=None,
   funcs_js = [output[0] for output in outputs]
 
   outputs = None
-  if DEBUG: print >> sys.stderr, '  emscript: phase 2b took %s seconds' % (time.time() - t)
+  if DEBUG: logging.debug('  emscript: phase 2b took %s seconds' % (time.time() - t))
   if DEBUG: t = time.time()
 
   # calculations on merged forwarded data
@@ -343,7 +343,7 @@ def emscript(infile, settings, outfile, libraries=[], compiler_engine=None,
     else:
       curr = i
       i += 2
-    #print >> sys.stderr, 'function indexing', indexed, curr, sig
+    #logging.debug('function indexing', indexed, curr, sig)
     forwarded_json['Functions']['indexedFunctions'][indexed] = curr # make sure not to modify this python object later - we use it in indexize
 
   def split_32(x):
@@ -381,7 +381,7 @@ def emscript(infile, settings, outfile, libraries=[], compiler_engine=None,
   forwarded_data = json.dumps(forwarded_json)
   forwarded_file = temp_files.get('.2.json').name
   open(forwarded_file, 'w').write(indexize(forwarded_data))
-  if DEBUG: print >> sys.stderr, '  emscript: phase 2c took %s seconds' % (time.time() - t)
+  if DEBUG: logging.debug('  emscript: phase 2c took %s seconds' % (time.time() - t))
 
   # Phase 3 - post
   if DEBUG: t = time.time()
@@ -542,7 +542,7 @@ def emscript(infile, settings, outfile, libraries=[], compiler_engine=None,
 
     # finalize
 
-    if DEBUG: print >> sys.stderr, 'asm text sizes', map(len, funcs_js), len(asm_setup), len(asm_global_vars), len(asm_global_funcs), len(pre_tables), len('\n'.join(function_tables_impls)), len(function_tables_defs.replace('\n', '\n  ')), len(exports), len(the_global), len(sending), len(receiving)
+    if DEBUG: logging.debug('asm text sizes', map(len, funcs_js), len(asm_setup), len(asm_global_vars), len(asm_global_funcs), len(pre_tables), len('\n'.join(function_tables_impls)), len(function_tables_defs.replace('\n', '\n  ')), len(exports), len(the_global), len(sending), len(receiving))
 
     funcs_js = ['''
 %s
@@ -690,7 +690,7 @@ Runtime.stackRestore = function(top) { asm['stackRestore'](top) };
   funcs_js = None
 
   outfile.write(indexize(post))
-  if DEBUG: print >> sys.stderr, '  emscript: phase 3 took %s seconds' % (time.time() - t)
+  if DEBUG: logging.debug('  emscript: phase 3 took %s seconds' % (time.time() - t))
 
   outfile.close()
 
@@ -782,11 +782,11 @@ def _main(environ):
   keywords, positional = parser.parse_args()
 
   if not keywords.suppressUsageWarning:
-    print >> sys.stderr, '''
+    logging.warning('''
 ==============================================================
 WARNING: You should normally never use this! Use emcc instead.
 ==============================================================
-  '''
+  ''')
 
   if len(positional) != 1:
     raise RuntimeError('Must provide exactly one positional argument. Got ' + str(len(positional)) + ': "' + '", "'.join(positional) + '"')
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