Compare two bootcharts and list timestamps for selected processes.
Usage: system/core/init/compare-bootcharts.py base_bootchart_dir
exp_bootchart_dir
For example, here is the output where the bootanimation is changed
from "d 0 0 part2" to "c 0 0 part2":
--
process: baseline experiment (delta)
- Unit is ms (a jiffy is 10 ms on the system)
------------------------------------
/init: 50 40 (-10)
/system/bin/surfaceflinger: 4320 4470 (+150)
/system/bin/bootanimation: 6980 6990 (+10)
zygote64: 10410 10640 (+230)
zygote: 10410 10640 (+230)
system_server: 15350 15150 (-200)
bootanimation ends at: 33790 31230 (-2560)
--
In this example bootanimation is finished (estimated) 2.56 seconds sooner.
Change-Id: I39d59897c8c53d7d662676813e884b9d58feec3c
diff --git a/init/compare-bootcharts.py b/init/compare-bootcharts.py
new file mode 100755
index 0000000..2057b55
--- /dev/null
+++ b/init/compare-bootcharts.py
@@ -0,0 +1,146 @@
+#!/usr/bin/env python
+
+# Copyright (C) 2015 The Android Open Source Project
+#
+# 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.
+
+"""Compare two bootcharts and list start/end timestamps on key processes.
+
+This script extracts two bootchart.tgz files and compares the timestamps
+in proc_ps.log for selected processes. The proc_ps.log file consists of
+repetitive blocks of the following format:
+
+timestamp1 (jiffies)
+dumps of /proc/<pid>/stat
+
+timestamp2
+dumps of /proc/<pid>/stat
+
+The timestamps are 200ms apart, and the creation time of selected processes
+are listed. The termination time of the boot animation process is also listed
+as a coarse indication about when the boot process is complete as perceived by
+the user.
+"""
+
+import sys
+import tarfile
+
+# The bootchart timestamps are 200ms apart, but the USER_HZ value is not
+# reported in the bootchart, so we use the first two timestamps to calculate
+# the wall clock time of a jiffy.
+jiffy_to_wallclock = {
+ '1st_timestamp': -1,
+ '2nd_timestamp': -1,
+ 'jiffy_to_wallclock': -1
+}
+
+def analyze_process_maps(process_map1, process_map2, jiffy_record):
+ # List interesting processes here
+ processes_of_interest = [
+ '/init',
+ '/system/bin/surfaceflinger',
+ '/system/bin/bootanimation',
+ 'zygote64',
+ 'zygote',
+ 'system_server'
+ ]
+
+ jw = jiffy_record['jiffy_to_wallclock']
+ print "process: baseline experiment (delta)"
+ print " - Unit is ms (a jiffy is %d ms on the system)" % jw
+ print "------------------------------------"
+ for p in processes_of_interest:
+ # e.g., 32-bit system doesn't have zygote64
+ if p in process_map1 and p in process_map2:
+ print "%s: %d %d (%+d)" % (
+ p, process_map1[p]['start_time'] * jw,
+ process_map2[p]['start_time'] * jw,
+ (process_map2[p]['start_time'] -
+ process_map1[p]['start_time']) * jw)
+
+ # Print the last tick for the bootanimation process
+ print "bootanimation ends at: %d %d (%+d)" % (
+ process_map1['/system/bin/bootanimation']['last_tick'] * jw,
+ process_map2['/system/bin/bootanimation']['last_tick'] * jw,
+ (process_map2['/system/bin/bootanimation']['last_tick'] -
+ process_map1['/system/bin/bootanimation']['last_tick']) * jw)
+
+def parse_proc_file(pathname, process_map, jiffy_record=None):
+ # Uncompress bootchart.tgz
+ with tarfile.open(pathname + '/bootchart.tgz', 'r:*') as tf:
+ try:
+ # Read proc_ps.log
+ f = tf.extractfile('proc_ps.log')
+
+ # Break proc_ps into chunks based on timestamps
+ blocks = f.read().split('\n\n')
+ for b in blocks:
+ lines = b.split('\n')
+ if not lines[0]:
+ break
+
+ # 200ms apart in jiffies
+ timestamp = int(lines[0]);
+
+ # Figure out the wall clock time of a jiffy
+ if jiffy_record is not None:
+ if jiffy_record['1st_timestamp'] == -1:
+ jiffy_record['1st_timestamp'] = timestamp
+ elif jiffy_record['jiffy_to_wallclock'] == -1:
+ # Not really needed but for debugging purposes
+ jiffy_record['2nd_timestamp'] = timestamp
+ value = 200 / (timestamp -
+ jiffy_record['1st_timestamp'])
+ # Fix the rounding error
+ # e.g., 201 jiffies in 200ms when USER_HZ is 1000
+ if value == 0:
+ value = 1
+ # e.g., 21 jiffies in 200ms when USER_HZ is 100
+ elif value == 9:
+ value = 10
+ jiffy_record['jiffy_to_wallclock'] = value
+
+ # Populate the process_map table
+ for line in lines[1:]:
+ segs = line.split(' ')
+
+ # 0: pid
+ # 1: process name
+ # 17: priority
+ # 18: nice
+ # 21: creation time
+
+ proc_name = segs[1].strip('()')
+ if proc_name in process_map:
+ process = process_map[proc_name]
+ else:
+ process = {'start_time': int(segs[21])}
+ process_map[proc_name] = process
+
+ process['last_tick'] = timestamp
+ finally:
+ f.close()
+
+def main():
+ if len(sys.argv) != 3:
+ print "Usage: %s base_bootchart_dir exp_bootchart_dir" % sys.argv[0]
+ sys.exit(1)
+
+ process_map1 = {}
+ process_map2 = {}
+ parse_proc_file(sys.argv[1], process_map1, jiffy_to_wallclock)
+ parse_proc_file(sys.argv[2], process_map2)
+ analyze_process_maps(process_map1, process_map2, jiffy_to_wallclock)
+
+if __name__ == "__main__":
+ main()