EAS Testing - Recents Fling on Android

The goal of this experiment is to collect frame statistics while swiping up and down tabs of recently opened applications on a Pixel device running Android with an EAS kernel. This process is name Recents Fling. The Analysis phase will consist in comparing EAS with other schedulers, that is comparing sched governor with:

- interactive
- performance
- powersave
- ondemand

For this experiment it is recommended to open many applications so that we can swipe over more recently opened applications.


In [1]:
import logging
from conf import LisaLogging
LisaLogging.setup()


2016-12-09 14:58:45,902 INFO    : root         : Using LISA logging configuration:
2016-12-09 14:58:45,902 INFO    : root         :   /home/vagrant/lisa/logging.conf

In [2]:
%pylab inline

import os
from time import sleep

# Support to access the remote target
import devlib
from env import TestEnv

# Import support for Android devices
from android import Screen, Workload

from devlib.utils.android import adb_command

# Support for trace events analysis
from trace import Trace

# Suport for FTrace events parsing and visualization
import trappy


Populating the interactive namespace from numpy and matplotlib

Test environment setup

For more details on this please check out examples/utils/testenv_example.ipynb.

devlib requires the ANDROID_HOME environment variable configured to point to your local installation of the Android SDK. If you have not this variable configured in the shell used to start the notebook server, you need to run a cell to define where your Android SDK is installed or specify the ANDROID_HOME in your target configuration.

In case more than one Android device are conencted to the host, you must specify the ID of the device you want to target in my_target_conf. Run adb devices on your host to get the ID.


In [3]:
import os
os.environ['ANDROID_HOME'] = '/ext/android-sdk-linux/'

In case more than one Android device are conencted to the host, you must specify the ID of the device you want to target in my_target_conf. Run adb devices on your host to get the ID.


In [4]:
# Setup a target configuration
my_conf = {
    
    # Target platform and board
    "platform"    : 'android',
    "board"       : 'pixel',

    # Device ID
    "device"      : "HT6670300102",
    
    # Android home
    "ANDROID_HOME" : "/home/vagrant/lisa/tools/android-sdk-linux",

    # Folder where all the results will be collected
    "results_dir" : "Android_RecentsFling",
    
    # Define devlib modules to load
    "modules"     : [
        'cpufreq'       # enable CPUFreq support
    ],

    # FTrace events to collect for all the tests configuration which have
    # the "ftrace" flag enabled
    "ftrace"  : {
         "events" : [
            "sched_switch",
            "sched_load_avg_cpu",
            "cpu_frequency",
            "cpu_capacity"
         ],
         "buffsize" : 10 * 1024,
    },

    # Tools required by the experiments
    "tools"   : [ 'trace-cmd' ],
}

In [5]:
# Initialize a test environment using:
te = TestEnv(my_conf)
target = te.target


