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
This commit is contained in:
Ben Cheng
parent
e106191436
commit
50bbde0e60
2 changed files with 169 additions and 0 deletions
146
init/compare-bootcharts.py
Executable file
146
init/compare-bootcharts.py
Executable file
|
|
@ -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()
|
||||
|
|
@ -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
|
||||
|
|
|
|||
Loading…
Reference in a new issue