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

Author: Ben Cheng

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()

init/readme.txt

@@ -347,6 +347,29 @@ running at 0s. You'll have to look at dmesg to work out when the kernel
 actually started init.
 
 
+Comparing two bootcharts
+------------------------
+A handy script named compare-bootcharts.py can be used to compare the
+start/end time of selected processes. The aforementioned grab-bootchart.sh
+will leave a bootchart tarball named bootchart.tgz at /tmp/android-bootchart.
+If two such barballs are preserved on the host machine under different
+directories, the script can list the timestamps differences. For example:
+
+Usage: system/core/init/compare-bootcharts.py base_bootchart_dir
+       exp_bootchart_dir
+
+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)
+
+
 Debugging init
 --------------
 By default, programs executed by init will drop stdout and stderr into