TRAPpy

TRAPpy (Trace Analysis and Plotting in Python) is a visualization tool to help analyze data generated on a device. It parses ftrace-like logs and creates in-memory data structures to be used for plotting and data analysis. More information can be found at https://github.com/ARM-software/trappy and https://pythonhosted.org/TRAPpy/.

A big part of the notebook below is target and test environment confituration as well as workload configuration, detailed in examples/utils/ and examples/wlgen/. For this reason those cells won't be documented in detail here in order to focus more on TRAPpy.


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


2016-12-12 12:31:07,128 INFO    : root         : Using LISA logging configuration:
2016-12-12 12:31:07,128 INFO    : root         :   /home/vagrant/lisa/logging.conf

In [2]:
# Generate plots inline
%pylab inline

import json
import os

# Support to initialise and configure your test environment
import devlib
from env import TestEnv

# Support to configure and run RTApp based workloads
from wlgen import RTA, Periodic, Ramp, Step, Pulse

# Suport for FTrace events parsing and visualization
import trappy
from trappy.ftrace import FTrace
from trace import Trace


Populating the interactive namespace from numpy and matplotlib

Test environment setup

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


In [3]:
# Setup a target configuration
my_target_conf = {
    
    "platform"    : 'linux',
    "board"       : 'juno',

    "modules"     : [
        'bl',
        'cpufreq'
    ],

    "host"        : '192.168.0.1',
    "username"    : 'root',
    "password"    : 'juno',
## Workload execution
    "rtapp-calib" : {
        '0': 361, '1': 138, '2': 138, '3': 352, '4': 360, '5': 353
    }

}

my_tests_conf = {

    "tools"   : ['rt-app', 'taskset', 'trace-cmd'],

    "ftrace"  : {
         "events" : [
            'sched_migrate_task',
            'sched_process_exec',
            'sched_process_fork',
            'sched_stat_iowait',
            'sched_switch',
            'sched_wakeup',
            'sched_wakeup_new',
            'sched_overutilized',
            'cpu_capacity',
            'sched_load_avg_cpu',
            'sched_load_avg_task',
            'sched_boost_cpu',
            'sched_boost_task',
            'sched_energy_diff',
            'cpu_frequency',
            'cpu_idle',
            'sched_tune_config',
         ],
         "buffsize" : 10240
    },

}

te = TestEnv(target_conf=my_target_conf, test_conf=my_tests_conf)
target = te.target


2016-12-12 12:31:10,081 INFO    : TestEnv      : Using base path: /home/vagrant/lisa
2016-12-12 12:31:10,082 INFO    : TestEnv      : Loading custom (inline) target configuration
2016-12-12 12:31:10,083 INFO    : TestEnv      : Loading custom (inline) test configuration
2016-12-12 12:31:10,083 INFO    : TestEnv      : Devlib modules to load: ['bl', 'cpufreq', 'hwmon']
2016-12-12 12:31:10,084 INFO    : TestEnv      : Connecting linux target:
2016-12-12 12:31:10,084 INFO    : TestEnv      :   username : root
2016-12-12 12:31:10,085 INFO    : TestEnv      :       host : 192.168.0.1
2016-12-12 12:31:10,085 INFO    : TestEnv      :   password : juno
2016-12-12 12:31:10,086 INFO    : TestEnv      : Connection settings:
2016-12-12 12:31:10,086 INFO    : TestEnv      :    {'username': 'root', 'host': '192.168.0.1', 'password': 'juno'}
2016-12-12 12:31:26,882 INFO    : TestEnv      : Initializing target workdir:
2016-12-12 12:31:26,883 INFO    : TestEnv      :    /root/devlib-target
2016-12-12 12:31:44,132 INFO    : TestEnv      : Topology:
2016-12-12 12:31:44,133 INFO    : TestEnv      :    [[0, 3, 4, 5], [1, 2]]
2016-12-12 12:31:45,383 INFO    : TestEnv      : Loading default EM:
2016-12-12 12:31:45,384 INFO    : TestEnv      :    /home/vagrant/lisa/libs/utils/platforms/juno.json
2016-12-12 12:31:49,435 INFO    : TestEnv      : Enabled tracepoints:
2016-12-12 12:31:49,436 INFO    : TestEnv      :    sched_migrate_task
2016-12-12 12:31:49,437 INFO    : TestEnv      :    sched_process_exec
2016-12-12 12:31:49,438 INFO    : TestEnv      :    sched_process_fork
2016-12-12 12:31:49,439 INFO    : TestEnv      :    sched_stat_iowait
2016-12-12 12:31:49,440 INFO    : TestEnv      :    sched_switch
2016-12-12 12:31:49,440 INFO    : TestEnv      :    sched_wakeup
2016-12-12 12:31:49,441 INFO    : TestEnv      :    sched_wakeup_new
2016-12-12 12:31:49,442 INFO    : TestEnv      :    sched_overutilized
2016-12-12 12:31:49,443 INFO    : TestEnv      :    cpu_capacity
2016-12-12 12:31:49,443 INFO    : TestEnv      :    sched_load_avg_cpu
2016-12-12 12:31:49,444 INFO    : TestEnv      :    sched_load_avg_task
2016-12-12 12:31:49,445 INFO    : TestEnv      :    sched_boost_cpu
2016-12-12 12:31:49,446 INFO    : TestEnv      :    sched_boost_task
2016-12-12 12:31:49,446 INFO    : TestEnv      :    sched_energy_diff
2016-12-12 12:31:49,447 INFO    : TestEnv      :    cpu_frequency
2016-12-12 12:31:49,448 INFO    : TestEnv      :    cpu_idle
2016-12-12 12:31:49,448 INFO    : TestEnv      :    sched_tune_config
2016-12-12 12:31:49,448 WARNING : TestEnv      : Using configuration provided RTApp calibration
2016-12-12 12:31:49,449 INFO    : TestEnv      : Using RT-App calibration values:
2016-12-12 12:31:49,449 INFO    : TestEnv      :    {"0": 361, "1": 138, "2": 138, "3": 352, "4": 360, "5": 353}
2016-12-12 12:31:49,450 INFO    : EnergyMeter  : Scanning for HWMON channels, may take some time...
2016-12-12 12:31:49,452 INFO    : EnergyMeter  : Channels selected for energy sampling:
2016-12-12 12:31:49,452 INFO    : EnergyMeter  :    BOARDBIG_energy
2016-12-12 12:31:49,452 INFO    : EnergyMeter  :    BOARDLITTLE_energy
2016-12-12 12:31:49,453 INFO    : TestEnv      : Set results folder to:
2016-12-12 12:31:49,453 INFO    : TestEnv      :    /home/vagrant/lisa/results/20161212_123149
2016-12-12 12:31:49,454 INFO    : TestEnv      : Experiment results available also in:
2016-12-12 12:31:49,454 INFO    : TestEnv      :    /home/vagrant/lisa/results_latest

