Tutorial Goal

This tutorial aims to show some example of data analysis and visualization from a set of trace events collected trace. These analysis are mainly supported by TRAPpy and other standard PANDAs APIs.


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

Trace Parsing


In [318]:
# Events we are interested to collect from the trace
my_events = [
    "sched_switch",
    "sched_wakeup",
    "sched_contrib_scale_f",
    "sched_load_avg_cpu",
    "sched_load_avg_task",
    "sched_tune_tasks_update",
    "sched_boost_cpu",
    "sched_boost_task",
    "sched_energy_diff",
    "sched_overutilized",
    "cpu_frequency",
    "cpu_capacity"
]

# Let's use an example trace
trace_file = './example_results/trace.dat'

In [319]:
# Use TRAPpy support to convert a trace into a PANDAs DataFrame
import trappy

ftrace = trappy.FTrace(
    name="PandasExamples",
    path=trace_file,
    scope='custom',
    events=my_events,
    window=(0,None))

Trace visualization


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


Accessing DataFrame tables


In [321]:
# Let's have a look at the generated file
!ls -la example_results


total 461132
drwxrwxr-x  4 derkling derkling      4096 Mar  3 10:51 .
drwxrwxr-x 14 derkling derkling      4096 Mar  2 16:24 ..
-rw-rw-r--  1 derkling derkling      9646 Mar  2 16:24 01_IPythonNotebooksUsage.ipynb
-rw-rw-r--  1 derkling derkling     69766 Mar  2 16:59 02_TestEnvUsage.ipynb
-rw-rw-r--  1 derkling derkling     49598 Mar  2 17:20 03_WlGenUsage.ipynb
-rw-rw-r--  1 derkling derkling     18062 Mar  2 17:20 04_ExecutorUsage.ipynb
-rw-rw-r--  1 derkling derkling    170388 Mar  3 10:51 05_TrappyUsage.ipynb
-rw-rw-r--  1 derkling derkling    319096 Mar  3 10:46 06_TraceAnalysis.ipynb
drwxrwxr-x  2 derkling derkling      4096 Mar  3 10:36 example_results
drwxr-xr-x  2 derkling derkling      4096 Mar  3 08:56 .ipynb_checkpoints
-rw-rw-r--  1 derkling derkling 241050436 Mar  2 17:23 trace.raw.txt
-rw-rw-r--  1 derkling derkling 230468272 Mar  2 17:23 trace.txt

Notice that the binary trace has been used to generate both textual (i.e. trace.txt) trace as well as a raw trace (trace.raw.txt).


In [322]:
logging.info("Example of (formatted) 'sched_switch' event:")
with open('./example_results/trace.txt', 'r') as fh:
    for line in fh:
        if line.find('sched_switch') == -1:
            continue
        print line
        break


10:51:52  INFO    : Example of (formatted) 'sched_switch' event:
           <...>-20278 [001]   713.575552: sched_switch:         trace-cmd:20278 [120] x ==> swapper/1:0 [120]


In [323]:
logging.info("Example of (raw) 'sched_switch' event:")
with open('./example_results/trace.raw.txt', 'r') as fh:
    for line in fh:
        if line.find('sched_switch') == -1:
            continue
        print line
        break


10:51:52  INFO    : Example of (raw) 'sched_switch' event:
           <...>-20278 [001]   713.575552: sched_switch:          prev_comm=trace-cmd prev_pid=20278 prev_prio=120 prev_state=64 next_comm=swapper/1 next_pid=0 next_prio=120

Every event correspond to a "table" which is exposed as an attribute of the TRAPpy::FTtrace object we created by parsing the trace.

We can use TRAPpy::FTrace::class_definitions, which is a dictionary tracking all the collected tables.


In [324]:
logging.info("List of events identified in the trace:")
for event in ftrace.class_definitions.keys():
    logging.info("   %s", event)


10:51:53  INFO    : List of events identified in the trace:
10:51:53  INFO    :    sched_load_avg_task
10:51:53  INFO    :    cpu_frequency
10:51:53  INFO    :    cpu_capacity
10:51:53  INFO    :    sched_load_avg_cpu
10:51:53  INFO    :    sched_boost_cpu
10:51:53  INFO    :    sched_tune_tasks_update
10:51:53  INFO    :    sched_boost_task
10:51:53  INFO    :    sched_overutilized
10:51:53  INFO    :    sched_energy_diff
10:51:53  INFO    :    sched_switch
10:51:53  INFO    :    sched_contrib_scale_f
10:51:53  INFO    :    sched_wakeup

In [325]:
# Let's get a reference to the PANDAs DataFrame corresponding to the
# "sched_switch" events
logging.info("The 'sched_switch' events are collected into this DataFrame:")
df = ftrace.sched_switch.data_frame
df#.head(2)


