1#!/usr/bin/env python
2
3# Copyright (C) 2015 The Android Open Source Project
4#
5# Licensed under the Apache License, Version 2.0 (the "License");
6# you may not use this file except in compliance with the License.
7# You may obtain a copy of the License at
8#
9#      http://www.apache.org/licenses/LICENSE-2.0
10#
11# Unless required by applicable law or agreed to in writing, software
12# distributed under the License is distributed on an "AS IS" BASIS,
13# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
14# See the License for the specific language governing permissions and
15# limitations under the License.
16
17"""Compare two bootcharts and list start/end timestamps on key processes.
18
19This script extracts two bootchart.tgz files and compares the timestamps
20in proc_ps.log for selected processes. The proc_ps.log file consists of
21repetitive blocks of the following format:
22
23timestamp1 (jiffies)
24dumps of /proc/<pid>/stat
25
26timestamp2
27dumps of /proc/<pid>/stat
28
29The timestamps are 200ms apart, and the creation time of selected processes
30are listed. The termination time of the boot animation process is also listed
31as a coarse indication about when the boot process is complete as perceived by
32the user.
33"""
34
35import sys
36import tarfile
37
38# The bootchart timestamps are 200ms apart, but the USER_HZ value is not
39# reported in the bootchart, so we use the first two timestamps to calculate
40# the wall clock time of a jiffy.
41jiffy_to_wallclock = {
42   '1st_timestamp': -1,
43   '2nd_timestamp': -1,
44   'jiffy_to_wallclock': -1
45}
46
47def analyze_process_maps(process_map1, process_map2, jiffy_record):
48    # List interesting processes here
49    processes_of_interest = [
50        '/init',
51        '/system/bin/surfaceflinger',
52        '/system/bin/bootanimation',
53        'zygote64',
54        'zygote',
55        'system_server'
56    ]
57
58    jw = jiffy_record['jiffy_to_wallclock']
59    print "process: baseline experiment (delta)"
60    print " - Unit is ms (a jiffy is %d ms on the system)" % jw
61    print "------------------------------------"
62    for p in processes_of_interest:
63        # e.g., 32-bit system doesn't have zygote64
64        if p in process_map1 and p in process_map2:
65            print "%s: %d %d (%+d)" % (
66                p, process_map1[p]['start_time'] * jw,
67                process_map2[p]['start_time'] * jw,
68                (process_map2[p]['start_time'] -
69                 process_map1[p]['start_time']) * jw)
70
71    # Print the last tick for the bootanimation process
72    print "bootanimation ends at: %d %d (%+d)" % (
73        process_map1['/system/bin/bootanimation']['last_tick'] * jw,
74        process_map2['/system/bin/bootanimation']['last_tick'] * jw,
75        (process_map2['/system/bin/bootanimation']['last_tick'] -
76            process_map1['/system/bin/bootanimation']['last_tick']) * jw)
77
78def parse_proc_file(pathname, process_map, jiffy_record=None):
79    # Uncompress bootchart.tgz
80    with tarfile.open(pathname + '/bootchart.tgz', 'r:*') as tf:
81        try:
82            # Read proc_ps.log
83            f = tf.extractfile('proc_ps.log')
84
85            # Break proc_ps into chunks based on timestamps
86            blocks = f.read().split('\n\n')
87            for b in blocks:
88                lines = b.split('\n')
89                if not lines[0]:
90                    break
91
92                # 200ms apart in jiffies
93                timestamp = int(lines[0]);
94
95                # Figure out the wall clock time of a jiffy
96                if jiffy_record is not None:
97                    if jiffy_record['1st_timestamp'] == -1:
98                        jiffy_record['1st_timestamp'] = timestamp
99                    elif jiffy_record['jiffy_to_wallclock'] == -1:
100                        # Not really needed but for debugging purposes
101                        jiffy_record['2nd_timestamp'] = timestamp
102                        value = 200 / (timestamp -
103                                       jiffy_record['1st_timestamp'])
104                        # Fix the rounding error
105                        # e.g., 201 jiffies in 200ms when USER_HZ is 1000
106                        if value == 0:
107                            value = 1
108                        # e.g., 21 jiffies in 200ms when USER_HZ is 100
109                        elif value == 9:
110                            value = 10
111                        jiffy_record['jiffy_to_wallclock'] = value
112
113                # Populate the process_map table
114                for line in lines[1:]:
115                    segs = line.split(' ')
116
117                    #  0: pid
118                    #  1: process name
119                    # 17: priority
120                    # 18: nice
121                    # 21: creation time
122
123                    proc_name = segs[1].strip('()')
124                    if proc_name in process_map:
125                        process = process_map[proc_name]
126                    else:
127                        process = {'start_time': int(segs[21])}
128                        process_map[proc_name] = process
129
130                    process['last_tick'] = timestamp
131        finally:
132            f.close()
133
134def main():
135    if len(sys.argv) != 3:
136        print "Usage: %s base_bootchart_dir exp_bootchart_dir" % sys.argv[0]
137        sys.exit(1)
138
139    process_map1 = {}
140    process_map2 = {}
141    parse_proc_file(sys.argv[1], process_map1, jiffy_to_wallclock)
142    parse_proc_file(sys.argv[2], process_map2)
143    analyze_process_maps(process_map1, process_map2, jiffy_to_wallclock)
144
145if __name__ == "__main__":
146    main()
147