Run Generic Automated EAS tests

This is a starting-point notebook for running tests from the generic EAS suite in tests/eas/generic.py. The test classes that are imported here provide helper methods to aid analysis of the cause of failure. You can use Python's help built-in to find those methods (or you can just read the docstrings in the code).

These tests make estimation of the energy efficiency of task placements, without directly examining the behaviour of cpufreq or cpuidle. Several test classes are provided, the only difference between them being the workload that is used.

Setup


In [1]:
%load_ext autoreload
%autoreload 2
%matplotlib inline

import logging
from conf import LisaLogging
LisaLogging.setup()#level=logging.WARNING)

import pandas as pd

from perf_analysis import PerfAnalysis

import trappy
from trappy import ILinePlot
from trappy.stats.grammar import Parser


2017-01-23 18:50:17,847 INFO    : root         : Using LISA logging configuration:
2017-01-23 18:50:17,847 INFO    : root         :   /home/brendan/sources/lisa/logging.conf

Run test workload

If you simply want to run all the tests and get pass/fail results, use this command in the LISA shell: lisa-test tests/eas/generic.py. This notebook is intended as a starting point for analysing what scheduler behaviour was judged to be faulty.

Target configuration is taken from $LISA_HOME/target.config - you'll need to edit that file to provide connection details for the target you want to test.


In [2]:
from tests.eas.generic import TwoBigTasks, TwoBigThreeSmall, RampUp, RampDown, EnergyModelWakeMigration, OneSmallTask

By default we'll run the EnergyModelWakeMigration test, which runs a workload alternating between high and low-intensity. All the other test classes shown above have the same interface, but run different workloads. To run the tests on different workloads, change this line below:


In [ ]:
t = EnergyModelWakeMigration(methodName="test_task_placement")
print t.__doc__


    Test EAS for tasks alternating beetween 10% and 50%
    

In [ ]:
t.setUpClass()


