Merge pull request #1631 from juj/responsive_logging

Responsive logging

3 files changed, 56 insertions, 38 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..63dcefca 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
@@ -84,10 +85,6 @@ class WindowsPopen:
     except:
       pass # Mute all exceptions in dtor, particularly if we didn't use a response file, self.response_filename doesn't exist.
 
-# Install our replacement Popen handler if we are running on Windows to avoid python spawn process function.
-if os.name == 'nt':
-  Popen = WindowsPopen
-
 __rootpath__ = os.path.abspath(os.path.dirname(os.path.dirname(__file__)))
 def path_from_root(*pathelems):
   return os.path.join(__rootpath__, *pathelems)
@@ -250,6 +247,19 @@ except Exception, e:
   logging.error('Error in evaluating %s (at %s): %s, text: %s' % (EM_CONFIG, CONFIG_FILE, str(e), config_text))
   sys.exit(1)
 
+try:
+  EM_POPEN_WORKAROUND
+except:
+  EM_POPEN_WORKAROUND = os.environ.get('EM_POPEN_WORKAROUND')
+
+# Install our replacement Popen handler if we are running on Windows to avoid python spawn process function.
+# nb. This is by default disabled since it has the adverse effect of buffering up all logging messages, which makes
+# builds look unresponsive (messages are printed only after the whole build finishes). Whether this workaround is needed 
+# seems to depend on how the host application that invokes emcc has set up its stdout and stderr.
+if EM_POPEN_WORKAROUND and os.name == 'nt':
+  logging.debug('Installing Popen workaround handler to avoid bug http://bugs.python.org/issue3905')
+  Popen = WindowsPopen
+
 # Expectations
 
 EXPECTED_LLVM_VERSION = (3,2)