2016-12-09 14:58:50,762 INFO    : TestEnv      : Using base path: /home/vagrant/lisa
2016-12-09 14:58:50,763 INFO    : TestEnv      : Loading custom (inline) target configuration
2016-12-09 14:58:50,764 INFO    : TestEnv      : External tools using:
2016-12-09 14:58:50,765 INFO    : TestEnv      :    ANDROID_HOME: /home/vagrant/lisa/tools/android-sdk-linux
2016-12-09 14:58:50,766 INFO    : TestEnv      :    CATAPULT_HOME: /home/vagrant/lisa/tools/catapult
2016-12-09 14:58:50,767 INFO    : TestEnv      : Loading board:
2016-12-09 14:58:50,767 INFO    : TestEnv      :    /home/vagrant/lisa/libs/utils/platforms/pixel.json
2016-12-09 14:58:50,768 INFO    : TestEnv      : Devlib modules to load: [u'bl', u'cpufreq']
2016-12-09 14:58:50,768 INFO    : TestEnv      : Connecting Android target [HT6670300102]
2016-12-09 14:58:50,769 INFO    : TestEnv      : Connection settings:
2016-12-09 14:58:50,769 INFO    : TestEnv      :    {'device': 'HT6670300102'}
2016-12-09 14:58:50,855 INFO    : android      : ls command is set to ls -1
2016-12-09 14:58:51,610 INFO    : TestEnv      : Initializing target workdir:
2016-12-09 14:58:51,613 INFO    : TestEnv      :    /data/local/tmp/devlib-target
2016-12-09 14:58:54,009 INFO    : TestEnv      : Topology:
2016-12-09 14:58:54,012 INFO    : TestEnv      :    [[0, 1], [2, 3]]
2016-12-09 14:58:54,279 INFO    : TestEnv      : Loading default EM:
2016-12-09 14:58:54,282 INFO    : TestEnv      :    /home/vagrant/lisa/libs/utils/platforms/pixel.json
2016-12-09 14:58:55,219 INFO    : TestEnv      : Enabled tracepoints:
2016-12-09 14:58:55,220 INFO    : TestEnv      :    sched_switch
2016-12-09 14:58:55,221 INFO    : TestEnv      :    sched_load_avg_cpu
2016-12-09 14:58:55,221 INFO    : TestEnv      :    cpu_frequency
2016-12-09 14:58:55,222 INFO    : TestEnv      :    cpu_capacity
2016-12-09 14:58:55,222 WARNING : TestEnv      : Wipe previous contents of the results folder:
2016-12-09 14:58:55,223 WARNING : TestEnv      :    /home/vagrant/lisa/results/Android_RecentsFling
2016-12-09 14:58:55,291 INFO    : TestEnv      : Set results folder to:
2016-12-09 14:58:55,291 INFO    : TestEnv      :    /home/vagrant/lisa/results/Android_RecentsFling
2016-12-09 14:58:55,292 INFO    : TestEnv      : Experiment results available also in:
2016-12-09 14:58:55,292 INFO    : TestEnv      :    /home/vagrant/lisa/results_latest

Support Functions

This set of support functions will help us running the benchmark using different CPUFreq governors.


In [6]:
def set_performance():
    target.cpufreq.set_all_governors('performance')

def set_powersave():
    target.cpufreq.set_all_governors('powersave')

def set_interactive():
    target.cpufreq.set_all_governors('interactive')

def set_sched():
    target.cpufreq.set_all_governors('sched')

def set_ondemand():
    target.cpufreq.set_all_governors('ondemand')
    
    for cpu in target.list_online_cpus():
        tunables = target.cpufreq.get_governor_tunables(cpu)
        target.cpufreq.set_governor_tunables(
            cpu,
            'ondemand',
            **{'sampling_rate' : tunables['sampling_rate_min']}
        )

In [7]:
# CPUFreq configurations to test
confs = {
    'performance' : {
        'label' : 'prf',
        'set' :  set_performance,
    },
    'powersave' : {
        'label' : 'pws',
        'set' :  set_powersave,
    },
     'interactive' : {
         'label' : 'int',
         'set' :  set_interactive,
     },
    'sched' : {
        'label' : 'sch',
        'set' :  set_sched,
    },
    'ondemand' : {
        'label' : 'odm',
        'set' :  set_ondemand,
    }
}

# The set of results for each comparison test
results = {}

