Kernel Functions Profiling

This notebook is there to show how to do some simple function profiling using LISA.

We'll be using the Ftrace function profiler (See "Function profiling" in https://lwn.net/Articles/370423/) for that, and will present the relevant Python APIs from Devlib & LISA that make it easier to use.


In [1]:
import logging
from lisa.utils import setup_logging
setup_logging()


2019-02-26 16:55:21,469 INFO    : root         : Using LISA logging configuration:
2019-02-26 16:55:21,470 INFO    : root         :   /data/work/lisa/logging.conf

In [2]:
import os
from lisa.target import Target, TargetConf


2019-02-26 16:55:21,487 INFO    : root         : Generating grammar tables from /usr/lib/python3.5/lib2to3/Grammar.txt
2019-02-26 16:55:21,510 INFO    : root         : Generating grammar tables from /usr/lib/python3.5/lib2to3/PatternGrammar.txt

Target configuration

The only target requirement here is to have enough Ftrace goodies enabled (look at the requirements for CONFIG_FUNCTION_PROFILER)


In [3]:
target = Target(
    kind='linux',
    name='myhikey960',
    host='192.168.0.1',
    username='root',
    password='root',
)


2019-02-26 16:55:22,134 INFO    : lisa.target.Target : Creating result directory: /data/work/lisa/results/Target-myhikey960-20190226_165522.134327
2019-02-26 16:55:22,137 INFO    : lisa.target.Target : linux myhikey960 target connection settings:
2019-02-26 16:55:22,138 INFO    : lisa.target.Target :       host : 192.168.0.1
2019-02-26 16:55:22,140 INFO    : lisa.target.Target :   password : root
2019-02-26 16:55:22,141 INFO    : lisa.target.Target :       port : 22
2019-02-26 16:55:22,142 INFO    : lisa.target.Target :   username : root
2019-02-26 16:55:22,160 INFO    : lisa.target.Target : Devlib modules to load: bl, cgroups, cpufreq, cpuidle, devfreq, fastboot, gem5stats, gpufreq, hotplug, hwmon, mbed-fan, odroidxu3-fan, sched, thermal
2019-02-26 16:55:26,735 WARNING : LinuxTarget  : Module devfreq is not supported by the target
2019-02-26 16:55:26,738 WARNING : LinuxTarget  : Module fastboot is not supported by the target
2019-02-26 16:55:26,739 WARNING : LinuxTarget  : Module gem5stats is not supported by the target
2019-02-26 16:55:26,904 WARNING : LinuxTarget  : Module gpufreq is not supported by the target
2019-02-26 16:55:27,581 WARNING : LinuxTarget  : Module odroidxu3-fan is not supported by the target
2019-02-26 16:55:29,475 INFO    : CGroups      : Available controllers:
2019-02-26 16:55:29,988 INFO    : CGroups      :   cpuset       : /root/devlib-target/cgroups/devlib_cgh3
2019-02-26 16:55:30,494 INFO    : CGroups      :   cpu          : /root/devlib-target/cgroups/devlib_cgh2
2019-02-26 16:55:30,991 INFO    : CGroups      :   cpuacct      : /root/devlib-target/cgroups/devlib_cgh2
2019-02-26 16:55:31,496 INFO    : CGroups      :   blkio        : /root/devlib-target/cgroups/devlib_cgh4
2019-02-26 16:55:32,005 INFO    : CGroups      :   memory       : /root/devlib-target/cgroups/devlib_cgh6
2019-02-26 16:55:32,516 INFO    : CGroups      :   devices      : /root/devlib-target/cgroups/devlib_cgh10
2019-02-26 16:55:33,020 INFO    : CGroups      :   freezer      : /root/devlib-target/cgroups/devlib_cgh7
2019-02-26 16:55:33,527 INFO    : CGroups      :   perf_event   : /root/devlib-target/cgroups/devlib_cgh5
2019-02-26 16:55:34,031 INFO    : CGroups      :   hugetlb      : /root/devlib-target/cgroups/devlib_cgh8
2019-02-26 16:55:34,544 INFO    : CGroups      :   pids         : /root/devlib-target/cgroups/devlib_cgh9
2019-02-26 16:55:34,713 WARNING : lisa.target.Target : Failed to initialized "devfreq" devlib Module
2019-02-26 16:55:34,714 WARNING : lisa.target.Target : Failed to initialized "fastboot" devlib Module
2019-02-26 16:55:34,715 WARNING : lisa.target.Target : Failed to initialized "gem5stats" devlib Module
2019-02-26 16:55:34,715 WARNING : lisa.target.Target : Failed to initialized "gpufreq" devlib Module
2019-02-26 16:55:34,716 WARNING : lisa.target.Target : Failed to initialized "mbed-fan" devlib Module
2019-02-26 16:55:34,717 WARNING : lisa.target.Target : Failed to initialized "odroidxu3-fan" devlib Module
2019-02-26 16:55:34,718 INFO    : lisa.platforms.platinfo.PlatformInfo : Attempting to read energy model from target
2019-02-26 16:55:35,378 INFO    : lisa.energy_model.EnergyModel.EMReader : Attempting to load EM using from_debugfsEM_target
2019-02-26 16:55:40,913 INFO    : lisa.target.Target : Effective platform information:
|- abi from target (str): arm64
|- cpu-capacities from target (dict): {0: 462, 1: 462, 2: 462, 3: 462, 4: 1024, 5: 1024, 6: 1024, 7: 1024}
|- cpus-count from target (int): 8
|- freq-domains from target (list): [[0, 1, 2, 3], [4, 5, 6, 7]]
|- freqs from target (dict): {0: [533000, 999000, 1402000, 1709000, 1844000], 1: [533000, 999000, 1402000, 1709000, 1844000], 2: [533000, 999000, 1402000, 1709000, 1844000], 3: [533000, 999000, 1402000, 1709000, 1844000], 4: [903000, 1421000, 1805000, 2112000, 2362000], 5: [903000, 1421000, 1805000, 2112000, 2362000], 6: [903000, 1421000, 1805000, 2112000, 2362000], 7: [903000, 1421000, 1805000, 2112000, 2362000]}
+- kernel:
    |- config from target (TypedKernelConfig): <kernel config>
    |- version from target (KernelVersion): 5.0.0-rc6-00099-g5441513e6c1c 29 SMP PREEMPT Tue Feb 26 16:27:53 GMT 2019
