1. Prepare SSH connection


In [7]:
import logging
reload(logging)
logging.basicConfig(
    format='%(asctime)-9s %(levelname)-8s: %(message)s',
    datefmt='%I:%M:%S')

# Enable logging at INFO level
logging.getLogger().setLevel(logging.DEBUG)
# Comment the follwing line to disable devlib debugging statements
logging.getLogger('ssh').setLevel(logging.DEBUG)

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

import json
import os
import subprocess

# Support to access the remote target
import devlib
from env import TestEnv

# Support for trace events analysis
from trace import Trace
#from trace_analysis import TraceAnalysis

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

# Support for performance analysis of RTApp workloads
from perf_analysis import PerfAnalysis

# Suport for FTrace events parsing and visualization
import trappy


Populating the interactive namespace from numpy and matplotlib
/home/lubaoquan/anaconda2/lib/python2.7/site-packages/IPython/core/magics/pylab.py:161: UserWarning: pylab import has clobbered these variables: ['trace']
`%matplotlib` prevents importing * from pylab and numpy
  "\n`%matplotlib` prevents importing * from pylab and numpy"

In [9]:
# Let's use an example trace
#!pwd
#tracefile = os.path.join(res_dir, 'trace.dat')
platformfile = os.path.join("../../results/eas_acceptance/rtapp:energy_aware:early_and_migrators", 'platform.json')

In [10]:
# Trace events of interest
events_to_parse = [
                "sched_overutilized",
                "sched_energy_diff",
                "sched_load_avg_task",
                "sched_load_avg_cpu",
                "sched_migrate_task",
                "sched_switch"
]

# Platform description
with open(platformfile, 'r') as fh:
    platform = json.load(fh)

# Time range from the analysis
(t_min, t_max) = (0, None)

platform['nrg_model']['little']['cpu']['cap_max'] = 1024
platform['clusters']['little'] = [0, 1, 2, 3]
        
platform['nrg_model']['big']['cpu']['cap_max'] = 1024
platform['clusters']['big'] = [4, 5, 6, 7]
platform['cpus_count'] = 8

logging.info("CPUs max capacities:")
logging.info("   big: %5d (cpus: %s)",
             platform['nrg_model']['big']['cpu']['cap_max'],
             platform['clusters']['big'])
logging.info("LITTLE: %5d (cpus: %s)",
             platform['nrg_model']['little']['cpu']['cap_max'],
             platform['clusters']['little'])


04:11:45  INFO    : CPUs max capacities:
04:11:45  INFO    :    big:  1024 (cpus: [4, 5, 6, 7])
04:11:45  INFO    : LITTLE:  1024 (cpus: [0, 1, 2, 3])

In [11]:
# Load the LISA::Trace parsing module
from trace import Trace

results_dir="../../results/eas_acceptance"
dirlist=os.listdir(results_dir)

for filename in dirlist:
    #print filename
    filepath=os.path.join(results_dir, filename)
    res_dir=filepath+"/1"
    trace = Trace(platform, res_dir, events_to_parse, window=(t_min,t_max))
    trace.setXTimeRange(t_min, t_max)
    trace.analysis.frequency.plotClusterFrequencies()
    #trace.analysis.frequency.plotCPUFrequencyResidency(cpus=1)
    #trace.analysis.frequency.plotClusterFrequencyResidency(clusters='LITTLE')
    #trace.analysis.tasks.plotBigTasks(max_tasks=10, min_samples=100, min_utilization=10)
    #trace.analysis.tasks.plotTasks(tasks='rt-app-task0')
    #trace.analysis.tasks.plotBigTasks(max_tasks=10, min_samples=100, min_utilization=10)


