Implement parallel support on LogmanTrace on Windows.

tools/isolate/trace_inputs.py

 #!/usr/bin/env python
 # coding=utf-8
 # Copyright (c) 2012 The Chromium Authors. All rights reserved.
 # Use of this source code is governed by a BSD-style license that can be
 # found in the LICENSE file.
 
 """Traces an executable and its child processes and extract the files accessed
 by them.
 
 The implementation uses OS-specific API. The native Kernel logger and the ETL
@@ skipping 2180 matching lines @@
     # at 19 or higher is dependent on the specific event.
     EVENT_NAME = 0
     TYPE = 1
     PID = 9
     TID = 10
     PROCESSOR_ID = 11
     TIMESTAMP = 16
     NULL_GUID = '{00000000-0000-0000-0000-000000000000}'
     USER_DATA = 19
 
+    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):
-      """Uses logman.exe to start and stop the NT Kernel Logger while the
-      executable to be traced is run.
-      """
       logging.info('trace(%s, %s, %s, %s)' % (cmd, cwd, tracename, output))
       with self._lock:
         if not self._initialized:
           raise TracingFailure(
               'Called Tracer.trace() on an unitialized object',
               None, None, None, tracename)
         assert tracename not in (i['trace'] for i in self._traces)
 
       # Use "logman -?" for help.
 
       stdout = stderr = None
       if output:
         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)
         self._traces.append({
           'command': cmd,
           'cwd': cwd,
           'pid': child.pid,
           'trace': tracename,
           'output': out,
         })
 
       return child.returncode, out
 
-    @classmethod
-    def _start_log(cls, etl):
-      """Starts the log collection.
+    def close(self, _timeout=None):
+      """Stops the kernel log collection and converts the traces to text
+      representation.
+      """
+      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)
 
-      One can get the list of potentially interesting providers with:
-      "logman query providers | findstr /i file"
-      """
-      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:
+        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."""
       super(LogmanTrace.Tracer, self).post_process_log()
       logformat = 'csv'
       self._convert_log(logformat)
 
       if logformat == 'csv_utf16':
         def load_file():
           def utf_8_encoder(unicode_csv_data):
@@ skipping 161 matching lines @@
   def parse_log(cls, logname, blacklist):
     logging.info('parse_log(%s, %s)' % (logname, blacklist))
 
     def blacklist_more(filepath):
       # All the NTFS metadata is in the form x:\$EXTEND or stuff like that.
       return blacklist(filepath) or re.match(r'[A-Z]\:\\\$EXTEND', filepath)
 
     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)
       out.append(
           {
             'results': context.to_results(),
             'trace': item['trace'],
             'output': item['output'],
           })
     return out
@@ skipping 274 matching lines @@
       for fn in dir(sys.modules[__name__])
       if fn.startswith('CMD')))
 
   command = get_command_handler(argv[0] if argv else None)
   parser = gen_parser(command)
   return command(parser, argv[1:])
 
 
 if __name__ == '__main__':
   sys.exit(main(sys.argv[1:]))