|- name from target-conf (str): myhikey960
|- nrg-model from target (EnergyModel): <lisa.energy_model.EnergyModel object at 0x7fcd3f7b62e8>
|- os from target (str): linux
+- rtapp:
    |- calib from target (DeferredValue): <lazy value of RTA.get_cpu_calibrations>
|- capacity-classes from target(platform-info/cpu-capacities) (list): [[0, 1, 2, 3], [4, 5, 6, 7]]

Experiment setup

We can run whatever we want here, let's just build a simple ((1 20% task) x NR_CPUS) workload


In [4]:
from lisa.wlgen.rta import RTA, Periodic

In [5]:
rtapp_profile = {}

for cpu in range(target.number_of_cpus):
    rtapp_profile["task{}".format(cpu)] = Periodic(duty_cycle_pct=20)

In [6]:
wload = RTA.by_profile(target, rtapp_profile, name='profiling_wload')


2019-02-26 16:55:41,167 INFO    : lisa.target.Target : Creating result directory: /data/work/lisa/results/Target-myhikey960-20190226_165522.134327/RTA-profiling_wload-20190226_165541.167219
2019-02-26 16:55:47,120 INFO    : lisa.wlgen.rta.RTA : CPU0 calibration...
2019-02-26 16:55:47,451 INFO    : lisa.wlgen.rta.RTA : Calibration value: CPU0
2019-02-26 16:55:47,453 INFO    : lisa.wlgen.rta.RTA : Default policy: SCHED_OTHER
2019-02-26 16:55:47,454 INFO    : lisa.wlgen.rta.RTA : ------------------------
2019-02-26 16:55:47,456 INFO    : lisa.wlgen.rta.RTA : task [task1], sched: using default policy
2019-02-26 16:55:47,457 INFO    : lisa.wlgen.rta.RTA :  | start delay: 0.000000 [s]
2019-02-26 16:55:47,459 INFO    : lisa.wlgen.rta.RTA :  | loops count: 1
2019-02-26 16:55:47,461 INFO    : lisa.wlgen.rta.RTA :  + phase_000001
2019-02-26 16:55:47,462 INFO    : lisa.wlgen.rta.Phase :  | batch 0.001000 [s]
2019-02-26 16:55:47,707 INFO    : lisa.wlgen.rta.RTA : Execution start: /root/devlib-target/bin/rt-app /root/devlib-target/rta_calib_cpu0.json 2>&1
2019-02-26 16:55:54,238 INFO    : lisa.wlgen.rta.RTA : Execution complete
2019-02-26 16:55:54,495 INFO    : lisa.wlgen.rta.RTA : CPU1 calibration...
2019-02-26 16:55:54,834 INFO    : lisa.wlgen.rta.RTA : Calibration value: CPU1
2019-02-26 16:55:54,836 INFO    : lisa.wlgen.rta.RTA : Default policy: SCHED_OTHER
2019-02-26 16:55:54,837 INFO    : lisa.wlgen.rta.RTA : ------------------------
2019-02-26 16:55:54,839 INFO    : lisa.wlgen.rta.RTA : task [task1], sched: using default policy
2019-02-26 16:55:54,840 INFO    : lisa.wlgen.rta.RTA :  | start delay: 0.000000 [s]
2019-02-26 16:55:54,841 INFO    : lisa.wlgen.rta.RTA :  | loops count: 1
2019-02-26 16:55:54,843 INFO    : lisa.wlgen.rta.RTA :  + phase_000001
2019-02-26 16:55:54,844 INFO    : lisa.wlgen.rta.Phase :  | batch 0.001000 [s]
2019-02-26 16:55:55,136 INFO    : lisa.wlgen.rta.RTA : Execution start: /root/devlib-target/bin/rt-app /root/devlib-target/rta_calib_cpu1.json 2>&1
2019-02-26 16:56:01,658 INFO    : lisa.wlgen.rta.RTA : Execution complete
2019-02-26 16:56:01,917 INFO    : lisa.wlgen.rta.RTA : CPU2 calibration...
2019-02-26 16:56:02,250 INFO    : lisa.wlgen.rta.RTA : Calibration value: CPU2
2019-02-26 16:56:02,252 INFO    : lisa.wlgen.rta.RTA : Default policy: SCHED_OTHER
2019-02-26 16:56:02,253 INFO    : lisa.wlgen.rta.RTA : ------------------------
2019-02-26 16:56:02,255 INFO    : lisa.wlgen.rta.RTA : task [task1], sched: using default policy
2019-02-26 16:56:02,256 INFO    : lisa.wlgen.rta.RTA :  | start delay: 0.000000 [s]
2019-02-26 16:56:02,258 INFO    : lisa.wlgen.rta.RTA :  | loops count: 1
2019-02-26 16:56:02,260 INFO    : lisa.wlgen.rta.RTA :  + phase_000001
2019-02-26 16:56:02,262 INFO    : lisa.wlgen.rta.Phase :  | batch 0.001000 [s]
2019-02-26 16:56:02,506 INFO    : lisa.wlgen.rta.RTA : Execution start: /root/devlib-target/bin/rt-app /root/devlib-target/rta_calib_cpu2.json 2>&1
2019-02-26 16:56:09,032 INFO    : lisa.wlgen.rta.RTA : Execution complete
2019-02-26 16:56:09,320 INFO    : lisa.wlgen.rta.RTA : CPU3 calibration...
2019-02-26 16:56:09,654 INFO    : lisa.wlgen.rta.RTA : Calibration value: CPU3
2019-02-26 16:56:09,656 INFO    : lisa.wlgen.rta.RTA : Default policy: SCHED_OTHER
2019-02-26 16:56:09,657 INFO    : lisa.wlgen.rta.RTA : ------------------------
2019-02-26 16:56:09,659 INFO    : lisa.wlgen.rta.RTA : task [task1], sched: using default policy
2019-02-26 16:56:09,660 INFO    : lisa.wlgen.rta.RTA :  | start delay: 0.000000 [s]
2019-02-26 16:56:09,661 INFO    : lisa.wlgen.rta.RTA :  | loops count: 1
2019-02-26 16:56:09,662 INFO    : lisa.wlgen.rta.RTA :  + phase_000001
2019-02-26 16:56:09,664 INFO    : lisa.wlgen.rta.Phase :  | batch 0.001000 [s]
2019-02-26 16:56:09,906 INFO    : lisa.wlgen.rta.RTA : Execution start: /root/devlib-target/bin/rt-app /root/devlib-target/rta_calib_cpu3.json 2>&1
2019-02-26 16:56:16,435 INFO    : lisa.wlgen.rta.RTA : Execution complete
2019-02-26 16:56:16,686 INFO    : lisa.wlgen.rta.RTA : CPU4 calibration...
2019-02-26 16:56:17,020 INFO    : lisa.wlgen.rta.RTA : Calibration value: CPU4
2019-02-26 16:56:17,021 INFO    : lisa.wlgen.rta.RTA : Default policy: SCHED_OTHER
2019-02-26 16:56:17,023 INFO    : lisa.wlgen.rta.RTA : ------------------------
2019-02-26 16:56:17,024 INFO    : lisa.wlgen.rta.RTA : task [task1], sched: using default policy
2019-02-26 16:56:17,025 INFO    : lisa.wlgen.rta.RTA :  | start delay: 0.000000 [s]
2019-02-26 16:56:17,027 INFO    : lisa.wlgen.rta.RTA :  | loops count: 1
2019-02-26 16:56:17,028 INFO    : lisa.wlgen.rta.RTA :  + phase_000001
2019-02-26 16:56:17,029 INFO    : lisa.wlgen.rta.Phase :  | batch 0.001000 [s]
2019-02-26 16:56:17,274 INFO    : lisa.wlgen.rta.RTA : Execution start: /root/devlib-target/bin/rt-app /root/devlib-target/rta_calib_cpu4.json 2>&1
2019-02-26 16:56:22,613 INFO    : lisa.wlgen.rta.RTA : Execution complete
2019-02-26 16:56:22,863 INFO    : lisa.wlgen.rta.RTA : CPU5 calibration...
2019-02-26 16:56:23,197 INFO    : lisa.wlgen.rta.RTA : Calibration value: CPU5
2019-02-26 16:56:23,199 INFO    : lisa.wlgen.rta.RTA : Default policy: SCHED_OTHER
2019-02-26 16:56:23,200 INFO    : lisa.wlgen.rta.RTA : ------------------------
2019-02-26 16:56:23,201 INFO    : lisa.wlgen.rta.RTA : task [task1], sched: using default policy
2019-02-26 16:56:23,202 INFO    : lisa.wlgen.rta.RTA :  | start delay: 0.000000 [s]
2019-02-26 16:56:23,204 INFO    : lisa.wlgen.rta.RTA :  | loops count: 1
2019-02-26 16:56:23,206 INFO    : lisa.wlgen.rta.RTA :  + phase_000001
2019-02-26 16:56:23,207 INFO    : lisa.wlgen.rta.Phase :  | batch 0.001000 [s]
2019-02-26 16:56:23,458 INFO    : lisa.wlgen.rta.RTA : Execution start: /root/devlib-target/bin/rt-app /root/devlib-target/rta_calib_cpu5.json 2>&1
2019-02-26 16:56:27,768 INFO    : lisa.wlgen.rta.RTA : Execution complete
2019-02-26 16:56:28,020 INFO    : lisa.wlgen.rta.RTA : CPU6 calibration...
2019-02-26 16:56:28,356 INFO    : lisa.wlgen.rta.RTA : Calibration value: CPU6
2019-02-26 16:56:28,357 INFO    : lisa.wlgen.rta.RTA : Default policy: SCHED_OTHER
2019-02-26 16:56:28,359 INFO    : lisa.wlgen.rta.RTA : ------------------------
2019-02-26 16:56:28,360 INFO    : lisa.wlgen.rta.RTA : task [task1], sched: using default policy
2019-02-26 16:56:28,361 INFO    : lisa.wlgen.rta.RTA :  | start delay: 0.000000 [s]
2019-02-26 16:56:28,363 INFO    : lisa.wlgen.rta.RTA :  | loops count: 1
2019-02-26 16:56:28,364 INFO    : lisa.wlgen.rta.RTA :  + phase_000001
2019-02-26 16:56:28,366 INFO    : lisa.wlgen.rta.Phase :  | batch 0.001000 [s]
2019-02-26 16:56:28,609 INFO    : lisa.wlgen.rta.RTA : Execution start: /root/devlib-target/bin/rt-app /root/devlib-target/rta_calib_cpu6.json 2>&1
2019-02-26 16:56:33,947 INFO    : lisa.wlgen.rta.RTA : Execution complete
2019-02-26 16:56:34,239 INFO    : lisa.wlgen.rta.RTA : CPU7 calibration...
2019-02-26 16:56:34,571 INFO    : lisa.wlgen.rta.RTA : Calibration value: CPU7
2019-02-26 16:56:34,573 INFO    : lisa.wlgen.rta.RTA : Default policy: SCHED_OTHER
2019-02-26 16:56:34,575 INFO    : lisa.wlgen.rta.RTA : ------------------------
2019-02-26 16:56:34,576 INFO    : lisa.wlgen.rta.RTA : task [task1], sched: using default policy
2019-02-26 16:56:34,577 INFO    : lisa.wlgen.rta.RTA :  | start delay: 0.000000 [s]
2019-02-26 16:56:34,579 INFO    : lisa.wlgen.rta.RTA :  | loops count: 1
2019-02-26 16:56:34,580 INFO    : lisa.wlgen.rta.RTA :  + phase_000001
2019-02-26 16:56:34,581 INFO    : lisa.wlgen.rta.Phase :  | batch 0.001000 [s]
2019-02-26 16:56:34,823 INFO    : lisa.wlgen.rta.RTA : Execution start: /root/devlib-target/bin/rt-app /root/devlib-target/rta_calib_cpu7.json 2>&1
2019-02-26 16:56:40,162 INFO    : lisa.wlgen.rta.RTA : Execution complete
2019-02-26 16:56:40,407 INFO    : lisa.wlgen.rta.RTA : Target RT-App calibration: {0: 302, 1: 302, 2: 302, 3: 302, 4: 155, 5: 155, 6: 155, 7: 155}
2019-02-26 16:56:41,962 INFO    : lisa.wlgen.rta.RTA : Calibration value: 155
2019-02-26 16:56:41,963 INFO    : lisa.wlgen.rta.RTA : Default policy: SCHED_OTHER
2019-02-26 16:56:41,964 INFO    : lisa.wlgen.rta.RTA : ------------------------
2019-02-26 16:56:41,965 INFO    : lisa.wlgen.rta.RTA : task [task2], sched: using default policy
2019-02-26 16:56:41,966 INFO    : lisa.wlgen.rta.RTA :  | start delay: 0.000000 [s]
2019-02-26 16:56:41,967 INFO    : lisa.wlgen.rta.RTA :  | loops count: 1
2019-02-26 16:56:41,968 INFO    : lisa.wlgen.rta.RTA :  + phase_000001
2019-02-26 16:56:41,969 INFO    : lisa.wlgen.rta.Phase :  | duration 1.000000 [s] (10 loops)
2019-02-26 16:56:41,970 INFO    : lisa.wlgen.rta.Phase :  |  period   100000 [us], duty_cycle  20 %
2019-02-26 16:56:41,971 INFO    : lisa.wlgen.rta.Phase :  |  run_time  20000 [us], sleep_time  80000 [us]
2019-02-26 16:56:41,972 INFO    : lisa.wlgen.rta.RTA : ------------------------
2019-02-26 16:56:41,974 INFO    : lisa.wlgen.rta.RTA : task [task7], sched: using default policy
2019-02-26 16:56:41,979 INFO    : lisa.wlgen.rta.RTA :  | start delay: 0.000000 [s]
2019-02-26 16:56:41,979 INFO    : lisa.wlgen.rta.RTA :  | loops count: 1
2019-02-26 16:56:41,981 INFO    : lisa.wlgen.rta.RTA :  + phase_000001
2019-02-26 16:56:41,982 INFO    : lisa.wlgen.rta.Phase :  | duration 1.000000 [s] (10 loops)
2019-02-26 16:56:41,983 INFO    : lisa.wlgen.rta.Phase :  |  period   100000 [us], duty_cycle  20 %
2019-02-26 16:56:41,984 INFO    : lisa.wlgen.rta.Phase :  |  run_time  20000 [us], sleep_time  80000 [us]
2019-02-26 16:56:41,985 INFO    : lisa.wlgen.rta.RTA : ------------------------
2019-02-26 16:56:41,987 INFO    : lisa.wlgen.rta.RTA : task [task5], sched: using default policy
2019-02-26 16:56:41,988 INFO    : lisa.wlgen.rta.RTA :  | start delay: 0.000000 [s]
2019-02-26 16:56:41,989 INFO    : lisa.wlgen.rta.RTA :  | loops count: 1
2019-02-26 16:56:41,990 INFO    : lisa.wlgen.rta.RTA :  + phase_000001
2019-02-26 16:56:41,990 INFO    : lisa.wlgen.rta.Phase :  | duration 1.000000 [s] (10 loops)
2019-02-26 16:56:41,991 INFO    : lisa.wlgen.rta.Phase :  |  period   100000 [us], duty_cycle  20 %
2019-02-26 16:56:41,992 INFO    : lisa.wlgen.rta.Phase :  |  run_time  20000 [us], sleep_time  80000 [us]
2019-02-26 16:56:41,993 INFO    : lisa.wlgen.rta.RTA : ------------------------
2019-02-26 16:56:41,994 INFO    : lisa.wlgen.rta.RTA : task [task3], sched: using default policy
2019-02-26 16:56:41,994 INFO    : lisa.wlgen.rta.RTA :  | start delay: 0.000000 [s]
2019-02-26 16:56:41,995 INFO    : lisa.wlgen.rta.RTA :  | loops count: 1
2019-02-26 16:56:41,996 INFO    : lisa.wlgen.rta.RTA :  + phase_000001
2019-02-26 16:56:41,996 INFO    : lisa.wlgen.rta.Phase :  | duration 1.000000 [s] (10 loops)
2019-02-26 16:56:42,002 INFO    : lisa.wlgen.rta.Phase :  |  period   100000 [us], duty_cycle  20 %
2019-02-26 16:56:42,003 INFO    : lisa.wlgen.rta.Phase :  |  run_time  20000 [us], sleep_time  80000 [us]
2019-02-26 16:56:42,004 INFO    : lisa.wlgen.rta.RTA : ------------------------
2019-02-26 16:56:42,004 INFO    : lisa.wlgen.rta.RTA : task [task6], sched: using default policy
2019-02-26 16:56:42,005 INFO    : lisa.wlgen.rta.RTA :  | start delay: 0.000000 [s]
2019-02-26 16:56:42,007 INFO    : lisa.wlgen.rta.RTA :  | loops count: 1
2019-02-26 16:56:42,008 INFO    : lisa.wlgen.rta.RTA :  + phase_000001
2019-02-26 16:56:42,009 INFO    : lisa.wlgen.rta.Phase :  | duration 1.000000 [s] (10 loops)
2019-02-26 16:56:42,010 INFO    : lisa.wlgen.rta.Phase :  |  period   100000 [us], duty_cycle  20 %
2019-02-26 16:56:42,011 INFO    : lisa.wlgen.rta.Phase :  |  run_time  20000 [us], sleep_time  80000 [us]
2019-02-26 16:56:42,012 INFO    : lisa.wlgen.rta.RTA : ------------------------
2019-02-26 16:56:42,012 INFO    : lisa.wlgen.rta.RTA : task [task0], sched: using default policy
2019-02-26 16:56:42,014 INFO    : lisa.wlgen.rta.RTA :  | start delay: 0.000000 [s]
2019-02-26 16:56:42,015 INFO    : lisa.wlgen.rta.RTA :  | loops count: 1
2019-02-26 16:56:42,016 INFO    : lisa.wlgen.rta.RTA :  + phase_000001
2019-02-26 16:56:42,017 INFO    : lisa.wlgen.rta.Phase :  | duration 1.000000 [s] (10 loops)
2019-02-26 16:56:42,019 INFO    : lisa.wlgen.rta.Phase :  |  period   100000 [us], duty_cycle  20 %
2019-02-26 16:56:42,020 INFO    : lisa.wlgen.rta.Phase :  |  run_time  20000 [us], sleep_time  80000 [us]
2019-02-26 16:56:42,021 INFO    : lisa.wlgen.rta.RTA : ------------------------
2019-02-26 16:56:42,022 INFO    : lisa.wlgen.rta.RTA : task [task1], sched: using default policy
2019-02-26 16:56:42,023 INFO    : lisa.wlgen.rta.RTA :  | start delay: 0.000000 [s]
2019-02-26 16:56:42,025 INFO    : lisa.wlgen.rta.RTA :  | loops count: 1
2019-02-26 16:56:42,025 INFO    : lisa.wlgen.rta.RTA :  + phase_000001
2019-02-26 16:56:42,026 INFO    : lisa.wlgen.rta.Phase :  | duration 1.000000 [s] (10 loops)
2019-02-26 16:56:42,027 INFO    : lisa.wlgen.rta.Phase :  |  period   100000 [us], duty_cycle  20 %
2019-02-26 16:56:42,027 INFO    : lisa.wlgen.rta.Phase :  |  run_time  20000 [us], sleep_time  80000 [us]
2019-02-26 16:56:42,028 INFO    : lisa.wlgen.rta.RTA : ------------------------
2019-02-26 16:56:42,029 INFO    : lisa.wlgen.rta.RTA : task [task4], sched: using default policy
2019-02-26 16:56:42,030 INFO    : lisa.wlgen.rta.RTA :  | start delay: 0.000000 [s]
2019-02-26 16:56:42,031 INFO    : lisa.wlgen.rta.RTA :  | loops count: 1
2019-02-26 16:56:42,032 INFO    : lisa.wlgen.rta.RTA :  + phase_000001
2019-02-26 16:56:42,033 INFO    : lisa.wlgen.rta.Phase :  | duration 1.000000 [s] (10 loops)
2019-02-26 16:56:42,035 INFO    : lisa.wlgen.rta.Phase :  |  period   100000 [us], duty_cycle  20 %
2019-02-26 16:56:42,036 INFO    : lisa.wlgen.rta.Phase :  |  run_time  20000 [us], sleep_time  80000 [us]

