Add scripts for reporting on timer frequency changes

Raising the Windows timer interrupt frequency gives Sleep(n) and timeouts from WaitForSingleObject better granularity but wastes power. It is important to avoid leaving the timer interrupt frequency raised unnecessarily, as I blogged about here: https://randomascii.wordpress.com/2013/07/08/windows-timer-resolution-megawatts-wasted/ Unfortunately the Microsoft tools for analyzing this are poor. clockres doesn't say who has raised the interrupt frequency. clockres doesn't distinguish between the user and kernel interrupt frequencies and apparently they are totally different. Both clockres and powercfg /energy sample a single moment in time, which fails for programs like Chrome which repeatedly alter the timer interrupt frequency. With this change you can just run trace_timer_intervals.bat from an administrator command prompt from the UIforETW\bin directory and it will generate a report for the time period of the trace you record.
google · May 27, 2019 · c5fcbc0 · c5fcbc0
1 parent f198783
commit c5fcbc0
Show file tree

Hide file tree

Showing 3 changed files with 269 additions and 0 deletions.
diff --git a/bin/summarize_timer_intervals.py b/bin/summarize_timer_intervals.py
@@ -0,0 +1,155 @@
+# Copyright 2019 Google Inc. All Rights Reserved.
+#
+# Licensed under the Apache License, Version 2.0 (the "License");
+# you may not use this file except in compliance with the License.
+# You may obtain a copy of the License at
+#
+#     http://www.apache.org/licenses/LICENSE-2.0
+#
+# Unless required by applicable law or agreed to in writing, software
+# distributed under the License is distributed on an "AS IS" BASIS,
+# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+# See the License for the specific language governing permissions and
+# limitations under the License.
+
+'''
+This script extracts timer frequency/interval data from an ETW trace and
+summarizes it by process in order to understand what processes are raising the
+system-global timer interrupt frequency, how frequently, and for how long. The
+trace can be one recorded by UIforETW or, if you are just interested in timer
+information, one recorded by trace_timer_intervals.bat.
+
+For more information on why this matters see this blog post:
+https://randomascii.wordpress.com/2013/07/08/windows-timer-resolution-megawatts-wasted/
+
+The initial trace conversion is done using wpaexporter. See
+https://randomascii.wordpress.com/2013/11/04/exporting-arbitrary-data-from-xperf-etl-files/
+for details on wpaexporter.
+
+The output from wpaexporter goes to Generic_Events_Timer_Intervals_by_Process.csv.
+The first line is column labels and the rest is the fields from the profile.
+
+The one known flaw is that if a process raises the timer interrupt frequency
+before tracing starts and then lowers it towards the end of the trace then this
+will not be tracked because we have no way of knowing what frequency the
+proccess requested.
+'''
+
+from __future__ import print_function
+
+import os
+import re
+import subprocess
+import sys
+import time
+
+# 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 = sys.argv[1]
+
+scriptPath = os.path.abspath(sys.argv[0])
+scriptDir = os.path.split(scriptPath)[0]
+
+profilePath = os.path.join(scriptDir, 'timer_intervals.wpaProfile')
+if not os.path.exists(profilePath):
+  print('Couldn\'t find \"%s\". This should be part of the UIforETW repo and releases' % profilePath)
+  sys.exit(0)
+
+if os.environ.has_key('ProgramFiles(x86)'):
+  progFilesx86 = os.environ['ProgramFiles(x86)']
+else:
+  progFilesx86 = os.environ['ProgramFiles']
+wpaExporterPath = os.path.join(progFilesx86, r'Windows Kits\10\Windows Performance Toolkit\wpaexporter.EXE')
+if not os.path.exists(wpaExporterPath):
+  print('Couldn\'t find "%s". Make sure WPT 10 is installed.' % wpaExporterPath)
+  sys.exit(0)
+
+wpaCommand = r'"%s" "%s" -profile "%s"' % (wpaExporterPath, trace_name, profilePath)
+
+print('> %s' % wpaCommand)
+print(subprocess.check_output(wpaCommand, stderr=subprocess.STDOUT))
+
+# This dictionary of lists accumulates the data. The key is a process (pid) name
+# and the payload is a list containing interval/timestamp pairs. The timer
+# interrupt intervals are converted from hexadecimal 100ns units to floats
+# representing milliseconds.
+changes_by_process = {}
+
+# This tracks how many fake events were added, by process (pid) name. Fake
+# events are added to close out timer intervals and, for processes that leave
+# the timer interrupt raised for the entire trace, for the start and finish.
+# Note that a process that lowers the timer interrupt just before the end of
+# the trace will not properly be recorded.
+fake_events_added = {}
+
+# Process all of the lines in the output of wpaexporter, skipping the first line
+# which is just the column names.
+csv_name = 'Generic_Events_Timer_Intervals_by_Process.csv'
+# Skip over the header line
+for line in open(csv_name).readlines()[1:]:
+  parts = line.strip().split(',')
+  if len(parts) < 7:
+    print(line.strip())
+    continue
+  task_name, process_name, process, interval, timestamp, PID, app_name = parts
+  # Convert from hex (with leading 0x) to decimal and from 100 ns to ms units.
+  interval = int(interval[2:], 16) * 1e-4
+  timestamp = float(timestamp)
+  if task_name == 'SystemTimeResolutionRequestRundown':
+    process = os.path.split(app_name)[1] + ' (%d)' % int(PID[2:], 16)
+    if process in changes_by_process:
+      fake_events_added[process] = 1
+    else:
+      fake_events_added[process] = 2
+      # Add an entry at time==0 to so that this timer that was raised the entire
+      # time gets accounted for, then fall through to close it out.
+      changes_by_process[process] = [(interval, 0)]
+    # Fall through to add to list to ensure that the final time segment is
+    # closed out.
+  list = changes_by_process.get(process, [])
+  list.append((interval, timestamp))
+  changes_by_process[process] = list
+  final_timestamp = timestamp
+
+# Get process-type information for Chrome processes.
+import IdentifyChromeProcesses
+types_by_pid = IdentifyChromeProcesses.GetPIDToTypeMap(trace_name)
+
+print('Trace duration is %1.3f seconds.' % final_timestamp)
+for process in changes_by_process.keys():
+  entries = changes_by_process[process]
+  # Scan through all adjacent pairs to find how long the interval was at various
+  # levels.
+  intervals = {}
+  last_interval, last_timestamp = entries[0]
+  for interval, timestamp in entries[1:]:
+    data = intervals.get(last_interval, 0.0)
+    intervals[last_interval] = data + (timestamp - last_timestamp)
+    last_timestamp = timestamp
+    last_interval = interval
+  fake_events_count = 0
+  ps = '(%1.1f/s)' % (len(entries) / final_timestamp)
+  if process in fake_events_added:
+    fake_events_count = fake_events_added[process]
+    if fake_events_count == len(entries):
+      ps = '- frequency still raised at trace end'
+    else:
+      ps = '(%1.1f/s) - frequency still raised at trace end' % ((len(entries) - fake_events_count) / final_timestamp)
+  type_name = ''
+  pid_match = re.match(r'.*\((\d+)\)', process)
+  if pid_match:
+    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))
+  for interval in intervals.keys():
+    if interval > 0:
+      print('  %1.1f ms for %5.1f%% of the time' % (interval, 100 * intervals[interval] / final_timestamp))
diff --git a/bin/timer_intervals.wpaProfile b/bin/timer_intervals.wpaProfile
@@ -0,0 +1,80 @@
+<?xml version="1.0" encoding="utf-8"?>
+<WpaProfileContainer xmlns:xsd="http://www.w3.org/2001/XMLSchema" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" Version="2" xmlns="http://tempuri.org/SerializableElement.xsd">
+  <Content xsi:type="WpaProfile2">
+    <Sessions>
+      <Session Index="0">
+        <FileReferences />
+      </Session>
+    </Sessions>
+    <Views>
+      <View Guid="67b8486a-9cc3-4d36-978b-cfc07051f750" IsVisible="true" Title="Analysis">
+        <Graphs>
+          <Graph Guid="04f69f98-176e-4d1c-b44e-97f734996ab8" LayoutStyle="DataTable" Color="#FF005DE0" GraphHeight="46" IsMinimized="false" IsShown="true" IsExpanded="false" HelpText="{}{\rtf1\ansi\ansicpg1252\uc1\htmautsp\deff2{\fonttbl{\f0\fcharset0 Times New Roman;}{\f2\fcharset0 Segoe UI;}}{\colortbl\red0\green0\blue0;\red255\green255\blue255;}\loch\hich\dbch\pard\plain\ltrpar\itap0{\lang1033\fs18\f2\cf0 \cf0\ql{\f2 {\ltrch Shows every event in the trace, including the associated payload fields.}\li0\ri0\sa0\sb0\fi0\ql\par}&#xD;&#xA;{\f2 \li0\ri0\sa0\sb0\fi0\ql\par}&#xD;&#xA;{\f2 {\ltrch New capability - graph payload fields!}\li0\ri0\sa0\sb0\fi0\ql\par}&#xD;&#xA;{\f2 \li0\ri0\sa0\sb0\fi0\ql\par}&#xD;&#xA;{\f2 {\ltrch 1. Filter down to the event with the payload field you want to graph.}\li0\ri0\sa0\sb0\fi0\ql\par}&#xD;&#xA;{\f2 {\ltrch 2. Drag the column corresponding to the payload field you want to graph to the right of the blue bar.}\li0\ri0\sa0\sb0\fi0\ql\par}&#xD;&#xA;{\f2 {\ltrch 3. If the automatic graphing isn't representing your data correctly, go to View Editor and:}\li0\ri0\sa0\sb0\fi0\ql\par}&#xD;&#xA;{\f2 {\ltrch a. Adjust the aggregation mode for your column, or}\li0\ri0\sa0\sb0\fi0\ql\par}&#xD;&#xA;{\f2 {\ltrch b. Go to Advanced &gt; Graph Configuration and change your graphing aggregation mode.}\li0\ri0\sa0\sb0\fi0\ql\par}&#xD;&#xA;}&#xD;&#xA;}">
+            <Preset Name="Timer Intervals by Process" BarGraphIntervalCount="50" IsThreadActivityTable="false" GraphColumnCount="44" KeyColumnCount="4" LeftFrozenColumnCount="11" RightFrozenColumnCount="42" InitialFilterQuery="[Task Name]:*&quot;SystemTimeResolution(Change|RequestRundown)&quot;" InitialFilterShouldKeep="true" GraphFilterTopValue="0" GraphFilterThresholdValue="0" HelpText="{}{\rtf1\ansi\ansicpg1252\uc1\htmautsp\deff2{\fonttbl{\f0\fcharset0 Times New Roman;}{\f2\fcharset0 Segoe UI;}}{\colortbl\red0\green0\blue0;\red255\green255\blue255;}\loch\hich\dbch\pard\plain\ltrpar\itap0{\lang1033\fs18\f2\cf0 \cf0\ql{\f2 {\ltrch Groups all the events by provider, task, and opcode.}\li0\ri0\sa0\sb0\fi0\ql\par}&#xD;&#xA;}&#xD;&#xA;}">
+              <MetadataEntries>
+                <MetadataEntry Guid="edf01e5d-3644-4dbc-ab9d-f8954e6db6ea" Name="ThreadId" ColumnMetadata="EndThreadId" />
+                <MetadataEntry Guid="bbfc990a-b6c9-4dcd-858b-f040ab4a1efe" Name="Time" ColumnMetadata="StartTime" />
+                <MetadataEntry Guid="bbfc990a-b6c9-4dcd-858b-f040ab4a1efe" Name="Time" ColumnMetadata="EndTime" />
+              </MetadataEntries>
+              <HighlightEntries />
+              <Columns>
+                <Column Guid="8b4c40f8-0d99-437d-86ab-56ec200137dc" Name="Provider Name" SortPriority="1" Width="200" IsVisible="false" />
+                <Column Guid="2a23f9b1-65d6-46d2-87b2-72f3606b7f75" Name="Provider Id" SortPriority="2" Width="100" IsVisible="false" />
+                <Column Guid="5b51716b-b88f-443a-a396-c6316296d5f8" Name="Opcode Name" SortPriority="4" Width="80" IsVisible="false" />
+                <Column Guid="d446a182-5203-4a29-aca1-4ab9bea0d1b5" Name="Version" SortPriority="5" Width="80" IsVisible="false" />
+                <Column Guid="511777f7-30ef-4e86-bd0b-0facaf23a0d3" Name="Task Name" SortPriority="3" Width="244" IsVisible="true" />
+                <Column Guid="85d40897-ae0f-4a6b-aea3-b4bcd27c14f7" Name="Process Name" SortPriority="6" Width="100" IsVisible="true" />
+                <Column Guid="c72e1c5a-f6db-4c84-8c0b-85989e514075" Name="Id" SortPriority="7" Width="80" IsVisible="false" />
+                <Column Guid="27165170-b6d1-44fe-ac86-a52749c651f4" Name="Channel" SortPriority="8" Width="73" IsVisible="false" />
+                <Column Guid="704a10b2-3e2d-40e9-98c8-7f22e09f6d95" Name="Keyword" SortPriority="9" TextAlignment="Right" Width="205" CellFormat="x" IsVisible="false" />
+                <Column Guid="7ee6a5ff-1faf-428a-a7c2-7d2cb2b5cf26" Name="Process" SortPriority="10" Width="135" IsVisible="true">
+                  <ProcessOptionsParameter />
+                </Column>
+                <Column Guid="cb796d44-2927-5ac1-d231-4b71904c18f5" Name="Thread Name" SortPriority="11" Width="80" IsVisible="false" />
+                <Column Guid="82ddfdff-ee93-5f35-08ac-4705069618dc" Name="Thread Activity Tag" SortPriority="12" Width="80" IsVisible="false" />
+                <Column Guid="2818954f-2d30-5569-4510-dade0a5a605c" Name="Annotation" SortPriority="13" Width="80" IsVisible="false">
+                  <AnnotationsOptionsParameter>
+                    <AnnotationQueryEntries />
+                  </AnnotationsOptionsParameter>
+                </Column>
+                <Column Guid="90fe0b49-e3bb-440f-b829-5813c42108a1" Name="Event Name" SortPriority="14" Width="379" IsVisible="false" />
+                <Column Guid="72892fbe-0f55-426a-9aa1-26b6baf09ffb" Name="Event Type" SortPriority="15" Width="100" IsVisible="false" />
+                <Column Guid="0734f1a4-fbd9-4ff6-aec0-cf43875c8253" Name="Message" SortPriority="16" Width="100" IsVisible="false" />
+                <Column Guid="3be8610c-babb-4154-9970-1b2210928024" Name="Cpu" SortPriority="17" Width="137" IsVisible="false" />
+                <Column Guid="edf01e5d-3644-4dbc-ab9d-f8954e6db6ea" Name="ThreadId" SortPriority="18" Width="50" IsVisible="false" />
+                <Column Guid="0c5cf8cd-9b9e-5798-1a5d-09d429f7fa3c" Name="Field 1" SortPriority="19" Width="173" IsVisible="true" />
+                <Column Guid="bbfc990a-b6c9-4dcd-858b-f040ab4a1efe" Name="Time" SortOrder="Ascending" SortPriority="0" Width="80" IsVisible="true">
+                  <DateTimeTimestampOptionsParameter DateTimeEnabled="false" />
+                </Column>
+                <Column Guid="71badd11-26e5-56bc-44ec-12f4cc6a8f3e" Name="Field 2" SortPriority="20" Width="80" IsVisible="true" />
+                <Column Guid="411dba2d-5d6e-5272-8287-636d0841768c" Name="Field 3" SortPriority="21" Width="80" IsVisible="false" />
+                <Column Guid="048f5050-1f17-59b3-fa22-4b0781ee630b" Name="Field 4" SortPriority="22" Width="477" IsVisible="true" />
+                <Column Guid="94e48f22-d499-5227-bb04-be011b4159b0" Name="Field 5" SortPriority="23" Width="193" IsVisible="false" />
+                <Column Guid="c1054028-424a-59ba-e760-6d30abbd69c5" Name="Field 6" SortPriority="24" Width="80" IsVisible="false" />
+                <Column Guid="5cbc4b58-2de1-5449-55b2-4651d4edf90a" Name="Field 7" SortPriority="25" Width="80" IsVisible="false" />
+                <Column Guid="fc01e6c9-a43b-51a1-fd2e-112ba48aff65" Name="Field 8" SortPriority="26" Width="80" IsVisible="false" />
+                <Column Guid="e3dcf300-46e2-5c43-ef4b-2c3db489ec25" Name="Field 9" SortPriority="27" Width="80" IsVisible="false" />
+                <Column Guid="87c21ddb-4b29-58e3-5ddc-f114c5ca209a" Name="Field 10" SortPriority="28" Width="80" IsVisible="false" />
+                <Column Guid="65f8fe42-ad02-5016-3521-f93329c76227" Name="Field 11" SortPriority="29" Width="80" IsVisible="false" />
+                <Column Guid="03d48fd3-0fe4-57f5-a477-49beb0d70a1f" Name="Field 12" SortPriority="30" Width="80" IsVisible="false" />
+                <Column Guid="998f8e2d-0f5a-5a54-0133-226e2de62c0b" Name="Field 13" SortPriority="31" Width="80" IsVisible="false" />
+                <Column Guid="bb772c34-9600-5bf7-3f54-e6080f8a0611" Name="Field 14" SortPriority="32" Width="80" IsVisible="false" />
+                <Column Guid="1479add7-3dcb-580b-f1e9-87d5186ced61" Name="Field 15" SortPriority="33" Width="80" IsVisible="false" />
+                <Column Guid="23f4d26d-f02e-592e-f16b-2980410ed2b2" Name="Field 16" SortPriority="34" Width="80" IsVisible="false" />
+                <Column Guid="40dce5c1-dea9-5dbc-ab35-c942b2d0bc12" Name="Field 17" SortPriority="35" Width="80" IsVisible="false" />
+                <Column Guid="dab0dfee-6f35-5deb-6df3-0ea67c831edb" Name="Field 18" SortPriority="36" Width="80" IsVisible="false" />
+                <Column Guid="213da6f4-f8e3-5177-4d42-fef0d1e6b0cb" Name="Field 19" SortPriority="37" Width="80" IsVisible="false" />
+                <Column Guid="d14459a6-d8e9-5de7-3bca-ab658234e784" Name="Field 20" SortPriority="38" Width="80" IsVisible="false" />
+                <Column Guid="24d8ee5e-37d8-571b-a820-350e442abe6d" Name="Field 21" SortPriority="39" Width="80" IsVisible="false" />
+                <Column Guid="342f7677-17b2-4c7e-b9ec-e89612c49792" Name="Count" AggregationMode="Sum" SortPriority="40" Width="80" IsVisible="false" />
+              </Columns>
+            </Preset>
+          </Graph>
+        </Graphs>
+        <SessionIndices>
+          <SessionIndex>0</SessionIndex>
+        </SessionIndices>
+      </View>
+    </Views>
+  </Content>
+</WpaProfileContainer>
diff --git a/bin/trace_timer_intervals.bat b/bin/trace_timer_intervals.bat
@@ -0,0 +1,34 @@
+@rem Copyright 2015 Google Inc. All Rights Reserved.
+@rem
+@rem Licensed under the Apache License, Version 2.0 (the "License");
+@rem you may not use this file except in compliance with the License.
+@rem You may obtain a copy of the License at
+@rem
+@rem     http://www.apache.org/licenses/LICENSE-2.0
+@rem
+@rem Unless required by applicable law or agreed to in writing, software
+@rem distributed under the License is distributed on an "AS IS" BASIS,
+@rem WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+@rem See the License for the specific language governing permissions and
+@rem limitations under the License.
+
+@rem Use this batch file to record timer interrupt interval/frequency changes.
+@rem It relies on xperf, a Python script, wpaexporter, a .wpaProfile script,
+@rem and IdentifyChromeProcesses.py. The result will be a summary, per-process,
+@rem of what processes raised the timer frequency, to what level, how often, and
+@rem for how long.
+@rem The ETW traces also contain call stacks for all of the events recorded,
+@rem making it possible to find out where in ones code the timer interval
+@rem changes are coming from.
+
+@setlocal
+
+@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.
+pause
+@xperf.exe -capturestate TimerSession %user_providers%
+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"