2017-01-23 18:50:18,176 INFO    : LisaTest     : Setup tests execution engine...
2017-01-23 18:50:18,178 INFO    : TestEnv      : Using base path: /home/brejac01/sources/lisa
2017-01-23 18:50:18,178 INFO    : TestEnv      : Loading default (file) target configuration
2017-01-23 18:50:18,179 INFO    : TestEnv      : Loading target configuration [/home/brejac01/sources/lisa/target.config]...
2017-01-23 18:50:18,181 INFO    : TestEnv      : Loading custom (inline) test configuration
2017-01-23 18:50:18,182 INFO    : TestEnv      : Devlib modules to load: ['bl', u'cpuidle', 'cgroups', 'cpufreq']
2017-01-23 18:50:18,183 INFO    : TestEnv      : Connecting linux target:
2017-01-23 18:50:18,184 INFO    : TestEnv      :   username : brendan
2017-01-23 18:50:18,185 INFO    : TestEnv      :       host : 192.168.2.2
2017-01-23 18:50:18,186 INFO    : TestEnv      :   password : password
2017-01-23 18:50:18,187 INFO    : TestEnv      : Connection settings:
2017-01-23 18:50:18,188 INFO    : TestEnv      :    {'username': u'brendan', 'host': u'192.168.2.2', 'password': u'password'}
2017-01-23 18:50:25,803 INFO    : TestEnv      : Initializing target workdir:
2017-01-23 18:50:25,805 INFO    : TestEnv      :    /home/brendan/devlib-target
2017-01-23 18:50:29,349 INFO    : CGroups      : Available controllers:
2017-01-23 18:50:31,076 INFO    : CGroups      :   schedtune    : /home/brendan/devlib-target/cgroups/devlib_cgh2
2017-01-23 18:50:31,749 INFO    : TestEnv      : Topology:
2017-01-23 18:50:31,751 INFO    : TestEnv      :    [[0, 3, 4, 5], [1, 2]]
2017-01-23 18:50:34,373 INFO    : TestEnv      : Loading default EM:
2017-01-23 18:50:34,374 INFO    : TestEnv      :    /home/brejac01/sources/lisa/libs/utils/platforms/juno.json
2017-01-23 18:50:36,104 INFO    : TestEnv      : Enabled tracepoints:
2017-01-23 18:50:36,106 INFO    : TestEnv      :    sched_overutilized
2017-01-23 18:50:36,107 INFO    : TestEnv      :    sched_energy_diff
2017-01-23 18:50:36,108 INFO    : TestEnv      :    sched_load_avg_task
2017-01-23 18:50:36,109 INFO    : TestEnv      :    sched_load_avg_cpu
2017-01-23 18:50:36,110 INFO    : TestEnv      :    sched_migrate_task
2017-01-23 18:50:36,111 INFO    : TestEnv      :    sched_switch
2017-01-23 18:50:36,112 INFO    : TestEnv      :    cpu_frequency
2017-01-23 18:50:36,114 INFO    : EnergyMeter  : HWMON module not enabled
2017-01-23 18:50:36,115 WARNING : EnergyMeter  : Energy sampling disabled by configuration
2017-01-23 18:50:36,116 INFO    : TestEnv      : Set results folder to:
2017-01-23 18:50:36,117 INFO    : TestEnv      :    /home/brejac01/sources/lisa/results/20170123_185036
2017-01-23 18:50:36,118 INFO    : TestEnv      : Experiment results available also in:
2017-01-23 18:50:36,119 INFO    : TestEnv      :    /home/brejac01/sources/lisa/results_latest
2017-01-23 18:50:36,121 INFO    : Executor     : Loading custom (inline) test configuration
2017-01-23 18:50:36,121 INFO    : Executor     : 
2017-01-23 18:50:36,123 INFO    : Executor     : ################################################################################
2017-01-23 18:50:36,124 INFO    : Executor     : Experiments configuration
2017-01-23 18:50:36,125 INFO    : Executor     : ################################################################################
2017-01-23 18:50:36,126 INFO    : Executor     : Configured to run:
2017-01-23 18:50:36,127 INFO    : Executor     :      1 target configurations:
2017-01-23 18:50:36,128 INFO    : Executor     :       energy_aware
2017-01-23 18:50:36,129 INFO    : Executor     :      1 workloads (1 iterations each)
2017-01-23 18:50:36,130 INFO    : Executor     :       wake_migration
2017-01-23 18:50:36,131 INFO    : Executor     : Total: 1 experiments
2017-01-23 18:50:36,132 INFO    : Executor     : Results will be collected under:
2017-01-23 18:50:36,133 INFO    : Executor     :       /home/brejac01/sources/lisa/results/20170123_185036
2017-01-23 18:50:36,134 INFO    : Executor     : rt-app workloads found, installing tool on target
2017-01-23 18:50:38,252 INFO    : LisaTest     : Experiments execution...
2017-01-23 18:50:38,254 INFO    : Executor     : 
2017-01-23 18:50:38,255 INFO    : Executor     : ################################################################################
2017-01-23 18:50:38,256 INFO    : Executor     : Experiments execution
2017-01-23 18:50:38,257 INFO    : Executor     : ################################################################################
2017-01-23 18:50:38,258 INFO    : Executor     : 
2017-01-23 18:50:38,259 INFO    : Executor     : ================================================================================
2017-01-23 18:50:38,260 INFO    : Executor     : configuring target for [energy_aware] experiments
2017-01-23 18:50:39,976 INFO    : Executor     : Set scheduler feature: ENERGY_AWARE
2017-01-23 18:50:40,881 WARNING : Executor     : cpufreq governor not specified, using currently configured governor
2017-01-23 18:50:40,883 INFO    : Workload     : Setup new workload wake_migration
2017-01-23 18:50:40,884 INFO    : Workload     : Workload duration defined by longest task
2017-01-23 18:50:40,885 INFO    : Workload     : Default policy: SCHED_OTHER
2017-01-23 18:50:40,886 INFO    : Workload     : ------------------------
2017-01-23 18:50:40,888 INFO    : Workload     : task [task_wmig0], sched: using default policy
2017-01-23 18:50:40,889 INFO    : Workload     :  | calibration CPU: 1
2017-01-23 18:50:40,890 INFO    : Workload     :  | loops count: 2
2017-01-23 18:50:40,891 INFO    : Workload     : + phase_000001: duration 1.000000 [s] (10 loops)
2017-01-23 18:50:40,892 INFO    : Workload     : |  period   100000 [us], duty_cycle  10 %
2017-01-23 18:50:40,893 INFO    : Workload     : |  run_time  10000 [us], sleep_time  90000 [us]
2017-01-23 18:50:40,894 INFO    : Workload     : + phase_000002: duration 1.000000 [s] (10 loops)
2017-01-23 18:50:40,895 INFO    : Workload     : |  period   100000 [us], duty_cycle  50 %
2017-01-23 18:50:40,896 INFO    : Workload     : |  run_time  50000 [us], sleep_time  50000 [us]
2017-01-23 18:50:40,897 INFO    : Workload     : ------------------------
2017-01-23 18:50:40,897 INFO    : Workload     : task [task_wmig1], sched: using default policy
2017-01-23 18:50:40,898 INFO    : Workload     :  | calibration CPU: 1
2017-01-23 18:50:40,899 INFO    : Workload     :  | loops count: 2
2017-01-23 18:50:40,900 INFO    : Workload     : + phase_000001: duration 1.000000 [s] (10 loops)
2017-01-23 18:50:40,901 INFO    : Workload     : |  period   100000 [us], duty_cycle  10 %
2017-01-23 18:50:40,902 INFO    : Workload     : |  run_time  10000 [us], sleep_time  90000 [us]
2017-01-23 18:50:40,903 INFO    : Workload     : + phase_000002: duration 1.000000 [s] (10 loops)
2017-01-23 18:50:40,904 INFO    : Workload     : |  period   100000 [us], duty_cycle  50 %
2017-01-23 18:50:40,905 INFO    : Workload     : |  run_time  50000 [us], sleep_time  50000 [us]
2017-01-23 18:50:41,966 INFO    : Executor     : ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
2017-01-23 18:50:41,968 INFO    : Executor     : Experiment 0/1, [energy_aware:wake_migration] 1/1
2017-01-23 18:50:41,976 WARNING : Executor     : FTrace events collection enabled
2017-01-23 18:50:48,009 INFO    : Workload     : Workload execution START:
2017-01-23 18:50:48,011 INFO    : Workload     :    /home/brendan/devlib-target/bin/rt-app /home/brendan/devlib-target/run_dir/wake_migration_00.json 2>&1