In [8]:
def open_apps(n):
    """
    Open `n` apps on the device
    
    :param n: number of apps to open
    :type n: int
    """
    # Get a list of third-party packages
    android_version = target.getprop('ro.build.version.release')
    if android_version >= 'N':
        packages = target.execute('cmd package list packages | cut -d: -f 2')
        packages = packages.splitlines()
    else:
        packages = target.execute('pm list packages -3 | cut -d: -f 2')
        packages = packages.splitlines()

    # As a safe fallback let's use a list of standard Android AOSP apps which are always available
    if len(packages) < 8:
        packages = [
            'com.android.messaging',
            'com.android.calendar',
            'com.android.settings',
            'com.android.calculator2',
            'com.android.email',
            'com.android.music',
            'com.android.deskclock',
            'com.android.contacts',
        ]
    
    LAUNCH_CMD = 'monkey -p {} -c android.intent.category.LAUNCHER 1 '
    
    if n > len(packages):
        n = len(packages)
        
    logging.info('Trying to open %d apps...', n)
    started = 0
    for app in packages:
        logging.debug('    Launching %s', app)
        try:
            target.execute(LAUNCH_CMD.format(app))
            started = started + 1
            logging.info('  %2d starting %s...', started, app)
        except Exception:
            pass
        if started >= n:
            break
        
    # Close Recents
    target.execute('input keyevent KEYCODE_HOME')

In [9]:
def recentsfling_run(exp_dir):
    # Unlock device screen (assume no password required)
    target.execute('input keyevent 82')

    # Configure screen to max brightness and no dimming
    Screen.set_brightness(target, percent=100)
    Screen.set_dim(target, auto=False)
    Screen.set_timeout(target, 60*60*10) # 10 hours should be enought for an experiment

    # Open Recents on the target device
    target.execute('input keyevent KEYCODE_APP_SWITCH')
    # Allow the activity to start
    sleep(5)
    # Reset framestats collection
    target.execute('dumpsys gfxinfo --reset')
    
    w, h = target.screen_resolution
    x = w/2
    yl = int(0.2*h)
    yh = int(0.9*h)
    
    logging.info('Start Swiping Recents')
    for i in range(5):
        # Simulate two fast UP and DOWN swipes
        target.execute('input swipe {} {} {} {} 50'.format(x, yl, x, yh))
        sleep(0.3)
        target.execute('input swipe {} {} {} {} 50'.format(x, yh, x, yl))
        sleep(0.7)
    logging.info('Swiping Recents Completed')
    
    # Reset screen brightness and auto dimming
    Screen.set_defaults(target)

    # Get frame stats
    framestats_file = os.path.join(exp_dir, "framestats.txt")
    adb_command(target.adb_name, 'shell dumpsys gfxinfo com.android.systemui > {}'.format(framestats_file))
    
    # Close Recents
    target.execute('input keyevent KEYCODE_HOME')

    return framestats_file

In [10]:
def experiment(governor, exp_dir):
    os.system('mkdir -p {}'.format(exp_dir));

    logging.info('------------------------')
    logging.info('Run workload using %s governor', governor)
    confs[governor]['set']()
    
    # Start FTrace
    te.ftrace.start()
      
    ### Run the benchmark ###
    framestats_file = recentsfling_run(exp_dir)
    
    # Stop FTrace
    te.ftrace.stop()    

    # Collect and keep track of the trace
    trace_file = os.path.join(exp_dir, 'trace.dat')
    te.ftrace.get_trace(trace_file)
    
    # Parse trace
    tr = Trace(exp_dir,
               my_conf['ftrace']['events'],
               te.platform)
    
    # return all the experiment data
    return {
        'dir'             : exp_dir,
        'framestats_file' : framestats_file,
        'trace_file'      : trace_file,
        'ftrace'          : tr.ftrace,
        'trace'           : tr
    }

Run Flinger

Prepare Environment


In [11]:
N_APPS = 20

In [12]:
open_apps(N_APPS)

# Give apps enough time to open
sleep(5)


2016-12-09 14:59:08,075 INFO    : root         : Trying to open 8 apps...
2016-12-09 14:59:09,677 INFO    : root         :    1 starting com.android.settings...

Run workload and collect traces


In [13]:
# Unlock device screen (assume no password required)
target.execute('input keyevent 82')

# Run the benchmark in all the configured governors
for governor in confs:
    test_dir = os.path.join(te.res_dir, governor)
    results[governor] = experiment(governor, test_dir)


