Merge "Compare two bootcharts and list timestamps for selected processes."

#!/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()

actually started init.

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

Debugging init

--------------

--------------

By default, programs executed by init will drop stdout and stderr into

By default, programs executed by init will drop stdout and stderr into