Improve trace_timer_intervals

I've been using trace_timer_intervals.bat (and its associated Python
script which does all of the heavy lifting) to understand Chrome's
performance when changing the system timer interval. See
crbug.com/927165. When doing this it is convenient to filter the
results of who is changing the timer interrupt interval to just
Chrome, so I added a -f option for that, and switched to using
argparse.

At the same time I added detection of non-existent files, because
otherwise the failure modes are quite confusing.

And I changed the output to (mostly) summarize everything on a
single line per process. This is usually more readable.

bin/summarize_timer_intervals.py

@@ -40,23 +40,29 @@
 
 from __future__ import print_function
 
+import argparse
 import os
 import re
 import subprocess
 import sys
 import time
 
+parser = argparse.ArgumentParser(description="Identify and categorize chrome processes in an ETW trace.")
+parser.add_argument("trace", type=str, help="ETW trace to be processed")
+parser.add_argument("-f", "--filter_process", help="Only show results for the specified processes")
+args = parser.parse_args()
+
 # Our usage of subprocess seems to require Python 2.7+
 if sys.version_info.major == 2 and sys.version_info.minor < 7:
   print('Your python version is too old - 2.7 or higher required.')
   print('Python version is %s' % sys.version)
   sys.exit(0)
 
-if len(sys.argv) < 2:
-  print('Usage: %s tracename.etl')
-  sys.exit(0)
+trace_name = args.trace
 
-trace_name = sys.argv[1]
+if not os.path.exists(trace_name):
+  print('ETW trace file %s does not exist.' % trace_name)
+  sys.exit(0)
 
 scriptPath = os.path.abspath(sys.argv[0])
 scriptDir = os.path.split(scriptPath)[0]
@@ -128,6 +134,8 @@
 
 print('Trace duration is %1.3f seconds.' % final_timestamp)
 for process in changes_by_process.keys():
+  if args.filter_process and process.count(args.filter_process) < 1:
+    continue
   entries = changes_by_process[process]
   # Scan through all adjacent pairs to find how long the interval was at various
   # levels.
@@ -152,14 +160,14 @@
     pid = int(pid_match.groups()[0])
     if pid in types_by_pid:
       type_name = ' (Chrome %s)' % types_by_pid[pid]
-  print('%s%s: %d frequency changes %s' % (process, type_name, len(entries) - fake_events_count, ps))
   # Look for raised timer frequencies that end as the first entry. We don't know
   # what the timer interrupt frequency was before, but we know it was raised.
   if entries[0][0] == 0:
     intervals['Unknown'] = entries[0][1]
   for interval in intervals.keys():
     if type(interval) == type(0.0):
       if interval > 0:
-        print('  %1.1f ms for %5.1f%% of the time' % (interval, 100 * intervals[interval] / final_timestamp))
-    else:
-      print('  Unknown ms for %5.1f%% of the time' % (100 * intervals[interval] / final_timestamp))
+        print('  %1.1f ms for %5.1f%% of the time' % (interval, 100 * intervals[interval] / final_timestamp), end='')
+    #else:
+    #  print('  Unknown ms for %5.1f%% of the time' % (100 * intervals[interval] / final_timestamp), end='')
+  print('    %s%s: %d frequency changes %s' % (process, type_name, len(entries) - fake_events_count, ps))

bin/trace_timer_intervals.bat

@@ -23,6 +23,11 @@
 
 @setlocal
 
+@echo Run this batch file with -f=ProcessName to filter results to a specified
+@echo process. To reprocess the results afterwards run:
+@echo   python summarize_timer_intervals.py "%temp%\TimerDetails.etl"
+@echo and optionally specify -f=ProcessName
+
 @set user_providers=Microsoft-Windows-Kernel-Power:0x4000000000000004
 xperf.exe -start "NT Kernel Logger" -on PROC_THREAD+LOADER -f "%temp%\TimerDetailskernel.etl" -start TimerSession -on %user_providers%::'stack' -f "%temp%\TimerDetailsuser.etl"
 @echo Run your scenario and then press enter.
@@ -31,4 +36,4 @@ pause
 xperf.exe -stop TimerSession -stop "NT Kernel Logger"
 xperf.exe -merge "%temp%\TimerDetailskernel.etl" "%temp%\TimerDetailsuser.etl" "%temp%\TimerDetails.etl" -compress
 
-call python summarize_timer_intervals.py "%temp%\TimerDetails.etl"
+call python summarize_timer_intervals.py "%temp%\TimerDetails.etl" %*