10:51:53  INFO    : The 'sched_switch' events are collected into this DataFrame:
Out[325]:
__comm __cpu __pid next_comm next_pid next_prio prev_comm prev_pid prev_prio prev_state
Time
0.000272 <...> 1 20278 swapper/1 0 120 trace-cmd 20278 120 64
0.000348 <idle> 0 0 sh 20277 120 swapper/0 0 120 0
0.001321 <...> 0 20277 sudo 20276 120 sh 20277 120 64
0.001357 <idle> 1 0 rcu_preempt 7 120 swapper/1 0 120 0
0.001458 rcu_preempt 1 7 swapper/1 0 120 rcu_preempt 7 120 1
0.005202 <...> 0 20276 ksdioirqd/mmc2 1364 98 sudo 20276 120 1024
0.005349 ksdioirqd/mmc2 0 1364 rsyslogd 394 120 ksdioirqd/mmc2 1364 98 1
0.005464 <idle> 1 0 ksoftirqd/1 14 120 swapper/1 0 120 0
0.005528 ksoftirqd/1 1 14 rcu_preempt 7 120 ksoftirqd/1 14 120 1
0.005612 rcu_preempt 1 7 swapper/1 0 120 rcu_preempt 7 120 1
0.005616 rsyslogd 0 394 rs:main Q:Reg 380 120 rsyslogd 394 120 1
0.006245 rs:main 0 380 sudo 20276 120 rs:main Q:Reg 380 120 1
0.007334 <...> 0 20276 rcu_sched 8 120 sudo 20276 120 64
0.007425 <idle> 1 0 bash 19394 120 swapper/1 0 120 0
0.007450 <...> 0 8 swapper/0 0 120 rcu_sched 8 120 1
0.008416 bash 1 19394 kworker/1:2 19472 120 bash 19394 120 1
0.008562 <...> 1 19472 sshd 15461 120 kworker/1:2 19472 120 1
0.009328 sshd 1 15461 rcu_preempt 7 120 sshd 15461 120 1
0.009437 rcu_preempt 1 7 swapper/1 0 120 rcu_preempt 7 120 1
0.009632 <idle> 0 0 rcu_sched 8 120 swapper/0 0 120 0
0.009731 <...> 0 8 swapper/0 0 120 rcu_sched 8 120 1
0.013650 <idle> 1 0 ksoftirqd/1 14 120 swapper/1 0 120 0
0.013727 ksoftirqd/1 1 14 rcu_preempt 7 120 ksoftirqd/1 14 120 1
0.013839 rcu_preempt 1 7 swapper/1 0 120 rcu_preempt 7 120 1
0.017585 <idle> 0 0 ksdioirqd/mmc2 1364 98 swapper/0 0 120 0
0.017587 <idle> 1 0 rcu_preempt 7 120 swapper/1 0 120 0
0.017681 rcu_preempt 1 7 swapper/1 0 120 rcu_preempt 7 120 1
0.017830 ksdioirqd/mmc2 0 1364 ksoftirqd/0 3 120 ksdioirqd/mmc2 1364 98 1
0.017886 ksoftirqd/0 0 3 rcu_sched 8 120 ksoftirqd/0 3 120 1
0.017968 <...> 0 8 swapper/0 0 120 rcu_sched 8 120 1
... ... ... ... ... ... ... ... ... ... ...
35.301101 sudo 1 20990 ksdioirqd/mmc2 1364 98 sudo 20990 120 0
35.301191 ksdioirqd/mmc2 1 1364 sudo 20990 120 ksdioirqd/mmc2 1364 98 2
35.301333 sudo 1 20990 ksdioirqd/mmc2 1364 98 sudo 20990 120 1024
35.301381 ksdioirqd/mmc2 1 1364 sudo 20990 120 ksdioirqd/mmc2 1364 98 1
35.301421 <idle> 0 0 rcu_preempt 7 120 swapper/0 0 120 0
35.301516 rcu_preempt 0 7 swapper/0 0 120 rcu_preempt 7 120 1
35.301782 sudo 1 20990 rsyslogd 394 120 sudo 20990 120 1024
35.302128 rsyslogd 1 394 sudo 20990 120 rsyslogd 394 120 1
35.302198 <idle> 0 0 rs:main Q:Reg 380 120 swapper/0 0 120 0
35.302846 rs:main 0 380 swapper/0 0 120 rs:main Q:Reg 380 120 1
35.303877 <idle> 3 0 sudo 20991 120 swapper/3 0 120 0
35.303987 sudo 1 20990 swapper/1 0 120 sudo 20990 120 1
35.305325 sh 3 20991 migration/3 23 0 sudo 20991 120 1024
35.305428 migration/3 3 23 swapper/3 0 120 migration/3 23 0 1
35.305455 <idle> 1 0 sudo 20991 120 swapper/1 0 120 0
35.309369 <idle> 0 0 rcu_preempt 7 120 swapper/0 0 120 0
35.309480 rcu_preempt 0 7 swapper/0 0 120 rcu_preempt 7 120 1
35.311031 sh 1 20991 sudo 20990 120 sh 20991 120 1
35.311063 <idle> 3 0 sh 20992 120 swapper/3 0 120 0
35.311164 sudo 1 20990 swapper/1 0 120 sudo 20990 120 1
35.311548 trace-cmd 3 20992 migration/3 23 0 sh 20992 120 1024
35.311645 migration/3 3 23 swapper/3 0 120 migration/3 23 0 1
35.311839 <idle> 1 0 sh 20992 120 swapper/1 0 120 0
35.313244 trace-cmd 1 20992 ksdioirqd/mmc2 1364 98 trace-cmd 20992 120 1024
35.313342 ksdioirqd/mmc2 1 1364 ksoftirqd/1 14 120 ksdioirqd/mmc2 1364 98 2
35.313390 ksoftirqd/1 1 14 ksdioirqd/mmc2 1364 98 ksoftirqd/1 14 120 1024
35.313429 <idle> 0 0 rcu_preempt 7 120 swapper/0 0 120 0
35.313437 ksdioirqd/mmc2 1 1364 ksoftirqd/1 14 120 ksdioirqd/mmc2 1364 98 1
35.313485 ksoftirqd/1 1 14 trace-cmd 20992 120 ksoftirqd/1 14 120 1
35.313536 rcu_preempt 0 7 swapper/0 0 120 rcu_preempt 7 120 1

130884 rows × 10 columns

NOTE: We can use head() to report only a limited number of events


In [326]:
# All events parsed in the trace have an associated DataFrame
logging.info("This is the DataFrame for 'cpu_frequency' events:")
df = ftrace.cpu_frequency.data_frame
df.head(2)


10:51:53  INFO    : This is the DataFrame for 'cpu_frequency' events:
Out[326]:
__comm __cpu __pid cpu frequency
Time
0.661132 kschedfreq:2 2 119 2 1807000
0.661136 kschedfreq:2 2 119 3 1807000

Common DataFrame Operations

On DataFrames is possible to execute a number of different operations. Most commonly we are interested in:

  • focus only on certain columns
  • filtering events based on different conditions
  • joining two or more DataFrames
  • resuming statistical data of a DataFrame

Columns selection


In [330]:
df = ftrace.sched_switch.data_frame
df.head(2)


Out[330]:
__comm __cpu __pid next_comm next_pid next_prio prev_comm prev_pid prev_prio prev_state
Time
0.000272 <...> 1 20278 swapper/1 0 120 trace-cmd 20278 120 64
0.000348 <idle> 0 0 sh 20277 120 swapper/0 0 120 0

In [331]:
# The "ix" operator allow to select ranges of [rows:columns]
df = df.ix[:,'next_comm':'prev_state']
df.head(2)


Out[331]:
next_comm next_pid next_prio prev_comm prev_pid prev_prio prev_state
Time
0.000272 swapper/1 0 120 trace-cmd 20278 120 64
0.000348 sh 20277 120 swapper/0 0 120 0

In [332]:
# We can also filter by listing the columns we are interested into
tasks = df[['next_pid', 'next_comm']]
logging.info("Found %d sched_switch events: ", len(tasks))
tasks.head(2)


10:52:30  INFO    : Found 130884 sched_switch events: 
Out[332]:
next_pid next_comm
Time
0.000272 0 swapper/1
0.000348 20277 sh

In [333]:
# Create a map of {PID: TaskName}
pid_to_task = {int(task[0]): task[1] for task in tasks.drop_duplicates().values}
logging.info("The trace has %s unique PIDs", len(pid_to_task))
pid_to_task