Now, let's define the functions we want to do some profiling on. Do keep in mind all functions might not be profilable - that can happen if they are inline.


In [7]:
functions = [
    "scheduler_tick",
    "run_rebalance_domains"
]

We're using an FtraceCollector so might as well record some basic events to get a meaningful trace


In [8]:
events = [
    "sched_switch",
    "sched_wakeup",
    "sched_wakeup_new"
]

Running the experiment


In [9]:
from lisa.trace import FtraceCollector

In [10]:
ftrace_coll = FtraceCollector(target, events=events, functions=functions, buffer_size=10240)

with ftrace_coll:
    wload.run()

# Save the profiling stats
ftrace_coll.get_stats(os.path.join(wload.res_dir, "stats.json"))


2019-02-26 16:56:50,587 INFO    : lisa.wlgen.rta.RTA : Execution start: /root/devlib-target/bin/rt-app /root/devlib-target/profiling_wload.json 2>&1
2019-02-26 16:56:51,763 INFO    : lisa.wlgen.rta.RTA : Execution complete
Out[10]:
{0: {'run_rebalance_domains': {'avg': 23.607,
   'hits': 49,
   's_2': 461.905,
   'time': 1156.778},
  'scheduler_tick': {'avg': 14.732,
   'hits': 129,
   's_2': 73.636,
   'time': 1900.519}},
 1: {'run_rebalance_domains': {'avg': 13.903,
   'hits': 36,
   's_2': 26.722,
   'time': 500.522},
  'scheduler_tick': {'avg': 17.21,
   'hits': 68,
   's_2': 129.603,
   'time': 1170.315}},
 2: {'run_rebalance_domains': {'avg': 14.326,
   'hits': 136,
   's_2': 73.246,
   'time': 1948.428},
  'scheduler_tick': {'avg': 6.395,
   'hits': 226,
   's_2': 33.393,
   'time': 1445.303}},
 3: {'run_rebalance_domains': {'avg': 6.534,
   'hits': 11,
   's_2': 3.545,
   'time': 71.875},
  'scheduler_tick': {'avg': 10.807,
   'hits': 32,
   's_2': 10.798,
   'time': 345.836}},
 4: {'run_rebalance_domains': {'avg': 9.157,
   'hits': 67,
   's_2': 35.776,
   'time': 613.537},
  'scheduler_tick': {'avg': 6.605,
   'hits': 236,
   's_2': 9.492,
   'time': 1558.855}},
 5: {'run_rebalance_domains': {'avg': 9.699,
   'hits': 77,
   's_2': 61.791,
   'time': 746.874},
  'scheduler_tick': {'avg': 6.464,
   'hits': 170,
   's_2': 9.395,
   'time': 1098.95}},
 6: {'run_rebalance_domains': {'avg': 7.854,
   'hits': 62,
   's_2': 39.207,
   'time': 486.978},
  'scheduler_tick': {'avg': 5.931,
   'hits': 152,
   's_2': 6.032,
   'time': 901.571}},
 7: {'run_rebalance_domains': {'avg': 9.505,
   'hits': 72,
   's_2': 45.281,
   'time': 684.375},
  'scheduler_tick': {'avg': 6.776,
   'hits': 177,
   's_2': 14.189,
   'time': 1199.471}}}