Workload configuration and execution

For more details on this please check out examples/wlgen/rtapp_example.ipynb.


In [4]:
# Create a new RTApp workload generator using the calibration values
rtapp = RTA(target, 'trappy', calibration=te.calibration())

# Configure this RTApp instance to:
rtapp.conf(
    kind='profile',
    
    params={
        'task_per20': Periodic(
            period_ms=100,
            duty_cycle_pct=20,
            duration_s=5,
            cpus=None,
            sched={
                "policy": "FIFO",
            },
            delay_s=0
        ).get(),

        'task_rmp20_5-60': Ramp(
            period_ms=100,
            start_pct=5,
            end_pct=65,
            delta_pct=20,
            time_s=1,
            cpus="0"
        ).get(),

        'task_stp10-50': Step(
            period_ms=100,
            start_pct=0,
            end_pct=50,
            time_s=1,
            delay_s=0.5
        ).get(),

        'task_pls5-80': Pulse(
            period_ms=100,
            start_pct=65,
            end_pct=5,
            time_s=1,
            delay_s=0.5
        ).get(),
    },

    run_dir=target.working_directory
    
);


2016-12-12 12:32:22,824 INFO    : Workload     : Setup new workload trappy
2016-12-12 12:32:22,825 INFO    : Workload     : Workload duration defined by longest task
2016-12-12 12:32:22,826 INFO    : Workload     : Default policy: SCHED_OTHER
2016-12-12 12:32:22,826 INFO    : Workload     : ------------------------
2016-12-12 12:32:22,827 INFO    : Workload     : task [task_per20], sched: {'policy': 'FIFO'}
2016-12-12 12:32:22,827 INFO    : Workload     :  | calibration CPU: 1
2016-12-12 12:32:22,828 INFO    : Workload     :  | loops count: 1
2016-12-12 12:32:22,828 INFO    : Workload     : + phase_000001: duration 5.000000 [s] (50 loops)
2016-12-12 12:32:22,829 INFO    : Workload     : |  period   100000 [us], duty_cycle  20 %
2016-12-12 12:32:22,829 INFO    : Workload     : |  run_time  20000 [us], sleep_time  80000 [us]
2016-12-12 12:32:22,830 INFO    : Workload     : ------------------------
2016-12-12 12:32:22,830 INFO    : Workload     : task [task_pls5-80], sched: using default policy
2016-12-12 12:32:22,831 INFO    : Workload     :  | start delay: 0.500000 [s]
2016-12-12 12:32:22,831 INFO    : Workload     :  | calibration CPU: 1
2016-12-12 12:32:22,832 INFO    : Workload     :  | loops count: 1
2016-12-12 12:32:22,832 INFO    : Workload     : + phase_000001: duration 1.000000 [s] (10 loops)
2016-12-12 12:32:22,833 INFO    : Workload     : |  period   100000 [us], duty_cycle  65 %
2016-12-12 12:32:22,833 INFO    : Workload     : |  run_time  65000 [us], sleep_time  35000 [us]
2016-12-12 12:32:22,834 INFO    : Workload     : + phase_000002: duration 1.000000 [s] (10 loops)
2016-12-12 12:32:22,834 INFO    : Workload     : |  period   100000 [us], duty_cycle   5 %
2016-12-12 12:32:22,834 INFO    : Workload     : |  run_time   5000 [us], sleep_time  95000 [us]
2016-12-12 12:32:22,835 INFO    : Workload     : ------------------------
2016-12-12 12:32:22,836 INFO    : Workload     : task [task_rmp20_5-60], sched: using default policy
2016-12-12 12:32:22,836 INFO    : Workload     :  | calibration CPU: 1
2016-12-12 12:32:22,837 INFO    : Workload     :  | loops count: 1
2016-12-12 12:32:22,837 INFO    : Workload     :  | CPUs affinity: 0
2016-12-12 12:32:22,838 INFO    : Workload     : + phase_000001: duration 1.000000 [s] (10 loops)
2016-12-12 12:32:22,838 INFO    : Workload     : |  period   100000 [us], duty_cycle   5 %
2016-12-12 12:32:22,839 INFO    : Workload     : |  run_time   5000 [us], sleep_time  95000 [us]
2016-12-12 12:32:22,839 INFO    : Workload     : + phase_000002: duration 1.000000 [s] (10 loops)
2016-12-12 12:32:22,840 INFO    : Workload     : |  period   100000 [us], duty_cycle  25 %
2016-12-12 12:32:22,840 INFO    : Workload     : |  run_time  25000 [us], sleep_time  75000 [us]
2016-12-12 12:32:22,841 INFO    : Workload     : + phase_000003: duration 1.000000 [s] (10 loops)
2016-12-12 12:32:22,841 INFO    : Workload     : |  period   100000 [us], duty_cycle  45 %
2016-12-12 12:32:22,841 INFO    : Workload     : |  run_time  45000 [us], sleep_time  55000 [us]
2016-12-12 12:32:22,842 INFO    : Workload     : + phase_000004: duration 1.000000 [s] (10 loops)
2016-12-12 12:32:22,842 INFO    : Workload     : |  period   100000 [us], duty_cycle  65 %
2016-12-12 12:32:22,843 INFO    : Workload     : |  run_time  65000 [us], sleep_time  35000 [us]
2016-12-12 12:32:22,843 INFO    : Workload     : ------------------------
2016-12-12 12:32:22,844 INFO    : Workload     : task [task_stp10-50], sched: using default policy
2016-12-12 12:32:22,844 INFO    : Workload     :  | start delay: 0.500000 [s]
2016-12-12 12:32:22,844 INFO    : Workload     :  | calibration CPU: 1
2016-12-12 12:32:22,845 INFO    : Workload     :  | loops count: 1
2016-12-12 12:32:22,845 INFO    : Workload     :  + phase_000001: sleep 1.000000 [s]
2016-12-12 12:32:22,845 INFO    : Workload     : + phase_000002: duration 1.000000 [s] (10 loops)
2016-12-12 12:32:22,846 INFO    : Workload     : |  period   100000 [us], duty_cycle  50 %
2016-12-12 12:32:22,846 INFO    : Workload     : |  run_time  50000 [us], sleep_time  50000 [us]