10:52:33  INFO    : The trace has 855 unique PIDs
Out[333]:
{0: 'swapper/2',
 1: 'init',
 2: 'kthreadd',
 3: 'ksoftirqd/0',
 6: 'kworker/u8:0',
 7: 'rcu_preempt',
 8: 'rcu_sched',
 10: 'migration/0',
 11: 'watchdog/0',
 12: 'watchdog/1',
 13: 'migration/1',
 14: 'ksoftirqd/1',
 17: 'watchdog/2',
 18: 'migration/2',
 19: 'ksoftirqd/2',
 22: 'watchdog/3',
 23: 'migration/3',
 24: 'ksoftirqd/3',
 31: 'khungtaskd',
 66: 'fsnotify_mark',
 83: 'spi32766',
 88: 'kworker/1:1',
 89: 'kworker/0:1',
 110: 'kworker/u8:3',
 114: 'kworker/0:2',
 118: 'kschedfreq:0',
 119: 'kschedfreq:2',
 122: 'mmcqd/0',
 123: 'mmcqd/0boot0',
 124: 'mmcqd/0boot1',
 125: 'mmcqd/0rpmb',
 128: 'pvr_defer_free',
 129: 'pvr_device_wdg',
 134: 'kworker/3:2',
 136: 'kworker/0:1H',
 138: 'kworker/1:1H',
 166: 'udevd',
 209: 'jbd2/mmcblk0p1-',
 239: 'loop0',
 260: 'jbd2/dm-1-8',
 264: 'kworker/2:1H',
 286: 'kworker/3:1H',
 369: 'rsyslogd',
 380: 'rs:main Q:Reg',
 394: 'rsyslogd',
 395: 'rsyslogd',
 398: 'dbus-daemon',
 489: 'wpa_supplicant',
 492: 'daisydog',
 606: 'tcsd',
 615: 'chapsd',
 648: 'tcsd',
 649: 'powerd',
 650: 'permission_brok',
 656: 'inotify_reader',
 657: 'cryptohomed',
 658: 'tcsd',
 679: 'shill',
 843: 'dhcpcd',
 1150: 'mtpd',
 1179: 'metrics_daemon',
 1184: 'mtpd',
 1190: 'cras',
 1197: 'bluetoothd',
 1232: 'disks',
 1252: 'MountThread',
 1261: 'sshd',
 1264: 'update_engine',
 1364: 'ksdioirqd/mmc2',
 2108: 'warn_collector',
 2252: 'netfilter-queue',
 2266: 'tlsdated',
 2267: 'logger',
 2298: 'kworker/u9:4',
 15461: 'sshd',
 19394: 'bash',
 19469: 'kworker/2:3',
 19472: 'kworker/1:2',
 19861: 'kworker/u8:4',
 19897: 'session_manager',
 19918: 'debugd',
 19933: 'chrome',
 19936: 'sandbox_ipc_thr',
 19938: 'chrome',
 19944: 'nacl_helper_boo',
 19946: 'nacl_helper_non',
 19949: 'chrome',
 19950: 'chrome',
 19963: 'D-Bus thread',
 19964: 'WorkerPool/1996',
 19965: 'WorkerPool/1996',
 19966: 'CrShutdownDetec',
 19967: 'BrowserBlocking',
 19968: 'Chrome_DBThread',
 19969: 'Chrome_FileThre',
 19970: 'Chrome_FileUser',
 19971: 'Chrome_ProcessL',
 19972: 'Chrome_CacheThr',
 19973: 'Chrome_IOThread',
 19974: 'IndexedDB',
 19975: 'CompositorTileW',
 19976: 'AudioThread',
 19979: 'BrowserWatchdog',
 19987: 'handle-watcher-',
 19988: 'gpu-process_cra',
 19990: 'chrome',
 19994: 'CachePoolWorker',
 19995: 'BrowserBlocking',
 19997: 'evdev',
 20013: 'inotify_reader',
 20014: 'Chrome_HistoryT',
 20015: 'BrowserBlocking',
 20016: 'renderer_crash_',
 20017: 'chrome',
 20019: 'chrome',
 20020: 'Watchdog',
 20022: 'Chrome_ChildIOT',
 20023: 'Compositor',
 20024: 'CompositorTileW',
 20025: 'CompositorTileW',
 20026: 'chrome',
 20027: 'UsbEventHandler',
 20030: 'handle-watcher-',
 20032: 'Chrome_ChildIOT',
 20034: 'DrmThread',
 20035: 'handle-watcher-',
 20041: 'HTMLParserThrea',
 20043: 'WorkerPool/9',
 20046: 'WorkerPool/12',
 20052: 'chrome',
 20054: 'Chrome_ChildIOT',
 20055: 'Compositor',
 20056: 'CompositorTileW',
 20057: 'CompositorTileW',
 20058: 'handle-watcher-',
 20060: 'HTMLParserThrea',
 20062: 'WorkerPool/9',
 20064: 'WorkerPool/11',
 20066: 'WorkerPool/12',
 20067: 'WorkerPool/2006',
 20088: 'kworker/u9:0',
 20138: 'watch',
 20276: 'sudo',
 20277: 'sh',
 20282: 'sudo',
 20283: 'sh',
 20284: 'watch',
 20285: 'sh',
 20286: 'sh',
 20287: 'sudo',
 20288: 'sh',
 20289: 'shutils',
 20290: 'cat',
 20291: 'watch',
 20292: 'sh',
 20293: 'sh',
 20294: 'sshd',
 20295: 'sshd',
 20296: 'sshd',
 20297: 'sshd',
 20298: 'sshd',
 20299: 'sshd',
 20300: 'bash',
 20301: 'bash',
 20302: 'chrome',
 20303: 'netstat',
 20304: 'watch',
 20305: 'sh',
 20306: 'netstat',
 20307: 'sh',
 20308: 'netstat',
 20309: 'stop',
 20310: 'rm',
 20311: 'job-filter',
 20312: 'job-filter',
 20313: 'job-filter',
 20314: 'sh',
 20315: 'shill_logout_us',
 20316: 'sh',
 20317: 'basename',
 20318: 'mkdir',
 20319: 'rm',
 20320: 'dbus-send',
 20321: 'rm',
 20322: 'rm',
 20323: 'kworker/0:0',
 20324: 'Shutdown watchd',
 20325: 'Chrome_ProcessL',
 20326: 'kworker/u8:1',
 20327: 'sh',
 20328: 'bootstat',
 20329: 'cryptohome',
 20330: 'sh',
 20331: 'lsof',
 20332: 'sort',
 20333: 'lsof',
 20334: 'watch',
 20335: 'sh',
 20336: 'cat',
 20337: 'udevd',
 20338: 'sudo',
 20339: 'kill',
 20340: 'ps',
 20341: 'logger',
 20342: 'bootstat',
 20343: 'pkill',
 20344: 'pgrep',
 20345: 'sh',
 20346: 'cryptohome',
 20347: 'bootstat',
 20348: 'sshd',
 20349: 'rm',
 20350: 'status',
 20351: 'start',
 20352: 'job-filter',
 20353: 'sh',
 20354: 'job-filter',
 20355: 'job-filter',
 20356: 'pvrsrvctl',
 20357: 'sh',
 20358: 'sh',
 20359: 'touch',
 20360: 'bootstat',
 20361: 'chmod',
 20362: 'crossystem',
 20363: 'dump_vpd_log',
 20364: 'mkdir',
 20365: 'mktemp',
 20366: 'mkdir',
 20367: 'bootstat',
 20368: 'chown',
 20369: 'chmod',
 20370: 'lockbox-cache',
 20371: 'chmod',
 20372: 'mktemp',
 20373: 'mktemp',
 20374: 'mktemp',
 20375: 'getopt',
 20376: 'getopt',
 20377: 'dump_vpd_log',
 20378: 'dump_vpd_log',
 20379: 'dump_vpd_log',
 20380: 'dump_vpd_log',
 20381: 'grep',
 20382: 'dump_vpd_log',
 20383: 'grep',
 20384: 'dump_vpd_log',
 20385: 'grep',
 20386: 'watch',
 20387: 'sh',
 20388: 'cat',
 20389: 'dump_vpd_log',
 20390: 'grep',
 20391: 'dump_vpd_log',
 20392: 'grep',
 20393: 'dump_vpd_log',
 20394: 'grep',
 20395: 'dump_vpd_log',
 20396: 'grep',
 20397: 'dump_vpd_log',
 20398: 'grep',
 20399: 'dump_vpd_log',
 20400: 'grep',
 20401: 'dump_vpd_log',
 20402: 'grep',
 20403: 'dump_vpd_log',
 20404: 'grep',
 20405: 'dump_vpd_log',
 20406: 'grep',
 20407: 'dump_vpd_log',
 20408: 'grep',
 20409: 'dump_vpd_log',
 20410: 'dump_vpd_log',
 20411: 'dump_vpd_log',
 20412: 'dump_vpd_log',
 20413: 'dump_vpd_log',
 20414: 'dump_vpd_log',
 20415: 'dump_vpd_log',
 20416: 'dump_vpd_log',
 20417: 'dump_vpd_log',
 20418: 'dump_vpd_log',
 20419: 'dump_vpd_log',
 20420: 'dump_vpd_log',
 20421: 'dump_vpd_log',
 20422: 'dump_vpd_log',
 20423: 'dump_vpd_log',
 20424: 'sed',
 20425: 'dump_vpd_log',
 20426: 'dump_vpd_log',
 20427: 'dump_vpd_log',
 20428: 'dump_vpd_log',
 20429: 'dump_vpd_log',
 20430: 'dump_vpd_log',
 20431: 'dump_vpd_log',
 20432: 'getopt',
 20433: 'expr',
 20434: 'expr',
 20435: 'dump_vpd_log',
 20436: 'grep',
 20437: 'dump_vpd_log',
 20438: 'expr',
 20439: 'dump_vpd_log',
 20440: 'grep',
 20441: 'dump_vpd_log',
 20442: 'rm',
 20443: 'rm',
 20444: 'rm',
 20445: 'dirname',
 20446: 'dirname',
 20447: 'mkdir',
 20448: 'dump_vpd_log',
 20449: 'sed',
 20450: 'rm',
 20451: 'sh',
 20452: 'mkdir',
 20453: 'date',
 20454: 'ln',
 20455: 'chown',
 20456: 'session_manager',
 20457: 'job-filter',
 20458: 'ps',
 20459: 'sh',
 20460: 'chgrp',
 20461: 'chmod',
 20462: 'chgrp',
 20463: 'chmod',
 20464: 'chgrp',
 20465: 'chmod',
 20466: 'chgrp',
 20467: 'chmod',
 20468: 'chgrp',
 20469: 'chmod',
 20470: 'chgrp',
 20471: 'chmod',
 20472: 'session_manager',
 20473: 'cp',
 20474: 'is_developer_en',
 20475: 'crossystem',
 20476: 'debugd',
 20477: 'chrome',
 20478: 'minijail0',
 20479: 'is_developer_en',
 20480: 'crossystem',
 20481: 'sandbox_ipc_thr',
 20482: 'chrome',
 20483: 'ps',
 20484: 'chrome',
 20485: 'cryptohome',
 20486: 'nacl_helper_boo',
 20487: 'nacl_helper_boo',
 20488: 'nacl_helper_non',
 20489: 'nacl_helper_non',
 20490: 'chrome',
 20491: 'chrome',
 20492: 'chrome',
 20493: 'watch',
 20494: 'sh',
 20495: 'cat',
 20496: 'wget',
 20497: 'sleep',
 20498: 'dbus-send',
 20499: 'kworker/1:0',
 20500: 'sleep',
 20501: 'wget',
 20502: 'wget',
 20503: 'wget',
 20504: 'watch',
 20505: 'sh',
 20506: 'sh',
 20507: 'wget',
 20508: 'wget',
 20509: 'wget',
 20510: 'wget',
 20511: 'wget',
 20512: 'wget',
 20513: 'wget',
 20514: 'watch',
 20515: 'sh',
 20516: 'cat',
 20517: 'wget',
 20518: 'wget',
 20519: 'wget',
 20520: 'wget',
 20521: 'watch',
 20522: 'sh',
 20523: 'cat',
 20524: 'wget',
 20525: 'wget',
 20526: 'wget',
 20527: 'chrome',
 20528: 'watch',
 20529: 'sh',
 20530: 'sh',
 20531: 'sandbox_ipc_thr',
 20532: 'chrome',
 20533: 'chrome',
 20534: 'wget',
 20535: 'nacl_helper_boo',
 20536: 'nacl_helper_boo',
 20537: 'nacl_helper_non',
 20538: 'nacl_helper_non',
 20539: 'chrome',
 20540: 'chrome',
 20541: 'chrome',
 20542: 'D-Bus thread',
 20543: 'WorkerPool/2054',
 20544: 'WorkerPool/2054',
 20545: 'CrShutdownDetec',
 20546: 'BrowserBlocking',
 20547: 'Chrome_DBThread',
 20548: 'Chrome_FileThre',
 20549: 'Chrome_FileUser',
 20550: 'Chrome_ProcessL',
 20551: 'Chrome_CacheThr',
 20552: 'Chrome_IOThread',
 20553: 'IndexedDB',
 20554: 'CompositorTileW',
 20555: 'AudioThread',
 20556: 'crossystem',
 20557: 'handle-watcher-',
 20558: 'BrowserWatchdog',
 20559: 'gpu-process_cra',
 20560: 'chrome',
 20561: 'crossystem',
 20562: 'crossystem',
 20563: 'CachePoolWorker',
 20564: 'crossystem',
 20565: 'crossystem',
 20566: 'crossystem',
 20567: 'mosys',
 20568: 'crossystem',
 20569: 'mosys',
 20570: 'crossystem',
 20571: 'mosys',
 20572: 'crossystem',
 20573: 'crossystem',
 20574: 'crossystem',
 20575: 'crossystem',
 20576: 'wget',
 20577: 'crossystem',
 20578: 'crossystem',
 20579: 'crossystem',
 20580: 'crossystem',
 20581: 'crossystem',
 20582: 'mosys',
 20583: 'mosys',
 20584: 'mosys',
 20585: 'mosys',
 20586: 'mosys',
 20587: 'mosys',
 20588: 'mosys',
 20589: 'mosys',
 20590: 'mosys',
 20591: 'inotify_reader',
 20592: 'chrome',
 20593: 'chrome',
 20594: 'Watchdog',
 20595: 'evdev',
 20596: 'Chrome_ChildIOT',
 20597: 'DrmThread',
 20598: 'handle-watcher-',
 20599: 'BrowserBlocking',
 20600: 'Chrome_HistoryT',
 20601: 'BrowserBlocking',
 20602: 'Startup watchdo',
 20603: 'Chrome_DevTools',
 20604: 'WorkerPool/2060',
 20605: 'wget',
 20606: 'watch',
 20607: 'sh',
 20608: 'cat',
 20609: 'WorkerPool/2060',
 20610: 'WorkerPool/2061',
 20611: 'WorkerPool/2061',
 20612: 'chrome',
 20613: 'chrome',
 20614: 'renderer_crash_',
 20615: 'chrome',
 20616: 'Chrome_ChildIOT',
 20617: 'Compositor',
 20618: 'CompositorTileW',
 20619: 'CompositorTileW',
 20620: 'chrome',
 20621: 'UsbEventHandler',
 20622: 'handle-watcher-',
 20623: 'HTMLParserThrea',
 20624: 'WorkerPool/8',
 20625: 'watch',
 20626: 'sh',
 20627: 'cat',
 20628: 'WorkerPool/9',
 20629: 'WorkerPool/10',
 20630: 'WorkerPool/11',
 20631: 'watch',
 20632: 'sh',
 20633: 'cat',
 20634: 'cryptohome-path',
 20635: 'chrome',
 20636: 'tcsd',
 20637: 'df',
 20638: 'WorkerPool/12',
 20639: 'watch',
 20640: 'sh',
 20641: 'cat',
 20642: 'cryptohome-path',
 20643: 'df',
 20644: 'cryptohome-path',
 20645: 'df',
 20646: 'cryptohome-path',
 20647: 'df',
 20648: 'udevd',
 20649: 'sshd',
 20650: 'df',
 20651: 'sh',
 20652: 'chapsd',
 20653: 'crossystem',
 20654: 'rm',
 20655: 'job-filter',
 20656: 'init',
 20657: 'sh',
 20658: 'shill_login_use',
 20659: 'touch',
 20660: 'basename',
 20661: 'cryptohome-path',
 20662: 'basename',
 20663: 'cryptohome-path',
 20664: 'mkdir',
 20665: 'mkdir',
 20666: 'chrome',
 20667: 'ln',
 20668: 'mkdir',
 20669: 'ln',
 20670: 'dbus-send',
 20671: 'dbus-send',
 20672: 'keygen',
 20673: 'watch',
 20674: 'sh',
 20675: 'cryptohome-path',
 20676: 'sh',
 20677: 'Chrome_HistoryT',
 20678: 'df',
 20679: 'chrome',
 20680: 'Chrome_ChildIOT',
 20681: 'Compositor',
 20682: 'CompositorTileW',
 20683: 'CompositorTileW',
 20684: 'handle-watcher-',
 20685: 'chrome',
 20686: 'extension_crash',
 20687: 'chrome',
 20688: 'Chrome_ChildIOT',
 20689: 'Compositor',
 20690: 'CompositorTileW',
 20691: 'CompositorTileW',
 20692: 'handle-watcher-',
 20693: 'kworker/u9:1',
 20694: 'HTMLParserThrea',
 20695: 'HTMLParserThrea',
 20696: 'watch',
 20697: 'sh',
 20698: 'sh',
 20699: 'WorkerPool/8',
 20700: 'WorkerPool/9',
 20701: 'WorkerPool/10',
 20702: 'WorkerPool/11',
 20703: 'WorkerPool/12',
 20704: 'WorkerPool/13',
 20705: 'chrome',
 20706: 'Chrome_ChildIOT',
 20707: 'Compositor',
 20708: 'CompositorTileW',
 20709: 'CompositorTileW',
 20710: 'chrome',
 20711: 'handle-watcher-',
 20712: 'HTMLParserThrea',
 20713: 'chrome',
 20714: 'WorkerPool/8',
 20715: 'watch',
 20716: 'sh',
 20717: 'cat',
 20718: 'watch',
 20719: 'sh',
 20720: 'cat',
 20721: 'ScriptStreamerT',
 20722: 'WorkerPool/10',
 20723: 'WorkerPool/11',
 20724: 'watch',
 20725: 'sh',
 20726: 'cat',
 20727: 'watch',
 20728: 'sh',
 20729: 'cat',
 20730: 'chrome',
 20731: 'chrome',
 20732: 'Chrome_ChildIOT',
 20733: 'Compositor',
 20734: 'CompositorTileW',
 20735: 'CompositorTileW',
 20736: 'handle-watcher-',
 20737: 'chrome',
 20738: 'HTMLParserThrea',
 20739: 'watch',
 20740: 'sh',
 20741: 'cat',
 20742: 'watch',
 20743: 'sh',
 20744: 'cat',
 20745: 'watch',
 20746: 'sh',
 20747: 'cat',
 20748: 'mosys',
 20749: 'sh',
 20750: 'which',
 20751: 'flashrom',
 20752: 'sh',
 20753: 'sh',
 20754: 'watch',
 20755: 'sh',
 20756: 'cat',
 20757: 'WorkerPool/12',
 20758: 'watch',
 20759: 'sh',
 20760: 'cat',
 20761: 'watch',
 20762: 'sh',
 20763: 'cat',
 20764: 'watch',
 20765: 'sh',
 20766: 'cat',
 20767: 'watch',
 20768: 'sh',
 20769: 'cat',
 20770: 'watch',
 20771: 'sh',
 20772: 'sh',
 20773: 'ps',
 20774: 'watch',
 20775: 'sh',
 20776: 'sh',
 20777: 'status',
 20778: 'restart',
 20779: 'job-filter',
 20780: 'init',
 20781: 'init',
 20782: 'sh',
 20783: 'shill_logout_us',
 20784: 'basename',
 20785: 'sh',
 20786: 'mkdir',
 20787: 'dbus-send',
 20788: 'rm',
 20789: 'rm',
 20790: 'rm',
 20791: 'Shutdown watchd',
 20792: 'chrome',
 20793: 'Chrome_ProcessL',
 20794: 'kworker/0:3',
 20795: 'watch',
 20796: 'sh',
 20797: 'sh',
 20798: 'sh',
 20799: 'bootstat',
 20800: 'cryptohome',
 20801: 'chapsd',
 20802: 'sh',
 20803: 'lsof',
 20804: 'sort',
 20805: 'lsof',
 20806: 'sudo',
 20807: 'kill',
 20808: 'ps',
 20809: 'logger',
 20810: 'udevd',
 20811: 'bootstat',
 20812: 'pkill',
 20813: 'pgrep',
 20814: 'bootstat',
 20815: 'cryptohome',
 20816: 'bootstat',
 20817: 'job-filter',
 20818: 'job-filter',
 20819: 'sh',
 20820: 'sh',
 20821: 'init',
 20822: 'sh',
 20823: 'sh',
 20824: 'sh',
 20825: 'chmod',
 20826: 'bootstat',
 20827: 'sh',
 20828: 'dump_vpd_log',
 20829: 'mktemp',
 20830: 'mkdir',
 20831: 'dump_vpd_log',
 20832: 'chown',
 20833: 'bootstat',
 20834: 'chmod',
 20835: 'lockbox-cache',
 20836: 'chmod',
 20837: 'mktemp',
 20838: 'dump_vpd_log',
 20839: 'mktemp',
 20840: 'dump_vpd_log',
 20841: 'getopt',
 20842: 'dump_vpd_log',
 20843: 'dump_vpd_log',
 20844: 'awk',
 20845: 'dump_vpd_log',
 20846: 'grep',
 20847: 'dump_vpd_log',
 20848: 'grep',
 20849: 'dump_vpd_log',
 20850: 'dump_vpd_log',
 20851: 'dump_vpd_log',
 20852: 'grep',
 20853: 'watch',
 20854: 'sh',
 20855: 'dump_vpd_log',
 20856: 'grep',
 20857: 'sh',
 20858: 'dump_vpd_log',
 20859: 'grep',
 20860: 'dump_vpd_log',
 20861: 'grep',
 20862: 'dump_vpd_log',
 20863: 'grep',
 20864: 'dump_vpd_log',
 20865: 'grep',
 20866: 'dump_vpd_log',
 20867: 'grep',
 20868: 'dump_vpd_log',
 20869: 'grep',
 20870: 'dump_vpd_log',
 20871: 'grep',
 20872: 'dump_vpd_log',
 20873: 'grep',
 20874: 'dump_vpd_log',
 20875: 'dump_vpd_log',
 20876: 'dump_vpd_log',
 20877: 'dump_vpd_log',
 20878: 'dump_vpd_log',
 20879: 'dump_vpd_log',
 20880: 'dump_vpd_log',
 20881: 'dump_vpd_log',
 20882: 'dump_vpd_log',
 20883: 'dump_vpd_log',
 20884: 'dump_vpd_log',
 20885: 'dump_vpd_log',
 20886: 'dump_vpd_log',
 20887: 'dump_vpd_log',
 20888: 'dump_vpd_log',
 20889: 'dump_vpd_log',
 20890: 'dump_vpd_log',
 20891: 'dump_vpd_log',
 20892: 'dump_vpd_log',
 20893: 'dump_vpd_log',
 20894: 'dump_vpd_log',
 20895: 'dump_vpd_log',
 20896: 'dump_vpd_log',
 20897: 'getopt',
 20898: 'expr',
 20899: 'expr',
 20900: 'dump_vpd_log',
 20901: 'grep',
 20902: 'dump_vpd_log',
 20903: 'expr',
 20904: 'dump_vpd_log',
 20905: 'grep',
 20906: 'dump_vpd_log',
 20907: 'rm',
 20908: 'rm',
 20909: 'rm',
 20910: 'dirname',
 20911: 'dirname',
 20912: 'mkdir',
 20913: 'dump_vpd_log',
 20914: 'sed',
 20915: 'rm',
 20916: 'sh',
 20917: 'mkdir',
 20918: 'date',
 20919: 'ln',
 20920: 'chown',
 20921: 'session_manager',
 20922: 'job-filter',
 20923: 'sshd',
 20924: 'sh',
 20925: 'chgrp',
 20926: 'sh',
 20927: 'sh',
 20928: 'sh',
 20929: 'sh',
 20930: 'sh',
 20931: 'sshd',
 20932: 'sh',
 20933: 'crossystem',
 20934: 'chmod',
 20935: 'sh',
 20936: 'chmod',
 20937: 'is_developer_en',
 20938: 'sh',
 20939: 'crossystem',
 20940: 'chmod',
 20941: 'watch',
 20942: 'sh',
 20943: 'sh',
 20944: 'cp',
 20945: 'debugd',
 20946: 'mosys',
 20947: 'sh',
 20948: 'which',
 20949: 'flashrom',
 20950: 'sh',
 20951: 'crossystem',
 20952: 'sshd',
 20953: 'sshd',
 20954: 'sshd',
 20955: 'sshd',
 20956: 'cryptohome-path',
 20957: 'minijail0',
 20958: 'is_developer_en',
 20959: 'is_developer_en',
 20960: 'chrome',
 20961: 'sshd',
 20962: 'sshd',
 20963: 'sandbox_ipc_thr',
 20964: 'chrome',
 20965: 'chrome',
 20966: 'sshd',
 20967: 'sshd',
 20968: 'sshd',
 20969: 'sshd',
 20970: 'bash',
 20971: 'nacl_helper_boo',
 20972: 'nacl_helper_boo',
 20973: 'nacl_helper_non',
 20974: 'nacl_helper_non',
 20975: 'chrome',
 20976: 'chrome',
 20977: 'chrome',
 20978: 'sudo',
 20979: 'sh',
 20980: 'shutils',
 20981: 'cat',
 20982: 'watch',
 20983: 'sh',
 20984: 'sh',
 20985: 'sudo',
 20986: 'sudo',
 20987: 'watch',
 20988: 'sh',
 20989: 'sh',
 20990: 'sudo',
 20991: 'sudo',
 20992: 'trace-cmd'}