2016-12-09 14:59:18,399 INFO    : root         : ------------------------
2016-12-09 14:59:18,402 INFO    : root         : Run workload using performance governor
2016-12-09 14:59:20,895 INFO    : Screen       : Set brightness: 100%
2016-12-09 14:59:21,308 INFO    : Screen       : Dim screen mode: OFF
2016-12-09 14:59:21,782 INFO    : Screen       : Screen timeout: 36000 [s]
2016-12-09 14:59:27,693 INFO    : root         : Start Swiping Recents
2016-12-09 14:59:37,783 INFO    : root         : Swiping Recents Completed
2016-12-09 14:59:37,784 INFO    : Screen       : Set orientation: AUTO
2016-12-09 14:59:39,042 INFO    : Screen       : Set brightness: AUTO
2016-12-09 14:59:39,496 INFO    : Screen       : Dim screen mode: ON
2016-12-09 14:59:39,932 INFO    : Screen       : Screen timeout: 30 [s]
2016-12-09 14:59:45,387 INFO    : Trace        : Parsing FTrace format...
2016-12-09 14:59:53,031 INFO    : Trace        : Collected events spans a 21.305 [s] time interval
2016-12-09 14:59:53,031 INFO    : Trace        : Set plots time range to (0.000000, 21.305402)[s]
2016-12-09 14:59:53,032 INFO    : Analysis     : Registering trace analysis modules:
2016-12-09 14:59:53,033 INFO    : Analysis     :    tasks
2016-12-09 14:59:53,034 INFO    : Analysis     :    status
2016-12-09 14:59:53,034 INFO    : Analysis     :    frequency
2016-12-09 14:59:53,035 INFO    : Analysis     :    cpus
2016-12-09 14:59:53,036 INFO    : Analysis     :    latency
2016-12-09 14:59:53,037 INFO    : Analysis     :    idle
2016-12-09 14:59:53,038 INFO    : Analysis     :    functions
2016-12-09 14:59:53,038 INFO    : Analysis     :    eas
2016-12-09 14:59:53,051 INFO    : root         : ------------------------
2016-12-09 14:59:53,052 INFO    : root         : Run workload using sched governor
2016-12-09 14:59:56,256 INFO    : Screen       : Set brightness: 100%
2016-12-09 14:59:56,708 INFO    : Screen       : Dim screen mode: OFF
2016-12-09 14:59:57,303 INFO    : Screen       : Screen timeout: 36000 [s]
2016-12-09 15:00:03,345 INFO    : root         : Start Swiping Recents
2016-12-09 15:00:13,864 INFO    : root         : Swiping Recents Completed
2016-12-09 15:00:13,865 INFO    : Screen       : Set orientation: AUTO
2016-12-09 15:00:15,221 INFO    : Screen       : Set brightness: AUTO
2016-12-09 15:00:15,718 INFO    : Screen       : Dim screen mode: ON
2016-12-09 15:00:16,189 INFO    : Screen       : Screen timeout: 30 [s]
2016-12-09 15:00:27,259 INFO    : Trace        : Parsing FTrace format...
2016-12-09 15:00:35,017 INFO    : Trace        : Platform clusters verified to be Frequency coherent
2016-12-09 15:00:38,715 INFO    : Trace        : Collected events spans a 22.739 [s] time interval
2016-12-09 15:00:38,715 INFO    : Trace        : Set plots time range to (0.000000, 22.739051)[s]
2016-12-09 15:00:38,716 INFO    : Analysis     : Registering trace analysis modules:
2016-12-09 15:00:38,716 INFO    : Analysis     :    tasks
2016-12-09 15:00:38,717 INFO    : Analysis     :    status
2016-12-09 15:00:38,717 INFO    : Analysis     :    frequency
2016-12-09 15:00:38,718 INFO    : Analysis     :    cpus
2016-12-09 15:00:38,719 INFO    : Analysis     :    latency
2016-12-09 15:00:38,719 INFO    : Analysis     :    idle
2016-12-09 15:00:38,720 INFO    : Analysis     :    functions
2016-12-09 15:00:38,720 INFO    : Analysis     :    eas
2016-12-09 15:00:38,735 INFO    : root         : ------------------------
2016-12-09 15:00:38,736 INFO    : root         : Run workload using powersave governor
2016-12-09 15:00:49,017 INFO    : Screen       : Set brightness: 100%
2016-12-09 15:00:51,668 INFO    : Screen       : Dim screen mode: OFF
2016-12-09 15:00:54,328 INFO    : Screen       : Screen timeout: 36000 [s]
2016-12-09 15:01:03,584 INFO    : root         : Start Swiping Recents
2016-12-09 15:01:37,809 INFO    : root         : Swiping Recents Completed
2016-12-09 15:01:37,812 INFO    : Screen       : Set orientation: AUTO
2016-12-09 15:01:46,394 INFO    : Screen       : Set brightness: AUTO
2016-12-09 15:01:48,971 INFO    : Screen       : Dim screen mode: ON
2016-12-09 15:01:51,561 INFO    : Screen       : Screen timeout: 30 [s]
2016-12-09 15:02:17,487 INFO    : Trace        : Parsing FTrace format...
2016-12-09 15:02:33,993 INFO    : Trace        : Collected events spans a 75.655 [s] time interval
2016-12-09 15:02:33,994 INFO    : Trace        : Set plots time range to (0.000000, 75.654834)[s]
2016-12-09 15:02:33,994 INFO    : Analysis     : Registering trace analysis modules:
2016-12-09 15:02:33,995 INFO    : Analysis     :    tasks
2016-12-09 15:02:33,996 INFO    : Analysis     :    status
2016-12-09 15:02:33,996 INFO    : Analysis     :    frequency
2016-12-09 15:02:33,997 INFO    : Analysis     :    cpus
2016-12-09 15:02:33,997 INFO    : Analysis     :    latency
2016-12-09 15:02:33,998 INFO    : Analysis     :    idle
2016-12-09 15:02:33,998 INFO    : Analysis     :    functions
2016-12-09 15:02:33,999 INFO    : Analysis     :    eas
2016-12-09 15:02:34,022 INFO    : root         : ------------------------
2016-12-09 15:02:34,023 INFO    : root         : Run workload using ondemand governor
2016-12-09 15:02:41,668 INFO    : Screen       : Set brightness: 100%
2016-12-09 15:02:42,139 INFO    : Screen       : Dim screen mode: OFF
2016-12-09 15:02:42,656 INFO    : Screen       : Screen timeout: 36000 [s]
2016-12-09 15:02:48,429 INFO    : root         : Start Swiping Recents
2016-12-09 15:02:59,047 INFO    : root         : Swiping Recents Completed
2016-12-09 15:02:59,050 INFO    : Screen       : Set orientation: AUTO
2016-12-09 15:03:00,468 INFO    : Screen       : Set brightness: AUTO
2016-12-09 15:03:00,966 INFO    : Screen       : Dim screen mode: ON
2016-12-09 15:03:01,444 INFO    : Screen       : Screen timeout: 30 [s]
2016-12-09 15:03:12,685 INFO    : Trace        : Parsing FTrace format...
2016-12-09 15:03:21,734 INFO    : Trace        : Platform clusters verified to be Frequency coherent
2016-12-09 15:03:26,708 INFO    : Trace        : Collected events spans a 22.503 [s] time interval
2016-12-09 15:03:26,708 INFO    : Trace        : Set plots time range to (0.000000, 22.502716)[s]
2016-12-09 15:03:26,709 INFO    : Analysis     : Registering trace analysis modules:
2016-12-09 15:03:26,710 INFO    : Analysis     :    tasks
2016-12-09 15:03:26,710 INFO    : Analysis     :    status
2016-12-09 15:03:26,711 INFO    : Analysis     :    frequency
2016-12-09 15:03:26,711 INFO    : Analysis     :    cpus
2016-12-09 15:03:26,712 INFO    : Analysis     :    latency
2016-12-09 15:03:26,712 INFO    : Analysis     :    idle
2016-12-09 15:03:26,713 INFO    : Analysis     :    functions
2016-12-09 15:03:26,713 INFO    : Analysis     :    eas
2016-12-09 15:03:26,730 INFO    : root         : ------------------------
2016-12-09 15:03:26,731 INFO    : root         : Run workload using interactive governor
2016-12-09 15:03:29,716 INFO    : Screen       : Set brightness: 100%
2016-12-09 15:03:30,177 INFO    : Screen       : Dim screen mode: OFF
2016-12-09 15:03:30,645 INFO    : Screen       : Screen timeout: 36000 [s]
2016-12-09 15:03:36,422 INFO    : root         : Start Swiping Recents
2016-12-09 15:03:46,719 INFO    : root         : Swiping Recents Completed
2016-12-09 15:03:46,721 INFO    : Screen       : Set orientation: AUTO
2016-12-09 15:03:48,071 INFO    : Screen       : Set brightness: AUTO
2016-12-09 15:03:48,532 INFO    : Screen       : Dim screen mode: ON
2016-12-09 15:03:48,991 INFO    : Screen       : Screen timeout: 30 [s]
2016-12-09 15:03:55,795 INFO    : Trace        : Parsing FTrace format...
2016-12-09 15:04:06,933 INFO    : Trace        : Collected events spans a 21.791 [s] time interval
2016-12-09 15:04:06,934 INFO    : Trace        : Set plots time range to (0.000000, 21.791161)[s]
2016-12-09 15:04:06,934 INFO    : Analysis     : Registering trace analysis modules:
2016-12-09 15:04:06,935 INFO    : Analysis     :    tasks
2016-12-09 15:04:06,936 INFO    : Analysis     :    status
2016-12-09 15:04:06,936 INFO    : Analysis     :    frequency
2016-12-09 15:04:06,937 INFO    : Analysis     :    cpus
2016-12-09 15:04:06,938 INFO    : Analysis     :    latency
2016-12-09 15:04:06,938 INFO    : Analysis     :    idle
2016-12-09 15:04:06,939 INFO    : Analysis     :    functions
2016-12-09 15:04:06,939 INFO    : Analysis     :    eas