In [5]:
logging.info('#### Setup FTrace')
te.ftrace.start()

logging.info('#### Start energy sampling')
te.emeter.reset()

logging.info('#### Start RTApp execution')
rtapp.run(out_dir=te.res_dir, cgroup="")

logging.info('#### Read energy consumption: %s/energy.json', te.res_dir)
nrg_report = te.emeter.report(out_dir=te.res_dir)

logging.info('#### Stop FTrace')
te.ftrace.stop()

trace_file = os.path.join(te.res_dir, 'trace.dat')
logging.info('#### Save FTrace: %s', trace_file)
te.ftrace.get_trace(trace_file)

logging.info('#### Save platform description: %s/platform.json', te.res_dir)
(plt, plt_file) = te.platform_dump(te.res_dir)


2016-12-12 12:32:26,010 INFO    : root         : #### Setup FTrace
2016-12-12 12:32:30,739 INFO    : root         : #### Start energy sampling
2016-12-12 12:32:31,368 INFO    : root         : #### Start RTApp execution
2016-12-12 12:32:31,370 INFO    : Workload     : Workload execution START:
2016-12-12 12:32:31,372 INFO    : Workload     :    /root/devlib-target/bin/rt-app /root/devlib-target/trappy_00.json 2>&1
2016-12-12 12:32:48,588 INFO    : root         : #### Read energy consumption: /home/vagrant/lisa/results/20161212_123149/energy.json
2016-12-12 12:32:49,213 INFO    : root         : #### Stop FTrace
2016-12-12 12:32:51,475 INFO    : root         : #### Save FTrace: /home/vagrant/lisa/results/20161212_123149/trace.dat
2016-12-12 12:32:55,529 INFO    : root         : #### Save platform description: /home/vagrant/lisa/results/20161212_123149/platform.json

Trace inspection


In [6]:
# NOTE: The interactive trace visualization is available only if you run
#       the workload to generate a new trace-file
trappy.plotter.plot_trace(te.res_dir)