Events grouping


In [118]:
# Group events by "PID" and compute 
most_switching = df.groupby('next_pid').describe(include=['object'])
most_switching.head()


Out[118]:
next_comm prev_comm
next_pid
0 count 20400 20400
unique 4 158
top swapper/1 chrome
freq 8442 5964
1 count 372 372

In [119]:
most_switching = most_switching.unstack()
most_switching.head()


Out[119]:
next_comm prev_comm
count unique top freq count unique top freq
next_pid
0 20400 4 swapper/1 8442 20400 158 chrome 5964
1 372 1 init 372 372 33 dbus-daemon 90
2 5 1 kthreadd 5 5 5 swapper/1 1
3 761 1 ksoftirqd/0 761 761 36 rcu_preempt 246
6 2275 1 kworker/u8:0 2275 2275 64 chrome 475

In [124]:
most_switching = most_switching['next_comm']\
                 .sort_values(by=['count'], ascending=False)
most_switching.head()


Out[124]:
count unique top freq
next_pid
0 20400 4 swapper/1 8442
20552 9224 2 Chrome_IOThread 9223
20527 8309 2 chrome 8307
20560 6898 3 chrome 6797
7 5516 1 rcu_preempt 5516

In [231]:
most_switching_pid  = most_switching.index[1]
most_switching_task = most_switching.values[1][2]
task_name = "{}:{}".format(most_switching_pid, most_switching_task)
logging.info("The second most swithing task is: [%s]", task_name)