2017-01-23 18:50:57,357 INFO    : Executor     : Collected FTrace binary trace:
2017-01-23 18:50:57,359 INFO    : Executor     :    <res_dir>/rtapp:energy_aware:wake_migration/1/trace.dat
2017-01-23 18:50:57,360 INFO    : Executor     : Collected FTrace function profiling:
2017-01-23 18:50:57,361 INFO    : Executor     :    <res_dir>/rtapp:energy_aware:wake_migration/1/trace_stat.json
2017-01-23 18:50:57,362 INFO    : Executor     : --------------------------------------------------------------------------------
2017-01-23 18:50:57,363 INFO    : Executor     : 
2017-01-23 18:50:57,365 INFO    : Executor     : ################################################################################
2017-01-23 18:50:57,366 INFO    : Executor     : Experiments execution completed
2017-01-23 18:50:57,367 INFO    : Executor     : ################################################################################
2017-01-23 18:50:57,368 INFO    : Executor     : Results available in:
2017-01-23 18:50:57,369 INFO    : Executor     :       /home/brejac01/sources/lisa/results/20170123_185036

In [ ]:
experiment = t.executor.experiments[0]

Examine trace

get_power_df and get_expected_power_df look at the ftrace results from the workload estimation and judge the energy efficiency of the system, considering only task placement (assuming perfect load-tracking/prediction, cpuidle, and cpufreq systems). The energy estimation doesn't take every single wakeup and idle period into account, but simply estimates an average power usage over the time that each task spent attached to each CPU during each phase of the rt-app workload.

These return DataFrames estimating the energy usage of the system under each task placement. estimated_power will represent this estimation for the scheduling pattern that we actually observed, while expected_power will represent our estimation of how much power an optimal scheduling pattern would use.

Check the docstrings for these functions (and other functions in the test class) for more detail.


In [ ]:
# print t.get_power_df.__doc__
estimated_power = t.get_power_df(experiment)

In [ ]:
# print t.get_expected_power_df.__doc__
expected_power = t.get_expected_power_df(experiment)


