kernel_functions_profiling


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)