In [11]:
!tree {wload.res_dir}


/data/work/lisa/results/Target-myhikey960-20190226_165522.134327/RTA-profiling_wload-20190226_165541.167219
├── output.log
├── profiling_wload.json
├── rt-app-task0-0.log
├── rt-app-task0-4.log
├── rt-app-task0-5.log
├── rt-app-task1-0.log
├── rt-app-task1-3.log
├── rt-app-task1-6.log
├── rt-app-task1-7.log
├── rt-app-task2-0.log
├── rt-app-task2-2.log
├── rt-app-task2-6.log
├── rt-app-task3-3.log
├── rt-app-task3-5.log
├── rt-app-task3-6.log
├── rt-app-task3-7.log
├── rt-app-task4-1.log
├── rt-app-task4-4.log
├── rt-app-task4-7.log
├── rt-app-task5-1.log
├── rt-app-task5-2.log
├── rt-app-task5-5.log
├── rt-app-task6-0.log
├── rt-app-task6-1.log
├── rt-app-task6-4.log
├── rt-app-task7-0.log
├── rt-app-task7-1.log
├── rt-app-task7-3.log
├── rt-app-task7-6.log
├── stats.json
└── trace.dat

0 directories, 31 files

Loading the function profiling

The profiling stats are JSON so let's load it up into a dict