UI Performance Analysis


In [14]:
for governor in confs:
    framestats_file = results[governor]['framestats_file']
    print "Frame Statistics for {} governor".format(governor.upper())
    !sed '/Stats since/,/99th/!d;/99th/q' $framestats_file
    print ""


Frame Statistics for PERFORMANCE governor
Stats since: 22107824648ns
Total frames rendered: 10844
Janky frames: 550 (5.07%)
50th percentile: 6ms
90th percentile: 11ms
95th percentile: 16ms
99th percentile: 61ms

Frame Statistics for SCHED governor
Stats since: 22107824648ns
Total frames rendered: 11367
Janky frames: 555 (4.88%)
50th percentile: 6ms
90th percentile: 10ms
95th percentile: 16ms
99th percentile: 61ms

Frame Statistics for POWERSAVE governor
Stats since: 22107824648ns
Total frames rendered: 11500
Janky frames: 645 (5.61%)
50th percentile: 6ms
90th percentile: 11ms
95th percentile: 18ms
99th percentile: 61ms

Frame Statistics for ONDEMAND governor
Stats since: 22107824648ns
Total frames rendered: 11660
Janky frames: 661 (5.67%)
50th percentile: 6ms
90th percentile: 11ms
95th percentile: 18ms
99th percentile: 61ms

Frame Statistics for INTERACTIVE governor
Stats since: 22107824648ns
Total frames rendered: 12174
Janky frames: 661 (5.43%)
50th percentile: 6ms
90th percentile: 11ms
95th percentile: 17ms
99th percentile: 61ms