2017-01-23 18:50:58,352 INFO    : EnergyModel  :    EnergyModel - Searching 36 configurations for optimal task placement...
2017-01-23 18:50:58,355 INFO    : EnergyModel  :    EnergyModel - Done
2017-01-23 18:50:58,356 INFO    : EnergyModel  :    EnergyModel - Searching 36 configurations for optimal task placement...
2017-01-23 18:50:58,361 INFO    : EnergyModel  :    EnergyModel - Done
2017-01-23 18:50:58,363 INFO    : EnergyModel  :    EnergyModel - Searching 36 configurations for optimal task placement...
2017-01-23 18:50:58,367 INFO    : EnergyModel  :    EnergyModel - Done
2017-01-23 18:50:58,369 INFO    : EnergyModel  :    EnergyModel - Searching 36 configurations for optimal task placement...
2017-01-23 18:50:58,374 INFO    : EnergyModel  :    EnergyModel - Done
2017-01-23 18:50:58,375 INFO    : EnergyModel  :    EnergyModel - Searching 36 configurations for optimal task placement...
2017-01-23 18:50:58,378 INFO    : EnergyModel  :    EnergyModel - Done
2017-01-23 18:50:58,380 INFO    : EnergyModel  :    EnergyModel - Searching 36 configurations for optimal task placement...
2017-01-23 18:50:58,381 INFO    : EnergyModel  :    EnergyModel - Done

Plot Schedule


In [ ]:
trace = t.get_trace(experiment)

In [ ]:
trappy.plotter.plot_trace(trace.ftrace)


Plot estimated ideal and estimated power usage

This plot shows how the power estimation for the observed scheduling pattern varies from the estimated power for an ideal schedule.

Where the plotted value for the observed power is higher than the plotted ideal power, the system was wasting power (e.g. a low-intensity task was unnecessarily placed on a high-power CPU). Where the observed value is lower than the ideal value, this means the system was too efficient (e.g. a high-intensity task was placed on a low-power CPU that could not accomadate its compute requirements).


In [ ]:
df = pd.concat([
        expected_power.sum(axis=1), estimated_power.sum(axis=1)], 
               axis=1, keys=['ideal_power', 'observed_power']).fillna(method='ffill')

ILinePlot(df, column=df.columns.tolist(), drawstyle='steps-post').view()


Plot CPU frequency


In [ ]:
trace.analysis.frequency.plotClusterFrequencies()


2017-01-23 18:50:59,019 WARNING : Analysis     : Events [cpu_frequency] not found, plot DISABLED!

Assertions

These are the assertions used to generate pass/fail results s. They aren't very useful in this interactive context - it's much more interesting to examine plots like the one above and see whether the behaviour was desirable or not. These are intended for automated regression testing. Nonetheless, let's see what the results would be for this run.

test_slack checks the "slack" reported by the rt-app workload. If this slack was negative, this means the workload didn't receive enough CPU capacity. In a real system this would represent lacking interactive performance.


In [ ]:
try:
    t.test_slack()
except AssertionError as e:
    print "test_slack failed:"
    print e
else:
    print "test_slack passed"


test_slack failed:
task task_wmig0 missed 10.0% of activations
	Check trace file: /home/brejac01/sources/lisa/results/20170123_185036/rtapp:energy_aware:wake_migration/1/trace.dat

test_task_placement checks that the task placement was energy efficient, taking advantage of lower-power CPUs whenever possible.


In [ ]:
try:
    t.test_task_placement()
except AssertionError as e:
    print "test_task_placement failed:"
    print e
else:
    print "test_task_placement passed"


2017-01-23 18:50:59,076 INFO    : EnergyModel  :    EnergyModel - Searching 36 configurations for optimal task placement...
2017-01-23 18:50:59,079 INFO    : EnergyModel  :    EnergyModel - Done
2017-01-23 18:50:59,080 INFO    : EnergyModel  :    EnergyModel - Searching 36 configurations for optimal task placement...
2017-01-23 18:50:59,083 INFO    : EnergyModel  :    EnergyModel - Done
2017-01-23 18:50:59,084 INFO    : EnergyModel  :    EnergyModel - Searching 36 configurations for optimal task placement...
2017-01-23 18:50:59,086 INFO    : EnergyModel  :    EnergyModel - Done
2017-01-23 18:50:59,087 INFO    : EnergyModel  :    EnergyModel - Searching 36 configurations for optimal task placement...
2017-01-23 18:50:59,090 INFO    : EnergyModel  :    EnergyModel - Done
2017-01-23 18:50:59,092 INFO    : EnergyModel  :    EnergyModel - Searching 36 configurations for optimal task placement...
2017-01-23 18:50:59,094 INFO    : EnergyModel  :    EnergyModel - Done
2017-01-23 18:50:59,095 INFO    : EnergyModel  :    EnergyModel - Searching 36 configurations for optimal task placement...
2017-01-23 18:50:59,096 INFO    : EnergyModel  :    EnergyModel - Done
test_task_placement passed