07:08:50  INFO    : The second most swithing task is: [20552:Chrome_IOThread]

Filtering by column value


In [188]:
# Lets use the previous information to filter values of another DataFrame
# Here we use the events reporting the task utilization signal
df = ftrace.sched_load_avg_task.data_frame.ix[:,'comm':'util_sum']
logging.info("Total events: %d", len(df))
df.head()


06:45:37  INFO    : Total events: 220234
Out[188]:
comm cpu load_avg load_sum period_contrib pid util_avg util_sum
Time
0.000014 trace-cmd 1 58 2811439 916 20278 33 1601714
0.000229 trace-cmd 1 59 2820191 111 20278 33 1612418
0.000334 sh 0 0 0 957 20277 0 0
0.000982 sh 0 5 285169 710 20277 3 164585
0.001178 sh 0 5 355825 903 20277 3 205364

In [189]:
# Select only events for the task of interest
select = (df.pid == most_switching_pid)

task_events = df[select]
logging.info("Selected events: %d", len(task_events))
task_events.head()


06:45:37  INFO    : Selected events: 19129
Out[189]:
comm cpu load_avg load_sum period_contrib pid util_avg util_sum
Time
10.277545 chrome 3 5 279939 876 20552 0 0
10.278066 Chrome_IOThread 3 8 421520 374 20552 3 147580
10.278226 Chrome_IOThread 3 8 421520 501 20552 3 147580
10.279379 Chrome_IOThread 3 15 739012 629 20552 9 470942
10.279542 Chrome_IOThread 3 15 739012 765 20552 9 470942

