The goal of this experiment is to test out GMaps on a Pixel device running Android and collect results.
In [1]:
from conf import LisaLogging
LisaLogging.setup()
In [2]:
%pylab inline
import json
import os
# Support to access the remote target
import devlib
from env import TestEnv
# Import support for Android devices
from android import Screen, Workload
# Support for trace events analysis
from trace import Trace
# Suport for FTrace events parsing and visualization
import trappy
import pandas as pd
import sqlite3
from IPython.display import display
In [3]:
def experiment():
# Configure governor
target.cpufreq.set_all_governors('sched')
# Get workload
wload = Workload.getInstance(te, 'GMaps')
# Run GMaps
wload.run(out_dir=te.res_dir,
collect="ftrace",
location_search="London British Museum",
swipe_count=10)
# Dump platform descriptor
te.platform_dump(te.res_dir)
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 [4]:
# Setup target configuration
my_conf = {
# Target platform and board
"platform" : 'android',
"board" : 'pixel',
# Device serial ID
# Not required if there is only one device connected to your computer
"device" : "HT67M0300128",
# Android home
# Not required if already exported in your .bashrc
"ANDROID_HOME" : "/home/vagrant/lisa/tools/",
# Folder where all the results will be collected
"results_dir" : "Gmaps_example",
# 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_wakeup",
"sched_wakeup_new",
"sched_overutilized",
"sched_load_avg_cpu",
"sched_load_avg_task",
"sched_load_waking_task",
"cpu_capacity",
"cpu_frequency",
"cpu_idle",
"sched_tune_config",
"sched_tune_tasks_update",
"sched_tune_boostgroup_update",
"sched_tune_filter",
"sched_boost_cpu",
"sched_boost_task",
"sched_energy_diff"
],
"buffsize" : 100 * 1024,
},
# Tools required by the experiments
"tools" : [ 'trace-cmd', 'taskset'],
}
In [5]:
# Initialize a test environment using:
te = TestEnv(my_conf, wipe=False)
target = te.target
In [6]:
results = experiment()
For more information on this please check examples/trace_analysis/TraceAnalysis_TasksLatencies.ipynb.
In [7]:
# Load traces in memory (can take several minutes)
platform_file = os.path.join(te.res_dir, 'platform.json')
with open(platform_file, 'r') as fh:
platform = json.load(fh)
trace_file = os.path.join(te.res_dir, 'trace.dat')
trace = Trace(trace_file, my_conf['ftrace']['events'], platform, normalize_time=False)
In [8]:
# Find exact task name & PID
for pid, name in trace.getTasks().iteritems():
if "GLRunner" in name:
glrunner = {"pid" : pid, "name" : name}
print("name=\"" + glrunner["name"] + "\"" + " pid=" + str(glrunner["pid"]))
In this example we are looking at a specific task : GLRunner. GLRunner is a very CPU-heavy task, and is also boosted (member of the top-app group) in EAS, which makes it an interesting task to study.
To study the behaviour of GLRunner, we'll be looking at the wakeup decisions of the scheduler. We'll be looking for times at which the task took "too long" to wake up, i.e it was runnable and had to wait some time to actually be run. In our case that latency treshold is (arbitrarily) set to 1ms.
We're also on the lookout for when the task has been moved from one CPU to another. Depending on several parameters (kernel version, boost values, etc), the task could erroneously be switched to another CPU which could induce wakeup latencies.
Finally, we're only interested in scheduling decisions made by EAS, so we'll only be looking at wakeup latencies that occured when the system was not overutilized, i.e EAS was enabled.
In [9]:
# Helper functions to pinpoint issues
def find_prev_cpu(trace, taskname, time):
sdf = trace.data_frame.trace_event('sched_switch')
sdf = sdf[sdf.prev_comm == taskname]
sdf = sdf[sdf.index <= time]
sdf = sdf.tail(1)
wdf = trace.data_frame.trace_event('sched_wakeup')
wdf = wdf[wdf.comm == taskname]
wdf = wdf[wdf.index <= time]
# We're looking for the previous wake event,
# not the one related to the wake latency
wdf = wdf.tail(2)
stime = sdf.index[0]
wtime = wdf.index[1]
if stime > wtime:
res = wdf["target_cpu"].values[0]
else:
res = sdf["__cpu"].values[0]
return res
def find_next_cpu(trace, taskname, time):
wdf = trace.data_frame.trace_event('sched_wakeup')
wdf = wdf[wdf.comm == taskname]
wdf = wdf[wdf.index <= time].tail(1)
return wdf["target_cpu"].values[0]
def trunc(value, precision):
offset = pow(10, precision)
res = int(value * offset)
return float(res) / offset
In [10]:
# Look for latencies > 1 ms
df = trace.data_frame.latency_wakeup_df(glrunner["pid"])
df = df[df.wakeup_latency > 0.001]
# Load times at which system was overutilized (EAS disabled)
ou_df = trace.data_frame.overutilized()
In [11]:
# Find which wakeup latencies were induced by EAS
# Times to look at will be saved in a times.txt file
eas_latencies = []
times_file = te.res_dir + "/times.txt"
!touch {times_file}
for time, cols in df.iterrows():
# Check if cpu was over-utilized (EAS disabled)
ou_row = ou_df[:time].tail(1)
if ou_row.empty:
continue
was_eas = ou_row.iloc[0, 1] < 1.0
if (was_eas):
toprint = "{:.1f}ms @ {}".format(cols[0] * 1000, trunc(time, 5))
next_cpu = find_next_cpu(trace, glrunner["name"], time)
prev_cpu = find_prev_cpu(trace, glrunner["name"], time)
if (next_cpu != prev_cpu):
toprint += " [CPU SWITCH]"
print toprint
eas_latencies.append([time, cols[0]])
!echo {toprint} >> {times_file}
For more information on this please check examples/trace_analysis/TraceAnalysis_TasksLatencies.ipynb.
Here each latency is plotted in order to double-check that it was truly induced by an EAS decision. In LISA, the latency plots have a red background when the system is overutilized, which shouldn't be the case here.
In [12]:
# Plot each EAS-induced latency (blue cross)
# If the background is red, system was over-utilized and the latency wasn't caused by EAS
for start, latency in eas_latencies:
trace.setXTimeRange(start - 0.002, start + 0.002)
trace.analysis.latency.plotLatency(task=glrunner["pid"], tag=str(start))
trace.analysis.cpus.plotCPU(cpus=[2,3])
This plot displays the whole duration of the experiment, it can be used to see how often the system was overutilized or how much latency was involved.
In [13]:
# Plots all of the latencies over the duration of the experiment
trace.setXTimeRange(trace.window[0] + 1, trace.window[1])
trace.analysis.latency.plotLatency(task=glrunner["pid"])
Out[13]:
In [15]:
!kernelshark {trace_file} 2>/dev/null