150bbde0e60e31a9db77e9f963154f9e579068cb0Ben Cheng#!/usr/bin/env python 250bbde0e60e31a9db77e9f963154f9e579068cb0Ben Cheng 350bbde0e60e31a9db77e9f963154f9e579068cb0Ben Cheng# Copyright (C) 2015 The Android Open Source Project 450bbde0e60e31a9db77e9f963154f9e579068cb0Ben Cheng# 550bbde0e60e31a9db77e9f963154f9e579068cb0Ben Cheng# Licensed under the Apache License, Version 2.0 (the "License"); 650bbde0e60e31a9db77e9f963154f9e579068cb0Ben Cheng# you may not use this file except in compliance with the License. 750bbde0e60e31a9db77e9f963154f9e579068cb0Ben Cheng# You may obtain a copy of the License at 850bbde0e60e31a9db77e9f963154f9e579068cb0Ben Cheng# 950bbde0e60e31a9db77e9f963154f9e579068cb0Ben Cheng# http://www.apache.org/licenses/LICENSE-2.0 1050bbde0e60e31a9db77e9f963154f9e579068cb0Ben Cheng# 1150bbde0e60e31a9db77e9f963154f9e579068cb0Ben Cheng# Unless required by applicable law or agreed to in writing, software 1250bbde0e60e31a9db77e9f963154f9e579068cb0Ben Cheng# distributed under the License is distributed on an "AS IS" BASIS, 1350bbde0e60e31a9db77e9f963154f9e579068cb0Ben Cheng# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. 1450bbde0e60e31a9db77e9f963154f9e579068cb0Ben Cheng# See the License for the specific language governing permissions and 1550bbde0e60e31a9db77e9f963154f9e579068cb0Ben Cheng# limitations under the License. 1650bbde0e60e31a9db77e9f963154f9e579068cb0Ben Cheng 1750bbde0e60e31a9db77e9f963154f9e579068cb0Ben Cheng"""Compare two bootcharts and list start/end timestamps on key processes. 1850bbde0e60e31a9db77e9f963154f9e579068cb0Ben Cheng 1950bbde0e60e31a9db77e9f963154f9e579068cb0Ben ChengThis script extracts two bootchart.tgz files and compares the timestamps 2050bbde0e60e31a9db77e9f963154f9e579068cb0Ben Chengin proc_ps.log for selected processes. The proc_ps.log file consists of 2150bbde0e60e31a9db77e9f963154f9e579068cb0Ben Chengrepetitive blocks of the following format: 2250bbde0e60e31a9db77e9f963154f9e579068cb0Ben Cheng 2350bbde0e60e31a9db77e9f963154f9e579068cb0Ben Chengtimestamp1 (jiffies) 2450bbde0e60e31a9db77e9f963154f9e579068cb0Ben Chengdumps of /proc/<pid>/stat 2550bbde0e60e31a9db77e9f963154f9e579068cb0Ben Cheng 2650bbde0e60e31a9db77e9f963154f9e579068cb0Ben Chengtimestamp2 2750bbde0e60e31a9db77e9f963154f9e579068cb0Ben Chengdumps of /proc/<pid>/stat 2850bbde0e60e31a9db77e9f963154f9e579068cb0Ben Cheng 2950bbde0e60e31a9db77e9f963154f9e579068cb0Ben ChengThe timestamps are 200ms apart, and the creation time of selected processes 3050bbde0e60e31a9db77e9f963154f9e579068cb0Ben Chengare listed. The termination time of the boot animation process is also listed 3150bbde0e60e31a9db77e9f963154f9e579068cb0Ben Chengas a coarse indication about when the boot process is complete as perceived by 3250bbde0e60e31a9db77e9f963154f9e579068cb0Ben Chengthe user. 3350bbde0e60e31a9db77e9f963154f9e579068cb0Ben Cheng""" 3450bbde0e60e31a9db77e9f963154f9e579068cb0Ben Cheng 3550bbde0e60e31a9db77e9f963154f9e579068cb0Ben Chengimport sys 3650bbde0e60e31a9db77e9f963154f9e579068cb0Ben Chengimport tarfile 3750bbde0e60e31a9db77e9f963154f9e579068cb0Ben Cheng 3850bbde0e60e31a9db77e9f963154f9e579068cb0Ben Cheng# The bootchart timestamps are 200ms apart, but the USER_HZ value is not 3950bbde0e60e31a9db77e9f963154f9e579068cb0Ben Cheng# reported in the bootchart, so we use the first two timestamps to calculate 4050bbde0e60e31a9db77e9f963154f9e579068cb0Ben Cheng# the wall clock time of a jiffy. 4150bbde0e60e31a9db77e9f963154f9e579068cb0Ben Chengjiffy_to_wallclock = { 4250bbde0e60e31a9db77e9f963154f9e579068cb0Ben Cheng '1st_timestamp': -1, 4350bbde0e60e31a9db77e9f963154f9e579068cb0Ben Cheng '2nd_timestamp': -1, 4450bbde0e60e31a9db77e9f963154f9e579068cb0Ben Cheng 'jiffy_to_wallclock': -1 4550bbde0e60e31a9db77e9f963154f9e579068cb0Ben Cheng} 4650bbde0e60e31a9db77e9f963154f9e579068cb0Ben Cheng 4750bbde0e60e31a9db77e9f963154f9e579068cb0Ben Chengdef analyze_process_maps(process_map1, process_map2, jiffy_record): 4850bbde0e60e31a9db77e9f963154f9e579068cb0Ben Cheng # List interesting processes here 4950bbde0e60e31a9db77e9f963154f9e579068cb0Ben Cheng processes_of_interest = [ 5050bbde0e60e31a9db77e9f963154f9e579068cb0Ben Cheng '/init', 5150bbde0e60e31a9db77e9f963154f9e579068cb0Ben Cheng '/system/bin/surfaceflinger', 5250bbde0e60e31a9db77e9f963154f9e579068cb0Ben Cheng '/system/bin/bootanimation', 5350bbde0e60e31a9db77e9f963154f9e579068cb0Ben Cheng 'zygote64', 5450bbde0e60e31a9db77e9f963154f9e579068cb0Ben Cheng 'zygote', 5550bbde0e60e31a9db77e9f963154f9e579068cb0Ben Cheng 'system_server' 5650bbde0e60e31a9db77e9f963154f9e579068cb0Ben Cheng ] 5750bbde0e60e31a9db77e9f963154f9e579068cb0Ben Cheng 5850bbde0e60e31a9db77e9f963154f9e579068cb0Ben Cheng jw = jiffy_record['jiffy_to_wallclock'] 5950bbde0e60e31a9db77e9f963154f9e579068cb0Ben Cheng print "process: baseline experiment (delta)" 6050bbde0e60e31a9db77e9f963154f9e579068cb0Ben Cheng print " - Unit is ms (a jiffy is %d ms on the system)" % jw 6150bbde0e60e31a9db77e9f963154f9e579068cb0Ben Cheng print "------------------------------------" 6250bbde0e60e31a9db77e9f963154f9e579068cb0Ben Cheng for p in processes_of_interest: 6350bbde0e60e31a9db77e9f963154f9e579068cb0Ben Cheng # e.g., 32-bit system doesn't have zygote64 6450bbde0e60e31a9db77e9f963154f9e579068cb0Ben Cheng if p in process_map1 and p in process_map2: 6550bbde0e60e31a9db77e9f963154f9e579068cb0Ben Cheng print "%s: %d %d (%+d)" % ( 6650bbde0e60e31a9db77e9f963154f9e579068cb0Ben Cheng p, process_map1[p]['start_time'] * jw, 6750bbde0e60e31a9db77e9f963154f9e579068cb0Ben Cheng process_map2[p]['start_time'] * jw, 6850bbde0e60e31a9db77e9f963154f9e579068cb0Ben Cheng (process_map2[p]['start_time'] - 6950bbde0e60e31a9db77e9f963154f9e579068cb0Ben Cheng process_map1[p]['start_time']) * jw) 7050bbde0e60e31a9db77e9f963154f9e579068cb0Ben Cheng 7150bbde0e60e31a9db77e9f963154f9e579068cb0Ben Cheng # Print the last tick for the bootanimation process 7250bbde0e60e31a9db77e9f963154f9e579068cb0Ben Cheng print "bootanimation ends at: %d %d (%+d)" % ( 7350bbde0e60e31a9db77e9f963154f9e579068cb0Ben Cheng process_map1['/system/bin/bootanimation']['last_tick'] * jw, 7450bbde0e60e31a9db77e9f963154f9e579068cb0Ben Cheng process_map2['/system/bin/bootanimation']['last_tick'] * jw, 7550bbde0e60e31a9db77e9f963154f9e579068cb0Ben Cheng (process_map2['/system/bin/bootanimation']['last_tick'] - 7650bbde0e60e31a9db77e9f963154f9e579068cb0Ben Cheng process_map1['/system/bin/bootanimation']['last_tick']) * jw) 7750bbde0e60e31a9db77e9f963154f9e579068cb0Ben Cheng 7850bbde0e60e31a9db77e9f963154f9e579068cb0Ben Chengdef parse_proc_file(pathname, process_map, jiffy_record=None): 7950bbde0e60e31a9db77e9f963154f9e579068cb0Ben Cheng # Uncompress bootchart.tgz 8050bbde0e60e31a9db77e9f963154f9e579068cb0Ben Cheng with tarfile.open(pathname + '/bootchart.tgz', 'r:*') as tf: 8150bbde0e60e31a9db77e9f963154f9e579068cb0Ben Cheng try: 8250bbde0e60e31a9db77e9f963154f9e579068cb0Ben Cheng # Read proc_ps.log 8350bbde0e60e31a9db77e9f963154f9e579068cb0Ben Cheng f = tf.extractfile('proc_ps.log') 8450bbde0e60e31a9db77e9f963154f9e579068cb0Ben Cheng 8550bbde0e60e31a9db77e9f963154f9e579068cb0Ben Cheng # Break proc_ps into chunks based on timestamps 8650bbde0e60e31a9db77e9f963154f9e579068cb0Ben Cheng blocks = f.read().split('\n\n') 8750bbde0e60e31a9db77e9f963154f9e579068cb0Ben Cheng for b in blocks: 8850bbde0e60e31a9db77e9f963154f9e579068cb0Ben Cheng lines = b.split('\n') 8950bbde0e60e31a9db77e9f963154f9e579068cb0Ben Cheng if not lines[0]: 9050bbde0e60e31a9db77e9f963154f9e579068cb0Ben Cheng break 9150bbde0e60e31a9db77e9f963154f9e579068cb0Ben Cheng 9250bbde0e60e31a9db77e9f963154f9e579068cb0Ben Cheng # 200ms apart in jiffies 9350bbde0e60e31a9db77e9f963154f9e579068cb0Ben Cheng timestamp = int(lines[0]); 9450bbde0e60e31a9db77e9f963154f9e579068cb0Ben Cheng 9550bbde0e60e31a9db77e9f963154f9e579068cb0Ben Cheng # Figure out the wall clock time of a jiffy 9650bbde0e60e31a9db77e9f963154f9e579068cb0Ben Cheng if jiffy_record is not None: 9750bbde0e60e31a9db77e9f963154f9e579068cb0Ben Cheng if jiffy_record['1st_timestamp'] == -1: 9850bbde0e60e31a9db77e9f963154f9e579068cb0Ben Cheng jiffy_record['1st_timestamp'] = timestamp 9950bbde0e60e31a9db77e9f963154f9e579068cb0Ben Cheng elif jiffy_record['jiffy_to_wallclock'] == -1: 10050bbde0e60e31a9db77e9f963154f9e579068cb0Ben Cheng # Not really needed but for debugging purposes 10150bbde0e60e31a9db77e9f963154f9e579068cb0Ben Cheng jiffy_record['2nd_timestamp'] = timestamp 10250bbde0e60e31a9db77e9f963154f9e579068cb0Ben Cheng value = 200 / (timestamp - 10350bbde0e60e31a9db77e9f963154f9e579068cb0Ben Cheng jiffy_record['1st_timestamp']) 10450bbde0e60e31a9db77e9f963154f9e579068cb0Ben Cheng # Fix the rounding error 10550bbde0e60e31a9db77e9f963154f9e579068cb0Ben Cheng # e.g., 201 jiffies in 200ms when USER_HZ is 1000 10650bbde0e60e31a9db77e9f963154f9e579068cb0Ben Cheng if value == 0: 10750bbde0e60e31a9db77e9f963154f9e579068cb0Ben Cheng value = 1 10850bbde0e60e31a9db77e9f963154f9e579068cb0Ben Cheng # e.g., 21 jiffies in 200ms when USER_HZ is 100 10950bbde0e60e31a9db77e9f963154f9e579068cb0Ben Cheng elif value == 9: 11050bbde0e60e31a9db77e9f963154f9e579068cb0Ben Cheng value = 10 11150bbde0e60e31a9db77e9f963154f9e579068cb0Ben Cheng jiffy_record['jiffy_to_wallclock'] = value 11250bbde0e60e31a9db77e9f963154f9e579068cb0Ben Cheng 11350bbde0e60e31a9db77e9f963154f9e579068cb0Ben Cheng # Populate the process_map table 11450bbde0e60e31a9db77e9f963154f9e579068cb0Ben Cheng for line in lines[1:]: 11550bbde0e60e31a9db77e9f963154f9e579068cb0Ben Cheng segs = line.split(' ') 11650bbde0e60e31a9db77e9f963154f9e579068cb0Ben Cheng 11750bbde0e60e31a9db77e9f963154f9e579068cb0Ben Cheng # 0: pid 11850bbde0e60e31a9db77e9f963154f9e579068cb0Ben Cheng # 1: process name 11950bbde0e60e31a9db77e9f963154f9e579068cb0Ben Cheng # 17: priority 12050bbde0e60e31a9db77e9f963154f9e579068cb0Ben Cheng # 18: nice 12150bbde0e60e31a9db77e9f963154f9e579068cb0Ben Cheng # 21: creation time 12250bbde0e60e31a9db77e9f963154f9e579068cb0Ben Cheng 12350bbde0e60e31a9db77e9f963154f9e579068cb0Ben Cheng proc_name = segs[1].strip('()') 12450bbde0e60e31a9db77e9f963154f9e579068cb0Ben Cheng if proc_name in process_map: 12550bbde0e60e31a9db77e9f963154f9e579068cb0Ben Cheng process = process_map[proc_name] 12650bbde0e60e31a9db77e9f963154f9e579068cb0Ben Cheng else: 12750bbde0e60e31a9db77e9f963154f9e579068cb0Ben Cheng process = {'start_time': int(segs[21])} 12850bbde0e60e31a9db77e9f963154f9e579068cb0Ben Cheng process_map[proc_name] = process 12950bbde0e60e31a9db77e9f963154f9e579068cb0Ben Cheng 13050bbde0e60e31a9db77e9f963154f9e579068cb0Ben Cheng process['last_tick'] = timestamp 13150bbde0e60e31a9db77e9f963154f9e579068cb0Ben Cheng finally: 13250bbde0e60e31a9db77e9f963154f9e579068cb0Ben Cheng f.close() 13350bbde0e60e31a9db77e9f963154f9e579068cb0Ben Cheng 13450bbde0e60e31a9db77e9f963154f9e579068cb0Ben Chengdef main(): 13550bbde0e60e31a9db77e9f963154f9e579068cb0Ben Cheng if len(sys.argv) != 3: 13650bbde0e60e31a9db77e9f963154f9e579068cb0Ben Cheng print "Usage: %s base_bootchart_dir exp_bootchart_dir" % sys.argv[0] 13750bbde0e60e31a9db77e9f963154f9e579068cb0Ben Cheng sys.exit(1) 13850bbde0e60e31a9db77e9f963154f9e579068cb0Ben Cheng 13950bbde0e60e31a9db77e9f963154f9e579068cb0Ben Cheng process_map1 = {} 14050bbde0e60e31a9db77e9f963154f9e579068cb0Ben Cheng process_map2 = {} 14150bbde0e60e31a9db77e9f963154f9e579068cb0Ben Cheng parse_proc_file(sys.argv[1], process_map1, jiffy_to_wallclock) 14250bbde0e60e31a9db77e9f963154f9e579068cb0Ben Cheng parse_proc_file(sys.argv[2], process_map2) 14350bbde0e60e31a9db77e9f963154f9e579068cb0Ben Cheng analyze_process_maps(process_map1, process_map2, jiffy_to_wallclock) 14450bbde0e60e31a9db77e9f963154f9e579068cb0Ben Cheng 14550bbde0e60e31a9db77e9f963154f9e579068cb0Ben Chengif __name__ == "__main__": 14650bbde0e60e31a9db77e9f963154f9e579068cb0Ben Cheng main() 147