In [194]:
# We can also compose a query using multiple conditions
select = (((task_events.cpu != 1) & (task_events.cpu != 2)) & ~(task_events.util_avg < 450))

task_events = task_events[select]
logging.info("Selected events: %d", len(task_events))
task_events.head()


06:47:30  INFO    : Selected events: 2007
Out[194]:
comm cpu load_avg load_sum period_contrib pid util_avg util_sum
Time
17.112905 Chrome_IOThread 3 989 47260557 91 20552 452 21592551
17.113017 Chrome_IOThread 3 989 47333261 196 20552 452 21592551
17.113273 Chrome_IOThread 3 989 47571853 429 20552 452 21831143
17.113552 Chrome_IOThread 3 989 47866765 717 20552 452 21831143
17.114018 Chrome_IOThread 3 990 47295142 143 20552 456 21817410

Row selection


In [198]:
# Row selection is also possible, which in our case corresponds to limiting 
# the events on a specified time frame
task_events.ix[21.1:22.9,].head()


Out[198]:
comm cpu load_avg load_sum period_contrib pid util_avg util_sum
Time
21.983876 Chrome_IOThread 3 860 41072776 117 20552 452 21610419
21.983908 Chrome_IOThread 3 860 41109640 153 20552 452 21610419
21.983928 Chrome_IOThread 3 860 41129096 172 20552 452 21629875
21.983987 Chrome_IOThread 3 860 41188488 230 20552 452 21629875
21.984067 Chrome_IOThread 3 860 41263240 303 20552 452 21704627

