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

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)

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