Implement parallel support on LogmanTrace on Windows.

tools/isolate/trace_inputs.py

Index: tools/isolate/trace_inputs.py
diff --git a/tools/isolate/trace_inputs.py b/tools/isolate/trace_inputs.py
index 515199f59731446eee88a113471f5a9abda36535..984a7b6a1637f1ea5f38983a332e1d18aa311807 100755
--- a/tools/isolate/trace_inputs.py
+++ b/tools/isolate/trace_inputs.py
@@ -2198,10 +2198,49 @@ class LogmanTrace(ApiBase):
     NULL_GUID = '{00000000-0000-0000-0000-000000000000}'
     USER_DATA = 19
 
-    def trace(self, cmd, cwd, tracename, output):
-      """Uses logman.exe to start and stop the NT Kernel Logger while the
-      executable to be traced is run.
+    def __init__(self, logname):
+      """Starts the log collection.
+
+      Requires administrative access. logman.exe is synchronous so no need for a
+      "warmup" call.  'Windows Kernel Trace' is *localized* so use its GUID
+      instead.  The GUID constant name is SystemTraceControlGuid. Lovely.
+
+      One can get the list of potentially interesting providers with:
+      "logman query providers | findstr /i file"
       """
+      super(LogmanTrace.Tracer, self).__init__(logname)
+      self._script = os.path.join(BASE_DIR, 'trace_child_process.py')
+      cmd_start = [
+        'logman.exe',
+        'start',
+        'NT Kernel Logger',
+        '-p', '{9e814aad-3204-11d2-9a82-006008a86939}',
+        # splitio,fileiocompletion,syscall,file,cswitch,img
+        '(process,fileio,thread)',
+        '-o', self._logname + '.etl',
+        '-ets',  # Send directly to kernel
+        # Values extracted out of thin air.
+        # Event Trace Session buffer size in kb.
+        '-bs', '10240',
+        # Number of Event Trace Session buffers.
+        '-nb', '16', '256',
+      ]
+      logging.debug('Running: %s' % cmd_start)
+      try:
+        subprocess.check_call(
+            cmd_start,
+            stdin=subprocess.PIPE,
+            stdout=subprocess.PIPE,
+            stderr=subprocess.STDOUT)
+      except subprocess.CalledProcessError, e:
+        if e.returncode == -2147024891:
+          print >> sys.stderr, 'Please restart with an elevated admin prompt'
+        elif e.returncode == -2144337737:
+          print >> sys.stderr, (
+              'A kernel trace was already running, stop it and try again')
+        raise
+
+    def trace(self, cmd, cwd, tracename, output):
       logging.info('trace(%s, %s, %s, %s)' % (cmd, cwd, tracename, output))
       with self._lock:
         if not self._initialized:
@@ -2217,32 +2256,28 @@ class LogmanTrace(ApiBase):
         stdout = subprocess.PIPE
         stderr = subprocess.STDOUT
 
-      # 1. Start the log collection.
-      self._start_log(self._logname + '.etl')
-
-      # 2. Run the child process.
+      # Run the child process.
       logging.debug('Running: %s' % cmd)
-      try:
-        # Use trace_child_process.py so we have a clear pid owner. Since
-        # trace_inputs.py can be used as a library and could trace mulitple
-        # processes simultaneously, it makes it more complex if the executable
-        # to be traced is executed directly here. It also solves issues related
-        # to logman.exe that needs to be executed to control the kernel trace.
-        child_cmd = [
-          sys.executable,
-          os.path.join(BASE_DIR, 'trace_child_process.py'),
-        ]
-        child = subprocess.Popen(
-            child_cmd + cmd,
-            cwd=cwd,
-            stdin=subprocess.PIPE,
-            stdout=stdout,
-            stderr=stderr)
-        logging.debug('Started child pid: %d' % child.pid)
-        out = child.communicate()[0]
-      finally:
-        # 3. Stop the log collection.
-        self._stop_log()
+      # Use trace_child_process.py so we have a clear pid owner. Since
+      # trace_inputs.py can be used as a library and could trace mulitple
+      # processes simultaneously, it makes it more complex if the executable to
+      # be traced is executed directly here. It also solves issues related to
+      # logman.exe that needs to be executed to control the kernel trace.
+      child_cmd = [
+        sys.executable,
+        self._script,
+        tracename,
+      ]
+      child = subprocess.Popen(
+          child_cmd + cmd,
+          cwd=cwd,
+          stdin=subprocess.PIPE,
+          stdout=stdout,
+          stderr=stderr)
+      logging.debug('Started child pid: %d' % child.pid)
+      out = child.communicate()[0]
+      # This doesn't mean all the grand-children are done. Sadly, we don't have
+      # a good way to determine that.
 
       with self._lock:
         assert tracename not in (i['trace'] for i in self._traces)
@@ -2256,56 +2291,35 @@ class LogmanTrace(ApiBase):
 
       return child.returncode, out
 
-    @classmethod
-    def _start_log(cls, etl):
-      """Starts the log collection.
-
-      One can get the list of potentially interesting providers with:
-      "logman query providers | findstr /i file"
+    def close(self, _timeout=None):
+      """Stops the kernel log collection and converts the traces to text
+      representation.
       """