04:11:45  DEBUG   : Loading [sched] events from trace in [../../results/eas_acceptance/rtapp:energy_aware:early_and_migrators/1]...
04:11:45  DEBUG   : Parsing events: ['sched_overutilized', 'sched_energy_diff', 'sched_load_avg_task', 'sched_load_avg_cpu', 'sched_migrate_task', 'sched_switch']
04:11:45  INFO    : Parsing FTrace format...
04:11:46  DEBUG   : Events found on trace:
04:11:46  DEBUG   :  - sched_load_avg_task
04:11:46  DEBUG   :  - sched_load_avg_cpu
04:11:46  DEBUG   :  - sched_migrate_task
04:11:46  DEBUG   :  - sched_overutilized
04:11:47  DEBUG   :  - sched_switch
04:11:47  DEBUG   :  - sched_energy_diff
04:11:47  DEBUG   : Lookup dataset for tasks...
04:11:47  DEBUG   : Lookup for task [swapper/3]...
04:11:47  DEBUG   :   task        swapper/3 found, pid: [0]
04:11:47  DEBUG   : Lookup for task [sh]...
04:11:47  DEBUG   :   task               sh found, pid: [25759, 25756, 25761, 25764, 25763, 25765, 25768, 25767, 25769, 25771, 25773, 25790, 25792, 25801, 25803, 25805, 25807, 25809, 25811, 25813, 25815, 25817, 25819, 25821, 25823, 25825, 25827, 25829, 25831, 25834, 25836, 25837, 25838, 25840, 25843, 25842, 25844, 25847, 25846, 25848]
04:11:47  DEBUG   : Lookup for task [rcu_preempt]...
04:11:47  DEBUG   :   task      rcu_preempt found, pid: [7]
04:11:47  DEBUG   : Lookup for task [rcu_sched]...
04:11:47  DEBUG   :   task        rcu_sched found, pid: [8]
04:11:47  DEBUG   : Lookup for task [kworker/u16:0]...
04:11:47  DEBUG   :   task    kworker/u16:0 found, pid: [24188]
04:11:47  DEBUG   : Lookup for task [swapper/1]...
04:11:47  DEBUG   :   task        swapper/1 found, pid: [0]
04:11:47  DEBUG   : Lookup for task [adbd]...
04:11:47  DEBUG   :   task             adbd found, pid: [3819, 25761, 25762, 25765, 25766, 25771, 25772, 25790, 25791, 25801, 25802, 25804, 25805, 25806, 25808, 25809, 25810, 25812, 25813, 25814, 25816, 25817, 25818, 25820, 25821, 25822, 25824, 25825, 25826, 25828, 25829, 25830, 25832, 25833, 25834, 25835, 25840, 25841, 25844, 25845]
04:11:47  DEBUG   : Lookup for task [->transport]...
04:11:47  DEBUG   :   task      ->transport found, pid: [3821]
04:11:47  DEBUG   : Lookup for task [<-transport]...
04:11:47  DEBUG   :   task      <-transport found, pid: [3822]
04:11:47  DEBUG   : Lookup for task [kworker/0:1]...
04:11:47  DEBUG   :   task      kworker/0:1 found, pid: [23716]
04:11:47  DEBUG   : Lookup for task [kworker/2:1]...
04:11:47  DEBUG   :   task      kworker/2:1 found, pid: [1111]
04:11:47  DEBUG   : Lookup for task [shell srvc 2575]...
04:11:47  DEBUG   :   task  shell srvc 2575 found, pid: [25757]
04:11:47  DEBUG   : Lookup for task [swapper/2]...
04:11:47  DEBUG   :   task        swapper/2 found, pid: [0]
04:11:47  DEBUG   : Lookup for task [swapper/0]...
04:11:47  DEBUG   :   task        swapper/0 found, pid: [0]
04:11:47  DEBUG   : Lookup for task [ksoftirqd/2]...
04:11:47  DEBUG   :   task      ksoftirqd/2 found, pid: [19]
04:11:47  DEBUG   : Lookup for task [kschedfreq:0]...
04:11:47  DEBUG   :   task     kschedfreq:0 found, pid: [16478]
04:11:47  DEBUG   : Lookup for task [su]...
04:11:47  DEBUG   :   task               su found, pid: [25764, 25768, 25837, 25843, 25847]
04:11:47  DEBUG   : Lookup for task [shell srvc 2576]...
04:11:47  DEBUG   :   task  shell srvc 2576 found, pid: [25762, 25766]
04:11:47  DEBUG   : Lookup for task [migration/2]...
04:11:47  DEBUG   :   task      migration/2 found, pid: [18]
04:11:47  DEBUG   : Lookup for task [shutils]...
04:11:47  DEBUG   :   task          shutils found, pid: [25769, 25770, 25773, 25774, 25775, 25776, 25777, 25778, 25779, 25780, 25781, 25782, 25783, 25784, 25785, 25786, 25787, 25788, 25789, 25838, 25839]
04:11:47  DEBUG   : Lookup for task [busybox]...
04:11:47  DEBUG   :   task          busybox found, pid: [25770, 25775, 25776, 25777, 25778, 25781, 25782, 25783, 25784, 25785, 25786, 25788, 25839]
04:11:47  DEBUG   : Lookup for task [ksoftirqd/3]...
04:11:47  DEBUG   :   task      ksoftirqd/3 found, pid: [24]
04:11:47  DEBUG   : Lookup for task [migration/3]...
04:11:47  DEBUG   :   task      migration/3 found, pid: [23]
04:11:47  DEBUG   : Lookup for task [true]...
04:11:47  DEBUG   :   task             true found, pid: [25776, 25778, 25782, 25784, 25786, 25788]
04:11:47  DEBUG   : Lookup for task [migration/1]...
04:11:47  DEBUG   :   task      migration/1 found, pid: [13]
04:11:47  DEBUG   : Lookup for task [kworker/4:1]...
04:11:47  DEBUG   :   task      kworker/4:1 found, pid: [1296]
04:11:47  DEBUG   : Lookup for task [swapper/4]...
04:11:47  DEBUG   :   task        swapper/4 found, pid: [0]
04:11:47  DEBUG   : Lookup for task [kworker/5:1]...
04:11:47  DEBUG   :   task      kworker/5:1 found, pid: [1297]
04:11:47  DEBUG   : Lookup for task [swapper/5]...
04:11:47  DEBUG   :   task        swapper/5 found, pid: [0]
04:11:47  DEBUG   : Lookup for task [kworker/6:1]...
04:11:47  DEBUG   :   task      kworker/6:1 found, pid: [1252]
04:11:47  DEBUG   : Lookup for task [swapper/6]...
04:11:47  DEBUG   :   task        swapper/6 found, pid: [0]
04:11:47  DEBUG   : Lookup for task [kworker/7:2]...
04:11:47  DEBUG   :   task      kworker/7:2 found, pid: [3824]
04:11:47  DEBUG   : Lookup for task [swapper/7]...
04:11:47  DEBUG   :   task        swapper/7 found, pid: [0]
04:11:47  DEBUG   : Lookup for task [kworker/3:1]...
04:11:47  DEBUG   :   task      kworker/3:1 found, pid: [1110]
04:11:47  DEBUG   : Lookup for task [shell srvc 2577]...
04:11:47  DEBUG   :   task  shell srvc 2577 found, pid: [25772]
04:11:47  DEBUG   : Lookup for task [rt-app]...
04:11:47  DEBUG   :   task           rt-app found, pid: [25792, 25793, 25796, 25795, 25794, 25797, 25798, 25799, 25800]
04:11:47  DEBUG   : Lookup for task [mmcqd/0]...
04:11:47  DEBUG   :   task          mmcqd/0 found, pid: [1196]
04:11:47  DEBUG   : Lookup for task [kworker/0:1H]...
04:11:47  DEBUG   :   task     kworker/0:1H found, pid: [1732]
04:11:47  DEBUG   : Lookup for task [task_early0]...
04:11:47  DEBUG   :   task      task_early0 found, pid: [25793]
04:11:47  DEBUG   : Lookup for task [task_early3]...
04:11:47  DEBUG   :   task      task_early3 found, pid: [25796]
04:11:47  DEBUG   : Lookup for task [task_migrator1]...
04:11:47  DEBUG   :   task   task_migrator1 found, pid: [25798]
04:11:47  DEBUG   : Lookup for task [task_early2]...
04:11:47  DEBUG   :   task      task_early2 found, pid: [25795]
04:11:47  DEBUG   : Lookup for task [task_migrator2]...
04:11:47  DEBUG   :   task   task_migrator2 found, pid: [25799]
04:11:47  DEBUG   : Lookup for task [task_early1]...
04:11:47  DEBUG   :   task      task_early1 found, pid: [25794]
04:11:47  DEBUG   : Lookup for task [task_migrator0]...
04:11:47  DEBUG   :   task   task_migrator0 found, pid: [25797]
04:11:47  DEBUG   : Lookup for task [task_migrator3]...
04:11:47  DEBUG   :   task   task_migrator3 found, pid: [25800]
04:11:47  DEBUG   : Lookup for task [kworker/u16:3]...
04:11:47  DEBUG   :   task    kworker/u16:3 found, pid: [25402]
04:11:47  DEBUG   : Lookup for task [kworker/1:1]...
Maximum estimated system energy: 5584
04:11:47  DEBUG   :   task      kworker/1:1 found, pid: [1188]
04:11:47  DEBUG   : Lookup for task [watchdog/0]...
04:11:47  DEBUG   :   task       watchdog/0 found, pid: [11]
04:11:47  DEBUG   : Lookup for task [watchdog/1]...
04:11:47  DEBUG   :   task       watchdog/1 found, pid: [12]
04:11:47  DEBUG   : Lookup for task [watchdog/2]...
04:11:47  DEBUG   :   task       watchdog/2 found, pid: [17]
04:11:47  DEBUG   : Lookup for task [watchdog/3]...
04:11:47  DEBUG   :   task       watchdog/3 found, pid: [22]
04:11:47  DEBUG   : Lookup for task [watchdog/4]...
04:11:47  DEBUG   :   task       watchdog/4 found, pid: [27]
04:11:47  DEBUG   : Lookup for task [watchdog/5]...
04:11:47  DEBUG   :   task       watchdog/5 found, pid: [32]
04:11:47  DEBUG   : Lookup for task [watchdog/6]...
04:11:47  DEBUG   :   task       watchdog/6 found, pid: [37]
04:11:47  DEBUG   : Lookup for task [watchdog/7]...
04:11:47  DEBUG   :   task       watchdog/7 found, pid: [42]
04:11:47  DEBUG   : Lookup for task [shell srvc 2579]...
04:11:47  DEBUG   :   task  shell srvc 2579 found, pid: [25791]
04:11:47  DEBUG   : Lookup for task [ls]...
04:11:47  DEBUG   :   task               ls found, pid: [25803, 25807, 25811, 25815, 25819, 25823, 25827, 25831]
04:11:47  DEBUG   : Lookup for task [shell srvc 2580]...
04:11:47  DEBUG   :   task  shell srvc 2580 found, pid: [25802, 25806, 25810]
04:11:47  DEBUG   : Lookup for task [service 36]...
04:11:47  DEBUG   :   task       service 36 found, pid: [25804, 25808, 25812, 25816, 25820, 25824, 25828, 25832, 25833]
04:11:47  DEBUG   : Lookup for task [shell srvc 2581]...
04:11:47  DEBUG   :   task  shell srvc 2581 found, pid: [25814, 25818]
04:11:47  DEBUG   : Lookup for task [shell srvc 2582]...
04:11:47  DEBUG   :   task  shell srvc 2582 found, pid: [25822, 25826, 25830]
04:11:47  DEBUG   : Lookup for task [shell srvc 2583]...
04:11:47  DEBUG   :   task  shell srvc 2583 found, pid: [25835]
04:11:47  DEBUG   : Lookup for task [shell srvc 2584]...
04:11:47  DEBUG   :   task  shell srvc 2584 found, pid: [25841]
04:11:47  DEBUG   : Lookup for task [ksoftirqd/6]...
04:11:47  DEBUG   :   task      ksoftirqd/6 found, pid: [39]
04:11:47  INFO    : Collected events spans a 9.438 [s] time interval
04:11:47  INFO    : Overutilized time: 6.371311 [s] (67.508% of trace time)
04:11:47  INFO    : Set plots time range to (0.000000, 9.437798)[s]
04:11:47  DEBUG   : Registering [<trace.Trace object at 0x7fd3cc62e3d0>] local data frames
04:11:47  DEBUG   :    functions_stats
04:11:47  DEBUG   :    trace_event
04:11:47  DEBUG   : Analysis: /home/lubaoquan/tools/lisa/arnold-lisa/libs/utils/analysis
04:11:47  DEBUG   : Syspath: ['/home/lubaoquan/tools/lisa/arnold-lisa/libs/utils/analysis', '/home/lubaoquan/tools/lisa/arnold-lisa/libs/utils/analysis', '/home/lubaoquan/tools/lisa/arnold-lisa/libs/utils/analysis', '/home/lubaoquan/tools/lisa/arnold-lisa/libs/utils/analysis', '/home/lubaoquan/tools/lisa/arnold-lisa/libs/utils/analysis', '/home/lubaoquan/tools/lisa/arnold-lisa/libs/utils/analysis', '/home/lubaoquan/tools/lisa/arnold-lisa/libs/utils/analysis', '/home/lubaoquan/tools/lisa/arnold-lisa/libs/utils/analysis', '/home/lubaoquan/tools/lisa/arnold-lisa/libs/utils/analysis', '', '/home/lubaoquan/tools/lisa/arnold-lisa/libs/bart', '/home/lubaoquan/tools/lisa/arnold-lisa/libs/trappy', '/home/lubaoquan/tools/lisa/arnold-lisa/libs/devlib', '/home/lubaoquan/tools/lisa/arnold-lisa/libs/wlgen', '/home/lubaoquan/tools/lisa/arnold-lisa/libs/utils', '/home/lubaoquan/tools/lisa/arnold-lisa/ipynb/android', '/home/lubaoquan/anaconda2/lib/python27.zip', '/home/lubaoquan/anaconda2/lib/python2.7', '/home/lubaoquan/anaconda2/lib/python2.7/plat-linux2', '/home/lubaoquan/anaconda2/lib/python2.7/lib-tk', '/home/lubaoquan/anaconda2/lib/python2.7/lib-old', '/home/lubaoquan/anaconda2/lib/python2.7/lib-dynload', '/home/lubaoquan/anaconda2/lib/python2.7/site-packages', '/home/lubaoquan/anaconda2/lib/python2.7/site-packages/Sphinx-1.4.6-py2.7.egg', '/home/lubaoquan/anaconda2/lib/python2.7/site-packages/setuptools-27.2.0-py2.7.egg', '/home/lubaoquan/anaconda2/lib/python2.7/site-packages/IPython/extensions', '/home/lubaoquan/.ipython']
04:11:47  INFO    : Registering trace analysis modules:
04:11:47  DEBUG   : Filename: tasks_analysis
04:11:47  DEBUG   : Registering [<tasks_analysis.TasksAnalysis object at 0x7fd3c7e11d10>] local data frames
04:11:47  DEBUG   :    rt_tasks
04:11:47  DEBUG   :    top_big_tasks
04:11:47  DEBUG   :    top_wakeup_tasks
04:11:47  DEBUG   :    trace_event
04:11:47  INFO    :    tasks
04:11:47  DEBUG   : Filename: cpus_analysis
04:11:47  DEBUG   : Registering [<cpus_analysis.CpusAnalysis object at 0x7fd3cca05cd0>] local data frames
04:11:47  DEBUG   :    context_switches
04:11:47  DEBUG   :    trace_event
04:11:47  INFO    :    cpus
04:11:47  DEBUG   : Filename: eas_analysis
04:11:47  DEBUG   : Registering [<eas_analysis.EasAnalysis object at 0x7fd3c7e11b50>] local data frames
04:11:47  DEBUG   :    trace_event
04:11:47  INFO    :    eas
04:11:47  DEBUG   : Filename: functions_analysis
04:11:47  DEBUG   : Registering [<functions_analysis.FunctionsAnalysis object at 0x7fd3c7e11cd0>] local data frames
04:11:47  DEBUG   :    trace_event
04:11:47  INFO    :    functions
04:11:47  DEBUG   : Filename: latency_analysis
04:11:47  DEBUG   : Registering [<latency_analysis.LatencyAnalysis object at 0x7fd3c7e112d0>] local data frames
04:11:47  DEBUG   :    latency_df
04:11:47  DEBUG   :    latency_preemption_df
04:11:47  DEBUG   :    latency_wakeup_df
04:11:47  DEBUG   :    trace_event
04:11:47  INFO    :    latency
04:11:47  DEBUG   : Filename: idle_analysis
04:11:47  DEBUG   : Registering [<idle_analysis.IdleAnalysis object at 0x7fd3c7e11190>] local data frames
04:11:47  DEBUG   :    cluster_idle_state_residency
04:11:47  DEBUG   :    cpu_idle_state_residency
04:11:47  DEBUG   :    trace_event
04:11:47  INFO    :    idle
04:11:47  DEBUG   : Filename: status_analysis
04:11:47  DEBUG   : Registering [<status_analysis.StatusAnalysis object at 0x7fd3cd676350>] local data frames
04:11:47  DEBUG   :    overutilized
04:11:47  DEBUG   :    trace_event
04:11:47  INFO    :    status
04:11:47  DEBUG   : Filename: frequency_analysis
04:11:47  DEBUG   : Registering [<frequency_analysis.FrequencyAnalysis object at 0x7fd3cd676390>] local data frames
04:11:47  DEBUG   :    cluster_frequency_residency
04:11:47  DEBUG   :    cpu_frequency_residency
04:11:47  DEBUG   :    trace_event
04:11:47  INFO    :    frequency
04:11:47  INFO    : Set plots time range to (0.000000, 9.437798)[s]
04:11:47  WARNING : Events [cpu_frequency] not found, plot DISABLED!
04:11:47  DEBUG   : Loading [sched] events from trace in [../../results/eas_acceptance/rtapp:energy_aware:wake_migration/1]...
04:11:47  DEBUG   : Parsing events: ['sched_overutilized', 'sched_energy_diff', 'sched_load_avg_task', 'sched_load_avg_cpu', 'sched_migrate_task', 'sched_switch']
04:11:47  INFO    : Parsing FTrace format...
04:11:49  DEBUG   : Events found on trace:
04:11:49  DEBUG   :  - sched_load_avg_task
04:11:49  DEBUG   :  - sched_load_avg_cpu
04:11:49  DEBUG   :  - sched_migrate_task
04:11:49  DEBUG   :  - sched_overutilized
04:11:49  DEBUG   :  - sched_switch
04:11:49  DEBUG   :  - sched_energy_diff
04:11:49  DEBUG   : Lookup dataset for tasks...
04:11:49  DEBUG   : Lookup for task [sh]...
04:11:49  DEBUG   :   task               sh found, pid: [26138, 26135, 26140, 26142, 26143, 26144, 26146, 26147, 26148, 26150, 26152, 26171, 26169, 26176, 26178, 26180, 26182, 26184, 26186, 26188, 26190, 26193, 26195, 26196, 26197, 26199, 26202, 26201, 26203, 26206, 26205, 26207]
04:11:49  DEBUG   : Lookup for task [kworker/u16:0]...
04:11:49  DEBUG   :   task    kworker/u16:0 found, pid: [24188]
04:11:49  DEBUG   : Lookup for task [swapper/2]...
04:11:49  DEBUG   :   task        swapper/2 found, pid: [0]
04:11:49  DEBUG   : Lookup for task [adbd]...
04:11:49  DEBUG   :   task             adbd found, pid: [3819, 26140, 26141, 26144, 26145, 26150, 26151, 26169, 26170, 26176, 26177, 26179, 26180, 26181, 26183, 26184, 26185, 26187, 26188, 26189, 26191, 26192, 26193, 26194, 26199, 26200, 26203, 26204]
04:11:49  DEBUG   : Lookup for task [->transport]...
04:11:49  DEBUG   :   task      ->transport found, pid: [3821]
04:11:49  DEBUG   : Lookup for task [kworker/3:1]...
04:11:49  DEBUG   :   task      kworker/3:1 found, pid: [1110]
04:11:49  DEBUG   : Lookup for task [swapper/3]...
04:11:49  DEBUG   :   task        swapper/3 found, pid: [0]
04:11:49  DEBUG   : Lookup for task [rcu_preempt]...
04:11:49  DEBUG   :   task      rcu_preempt found, pid: [7]
04:11:49  DEBUG   : Lookup for task [rcu_sched]...
04:11:49  DEBUG   :   task        rcu_sched found, pid: [8]
04:11:49  DEBUG   : Lookup for task [shell srvc 2613]...
04:11:49  DEBUG   :   task  shell srvc 2613 found, pid: [26136]
04:11:49  DEBUG   : Lookup for task [trace-cmd]...
04:11:49  DEBUG   :   task        trace-cmd found, pid: [26139]
04:11:49  DEBUG   : Lookup for task [swapper/1]...
04:11:49  DEBUG   :   task        swapper/1 found, pid: [0]
04:11:49  DEBUG   : Lookup for task [<-transport]...
04:11:49  DEBUG   :   task      <-transport found, pid: [3822]
04:11:49  DEBUG   : Lookup for task [migration/1]...
04:11:49  DEBUG   :   task      migration/1 found, pid: [13]
04:11:49  DEBUG   : Lookup for task [migration/2]...
04:11:49  DEBUG   :   task      migration/2 found, pid: [18]
04:11:49  DEBUG   : Lookup for task [kworker/2:1]...
04:11:49  DEBUG   :   task      kworker/2:1 found, pid: [1111]
04:11:49  DEBUG   : Lookup for task [kschedfreq:0]...
04:11:49  DEBUG   :   task     kschedfreq:0 found, pid: [16478]
04:11:49  DEBUG   : Lookup for task [swapper/4]...
04:11:49  DEBUG   :   task        swapper/4 found, pid: [0]
04:11:49  DEBUG   : Lookup for task [kworker/4:1]...
04:11:49  DEBUG   :   task      kworker/4:1 found, pid: [1296]
04:11:49  DEBUG   : Lookup for task [migration/3]...
04:11:49  DEBUG   :   task      migration/3 found, pid: [23]
04:11:49  DEBUG   : Lookup for task [su]...
04:11:49  DEBUG   :   task               su found, pid: [26143, 26147, 26196, 26202, 26206]
04:11:49  DEBUG   : Lookup for task [swapper/0]...
04:11:49  DEBUG   :   task        swapper/0 found, pid: [0]
04:11:49  DEBUG   : Lookup for task [shell srvc 2614]...
04:11:49  DEBUG   :   task  shell srvc 2614 found, pid: [26141, 26145]
04:11:49  DEBUG   : Lookup for task [swapper/5]...
04:11:49  DEBUG   :   task        swapper/5 found, pid: [0]
04:11:49  DEBUG   : Lookup for task [kworker/5:1]...
04:11:49  DEBUG   :   task      kworker/5:1 found, pid: [1297]
04:11:49  DEBUG   : Lookup for task [ksoftirqd/3]...
04:11:49  DEBUG   :   task      ksoftirqd/3 found, pid: [24]
04:11:49  DEBUG   : Lookup for task [shutils]...
04:11:49  DEBUG   :   task          shutils found, pid: [26148, 26149, 26152, 26153, 26154, 26155, 26156, 26157, 26158, 26159, 26160, 26161, 26162, 26163, 26164, 26165, 26166, 26167, 26168, 26197, 26198]
04:11:49  DEBUG   : Lookup for task [watchdog/0]...
04:11:49  DEBUG   :   task       watchdog/0 found, pid: [11]
04:11:49  DEBUG   : Lookup for task [busybox]...
04:11:49  DEBUG   :   task          busybox found, pid: [26149, 26153, 26154, 26155, 26156, 26158, 26160, 26161, 26162, 26163, 26164, 26165, 26167, 26198]
04:11:49  DEBUG   : Lookup for task [watchdog/1]...
04:11:49  DEBUG   :   task       watchdog/1 found, pid: [12]
04:11:49  DEBUG   : Lookup for task [watchdog/2]...
04:11:49  DEBUG   :   task       watchdog/2 found, pid: [17]
04:11:49  DEBUG   : Lookup for task [ksoftirqd/2]...
04:11:49  DEBUG   :   task      ksoftirqd/2 found, pid: [19]
04:11:49  DEBUG   : Lookup for task [watchdog/3]...
04:11:49  DEBUG   :   task       watchdog/3 found, pid: [22]
04:11:49  DEBUG   : Lookup for task [watchdog/4]...
04:11:49  DEBUG   :   task       watchdog/4 found, pid: [27]
04:11:49  DEBUG   : Lookup for task [watchdog/5]...
04:11:49  DEBUG   :   task       watchdog/5 found, pid: [32]
04:11:49  DEBUG   : Lookup for task [watchdog/6]...
04:11:49  DEBUG   :   task       watchdog/6 found, pid: [37]
04:11:49  DEBUG   : Lookup for task [swapper/6]...
04:11:49  DEBUG   :   task        swapper/6 found, pid: [0]
04:11:49  DEBUG   : Lookup for task [watchdog/7]...
04:11:49  DEBUG   :   task       watchdog/7 found, pid: [42]
04:11:49  DEBUG   : Lookup for task [swapper/7]...
04:11:49  DEBUG   :   task        swapper/7 found, pid: [0]
04:11:49  DEBUG   : Lookup for task [kworker/0:1]...
04:11:49  DEBUG   :   task      kworker/0:1 found, pid: [23716]
04:11:49  DEBUG   : Lookup for task [true]...
04:11:49  DEBUG   :   task             true found, pid: [26153, 26155, 26157, 26159, 26165, 26167]
04:11:49  DEBUG   : Lookup for task [kworker/6:1]...
04:11:49  DEBUG   :   task      kworker/6:1 found, pid: [1252]
04:11:49  DEBUG   : Lookup for task [kworker/7:2]...
04:11:49  DEBUG   :   task      kworker/7:2 found, pid: [3824]
04:11:49  DEBUG   : Lookup for task [shell srvc 2615]...
04:11:49  DEBUG   :   task  shell srvc 2615 found, pid: [26151]
04:11:49  DEBUG   : Lookup for task [rt-app]...
04:11:49  DEBUG   :   task           rt-app found, pid: [26171, 26172, 26174, 26175, 26173]
04:11:49  DEBUG   : Lookup for task [task_wmig3]...
04:11:49  DEBUG   :   task       task_wmig3 found, pid: [26175]
04:11:49  DEBUG   : Lookup for task [task_wmig1]...
04:11:49  DEBUG   :   task       task_wmig1 found, pid: [26173]
04:11:49  DEBUG   : Lookup for task [task_wmig0]...
04:11:49  DEBUG   :   task       task_wmig0 found, pid: [26172]
04:11:49  DEBUG   : Lookup for task [task_wmig2]...
04:11:49  DEBUG   :   task       task_wmig2 found, pid: [26174]
04:11:49  DEBUG   : Lookup for task [kworker/1:1]...
04:11:49  DEBUG   :   task      kworker/1:1 found, pid: [1188]
04:11:49  DEBUG   : Lookup for task [mmcqd/0]...
04:11:49  DEBUG   :   task          mmcqd/0 found, pid: [1196]
04:11:49  DEBUG   : Lookup for task [kworker/0:1H]...
Maximum estimated system energy: 5584
04:11:49  DEBUG   :   task     kworker/0:1H found, pid: [1732]
04:11:49  DEBUG   : Lookup for task [kworker/u16:3]...
04:11:49  DEBUG   :   task    kworker/u16:3 found, pid: [25402]
04:11:49  DEBUG   : Lookup for task [AlarmManager]...
04:11:49  DEBUG   :   task     AlarmManager found, pid: [2192]
04:11:49  DEBUG   : Lookup for task [ActivityManager]...
04:11:49  DEBUG   :   task  ActivityManager found, pid: [2170]
04:11:49  DEBUG   : Lookup for task [PowerManagerSer]...
04:11:49  DEBUG   :   task  PowerManagerSer found, pid: [2179]
04:11:49  DEBUG   : Lookup for task [system_server]...
04:11:49  DEBUG   :   task    system_server found, pid: [2150]
04:11:49  DEBUG   : Lookup for task [Binder:2245_2]...
04:11:49  DEBUG   :   task    Binder:2245_2 found, pid: [2282]
04:11:49  DEBUG   : Lookup for task [ndroid.systemui]...
04:11:49  DEBUG   :   task  ndroid.systemui found, pid: [2245]
04:11:49  DEBUG   : Lookup for task [Binder:2150_6]...
04:11:49  DEBUG   :   task    Binder:2150_6 found, pid: [2607]
04:11:49  DEBUG   : Lookup for task [Binder:2150_3]...
04:11:49  DEBUG   :   task    Binder:2150_3 found, pid: [2278]
04:11:49  DEBUG   : Lookup for task [Binder:2150_2]...
04:11:49  DEBUG   :   task    Binder:2150_2 found, pid: [2167]
04:11:49  DEBUG   : Lookup for task [Binder:2150_4]...
04:11:49  DEBUG   :   task    Binder:2150_4 found, pid: [2281]
04:11:49  DEBUG   : Lookup for task [Binder:2245_3]...
04:11:49  DEBUG   :   task    Binder:2245_3 found, pid: [2490]
04:11:49  DEBUG   : Lookup for task [Binder:2245_1]...
04:11:49  DEBUG   :   task    Binder:2245_1 found, pid: [2279]
04:11:49  DEBUG   : Lookup for task [Binder:2150_5]...
04:11:49  DEBUG   :   task    Binder:2150_5 found, pid: [2483]
04:11:49  DEBUG   : Lookup for task [Binder:2150_7]...
04:11:49  DEBUG   :   task    Binder:2150_7 found, pid: [2658]
04:11:49  DEBUG   : Lookup for task [Binder:2150_1]...
04:11:49  DEBUG   :   task    Binder:2150_1 found, pid: [2166]
04:11:49  DEBUG   : Lookup for task [Binder:2622_1]...
04:11:49  DEBUG   :   task    Binder:2622_1 found, pid: [2641]
04:11:49  DEBUG   : Lookup for task [ndroid.launcher]...
04:11:49  DEBUG   :   task  ndroid.launcher found, pid: [2622]
04:11:49  DEBUG   : Lookup for task [RenderThread]...
04:11:49  DEBUG   :   task     RenderThread found, pid: [2717, 2514]
04:11:49  DEBUG   : Lookup for task [Binder:1801_1]...
04:11:49  DEBUG   :   task    Binder:1801_1 found, pid: [1839]
04:11:49  DEBUG   : Lookup for task [EventThread]...
04:11:49  DEBUG   :   task      EventThread found, pid: [1990, 1992]
04:11:49  DEBUG   : Lookup for task [EventControl]...
04:11:49  DEBUG   :   task     EventControl found, pid: [2024]
04:11:49  DEBUG   : Lookup for task [VSyncThread]...
04:11:49  DEBUG   :   task      VSyncThread found, pid: [1998]
04:11:49  DEBUG   : Lookup for task [DispSync]...
04:11:49  DEBUG   :   task         DispSync found, pid: [1840]
04:11:49  DEBUG   : Lookup for task [Binder:1801_2]...
04:11:49  DEBUG   :   task    Binder:1801_2 found, pid: [1841]
04:11:49  DEBUG   : Lookup for task [Binder:1801_4]...
04:11:49  DEBUG   :   task    Binder:1801_4 found, pid: [2489]
04:11:49  DEBUG   : Lookup for task [MaliNotify]...
04:11:49  DEBUG   :   task       MaliNotify found, pid: [2729, 2754, 1984]
04:11:49  DEBUG   : Lookup for task [Binder:1801_5]...
04:11:49  DEBUG   :   task    Binder:1801_5 found, pid: [2722]
04:11:49  DEBUG   : Lookup for task [Binder:1801_3]...
04:11:49  DEBUG   :   task    Binder:1801_3 found, pid: [2091]
04:11:49  DEBUG   : Lookup for task [MaliWorker]...
04:11:49  DEBUG   :   task       MaliWorker found, pid: [2732, 2756, 2022]
04:11:49  DEBUG   : Lookup for task [surfaceflinger]...
04:11:49  DEBUG   :   task   surfaceflinger found, pid: [1801]
04:11:49  DEBUG   : Lookup for task [POSIX timer 1]...
04:11:49  DEBUG   :   task    POSIX timer 1 found, pid: [1989]
04:11:49  DEBUG   : Lookup for task [POSIX timer 2]...
04:11:49  DEBUG   :   task    POSIX timer 2 found, pid: [1991]
04:11:49  DEBUG   : Lookup for task [watchdog]...
04:11:49  DEBUG   :   task         watchdog found, pid: [2361]
04:11:49  DEBUG   : Lookup for task [android.fg]...
04:11:49  DEBUG   :   task       android.fg found, pid: [2175]
04:11:49  DEBUG   : Lookup for task [InputReader]...
04:11:49  DEBUG   :   task      InputReader found, pid: [2199]
04:11:49  DEBUG   : Lookup for task [InputDispatcher]...
04:11:49  DEBUG   :   task  InputDispatcher found, pid: [2198]
04:11:49  DEBUG   : Lookup for task [shell srvc 2616]...
04:11:49  DEBUG   :   task  shell srvc 2616 found, pid: [26170]
04:11:49  DEBUG   : Lookup for task [ls]...
04:11:49  DEBUG   :   task               ls found, pid: [26178, 26182, 26186, 26190]
04:11:49  DEBUG   : Lookup for task [shell srvc 2617]...
04:11:49  DEBUG   :   task  shell srvc 2617 found, pid: [26177]
04:11:49  DEBUG   : Lookup for task [service 36]...
04:11:49  DEBUG   :   task       service 36 found, pid: [26179, 26183, 26187, 26191, 26192]
04:11:49  DEBUG   : Lookup for task [shell srvc 2618]...
04:11:49  DEBUG   :   task  shell srvc 2618 found, pid: [26181, 26185, 26189]
04:11:49  DEBUG   : Lookup for task [shell srvc 2619]...
04:11:49  DEBUG   :   task  shell srvc 2619 found, pid: [26194, 26200]
04:11:49  INFO    : Collected events spans a 22.474 [s] time interval
04:11:49  INFO    : Overutilized time: 9.566835 [s] (42.568% of trace time)
04:11:49  INFO    : Set plots time range to (0.000000, 22.474334)[s]
04:11:49  DEBUG   : Registering [<trace.Trace object at 0x7fd3cc8bb590>] local data frames
04:11:49  DEBUG   :    functions_stats
04:11:49  DEBUG   :    trace_event
04:11:49  DEBUG   : Analysis: /home/lubaoquan/tools/lisa/arnold-lisa/libs/utils/analysis
04:11:49  DEBUG   : Syspath: ['/home/lubaoquan/tools/lisa/arnold-lisa/libs/utils/analysis', '/home/lubaoquan/tools/lisa/arnold-lisa/libs/utils/analysis', '/home/lubaoquan/tools/lisa/arnold-lisa/libs/utils/analysis', '/home/lubaoquan/tools/lisa/arnold-lisa/libs/utils/analysis', '/home/lubaoquan/tools/lisa/arnold-lisa/libs/utils/analysis', '/home/lubaoquan/tools/lisa/arnold-lisa/libs/utils/analysis', '/home/lubaoquan/tools/lisa/arnold-lisa/libs/utils/analysis', '/home/lubaoquan/tools/lisa/arnold-lisa/libs/utils/analysis', '/home/lubaoquan/tools/lisa/arnold-lisa/libs/utils/analysis', '/home/lubaoquan/tools/lisa/arnold-lisa/libs/utils/analysis', '', '/home/lubaoquan/tools/lisa/arnold-lisa/libs/bart', '/home/lubaoquan/tools/lisa/arnold-lisa/libs/trappy', '/home/lubaoquan/tools/lisa/arnold-lisa/libs/devlib', '/home/lubaoquan/tools/lisa/arnold-lisa/libs/wlgen', '/home/lubaoquan/tools/lisa/arnold-lisa/libs/utils', '/home/lubaoquan/tools/lisa/arnold-lisa/ipynb/android', '/home/lubaoquan/anaconda2/lib/python27.zip', '/home/lubaoquan/anaconda2/lib/python2.7', '/home/lubaoquan/anaconda2/lib/python2.7/plat-linux2', '/home/lubaoquan/anaconda2/lib/python2.7/lib-tk', '/home/lubaoquan/anaconda2/lib/python2.7/lib-old', '/home/lubaoquan/anaconda2/lib/python2.7/lib-dynload', '/home/lubaoquan/anaconda2/lib/python2.7/site-packages', '/home/lubaoquan/anaconda2/lib/python2.7/site-packages/Sphinx-1.4.6-py2.7.egg', '/home/lubaoquan/anaconda2/lib/python2.7/site-packages/setuptools-27.2.0-py2.7.egg', '/home/lubaoquan/anaconda2/lib/python2.7/site-packages/IPython/extensions', '/home/lubaoquan/.ipython']
04:11:49  INFO    : Registering trace analysis modules:
04:11:49  DEBUG   : Filename: tasks_analysis
04:11:49  DEBUG   : Registering [<tasks_analysis.TasksAnalysis object at 0x7fd3ccfe3450>] local data frames
04:11:49  DEBUG   :    rt_tasks
04:11:49  DEBUG   :    top_big_tasks
04:11:49  DEBUG   :    top_wakeup_tasks
04:11:49  DEBUG   :    trace_event
04:11:49  INFO    :    tasks
04:11:49  DEBUG   : Filename: cpus_analysis
04:11:49  DEBUG   : Registering [<cpus_analysis.CpusAnalysis object at 0x7fd3ccfe3210>] local data frames
04:11:49  DEBUG   :    context_switches
04:11:49  DEBUG   :    trace_event
04:11:49  INFO    :    cpus
04:11:49  DEBUG   : Filename: eas_analysis
04:11:49  DEBUG   : Registering [<eas_analysis.EasAnalysis object at 0x7fd3ccfe3750>] local data frames
04:11:49  DEBUG   :    trace_event
04:11:49  INFO    :    eas
04:11:49  DEBUG   : Filename: functions_analysis
04:11:49  DEBUG   : Registering [<functions_analysis.FunctionsAnalysis object at 0x7fd3ccfe3550>] local data frames
04:11:49  DEBUG   :    trace_event
04:11:49  INFO    :    functions
04:11:49  DEBUG   : Filename: latency_analysis
04:11:49  DEBUG   : Registering [<latency_analysis.LatencyAnalysis object at 0x7fd3ccfe3650>] local data frames
04:11:49  DEBUG   :    latency_df
04:11:49  DEBUG   :    latency_preemption_df
04:11:49  DEBUG   :    latency_wakeup_df
04:11:49  DEBUG   :    trace_event
04:11:49  INFO    :    latency
04:11:49  DEBUG   : Filename: idle_analysis
04:11:49  DEBUG   : Registering [<idle_analysis.IdleAnalysis object at 0x7fd3ccfe3d90>] local data frames
04:11:49  DEBUG   :    cluster_idle_state_residency
04:11:49  DEBUG   :    cpu_idle_state_residency
04:11:49  DEBUG   :    trace_event
04:11:49  INFO    :    idle
04:11:49  DEBUG   : Filename: status_analysis
04:11:49  DEBUG   : Registering [<status_analysis.StatusAnalysis object at 0x7fd3ccfe3490>] local data frames
04:11:49  DEBUG   :    overutilized
04:11:49  DEBUG   :    trace_event
04:11:49  INFO    :    status
04:11:49  DEBUG   : Filename: frequency_analysis
04:11:49  DEBUG   : Registering [<frequency_analysis.FrequencyAnalysis object at 0x7fd3ccfe3e90>] local data frames
04:11:49  DEBUG   :    cluster_frequency_residency
04:11:49  DEBUG   :    cpu_frequency_residency
04:11:49  DEBUG   :    trace_event
04:11:49  INFO    :    frequency
04:11:49  INFO    : Set plots time range to (0.000000, 22.474334)[s]
04:11:49  WARNING : Events [cpu_frequency] not found, plot DISABLED!
04:11:49  DEBUG   : Loading [sched] events from trace in [../../results/eas_acceptance/rtapp:energy_aware:fmig/1]...
04:11:49  DEBUG   : Parsing events: ['sched_overutilized', 'sched_energy_diff', 'sched_load_avg_task', 'sched_load_avg_cpu', 'sched_migrate_task', 'sched_switch']
04:11:49  INFO    : Parsing FTrace format...
04:11:51  DEBUG   : Events found on trace:
04:11:51  DEBUG   :  - sched_load_avg_task
04:11:51  DEBUG   :  - sched_load_avg_cpu
04:11:51  DEBUG   :  - sched_migrate_task
04:11:51  DEBUG   :  - sched_overutilized
04:11:51  DEBUG   :  - sched_switch
04:11:51  DEBUG   :  - sched_energy_diff
04:11:51  DEBUG   : Lookup dataset for tasks...
04:11:51  DEBUG   : Lookup for task [swapper/1]...
04:11:51  DEBUG   :   task        swapper/1 found, pid: [0]
04:11:51  DEBUG   : Lookup for task [sh]...
04:11:51  DEBUG   :   task               sh found, pid: [25590, 25587, 25592, 25594, 25595, 25596, 25598, 25599, 25600, 25602, 25604, 25621, 25623, 25628, 25630, 25632, 25634, 25636, 25638, 25640, 25642, 25645, 25648, 25647, 25649, 25651, 25654, 25653, 25655, 25658, 25657, 25659]
04:11:51  DEBUG   : Lookup for task [rcu_preempt]...
04:11:51  DEBUG   :   task      rcu_preempt found, pid: [7]
04:11:51  DEBUG   : Lookup for task [swapper/3]...
04:11:51  DEBUG   :   task        swapper/3 found, pid: [0]
04:11:51  DEBUG   : Lookup for task [rcu_sched]...
04:11:51  DEBUG   :   task        rcu_sched found, pid: [8]
04:11:51  DEBUG   : Lookup for task [kworker/u16:0]...
04:11:51  DEBUG   :   task    kworker/u16:0 found, pid: [24188]
04:11:51  DEBUG   : Lookup for task [adbd]...
04:11:51  DEBUG   :   task             adbd found, pid: [3819, 25592, 25593, 25596, 25597, 25602, 25603, 25621, 25622, 25628, 25629, 25631, 25632, 25633, 25635, 25636, 25637, 25639, 25640, 25641, 25643, 25644, 25645, 25646, 25651, 25652, 25655, 25656]
04:11:51  DEBUG   : Lookup for task [->transport]...
04:11:51  DEBUG   :   task      ->transport found, pid: [3821]
04:11:51  DEBUG   : Lookup for task [kworker/0:1]...
04:11:51  DEBUG   :   task      kworker/0:1 found, pid: [23716]
04:11:51  DEBUG   : Lookup for task [<-transport]...
04:11:51  DEBUG   :   task      <-transport found, pid: [3822]
04:11:51  DEBUG   : Lookup for task [shell srvc 2558]...
04:11:51  DEBUG   :   task  shell srvc 2558 found, pid: [25588]
04:11:51  DEBUG   : Lookup for task [swapper/0]...
04:11:51  DEBUG   :   task        swapper/0 found, pid: [0]
04:11:51  DEBUG   : Lookup for task [swapper/2]...
04:11:51  DEBUG   :   task        swapper/2 found, pid: [0]
04:11:51  DEBUG   : Lookup for task [migration/3]...
04:11:51  DEBUG   :   task      migration/3 found, pid: [23]
04:11:51  DEBUG   : Lookup for task [kschedfreq:0]...
04:11:51  DEBUG   :   task     kschedfreq:0 found, pid: [16478]
04:11:51  DEBUG   : Lookup for task [su]...
04:11:51  DEBUG   :   task               su found, pid: [25595, 25599, 25648, 25654, 25658]
04:11:51  DEBUG   : Lookup for task [kworker/1:1]...
04:11:51  DEBUG   :   task      kworker/1:1 found, pid: [1188]
04:11:51  DEBUG   : Lookup for task [shell srvc 2559]...
04:11:51  DEBUG   :   task  shell srvc 2559 found, pid: [25593, 25597]
04:11:51  DEBUG   : Lookup for task [migration/2]...
04:11:51  DEBUG   :   task      migration/2 found, pid: [18]
04:11:51  DEBUG   : Lookup for task [shutils]...
04:11:51  DEBUG   :   task          shutils found, pid: [25601, 25600, 25604, 25605, 25606, 25607, 25608, 25609, 25610, 25611, 25612, 25613, 25614, 25615, 25616, 25617, 25618, 25619, 25620, 25649, 25650]
04:11:51  DEBUG   : Lookup for task [kworker/2:1]...
04:11:51  DEBUG   :   task      kworker/2:1 found, pid: [1111]
04:11:51  DEBUG   : Lookup for task [ksoftirqd/0]...
04:11:51  DEBUG   :   task      ksoftirqd/0 found, pid: [3]
04:11:51  DEBUG   : Lookup for task [busybox]...
04:11:51  DEBUG   :   task          busybox found, pid: [25605, 25606, 25607, 25608, 25610, 25611, 25612, 25613, 25615, 25617, 25618, 25619, 25620, 25650]
04:11:51  DEBUG   : Lookup for task [true]...
04:11:51  DEBUG   :   task             true found, pid: [25605, 25609, 25611, 25613, 25615, 25617, 25619]
04:11:51  DEBUG   : Lookup for task [migration/1]...
04:11:51  DEBUG   :   task      migration/1 found, pid: [13]
04:11:51  DEBUG   : Lookup for task [kworker/4:1]...
04:11:51  DEBUG   :   task      kworker/4:1 found, pid: [1296]
04:11:51  DEBUG   : Lookup for task [swapper/4]...
04:11:51  DEBUG   :   task        swapper/4 found, pid: [0]
04:11:51  DEBUG   : Lookup for task [kworker/5:1]...
04:11:51  DEBUG   :   task      kworker/5:1 found, pid: [1297]
04:11:51  DEBUG   : Lookup for task [ksoftirqd/2]...
04:11:51  DEBUG   :   task      ksoftirqd/2 found, pid: [19]
04:11:51  DEBUG   : Lookup for task [swapper/5]...
04:11:51  DEBUG   :   task        swapper/5 found, pid: [0]
04:11:51  DEBUG   : Lookup for task [kworker/6:1]...
04:11:51  DEBUG   :   task      kworker/6:1 found, pid: [1252]
04:11:51  DEBUG   : Lookup for task [ksoftirqd/3]...
04:11:51  DEBUG   :   task      ksoftirqd/3 found, pid: [24]
04:11:51  DEBUG   : Lookup for task [swapper/6]...
04:11:51  DEBUG   :   task        swapper/6 found, pid: [0]
04:11:51  DEBUG   : Lookup for task [kworker/7:2]...
04:11:51  DEBUG   :   task      kworker/7:2 found, pid: [3824]
04:11:51  DEBUG   : Lookup for task [swapper/7]...
04:11:51  DEBUG   :   task        swapper/7 found, pid: [0]
04:11:51  DEBUG   : Lookup for task [shell srvc 2560]...
04:11:51  DEBUG   :   task  shell srvc 2560 found, pid: [25603]
04:11:51  DEBUG   : Lookup for task [rt-app]...
04:11:51  DEBUG   :   task           rt-app found, pid: [25623, 25624, 25627, 25626, 25625]
04:11:51  DEBUG   : Lookup for task [task_fmig0]...
04:11:51  DEBUG   :   task       task_fmig0 found, pid: [25624]
04:11:51  DEBUG   : Lookup for task [task_fmig3]...
04:11:51  DEBUG   :   task       task_fmig3 found, pid: [25627]
04:11:51  DEBUG   : Lookup for task [task_fmig2]...
04:11:51  DEBUG   :   task       task_fmig2 found, pid: [25626]
04:11:51  DEBUG   : Lookup for task [task_fmig1]...
04:11:51  DEBUG   :   task       task_fmig1 found, pid: [25625]
04:11:51  DEBUG   : Lookup for task [watchdog/0]...
Maximum estimated system energy: 5584
04:11:51  DEBUG   :   task       watchdog/0 found, pid: [11]
04:11:51  DEBUG   : Lookup for task [watchdog/1]...
04:11:51  DEBUG   :   task       watchdog/1 found, pid: [12]
04:11:51  DEBUG   : Lookup for task [watchdog/2]...
04:11:51  DEBUG   :   task       watchdog/2 found, pid: [17]
04:11:51  DEBUG   : Lookup for task [watchdog/3]...
04:11:51  DEBUG   :   task       watchdog/3 found, pid: [22]
04:11:51  DEBUG   : Lookup for task [watchdog/4]...
04:11:51  DEBUG   :   task       watchdog/4 found, pid: [27]
04:11:51  DEBUG   : Lookup for task [watchdog/5]...
04:11:51  DEBUG   :   task       watchdog/5 found, pid: [32]
04:11:51  DEBUG   : Lookup for task [watchdog/6]...
04:11:51  DEBUG   :   task       watchdog/6 found, pid: [37]
04:11:51  DEBUG   : Lookup for task [watchdog/7]...
04:11:51  DEBUG   :   task       watchdog/7 found, pid: [42]
04:11:51  DEBUG   : Lookup for task [mmcqd/0]...
04:11:51  DEBUG   :   task          mmcqd/0 found, pid: [1196]
04:11:51  DEBUG   : Lookup for task [kworker/0:1H]...
04:11:51  DEBUG   :   task     kworker/0:1H found, pid: [1732]
04:11:51  DEBUG   : Lookup for task [kworker/3:1]...
04:11:51  DEBUG   :   task      kworker/3:1 found, pid: [1110]
04:11:51  DEBUG   : Lookup for task [shell srvc 2562]...
04:11:51  DEBUG   :   task  shell srvc 2562 found, pid: [25622, 25629]
04:11:51  DEBUG   : Lookup for task [migration/0]...
04:11:51  DEBUG   :   task      migration/0 found, pid: [10]
04:11:51  DEBUG   : Lookup for task [ls]...
04:11:51  DEBUG   :   task               ls found, pid: [25630, 25634, 25638, 25642]
04:11:51  DEBUG   : Lookup for task [service 36]...
04:11:51  DEBUG   :   task       service 36 found, pid: [25631, 25635, 25639, 25643, 25644]
04:11:51  DEBUG   : Lookup for task [shell srvc 2563]...
04:11:51  DEBUG   :   task  shell srvc 2563 found, pid: [25633, 25637]
04:11:51  DEBUG   : Lookup for task [jbd2/mmcblk0p10]...
04:11:51  DEBUG   :   task  jbd2/mmcblk0p10 found, pid: [1733]
04:11:51  DEBUG   : Lookup for task [shell srvc 2564]...
04:11:51  DEBUG   :   task  shell srvc 2564 found, pid: [25641, 25646]
04:11:51  DEBUG   : Lookup for task [shell srvc 2565]...
04:11:51  DEBUG   :   task  shell srvc 2565 found, pid: [25652]
04:11:51  DEBUG   : Lookup for task [kworker/u16:3]...
04:11:51  DEBUG   :   task    kworker/u16:3 found, pid: [25402]
04:11:51  INFO    : Collected events spans a 7.466 [s] time interval
04:11:51  INFO    : Overutilized time: 0.226519 [s] (3.034% of trace time)
04:11:51  INFO    : Set plots time range to (0.000000, 7.466276)[s]
04:11:51  DEBUG   : Registering [<trace.Trace object at 0x7fd3ccfe3d10>] local data frames
04:11:51  DEBUG   :    functions_stats
04:11:51  DEBUG   :    trace_event
04:11:51  DEBUG   : Analysis: /home/lubaoquan/tools/lisa/arnold-lisa/libs/utils/analysis
04:11:51  DEBUG   : Syspath: ['/home/lubaoquan/tools/lisa/arnold-lisa/libs/utils/analysis', '/home/lubaoquan/tools/lisa/arnold-lisa/libs/utils/analysis', '/home/lubaoquan/tools/lisa/arnold-lisa/libs/utils/analysis', '/home/lubaoquan/tools/lisa/arnold-lisa/libs/utils/analysis', '/home/lubaoquan/tools/lisa/arnold-lisa/libs/utils/analysis', '/home/lubaoquan/tools/lisa/arnold-lisa/libs/utils/analysis', '/home/lubaoquan/tools/lisa/arnold-lisa/libs/utils/analysis', '/home/lubaoquan/tools/lisa/arnold-lisa/libs/utils/analysis', '/home/lubaoquan/tools/lisa/arnold-lisa/libs/utils/analysis', '/home/lubaoquan/tools/lisa/arnold-lisa/libs/utils/analysis', '/home/lubaoquan/tools/lisa/arnold-lisa/libs/utils/analysis', '', '/home/lubaoquan/tools/lisa/arnold-lisa/libs/bart', '/home/lubaoquan/tools/lisa/arnold-lisa/libs/trappy', '/home/lubaoquan/tools/lisa/arnold-lisa/libs/devlib', '/home/lubaoquan/tools/lisa/arnold-lisa/libs/wlgen', '/home/lubaoquan/tools/lisa/arnold-lisa/libs/utils', '/home/lubaoquan/tools/lisa/arnold-lisa/ipynb/android', '/home/lubaoquan/anaconda2/lib/python27.zip', '/home/lubaoquan/anaconda2/lib/python2.7', '/home/lubaoquan/anaconda2/lib/python2.7/plat-linux2', '/home/lubaoquan/anaconda2/lib/python2.7/lib-tk', '/home/lubaoquan/anaconda2/lib/python2.7/lib-old', '/home/lubaoquan/anaconda2/lib/python2.7/lib-dynload', '/home/lubaoquan/anaconda2/lib/python2.7/site-packages', '/home/lubaoquan/anaconda2/lib/python2.7/site-packages/Sphinx-1.4.6-py2.7.egg', '/home/lubaoquan/anaconda2/lib/python2.7/site-packages/setuptools-27.2.0-py2.7.egg', '/home/lubaoquan/anaconda2/lib/python2.7/site-packages/IPython/extensions', '/home/lubaoquan/.ipython']
04:11:51  INFO    : Registering trace analysis modules:
04:11:51  DEBUG   : Filename: tasks_analysis
04:11:51  DEBUG   : Registering [<tasks_analysis.TasksAnalysis object at 0x7fd3c77aeb10>] local data frames
04:11:51  DEBUG   :    rt_tasks
04:11:51  DEBUG   :    top_big_tasks
04:11:51  DEBUG   :    top_wakeup_tasks
04:11:51  DEBUG   :    trace_event
04:11:51  INFO    :    tasks
04:11:51  DEBUG   : Filename: cpus_analysis
04:11:51  DEBUG   : Registering [<cpus_analysis.CpusAnalysis object at 0x7fd3c77aec50>] local data frames
04:11:51  DEBUG   :    context_switches
04:11:51  DEBUG   :    trace_event
04:11:51  INFO    :    cpus
04:11:51  DEBUG   : Filename: eas_analysis
04:11:51  DEBUG   : Registering [<eas_analysis.EasAnalysis object at 0x7fd3c77ae510>] local data frames
04:11:51  DEBUG   :    trace_event
04:11:51  INFO    :    eas
04:11:51  DEBUG   : Filename: functions_analysis
04:11:51  DEBUG   : Registering [<functions_analysis.FunctionsAnalysis object at 0x7fd3c77ae050>] local data frames
04:11:51  DEBUG   :    trace_event
04:11:51  INFO    :    functions
04:11:51  DEBUG   : Filename: latency_analysis
04:11:51  DEBUG   : Registering [<latency_analysis.LatencyAnalysis object at 0x7fd3c77ae550>] local data frames
04:11:51  DEBUG   :    latency_df
04:11:51  DEBUG   :    latency_preemption_df
04:11:51  DEBUG   :    latency_wakeup_df
04:11:51  DEBUG   :    trace_event
04:11:51  INFO    :    latency
04:11:51  DEBUG   : Filename: idle_analysis
04:11:51  DEBUG   : Registering [<idle_analysis.IdleAnalysis object at 0x7fd3c77ae590>] local data frames
04:11:51  DEBUG   :    cluster_idle_state_residency
04:11:51  DEBUG   :    cpu_idle_state_residency
04:11:51  DEBUG   :    trace_event
04:11:51  INFO    :    idle
04:11:51  DEBUG   : Filename: status_analysis
04:11:51  DEBUG   : Registering [<status_analysis.StatusAnalysis object at 0x7fd3c7e11ed0>] local data frames
04:11:51  DEBUG   :    overutilized
04:11:51  DEBUG   :    trace_event
04:11:51  INFO    :    status
04:11:51  DEBUG   : Filename: frequency_analysis
04:11:51  DEBUG   : Registering [<frequency_analysis.FrequencyAnalysis object at 0x7fd3c7e11790>] local data frames
04:11:51  DEBUG   :    cluster_frequency_residency
04:11:51  DEBUG   :    cpu_frequency_residency
04:11:51  DEBUG   :    trace_event
04:11:51  INFO    :    frequency
04:11:51  INFO    : Set plots time range to (0.000000, 7.466276)[s]
04:11:51  WARNING : Events [cpu_frequency] not found, plot DISABLED!
04:11:51  DEBUG   : Loading [sched] events from trace in [../../results/eas_acceptance/rtapp:energy_aware:small_tasks/1]...
04:11:51  DEBUG   : Parsing events: ['sched_overutilized', 'sched_energy_diff', 'sched_load_avg_task', 'sched_load_avg_cpu', 'sched_migrate_task', 'sched_switch']
04:11:51  INFO    : Parsing FTrace format...
04:11:54  DEBUG   : Events found on trace:
04:11:54  DEBUG   :  - sched_load_avg_task
04:11:54  DEBUG   :  - sched_load_avg_cpu
04:11:54  DEBUG   :  - sched_migrate_task
04:11:54  DEBUG   :  - sched_overutilized
04:11:54  DEBUG   :  - sched_switch
04:11:54  DEBUG   :  - sched_energy_diff
04:11:54  DEBUG   : Lookup dataset for tasks...
04:11:54  DEBUG   : Lookup for task [swapper/3]...
04:11:54  DEBUG   :   task        swapper/3 found, pid: [0]
04:11:54  DEBUG   : Lookup for task [sh]...
04:11:54  DEBUG   :   task               sh found, pid: [25949, 25946, 25951, 25954, 25953, 25955, 25957, 25958, 25959, 25961, 25963, 25982, 25980, 25991, 25993, 25995, 25997, 25999, 26001, 26003, 26005, 26007, 26009, 26011, 26013, 26015, 26017, 26019, 26021, 26024, 26027, 26026, 26028, 26030, 26033, 26032, 26034, 26037, 26036, 26038]
04:11:54  DEBUG   : Lookup for task [rcu_preempt]...
04:11:54  DEBUG   :   task      rcu_preempt found, pid: [7]
04:11:54  DEBUG   : Lookup for task [rcu_sched]...
04:11:54  DEBUG   :   task        rcu_sched found, pid: [8]
04:11:54  DEBUG   : Lookup for task [kworker/u16:0]...
04:11:54  DEBUG   :   task    kworker/u16:0 found, pid: [24188]
04:11:54  DEBUG   : Lookup for task [adbd]...
04:11:54  DEBUG   :   task             adbd found, pid: [3819, 25951, 25952, 25955, 25956, 25961, 25962, 25980, 25981, 25991, 25992, 25994, 25995, 25996, 25998, 25999, 26000, 26002, 26003, 26004, 26006, 26007, 26008, 26010, 26011, 26012, 26014, 26015, 26016, 26018, 26019, 26020, 26022, 26023, 26024, 26025, 26030, 26031, 26034, 26035]
04:11:54  DEBUG   : Lookup for task [->transport]...
04:11:54  DEBUG   :   task      ->transport found, pid: [3821]
04:11:54  DEBUG   : Lookup for task [<-transport]...
04:11:54  DEBUG   :   task      <-transport found, pid: [3822]
04:11:54  DEBUG   : Lookup for task [kworker/0:1]...
04:11:54  DEBUG   :   task      kworker/0:1 found, pid: [23716]
04:11:54  DEBUG   : Lookup for task [shell srvc 2594]...
04:11:54  DEBUG   :   task  shell srvc 2594 found, pid: [25947]
04:11:54  DEBUG   : Lookup for task [swapper/2]...
04:11:54  DEBUG   :   task        swapper/2 found, pid: [0]
04:11:54  DEBUG   : Lookup for task [swapper/0]...
04:11:54  DEBUG   :   task        swapper/0 found, pid: [0]
04:11:54  DEBUG   : Lookup for task [kschedfreq:0]...
04:11:54  DEBUG   :   task     kschedfreq:0 found, pid: [16478]
04:11:54  DEBUG   : Lookup for task [su]...
04:11:54  DEBUG   :   task               su found, pid: [25954, 25958, 26027, 26033, 26037]
04:11:54  DEBUG   : Lookup for task [shell srvc 2595]...
04:11:54  DEBUG   :   task  shell srvc 2595 found, pid: [25952, 25956]
04:11:54  DEBUG   : Lookup for task [shutils]...
04:11:54  DEBUG   :   task          shutils found, pid: [25960, 25959, 25963, 25964, 25965, 25966, 25967, 25968, 25969, 25970, 25971, 25972, 25973, 25974, 25975, 25976, 25977, 25978, 25979, 26028, 26029]
04:11:54  DEBUG   : Lookup for task [migration/1]...
04:11:54  DEBUG   :   task      migration/1 found, pid: [13]
04:11:54  DEBUG   : Lookup for task [swapper/1]...
04:11:54  DEBUG   :   task        swapper/1 found, pid: [0]
04:11:54  DEBUG   : Lookup for task [kworker/0:0]...
04:11:54  DEBUG   :   task      kworker/0:0 found, pid: [25854]
04:11:54  DEBUG   : Lookup for task [ksoftirqd/2]...
04:11:54  DEBUG   :   task      ksoftirqd/2 found, pid: [19]
04:11:54  DEBUG   : Lookup for task [migration/2]...
04:11:54  DEBUG   :   task      migration/2 found, pid: [18]
04:11:54  DEBUG   : Lookup for task [busybox]...
04:11:54  DEBUG   :   task          busybox found, pid: [25964, 25965, 25966, 25971, 25972, 25973, 25974, 25975, 25976, 25977, 25978, 26029]
04:11:54  DEBUG   : Lookup for task [migration/0]...
04:11:54  DEBUG   :   task      migration/0 found, pid: [10]
04:11:54  DEBUG   : Lookup for task [true]...
04:11:54  DEBUG   :   task             true found, pid: [25966, 25970, 25972, 25974, 25976, 25978]
04:11:54  DEBUG   : Lookup for task [ksoftirqd/1]...
04:11:54  DEBUG   :   task      ksoftirqd/1 found, pid: [14]
04:11:54  DEBUG   : Lookup for task [migration/3]...
04:11:54  DEBUG   :   task      migration/3 found, pid: [23]
04:11:54  DEBUG   : Lookup for task [kworker/4:1]...
04:11:54  DEBUG   :   task      kworker/4:1 found, pid: [1296]
04:11:54  DEBUG   : Lookup for task [kworker/3:1]...
04:11:54  DEBUG   :   task      kworker/3:1 found, pid: [1110]
04:11:54  DEBUG   : Lookup for task [ksoftirqd/3]...
04:11:54  DEBUG   :   task      ksoftirqd/3 found, pid: [24]
04:11:54  DEBUG   : Lookup for task [swapper/4]...
04:11:54  DEBUG   :   task        swapper/4 found, pid: [0]
04:11:54  DEBUG   : Lookup for task [kworker/2:1]...
04:11:54  DEBUG   :   task      kworker/2:1 found, pid: [1111]
04:11:54  DEBUG   : Lookup for task [kworker/5:1]...
04:11:54  DEBUG   :   task      kworker/5:1 found, pid: [1297]
04:11:54  DEBUG   : Lookup for task [swapper/5]...
04:11:54  DEBUG   :   task        swapper/5 found, pid: [0]
04:11:54  DEBUG   : Lookup for task [kworker/6:1]...
04:11:54  DEBUG   :   task      kworker/6:1 found, pid: [1252]
04:11:54  DEBUG   : Lookup for task [swapper/6]...
04:11:54  DEBUG   :   task        swapper/6 found, pid: [0]
04:11:54  DEBUG   : Lookup for task [kworker/7:2]...
04:11:54  DEBUG   :   task      kworker/7:2 found, pid: [3824]
Maximum estimated system energy: 5584
04:11:54  DEBUG   : Lookup for task [swapper/7]...
04:11:54  DEBUG   :   task        swapper/7 found, pid: [0]
04:11:54  DEBUG   : Lookup for task [shell srvc 2596]...
04:11:54  DEBUG   :   task  shell srvc 2596 found, pid: [25962]
04:11:54  DEBUG   : Lookup for task [rt-app]...
04:11:54  DEBUG   :   task           rt-app found, pid: [25982, 25983, 25986, 25985, 25984, 25987, 25988, 25990, 25989]
04:11:54  DEBUG   : Lookup for task [task_taskpack0]...
04:11:54  DEBUG   :   task   task_taskpack0 found, pid: [25983]
04:11:54  DEBUG   : Lookup for task [task_taskpack3]...
04:11:54  DEBUG   :   task   task_taskpack3 found, pid: [25986]
04:11:54  DEBUG   : Lookup for task [task_taskpack2]...
04:11:54  DEBUG   :   task   task_taskpack2 found, pid: [25985]
04:11:54  DEBUG   : Lookup for task [task_taskpack1]...
04:11:54  DEBUG   :   task   task_taskpack1 found, pid: [25984]
04:11:54  DEBUG   : Lookup for task [task_taskpack4]...
04:11:54  DEBUG   :   task   task_taskpack4 found, pid: [25987]
04:11:54  DEBUG   : Lookup for task [task_taskpack5]...
04:11:54  DEBUG   :   task   task_taskpack5 found, pid: [25988]
04:11:54  DEBUG   : Lookup for task [task_taskpack6]...
04:11:54  DEBUG   :   task   task_taskpack6 found, pid: [25989]
04:11:54  DEBUG   : Lookup for task [task_taskpack7]...
04:11:54  DEBUG   :   task   task_taskpack7 found, pid: [25990]
04:11:54  DEBUG   : Lookup for task [kworker/1:1]...
04:11:54  DEBUG   :   task      kworker/1:1 found, pid: [1188]
04:11:54  DEBUG   : Lookup for task [kworker/u16:3]...
04:11:54  DEBUG   :   task    kworker/u16:3 found, pid: [25402]
04:11:54  DEBUG   : Lookup for task [watchdog/0]...
04:11:54  DEBUG   :   task       watchdog/0 found, pid: [11]
04:11:54  DEBUG   : Lookup for task [watchdog/1]...
04:11:54  DEBUG   :   task       watchdog/1 found, pid: [12]
04:11:54  DEBUG   : Lookup for task [watchdog/2]...
04:11:54  DEBUG   :   task       watchdog/2 found, pid: [17]
04:11:54  DEBUG   : Lookup for task [watchdog/3]...
04:11:54  DEBUG   :   task       watchdog/3 found, pid: [22]
04:11:54  DEBUG   : Lookup for task [watchdog/4]...
04:11:54  DEBUG   :   task       watchdog/4 found, pid: [27]
04:11:54  DEBUG   : Lookup for task [watchdog/5]...
04:11:54  DEBUG   :   task       watchdog/5 found, pid: [32]
04:11:54  DEBUG   : Lookup for task [watchdog/6]...
04:11:54  DEBUG   :   task       watchdog/6 found, pid: [37]
04:11:54  DEBUG   : Lookup for task [watchdog/7]...
04:11:54  DEBUG   :   task       watchdog/7 found, pid: [42]
04:11:54  DEBUG   : Lookup for task [shell srvc 2598]...
04:11:54  DEBUG   :   task  shell srvc 2598 found, pid: [25981]
04:11:54  DEBUG   : Lookup for task [ls]...
04:11:54  DEBUG   :   task               ls found, pid: [25993, 25997, 26001, 26005, 26009, 26013, 26017, 26021]
04:11:54  DEBUG   : Lookup for task [shell srvc 2599]...
04:11:54  DEBUG   :   task  shell srvc 2599 found, pid: [25992, 25996, 26000]
04:11:54  DEBUG   : Lookup for task [service 36]...
04:11:54  DEBUG   :   task       service 36 found, pid: [25994, 25998, 26002, 26006, 26010, 26014, 26018, 26022, 26023]
04:11:54  DEBUG   : Lookup for task [shell srvc 2600]...
04:11:54  DEBUG   :   task  shell srvc 2600 found, pid: [26004, 26008]
04:11:54  DEBUG   : Lookup for task [shell srvc 2601]...
04:11:54  DEBUG   :   task  shell srvc 2601 found, pid: [26012, 26016, 26020]
04:11:54  DEBUG   : Lookup for task [shell srvc 2602]...
04:11:54  DEBUG   :   task  shell srvc 2602 found, pid: [26025]
04:11:54  DEBUG   : Lookup for task [shell srvc 2603]...
04:11:54  DEBUG   :   task  shell srvc 2603 found, pid: [26031]
04:11:54  INFO    : Collected events spans a 8.806 [s] time interval
04:11:54  INFO    : Overutilized time: 0.216956 [s] (2.464% of trace time)
04:11:54  INFO    : Set plots time range to (0.000000, 8.806039)[s]
04:11:54  DEBUG   : Registering [<trace.Trace object at 0x7fd3c7e117d0>] local data frames
04:11:54  DEBUG   :    functions_stats
04:11:54  DEBUG   :    trace_event
04:11:54  DEBUG   : Analysis: /home/lubaoquan/tools/lisa/arnold-lisa/libs/utils/analysis
04:11:54  DEBUG   : Syspath: ['/home/lubaoquan/tools/lisa/arnold-lisa/libs/utils/analysis', '/home/lubaoquan/tools/lisa/arnold-lisa/libs/utils/analysis', '/home/lubaoquan/tools/lisa/arnold-lisa/libs/utils/analysis', '/home/lubaoquan/tools/lisa/arnold-lisa/libs/utils/analysis', '/home/lubaoquan/tools/lisa/arnold-lisa/libs/utils/analysis', '/home/lubaoquan/tools/lisa/arnold-lisa/libs/utils/analysis', '/home/lubaoquan/tools/lisa/arnold-lisa/libs/utils/analysis', '/home/lubaoquan/tools/lisa/arnold-lisa/libs/utils/analysis', '/home/lubaoquan/tools/lisa/arnold-lisa/libs/utils/analysis', '/home/lubaoquan/tools/lisa/arnold-lisa/libs/utils/analysis', '/home/lubaoquan/tools/lisa/arnold-lisa/libs/utils/analysis', '/home/lubaoquan/tools/lisa/arnold-lisa/libs/utils/analysis', '', '/home/lubaoquan/tools/lisa/arnold-lisa/libs/bart', '/home/lubaoquan/tools/lisa/arnold-lisa/libs/trappy', '/home/lubaoquan/tools/lisa/arnold-lisa/libs/devlib', '/home/lubaoquan/tools/lisa/arnold-lisa/libs/wlgen', '/home/lubaoquan/tools/lisa/arnold-lisa/libs/utils', '/home/lubaoquan/tools/lisa/arnold-lisa/ipynb/android', '/home/lubaoquan/anaconda2/lib/python27.zip', '/home/lubaoquan/anaconda2/lib/python2.7', '/home/lubaoquan/anaconda2/lib/python2.7/plat-linux2', '/home/lubaoquan/anaconda2/lib/python2.7/lib-tk', '/home/lubaoquan/anaconda2/lib/python2.7/lib-old', '/home/lubaoquan/anaconda2/lib/python2.7/lib-dynload', '/home/lubaoquan/anaconda2/lib/python2.7/site-packages', '/home/lubaoquan/anaconda2/lib/python2.7/site-packages/Sphinx-1.4.6-py2.7.egg', '/home/lubaoquan/anaconda2/lib/python2.7/site-packages/setuptools-27.2.0-py2.7.egg', '/home/lubaoquan/anaconda2/lib/python2.7/site-packages/IPython/extensions', '/home/lubaoquan/.ipython']
04:11:54  INFO    : Registering trace analysis modules:
04:11:54  DEBUG   : Filename: tasks_analysis
04:11:54  DEBUG   : Registering [<tasks_analysis.TasksAnalysis object at 0x7fd3c77ae750>] local data frames
04:11:54  DEBUG   :    rt_tasks
04:11:54  DEBUG   :    top_big_tasks
04:11:54  DEBUG   :    top_wakeup_tasks
04:11:54  DEBUG   :    trace_event
04:11:54  INFO    :    tasks
04:11:54  DEBUG   : Filename: cpus_analysis
04:11:54  DEBUG   : Registering [<cpus_analysis.CpusAnalysis object at 0x7fd3c7e11ad0>] local data frames
04:11:54  DEBUG   :    context_switches
04:11:54  DEBUG   :    trace_event
04:11:54  INFO    :    cpus
04:11:54  DEBUG   : Filename: eas_analysis
04:11:54  DEBUG   : Registering [<eas_analysis.EasAnalysis object at 0x7fd3c7e11210>] local data frames
04:11:54  DEBUG   :    trace_event
04:11:54  INFO    :    eas
04:11:54  DEBUG   : Filename: functions_analysis
04:11:54  DEBUG   : Registering [<functions_analysis.FunctionsAnalysis object at 0x7fd3c7e11f50>] local data frames
04:11:54  DEBUG   :    trace_event
04:11:54  INFO    :    functions
04:11:54  DEBUG   : Filename: latency_analysis
04:11:54  DEBUG   : Registering [<latency_analysis.LatencyAnalysis object at 0x7fd3c7e11f10>] local data frames
04:11:54  DEBUG   :    latency_df
04:11:54  DEBUG   :    latency_preemption_df
04:11:54  DEBUG   :    latency_wakeup_df
04:11:54  DEBUG   :    trace_event
04:11:54  INFO    :    latency
04:11:54  DEBUG   : Filename: idle_analysis
04:11:54  DEBUG   : Registering [<idle_analysis.IdleAnalysis object at 0x7fd3c7e11650>] local data frames
04:11:54  DEBUG   :    cluster_idle_state_residency
04:11:54  DEBUG   :    cpu_idle_state_residency
04:11:54  DEBUG   :    trace_event
04:11:54  INFO    :    idle
04:11:54  DEBUG   : Filename: status_analysis
04:11:54  DEBUG   : Registering [<status_analysis.StatusAnalysis object at 0x7fd3c7e11f90>] local data frames
04:11:54  DEBUG   :    overutilized
04:11:54  DEBUG   :    trace_event
04:11:54  INFO    :    status
04:11:54  DEBUG   : Filename: frequency_analysis
04:11:54  DEBUG   : Registering [<frequency_analysis.FrequencyAnalysis object at 0x7fd3c7e11690>] local data frames
04:11:54  DEBUG   :    cluster_frequency_residency
04:11:54  DEBUG   :    cpu_frequency_residency
04:11:54  DEBUG   :    trace_event
04:11:54  INFO    :    frequency
04:11:54  INFO    : Set plots time range to (0.000000, 8.806039)[s]
04:11:54  WARNING : Events [cpu_frequency] not found, plot DISABLED!

In [ ]: