diff --git a/get_wlat.py b/get_wlat.py new file mode 100755 index 0000000000000000000000000000000000000000..db54dc8366a9a2123d1b4ea12343097a67010315 --- /dev/null +++ b/get_wlat.py @@ -0,0 +1,144 @@ +#!/usr/bin/env python + +from collections import namedtuple +import trappy + +EventRow = namedtuple('EventRow', ['time', 'event', 'row']) +LatRow = namedtuple('LatRow', ['pid', 'switch_row', 'wake_row', 'last_wake_row', 'running', 'wake_pend', 'latency']) + +def print_event_rows(rows, start, end): + print "time".ljust(20) + "\t" + "event".ljust(10) + "\tpid" + "\tprevpid" + "\tnextpid" + for r in rows: + if r.time < start or r.time > end: + continue + if r.event == "switch": + nextpid = r.row['next_pid'] + prevpid = r.row['prev_pid'] + pid = -1 + elif r.event == "wake": + pid = r.row['pid'] + nextpid = -1 + prevpid = -1 + else: + raise RuntimeError("unknown event seen") + print str(r.time).ljust(20)[:20] + "\t" + r.event.ljust(10) + "\t" + str(pid) + "\t" + str(prevpid) + "\t" + str(nextpid) + +path_to_html = "/home/joelaf/repo/catapult/systrace/trace_sf-dispsync_rt_pull_fail_1504ms.html" + +systrace_obj = trappy.SysTrace(name="systrace", path=path_to_html, \ + scope="sched", events=["sched_switch", + "sched_wakeup", "sched_waking"]) + +df = systrace_obj.sched_switch.data_frame +# df = df[(df.next_prio < 100) | (df.prev_prio < 100)] +switch_df = df + +df = systrace_obj.sched_wakeup.data_frame +# df = df[df.prio < 100] +wake_df = df + +# Build list of rows +switch_rows = [EventRow(time=i, event="switch", row=row) for i, row in switch_df.iterrows()] +wake_rows = [EventRow(time=i, event="wake", row=row) for i, row in wake_df.iterrows()] +rows = switch_rows + wake_rows +rows = sorted(rows, key=lambda r: r.time) + +# Hash table of pid -> LatRow named tuple +latpids = {} + +for r in rows: + # a df row has a key which is the timestamp and a value which + # is of dtype object which has the trace event fields + row = r.row + event = r.event + time = r.time + + debug = False + dpid = 21047 + + if event == "switch": + prevpid = row['prev_pid'] + nextpid = row['next_pid'] + + debug = debug and (prevpid == dpid or nextpid == dpid) + + if (debug): + print "\nProcessing switch nextpid=" + str(nextpid) + " prevpid=" + str(prevpid) +\ + " time=" + str(time) + + # prev pid processing (switch out) + if latpids.has_key(prevpid): + if latpids[prevpid].running == 1: + latpids[prevpid] = latpids[prevpid]._replace(running=0) + if latpids[prevpid].wake_pend == 1: + print "Impossible: switch out during wake_pend " + str(r) + raise RuntimeError("error") + + if not latpids.has_key(nextpid): + continue + + # nextpid processing (switch in) + pid = nextpid + + if latpids[pid].running == 1: + print "INFO: previous pid switch-out not seen for an event, ignoring\n" + str(r) + continue + + latpids[pid] = latpids[pid]._replace(running=1) + + # Ignore latency calc for next-switch events for which wake never seen + # They are still valid in this scenario because of preemption + if latpids[pid].wake_pend == 0: + if debug: + print "wake_pend = 0, doing nothing" + continue + + # Measure latency + lat = time - latpids[pid].last_wake_row.time + + if lat > latpids[pid].latency: + if debug: + print "recording" + latpids[pid] = LatRow(pid, switch_row = r, + wake_row = latpids[pid].last_wake_row, + last_wake_row=None, latency=lat, running=1, wake_pend=0) + continue + if debug: + print "recording" + latpids[pid] = latpids[pid]._replace(running=1, wake_pend=0) + elif event == "wake": + pid = row["pid"] + debug = debug and (pid == dpid) + if (debug): + print "\nProcessing wake pid=" + str(pid) + " time=" + str(time) + if not latpids.has_key(pid): + latpids[pid] = LatRow(pid, switch_row=None, wake_row=None, + last_wake_row = r, running=0, latency=-1, wake_pend=1) + if debug: + print "new wakeup" + continue + if latpids[pid].running == 1 or latpids[pid].wake_pend == 1: + if debug: + print "already running or wake_pend" + # Task already running or a wakeup->switch pending, ignore + continue + if debug: + print "recording wake" + latpids[pid] = latpids[pid]._replace(last_wake_row = r, wake_pend=1) + else: + errmsg = "Parsing error: Unknown trace event in EventRow (" + str(event) + ")" + raise RuntimeError(errmsg) + +# Print PID, latency, start, end, sort +result = sorted(latpids.items(), key=lambda x: x[1].latency, reverse=True) + +print "PID".ljust(10) + "\t" + "name".ljust(20) + "\t" + "latency (secs)".ljust(20) + \ + "\t" + "start time".ljust(20) + "\t" + "end time".ljust(20) +for r in result: + l = r[1] # LatRow named tuple + if l.pid != r[0]: + raise RuntimeError("BUG: pid inconsitency found") # Sanity check + print str(r[0]).ljust(10) + "\t" + str(l.wake_row.row['comm']).ljust(20) + "\t" + \ + str(l.latency).ljust(20)[:20] + "\t" + str(l.wake_row.time).ljust(20)[:20] + \ + "\t" + str(l.switch_row.time).ljust(20)[:20] + diff --git a/get_wlat_cbs.py b/get_wlat_cbs.py new file mode 100755 index 0000000000000000000000000000000000000000..2ed6490275c309b76e56d1a8f5560997798bed49 --- /dev/null +++ b/get_wlat_cbs.py @@ -0,0 +1,154 @@ +#!/usr/bin/env python + +from collections import namedtuple +import trappy + +EventData = namedtuple('EventData', ['time', 'event', 'data']) +LatData = namedtuple('LatData', ['pid', 'switch_data', 'wake_data', 'last_wake_data', 'running', 'wake_pend', 'latency']) + +# path_to_html = "/home/joelaf/repo/catapult/systrace/trace_sf-dispsync_rt_pull_fail_1504ms.html" +# path_to_html = "/home/joelaf/Downloads/trace_sf_late_wakeup_ipi.html" +path_to_html = "/home/joelaf/repo/lisa/results/ChromeMonkey/trace.html" + +# Hash table of pid -> LatData named tuple +latpids = {} + +# Debugging aids for debugging within the callbacks +dpid = 21047 +debugg = False + +normalize = False # Normalize with the base timestamp +printrows = False # Debug aid to print all switch and wake events in a time range + +switch_events = [] +wake_events = [] +basetime = None + +def switch_cb(time, data): + event = "switch" + prevpid = data['prev_pid'] + nextpid = data['next_pid'] + + # print str(time) + ": " + str(data) + + global basetime, switch_events + basetime = time if (normalize and not basetime) else basetime + time = time - basetime if normalize else time + + e = EventData(time, event, data) + if printrows: + switch_events.append(e) + + debug = debugg and (prevpid == dpid or nextpid == dpid) + if debug: print ("\nProcessing switch nextpid=" + str(nextpid) + " prevpid=" + str(prevpid) + \ + " time=" + str(time)) + + # prev pid processing (switch out) + if latpids.has_key(prevpid): + if latpids[prevpid].running == 1: + latpids[prevpid] = latpids[prevpid]._replace(running=0) + if latpids[prevpid].wake_pend == 1: + print "Impossible: switch out during wake_pend " + str(e) + raise RuntimeError("error") + + if not latpids.has_key(nextpid): + return + + # nextpid processing (switch in) + pid = nextpid + if latpids[pid].running == 1: + print "INFO: previous pid switch-out not seen for an event, ignoring\n" + str(e) + return + latpids[pid] = latpids[pid]._replace(running=1) + + # Ignore latency calc for next-switch events for which wake never seen + # They are still valid in this scenario because of preemption + if latpids[pid].wake_pend == 0: + if debug: print "wake_pend = 0, doing nothing" + return + + if debug: print "recording" + # Measure latency + lat = time - latpids[pid].last_wake_data.time + if lat > latpids[pid].latency: + latpids[pid] = LatData(pid, switch_data = e, + wake_data = latpids[pid].last_wake_data, + last_wake_data=None, latency=lat, running=1, wake_pend=0) + return + latpids[pid] = latpids[pid]._replace(running=1, wake_pend=0) + +def wake_cb(time, data): + event = "wake" + pid = data["pid"] + debug = debugg and (pid == dpid) + + global basetime, wake_events + basetime = time if (normalize and not basetime) else basetime + time = time - basetime if normalize else time + + e = EventData(time, event, data) + wake_events.append(e) + + if data["prio"] > 99: + return + + if debug: print "\nProcessing wake pid=" + str(pid) + " time=" + str(time) + if not latpids.has_key(pid): + latpids[pid] = LatData(pid, switch_data=None, wake_data=None, + last_wake_data = e, running=0, latency=-1, wake_pend=1) + if debug: print "new wakeup" + return + + if latpids[pid].running == 1 or latpids[pid].wake_pend == 1: + if debug: print "already running or wake_pend" + # Task already running or a wakeup->switch pending, ignore + return + + if debug: print "recording wake" + latpids[pid] = latpids[pid]._replace(last_wake_data = e, wake_pend=1) + +systrace_obj = trappy.SysTrace(name="systrace", path=path_to_html, \ + scope="sched", events=["sched_switch", "sched_wakeup", "sched_waking"], + event_callbacks={ "sched_switch": switch_cb, "sched_wakeup": wake_cb, + "sched_waking": wake_cb }, + build_df=False, normalize_time=False) + +# Print the results: PID, latency, start, end, sort +result = sorted(latpids.items(), key=lambda x: x[1].latency, reverse=True) +print "PID".ljust(10) + "\t" + "name".ljust(20) + "\t" + "latency (secs)".ljust(20) + \ + "\t" + "start time".ljust(20) + "\t" + "end time".ljust(20) +for r in result[:20]: + l = r[1] # LatData named tuple + if l.pid != r[0]: + raise RuntimeError("BUG: pid inconsitency found") # Sanity check + wake_time = l.wake_data.time + switch_time = l.switch_data.time + + print str(r[0]).ljust(10) + "\t" + str(l.wake_data.data['comm']).ljust(20) + "\t" + \ + str(l.latency).ljust(20)[:20] + "\t" + str(wake_time).ljust(20)[:20] + \ + "\t" + str(switch_time).ljust(20)[:20] + +############################################################# +## Debugging aids to print all events in a given time range # +############################################################# +def print_event_rows(events, start, end): + print "time".ljust(20) + "\t" + "event".ljust(10) + "\tpid" + "\tprevpid" + "\tnextpid" + for e in events: + if e.time < start or e.time > end: + continue + if e.event == "switch": + nextpid = e.data['next_pid'] + prevpid = e.data['prev_pid'] + pid = -1 + elif e.event == "wake": + pid = e.data['pid'] + nextpid = -1 + prevpid = -1 + else: + raise RuntimeError("unknown event seen") + print str(e.time).ljust(20)[:20] + "\t" + e.event.ljust(10) + "\t" + str(pid) + "\t" + str(prevpid) + "\t" + str(nextpid) + +if printrows: + rows = switch_events + wake_events + rows = sorted(rows, key=lambda r: r.time) + print_event_rows(rows, 1.1, 1.2) diff --git a/libs/utils/android/screen.py b/libs/utils/android/screen.py index af80a5f07e7e0c7492fecf09506691d94e400e97..971760660c46b73ff61b08aa7162324845549757 100644 --- a/libs/utils/android/screen.py +++ b/libs/utils/android/screen.py @@ -16,6 +16,7 @@ # import logging +from system import System class Screen(object): """ @@ -136,4 +137,20 @@ class Screen(object): """ return target.execute('getprop ro.sf.lcd_density') + @staticmethod + def set_screen(target, on=True): + log = logging.getLogger('Screen') + if not on: + log.info('Setting screen OFF') + System.sleep(target) + return + log.info('Setting screen ON') + System.wakeup(target) + + @staticmethod + def unlock(target): + Screen.set_screen(target, on=True) + System.menu(target) + System.home(target) + # vim :set tabstop=4 shiftwidth=4 expandtab diff --git a/libs/utils/android/system.py b/libs/utils/android/system.py index 42e8c4dec7516ea88b6011d7bedb357baa55a72f..b9f7423d8cc042deef1f976b091c0e172e991131 100644 --- a/libs/utils/android/system.py +++ b/libs/utils/android/system.py @@ -31,7 +31,7 @@ class System(object): @staticmethod def systrace_start(target, trace_file, time=None, - events=['gfx', 'view', 'sched', 'freq', 'idle']): + events=['irq', 'sched'], bufsize=None): log = logging.getLogger('System') @@ -53,6 +53,9 @@ class System(object): if time is not None: trace_cmd += " -t {}".format(time) + if bufsize is not None: + trace_cmd += " -b {}".format(bufsize) + log.info('SysTrace: %s', trace_cmd) # Actually spawn systrace @@ -254,6 +257,26 @@ class System(object): """ target.execute('input keyevent KEYCODE_BACK') + @staticmethod + def wakeup(target): + """ + Wake up the system if its sleeping + + :param target: instance of devlib Android target + :type target: devlib.target.AndroidTarget + """ + target.execute('input keyevent KEYCODE_WAKEUP') + + @staticmethod + def sleep(target): + """ + Make system sleep if its awake + + :param target: instance of devlib Android target + :type target: devlib.target.AndroidTarget + """ + target.execute('input keyevent KEYCODE_SLEEP') + @staticmethod def gfxinfo_reset(target, apk_name): """ @@ -285,7 +308,7 @@ class System(object): GET_FRAMESTATS_CMD.format(apk_name, out_file)) @staticmethod - def monkey(target, apk_name, event_count=1): + def monkey(target, apk_name, event_count=1, check_exit_code=True, timeout=None): """ Wrapper for adb monkey tool. @@ -308,7 +331,11 @@ class System(object): :param event_count: number of events to generate :type event_count: int """ - target.execute('monkey -p {} {}'.format(apk_name, event_count)) + if timeout: + target.execute('timeout {} monkey -p {} {}'.format(timeout, apk_name, event_count), + check_exit_code=check_exit_code) + return + target.execute('monkey -p {} {}'.format(apk_name, event_count), check_exit_code=check_exit_code) @staticmethod def list_packages(target, apk_filter=''): diff --git a/libs/utils/android/workload.py b/libs/utils/android/workload.py index 626b65d501df675cf85f668540eb26a570539430..36caceae56a876566e4703d2ca10a790d37973c6 100644 --- a/libs/utils/android/workload.py +++ b/libs/utils/android/workload.py @@ -87,7 +87,7 @@ class Workload(object): **kwargs): raise RuntimeError('Not implemeted') - def tracingStart(self): + def tracingStart(self, bufsize=None): if 'ftrace' in self.collect and 'systrace' in self.collect: msg = 'ftrace and systrace cannot be used at the same time' raise ValueError(msg) @@ -104,7 +104,12 @@ class Workload(object): self._trace_time = match.group(1) if match else None self._log.info('Systrace START') self._systrace_output = System.systrace_start( - self._te, self.trace_file, self._trace_time) + self._te, self.trace_file, self._trace_time, bufsize=bufsize) + elif 'monsoon' in self.collect: + self._target.execute('svc power stayon usb') + self._target.execute('echo 0 > /sys/class/power_supply/battery/charging_enabled') + monsout = os.path.join(self.out_dir, 'monsoon.txt') + os.system("~/repo/monsoon/monsoon.par --timestamp --hz 5 --samples 300 > " + monsout) # Initialize energy meter results if 'energy' in self.collect and self._te.emeter: self._te.emeter.reset() diff --git a/libs/utils/android/workloads/chromemonkey.py b/libs/utils/android/workloads/chromemonkey.py new file mode 100644 index 0000000000000000000000000000000000000000..349b0efec59eeda2be3850b412a7e657f018f70d --- /dev/null +++ b/libs/utils/android/workloads/chromemonkey.py @@ -0,0 +1,67 @@ +# SPDX-License-Identifier: Apache-2.0 +# +# Copyright (C) 2015, ARM Limited and contributors. +# +# 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. +# + +import re +import os +import logging + +from android import Screen, System, Workload + +class ChromeMonkey(Workload): + """ + Android Chrome monkey tests workload + """ + + # Package required by this workload + package = 'com.android.chrome' + + def __init__(self, test_env): + super(ChromeMonkey, self).__init__(test_env) + self._log = logging.getLogger('ChromeMonkey') + self._log.debug('Workload created') + + def run(self, out_dir, duration_s, collect='', bufsize=10000): + """ + Run Chrome with random events from monkey. Useful to diagnose/trace + UI related issues. + + :param out_dir: Path to experiment directory where to store results. + :type out_dir: str + + :param collect: Specifies what to collect. Possible values: + - 'sched' + - 'systrace' + - 'ftrace' + - any combination of the above + :type collect: list(str) + """ + + # Keep track of mandatory parameters + self.out_dir = out_dir + self.collect = collect + + # Unlock device screen (assume no password required) + Screen.unlock(self._target) + + self.tracingStart(bufsize) + + # Use the monkey tool + self._log.info('Running monkey for %d [s]', duration_s) + System.monkey(self._target, self.package, event_count=100000, timeout=duration_s, + check_exit_code=False) + + self.tracingStop() diff --git a/libs/utils/android/workloads/gmaps.py b/libs/utils/android/workloads/gmaps.py index 380686d48d967b3bbde7f8dc80d2916d2cf8869a..838f5cf0e7e5db5b5f327a0d0b4870a89a58db70 100644 --- a/libs/utils/android/workloads/gmaps.py +++ b/libs/utils/android/workloads/gmaps.py @@ -70,9 +70,7 @@ class GMaps(Workload): # Set min brightness Screen.set_brightness(self._target, auto=False, percent=0) # Unlock device screen (assume no password required) - System.menu(self._target) - # Press Back button to be sure we run the video from the start - System.back(self._target) + Screen.unlock(self._target) # Use the monkey tool to start GMaps # This allows to subsequently set the screen orientation to LANDSCAPE diff --git a/libs/utils/android/workloads/jankbench.py b/libs/utils/android/workloads/jankbench.py index fcf76e8a00640b8ffff194147e95fc799374e244..5d17ded927292095f7d8cf0d96c5c99203632a05 100644 --- a/libs/utils/android/workloads/jankbench.py +++ b/libs/utils/android/workloads/jankbench.py @@ -102,9 +102,8 @@ class Jankbench(Workload): except KeyError: raise ValueError('Jankbench test [%s] not supported', test_name) - # Make sure we exit the app if already open - System.menu(self._target) - System.back(self._target) + # Unlock device screen (assume no password required) + Screen.unlock(self._target) # Close and clear application System.force_stop(self._target, self.package, clear=True) diff --git a/libs/utils/android/workloads/uibench.py b/libs/utils/android/workloads/uibench.py index bdba69fa88fbf17cbc0e654c293d14585b963b1f..3b24030ee235213d4f700f90ce712eca2d7bc0d0 100755 --- a/libs/utils/android/workloads/uibench.py +++ b/libs/utils/android/workloads/uibench.py @@ -85,9 +85,8 @@ class UiBench(Workload): self.out_dir = out_dir self.collect = collect - # Press Back button to be sure we run the video from the start - System.menu(self._target) - System.back(self._target) + # Unlock device screen (assume no password required) + Screen.unlock(self._target) # Close and clear application System.force_stop(self._target, self.package, clear=True) diff --git a/libs/utils/android/workloads/vellamo.py b/libs/utils/android/workloads/vellamo.py index 476266efa0959ac109917e836abd1b2f6d5e9412..c8863e8d2a0be714175262dc7d6d5886dcd7a899 100644 --- a/libs/utils/android/workloads/vellamo.py +++ b/libs/utils/android/workloads/vellamo.py @@ -94,8 +94,7 @@ class Vellamo(Workload): sleep_time = 3.5 # Unlock device screen (assume no password required) - System.menu(self._target) - System.back(self._target) + Screen.unlock(self._target) System.force_stop(self._target, self.package, clear=True) diff --git a/libs/utils/android/workloads/youtube.py b/libs/utils/android/workloads/youtube.py index a2461926e59344a7849296c27329271283658cf4..cdfbf2d0462207c3fbf5cc7e1088a272ae34a75a 100644 --- a/libs/utils/android/workloads/youtube.py +++ b/libs/utils/android/workloads/youtube.py @@ -66,9 +66,10 @@ class YouTube(Workload): self.collect = collect # Unlock device screen (assume no password required) - System.menu(self._target) - # Press Back button to be sure we run the video from the start - System.back(self._target) + Screen.unlock(self._target) + + # Stop youtube if already running + System.force_stop(self._target, self.package) # Use the monkey tool to start YouTube without playing any video. # This allows to subsequently set the screen orientation to LANDSCAPE diff --git a/libs/utils/energy.py b/libs/utils/energy.py index 9e78f45cff9789eae46b514b971f8f6963867598..f3753da97aced44f9ed9e33131b625d459167214 100644 --- a/libs/utils/energy.py +++ b/libs/utils/energy.py @@ -18,9 +18,12 @@ import devlib import json import os +import os.path import psutil import time import logging +from subprocess import Popen, STDOUT +from threading import Timer from collections import namedtuple from subprocess import Popen, PIPE, STDOUT @@ -118,6 +121,58 @@ class EnergyMeter(object): def report(self, out_dir): raise NotImplementedError('Missing implementation') +class Monsoon(EnergyMeter): + def print_log(self, errmsg, exception=0): + print errmsg + self._log.error(errmsg) + if exception == 1: + raise(Exception(errmsg)) + + def __init__(self, target, conf=None): + super(Monsoon, self).__init__(target, '') + + # Read config + # { 'config': { 'device_entry' : '/dev/ttyACM1', 'voltage' : 4.3 } } + try: + device_entry = conf['config']['device_entry'] + self.voltage = conf['config']['voltage'] + except: + device_entry = None + self.voltage = 4.3 + self._log.info("Invalid conf, using defaults. Example format is \ + { 'config': { 'device_entry' : '/dev/ttyACM1', 'voltage' : 4.3 }") + self._monsoon = devlib.MonsoonInstrument(self._target, device_entry) + + def reset_only(self): + m = self._monsoon + self._log.info('Initiailzing Monsoon') + # Waiting for monsoon to get ready + m.get_status() + # Provide power to the target + m.set_voltage(0) + m.set_current(8) + m.set_start_current(8) + m.set_voltage(self.voltage) + self._log.info("Monsoon ready for action") + + # Start a monsoon run asynchronously + def reset(self): + m = self._monsoon + self.reset_only() + m.start() + + # Kill an already running test and report in panda dataframes + def report(self): + return self._monsoon.report() + + # This is synchronous (block until duration) + def get_samples(self, duration): + return self._monsoon.get_samples_sync(duration) + + # Returns csv text output synchronously - function not typically used directly + def run_monsoon(self, args, stream=0, timeout=5): + return self._monsoon.run_monsoon(args, stream, timeout) + class HWMon(EnergyMeter): def __init__(self, target, conf=None, res_dir=None):