DataFrame Merging


In [218]:
# Let's make use of yet another DataFrame, let's look at the frequencies
frequencies = ftrace.cpu_frequency.data_frame

select = (frequencies.cpu == 0)
frequencies = frequencies.ix[21.1:22.9,'cpu':'frequency'][select]
logging.info("Selected events: %d", len(frequencies))
frequencies.head()


06:59:46  INFO    : Selected events: 17
Out[218]:
cpu frequency
Time
21.215426 0 1001000
21.265745 0 1404000
21.412728 0 507000
21.465761 0 1404000
21.541466 0 507000

In [222]:
# Let's merge the task signal frame with the CPUs frequencies
task_util_and_freq = task_events.join(
    frequencies,
    how='outer',
    lsuffix='lx_')#[['util_avg', 'frequency']]
logging.info("Selected events: %d", len(task_util_and_freq))
task_util_and_freq.tail()


06:59:59  INFO    : Selected events: 2024
Out[222]:
comm cpulx_ load_avg load_sum period_contrib pid util_avg util_sum cpu frequency
Time
22.701783 Chrome_IOThread 3 893 42702053 124 20552 457 21865198 NaN NaN
22.701807 Chrome_IOThread 3 893 42727653 149 20552 457 21865198 NaN NaN
22.701824 Chrome_IOThread 3 893 42743013 164 20552 457 21880558 NaN NaN
22.768356 NaN NaN NaN NaN NaN NaN NaN NaN 0 1183000
22.818657 NaN NaN NaN NaN NaN NaN NaN NaN 0 1404000

In [223]:
# The new table has the union of events from the two original tables
len(task_events) + len(frequencies)


Out[223]:
2024

In [224]:
# Let's propagate missing columns values...
task_util_and_freq = task_util_and_freq.fillna(method='ffill')
task_util_and_freq.tail()


Out[224]:
comm cpulx_ load_avg load_sum period_contrib pid util_avg util_sum cpu frequency
Time
22.701783 Chrome_IOThread 3 893 42702053 124 20552 457 21865198 0 1404000
22.701807 Chrome_IOThread 3 893 42727653 149 20552 457 21865198 0 1404000
22.701824 Chrome_IOThread 3 893 42743013 164 20552 457 21880558 0 1404000
22.768356 Chrome_IOThread 3 893 42743013 164 20552 457 21880558 0 1183000
22.818657 Chrome_IOThread 3 893 42743013 164 20552 457 21880558 0 1404000

In [226]:
# NOTE: missing values at the beginning can be fixe as well
#       ...but that behind that demo!
# LISA has a set of methods which provides a complete and realiable solutions
# to do this kind of compositions on data frames

Plotting

Using pylab


In [227]:
# Enable generation of Notebook emebedded plots
%pylab inline