In [14]:
import json

In [15]:
stats_path = os.path.join(wload.res_dir, "stats.json")

with open(stats_path, "r") as fh:
    # That ';' is just there to prevent Jupyter from dumping the dict in stdout
    stats = json.load(fh);

The data in the file is arranged like so:

  • For each CPU
    • For each function
      • time (µs)
      • hits (#)
      • s_2, AKA variance - apply sqrt() to get standard deviation
      • avg (µs)

To make it a bit simpler to manipulate, we're going to turn this data into a pandas DataFrame.


In [16]:
import pandas as pd

def stats_to_df(stats_dict):
    """
    Turn Ftrace function profiling stats into a pandas DataFtrame
    
    :param stats_dict: The stats dictionnary generated by FtraceCollector
    :type stats_dict: dict
    """
    data = []
    index = []
    
    for cpu, functions in stats_dict.items():
        index.append(int(cpu))
        columns = []
        line = []
        
        for function, stats in functions.items():
            
            for name, stat in stats.items():
                columns.append((function, name))
                line.append(stat)

        data.append(line)
        
    df = pd.DataFrame(data, index=index, columns=columns)
    df.columns = pd.MultiIndex.from_tuples(df.columns, names=["function", "cpu"])
    df = df.sort_index()
    return df

In [17]:
df = stats_to_df(stats)

Here's how the Dataframe looks like:


In [18]:
df


Out[18]:
function scheduler_tick run_rebalance_domains
cpu hits avg time s_2 hits avg time s_2
0 129 14.732 1900.519 73.636 49 23.607 1156.778 461.905
1 68 17.210 1170.315 129.603 36 13.903 500.522 26.722
2 226 6.395 1445.303 33.393 136 14.326 1948.428 73.246
3 32 10.807 345.836 10.798 11 6.534 71.875 3.545
4 236 6.605 1558.855 9.492 67 9.157 613.537 35.776
5 170 6.464 1098.950 9.395 77 9.699 746.874 61.791
6 152 5.931 901.571 6.032 62 7.854 486.978 39.207
7 177 6.776 1199.471 14.189 72 9.505 684.375 45.281

We can easily have a look at a specific function:


In [19]:
df.run_rebalance_domains


Out[19]:
cpu hits avg time s_2
0 49 23.607 1156.778 461.905
1 36 13.903 500.522 26.722
2 136 14.326 1948.428 73.246
3 11 6.534 71.875 3.545
4 67 9.157 613.537 35.776
5 77 9.699 746.874 61.791
6 62 7.854 486.978 39.207
7 72 9.505 684.375 45.281

It's also easy to get overall stats for one function. For instance, if we want the total number of hits for a function (summing up the number of hits over all CPUs), that can be done like so:


In [20]:
df.run_rebalance_domains.hits.sum()


Out[20]:
510

You can also get stats recorded on a single CPU like so:


In [21]:
df.run_rebalance_domains.loc[2]


Out[21]:
cpu
hits     136.000
avg       14.326
time    1948.428
s_2       73.246
Name: 2, dtype: float64

Visual profiling

Now that we have all of the relevant data in Dataframe format, it's very easy to make plots out of it


In [22]:
import matplotlib.pyplot as plt
import numpy as np

In [23]:
def plot_hits(df, function):
    fig, ax = plt.subplots(figsize=(16, 5))
    
    df[function].hits.plot.bar(ax=ax)    
    ax.set_title("Per-CPU hits of \"{}\"".format(function))
    ax.set_xlabel("CPU")
    ax.set_ylabel("# of hits")
    ax.grid(True)

In [24]:
def plot_time_avg(df, function):
    fig, ax = plt.subplots(figsize=(16, 5))
    
    # Let's compute the standard deviation to plot error bars
    stddev = df[function].s_2.apply(np.sqrt)
    
    df[function].avg.plot.bar(ax=ax, yerr=stddev, capsize=10)    
    ax.set_title("Per-CPU average time of \"{}\"".format(function))
    ax.set_xlabel("CPU")
    ax.set_ylabel("Average time (µs)")
    ax.grid(True)

In [25]:
for function in functions:
    plot_hits(df, function)
    plot_time_avg(df, function)