-      cmd_start = [
-        'logman.exe',
-        'start',
-        'NT Kernel Logger',
-        '-p', '{9e814aad-3204-11d2-9a82-006008a86939}',
-        # splitio,fileiocompletion,syscall,file,cswitch,img
-        '(process,fileio,thread)',
-        '-o', etl,
-        '-ets',  # Send directly to kernel
-        # Values extracted out of thin air.
-        '-bs', '1024',
-        '-nb', '200', '512',
-      ]
-      logging.debug('Running: %s' % cmd_start)
-      try:
+      with self._lock:
+        if not self._initialized:
+          raise TracingFailure(
+              'Called Tracer.close() on an unitialized object',
+              None, None, None)
+        # Save metadata, add 'format' key..
+        data = {
+          'format': 'csv',
+          'traces': self._traces,
+        }
+        write_json(self._logname, data, False)
+
+        cmd_stop = [
+          'logman.exe',
+          'stop',
+          'NT Kernel Logger',
+          '-ets',  # Sends the command directly to the kernel.
+        ]
+        logging.debug('Running: %s' % cmd_stop)
         subprocess.check_call(
-            cmd_start,
+            cmd_stop,
             stdin=subprocess.PIPE,
             stdout=subprocess.PIPE,
             stderr=subprocess.STDOUT)
-      except subprocess.CalledProcessError, e:
-        if e.returncode == -2147024891:
-          print >> sys.stderr, 'Please restart with an elevated admin prompt'
-        elif e.returncode == -2144337737:
-          print >> sys.stderr, (
-              'A kernel trace was already running, stop it and try again')
-        raise
-
-    @staticmethod
-    def _stop_log():
-      """Stops the kernel log collection."""
-      cmd_stop = [
-        'logman.exe',
-        'stop',
-        'NT Kernel Logger',
-        '-ets',  # Sends the command directly to the kernel.
-      ]
-      logging.debug('Running: %s' % cmd_stop)
-      subprocess.check_call(
-          cmd_stop,
-          stdin=subprocess.PIPE,
-          stdout=subprocess.PIPE,
-          stderr=subprocess.STDOUT)
+        self._initialized = False
 
     def post_process_log(self):
       """Converts the .etl file into .csv then into .json."""
@@ -2487,8 +2501,7 @@ class LogmanTrace(ApiBase):
     data = read_json(logname)
     lines = read_json(logname + '.json')
     out = []
-    for index, item in enumerate(data['traces']):
-      print >> sys.stderr, ('%d out of %d' % (index, len(data['traces'])))
+    for item in data['traces']:
       context = cls.Context(blacklist_more, item['pid'])
       for line in lines:
         context.on_line(line)