Populating the interactive namespace from numpy and matplotlib
WARNING: pylab import has clobbered these variables: ['e', 'select']
`%matplotlib` prevents importing * from pylab and numpy

In [229]:
task_util_and_freq[['util_avg', 'frequency']].plot(drawstyle="steps-post")


Out[229]:
<matplotlib.axes._subplots.AxesSubplot at 0x7f0c7e2c0890>

In [260]:
import matplotlib.gridspec as gridspec

t_min = 21.5
t_max = 23.0

gs = gridspec.GridSpec(2, 1, height_ratios=[2,1]);

plt.figure(figsize=(16, 8));
plt.suptitle("Task Utilization vs Frequency",
             y=.97, fontsize=16, horizontalalignment='center');

# Plot Utilization
data = task_util_and_freq['util_avg']
axes = plt.subplot(gs[0,0]);
data.plot(ax=axes, drawstyle='steps-post');
axes.set_title('Task [{}] Utilization'.format(task_name));
axes.set_ylabel('Utilization')
axes.set_xlim(t_min, t_max);
axes.grid(True);
axes.set_xticklabels([])
axes.set_xlabel('')


# Plot Frequencies
data = task_util_and_freq['frequency']/1000
axes = plt.subplot(gs[1,0]);
data.plot(ax=axes, drawstyle='steps-post');
axes.set_title('Frequencies');
axes.set_ylabel('MHz')
axes.set_xlim(t_min, t_max);
axes.grid(True);


Plots can be much better with just a little bit of setup and using the proper APIs.
That's why LISA aims at providing a predefined set of plot functions for commonly used analysis.

Using TRAPpy LinePlotter


In [306]:
# Consider the data frame for the frequency switching events
logging.info("Table for 'cpu_frequency' events:")
ftrace.cpu_frequency.data_frame.head(1)


08:01:48  INFO    : Table for 'cpu_frequency' events:
Out[306]:
__comm __cpu __pid cpu frequency start delta
Time
0.661132 kschedfreq:2 2 119 2 1807000 0.661132 0.000004

In [309]:
# It is possible to mix in the same plot multiple events

# The LinePlot module requires to specify a list of signals to plot.
# Each signal is defined as:
#       <event>:<column>
# where:
#  <event>   is one of the events collected from the trace by the FTrace object
#  <column>  is one of the column of the previously defined event
my_signals = [
    'cpu_frequency:frequency',
]

# These two paramatere are passed to the LinePlot call as long with the
# TRAPpy FTrace object
trappy.LinePlot(
    
    # FTrace object
    ftrace,
    
    # Signals to be plotted
    signals=my_signals,
    
    # Generate one plot for each value of the specified column
    pivot='cpu',
    
    # Generate only plots which satisfy these filters
    filters = {
        # Column
        # |     Values
        # |     |
        'cpu' : [0, 1]
    },
    
    # Formatting style
    drawstyle='steps-post',
    marker = '+'

).view()


Using TRAPpy Interactive LinePlotter


In [298]:
# We can also produce interacive plots
trappy.ILinePlot(
    ftrace,                         # TRAPpy RUN object
    signals=[
      'cpu_frequency:frequency'
    ],
    drawstyle='steps-post',
    per_line=1,
#     sync_zoom=True,
#     group='UtilVsFrequency',
    marker = '+').view()

trappy.ILinePlot(
    ftrace,                         # TRAPpy RUN object
    signals=[
      'sched_load_avg_task:util_avg'
    ],
    filters={
        'pid': [most_switching_pid]
    },
    drawstyle='steps-post',
    per_line=1,
#     sync_zoom=True,
#     group='UtilVsFrequency',
    marker = '+').view()


You can find much more exaples of plotting in TRAPpy on the example notebook available on the GitHub:
https://github.com/ARM-software/trappy/blob/master/doc/Plotter.ipynb

Data aggregation and analysis


In [274]:
df = ftrace.cpu_frequency.data_frame
df.head()


Out[274]:
__comm __cpu __pid cpu frequency start delta
Time
0.661132 kschedfreq:2 2 119 2 1807000 0.661132 0.000004
0.661136 kschedfreq:2 2 119 3 1807000 0.661136 0.051760
0.712896 kschedfreq:2 2 119 2 507000 0.712896 0.000009
0.712905 kschedfreq:2 2 119 3 507000 0.712905 0.473305
1.186210 sh 0 20289 0 507000 1.186210 0.000252

In [275]:
# Lets compute the residency on each OPP
df.loc[:,'start'] = df.index
df.loc[:,'delta'] = (df['start'] - df['start'].shift()).fillna(0).shift(-1)
df.head()


Out[275]:
__comm __cpu __pid cpu frequency start delta
Time
0.661132 kschedfreq:2 2 119 2 1807000 0.661132 0.000004
0.661136 kschedfreq:2 2 119 3 1807000 0.661136 0.051760
0.712896 kschedfreq:2 2 119 2 507000 0.712896 0.000009
0.712905 kschedfreq:2 2 119 3 507000 0.712905 0.473305
1.186210 sh 0 20289 0 507000 1.186210 0.000252

In [276]:
import pandas as pd

# Now we can get group by frequency and sum the partional residency times
freq_residencies = df.groupby('frequency')['delta'].sum()
logging.info("Residency time per OPP:")
df = pd.DataFrame(freq_residencies)
df


07:37:46  INFO    : Residency time per OPP:
Out[276]:
delta
frequency
507000 11.141186
702000 1.832051
1001000 2.810101
1105000 1.160819
1183000 1.321498
1209000 2.794528
1404000 9.991687
1612000 0.506026
1807000 2.727041

In [283]:
# Compute the relative residency time
tot = sum(freq_residencies)
#df = df.apply(lambda delta : 100*delta/tot)
for f in freq_residencies.index:
    logging.info("Freq %10dHz : %5.1f%%", f, 100*freq_residencies[f]/tot)


07:43:01  INFO    : Freq     507000Hz :  32.5%
07:43:01  INFO    : Freq     702000Hz :   5.3%
07:43:01  INFO    : Freq    1001000Hz :   8.2%
07:43:01  INFO    : Freq    1105000Hz :   3.4%
07:43:01  INFO    : Freq    1183000Hz :   3.9%
07:43:01  INFO    : Freq    1209000Hz :   8.2%
07:43:01  INFO    : Freq    1404000Hz :  29.1%
07:43:01  INFO    : Freq    1612000Hz :   1.5%
07:43:01  INFO    : Freq    1807000Hz :   8.0%

In [281]:
# Plot residency time
fig, axes = plt.subplots(1, 1, figsize=(16, 5));
df.plot(kind='bar', ax=axes)


Out[281]:
<matplotlib.axes._subplots.AxesSubplot at 0x7f0c79c6c9d0>