Add energy monitoring and characterization scripts

ORGANIZATION.md

@@ -33,6 +33,7 @@ special integration:
 * [`tests/ref`][tests/ref]: Reference tests.
 * [`tests/html`][tests/html]: Manual test cases and examples.
 * [`tests/power`][tests/power]: Tests for measuring power usage.
+* [`tests/heartbeats`][tests/heartbeats]: Tests for profiler-level timing and energy behavior.
 * [`tests/wpt`][tests/wpt]: Web platform tests and harness.
 
 ## Miscellaneous

components/profile/heartbeats.rs

@@ -51,6 +51,7 @@ pub fn init() {
     maybe_create_heartbeat(&mut hbs, ProfilerCategory::ScriptWebSocketEvent);
     maybe_create_heartbeat(&mut hbs, ProfilerCategory::ScriptWorkerEvent);
     maybe_create_heartbeat(&mut hbs, ProfilerCategory::ScriptXhrEvent);
+    maybe_create_heartbeat(&mut hbs, ProfilerCategory::ApplicationHeartbeat);
     unsafe {
         HBS = Some(mem::transmute(Box::new(hbs)));
     }
@@ -71,6 +72,12 @@ pub fn cleanup() {
     }
 }
 
+pub fn is_heartbeat_enabled(category: &ProfilerCategory) -> bool {
+    unsafe {
+        HBS.map_or(false, |m| (*m).contains_key(category))
+    }
+}
+
 /// Issue a heartbeat (if one exists) for the given category
 pub fn maybe_heartbeat(category: &ProfilerCategory,
                        start_time: u64,

components/profile/time.rs

@@ -6,12 +6,14 @@
 
 use heartbeats;
 use ipc_channel::ipc::{self, IpcReceiver};
+use profile_traits::energy::{energy_interval_ms, read_energy_uj};
 use profile_traits::time::{ProfilerCategory, ProfilerChan, ProfilerMsg, TimerMetadata};
 use std::borrow::ToOwned;
 use std::cmp::Ordering;
 use std::collections::BTreeMap;
 use std::f64;
 use std::thread::sleep_ms;
+use std_time::precise_time_ns;
 use util::task::spawn_named;
 
 pub trait Formattable {
@@ -93,6 +95,7 @@ impl Formattable for ProfilerCategory {
             ProfilerCategory::ScriptWebSocketEvent => "Script Web Socket Event",
             ProfilerCategory::ScriptWorkerEvent => "Script Worker Event",
             ProfilerCategory::ScriptXhrEvent => "Script Xhr Event",
+            ProfilerCategory::ApplicationHeartbeat => "Application Heartbeat",
         };
         format!("{}{}", padding, name)
     }
@@ -141,8 +144,49 @@ impl Profiler {
             }
         }
         heartbeats::init();
+        let profiler_chan = ProfilerChan(chan);
 
-        ProfilerChan(chan)
+        // only spawn the application-level profiler thread if its heartbeat is enabled
+        let run_ap_thread = || {
+            heartbeats::is_heartbeat_enabled(&ProfilerCategory::ApplicationHeartbeat)
+        };
+        if run_ap_thread() {
+            let profiler_chan = profiler_chan.clone();
+            // min of 1 heartbeat/sec, max of 20 should provide accurate enough power/energy readings
+            // waking up more frequently allows the thread to end faster on exit
+            const SLEEP_MS: u32 = 10;
+            const MIN_ENERGY_INTERVAL_MS: u32 = 50;
+            const MAX_ENERGY_INTERVAL_MS: u32 = 1000;
+            let interval_ms = enforce_range(MIN_ENERGY_INTERVAL_MS, MAX_ENERGY_INTERVAL_MS, energy_interval_ms());
+            let loop_count: u32 = (interval_ms as f32 / SLEEP_MS as f32).ceil() as u32;
+            spawn_named("Application heartbeat profiler".to_owned(), move || {
+                let mut start_time = precise_time_ns();
+                let mut start_energy = read_energy_uj();
+                loop {
+                    for _ in 0..loop_count {
+                        match run_ap_thread() {
+                            true => sleep_ms(SLEEP_MS),
+                            false => return,
+                        }
+                    }
+                    let end_time = precise_time_ns();
+                    let end_energy = read_energy_uj();
+                    // send using the inner channel
+                    // (using ProfilerChan.send() forces an unwrap and sometimes panics for this background profiler)
+                    let ProfilerChan(ref c) = profiler_chan;
+                    match c.send(ProfilerMsg::Time((ProfilerCategory::ApplicationHeartbeat, None),
+                                                   (start_time, end_time),
+                                                   (start_energy, end_energy))) {
+                        Ok(_) => {},
+                        Err(_) => return,
+                    };
+                    start_time = end_time;
+                    start_energy = end_energy;
+                }
+            });
+        }
+
+        profiler_chan
     }
 
     pub fn new(port: IpcReceiver<ProfilerMsg>) -> Profiler {
@@ -178,8 +222,8 @@ impl Profiler {
 
     fn handle_msg(&mut self, msg: ProfilerMsg) -> bool {
         match msg.clone() {
-            ProfilerMsg::Time(k, t) => {
+            ProfilerMsg::Time(k, t, e) => {
-                heartbeats::maybe_heartbeat(&k.0, t.0, t.1, 0, 0);
+                heartbeats::maybe_heartbeat(&k.0, t.0, t.1, e.0, e.1);
                 let ms = (t.1 - t.0) as f64 / 1000000f64;
                 self.find_or_insert(k, ms);
             },
@@ -224,3 +268,16 @@ impl Profiler {
         println!("");
     }
 }
+
+fn enforce_range<T>(min: T, max: T, value: T) -> T where T: Ord {
+    assert!(min <= max);
+    match value.cmp(&max) {
+        Ordering::Equal | Ordering::Greater => max,
+        Ordering::Less => {
+            match value.cmp(&min) {
+                Ordering::Equal | Ordering::Less => min,
+                Ordering::Greater => value,
+            }
+        },
+    }
+}

components/profile_traits/Cargo.toml

@@ -7,6 +7,9 @@ authors = ["The Servo Project Developers"]
 name = "profile_traits"
 path = "lib.rs"
 
+[features]
+energy-profiling = ["energymon", "energy-monitor"]
+
 [dependencies.ipc-channel]
 git = "https://github.com/pcwalton/ipc-channel"
 
@@ -14,6 +17,15 @@ git = "https://github.com/pcwalton/ipc-channel"
 version = "0.2"
 features = [ "serde_serialization" ]
 
+[dependencies.energymon]
+git = "https://github.com/energymon/energymon-rust.git"
+rev = "67f74732ac"
+optional = true
+
+[dependencies.energy-monitor]
+version = "0.1.0"
+optional = true
+
 [dependencies]
 serde = "0.5"
 serde_macros = "0.5"

components/profile_traits/energy.rs

@@ -0,0 +1,63 @@
+/* This Source Code Form is subject to the terms of the Mozilla Public
+ * License, v. 2.0. If a copy of the MPL was not distributed with this
+ * file, You can obtain one at http://mozilla.org/MPL/2.0/. */
+
+
+#[cfg(feature = "energy-profiling")]
+pub fn read_energy_uj() -> u64 {
+    energymon::read_energy_uj()
+}
+
+#[cfg(not(feature = "energy-profiling"))]
+pub fn read_energy_uj() -> u64 {
+    0
+}
+
+#[cfg(feature = "energy-profiling")]
+pub fn energy_interval_ms() -> u32 {
+    energymon::get_min_interval_ms()
+}
+
+#[cfg(not(feature = "energy-profiling"))]
+pub fn energy_interval_ms() -> u32 {
+    1000
+}
+
+#[cfg(feature = "energy-profiling")]
+mod energymon {
+    extern crate energymon;
+    extern crate energy_monitor;
+
+    use self::energy_monitor::EnergyMonitor;
+    use self::energymon::EnergyMon;
+    use std::mem;
+    use std::sync::{Once, ONCE_INIT};
+
+
+    static mut EM: Option<*mut EnergyMon> = None;
+
+    /// Read energy from the energy monitor, otherwise return 0.
+    pub fn read_energy_uj() -> u64 {
+        static ONCE: Once = ONCE_INIT;
+        ONCE.call_once(|| {
+            if let Ok(em) = EnergyMon::new() {
+                println!("Started energy monitoring from: {}", em.source());
+                unsafe {
+                    EM = Some(mem::transmute(Box::new(em)));
+                }
+            }
+        });
+
+        unsafe {
+            // EnergyMon implementations of EnergyMonitor always return a value
+            EM.map_or(0, |em| (*em).read_uj().unwrap())
+        }
+    }
+
+    pub fn get_min_interval_ms() -> u32 {
+        unsafe {
+            EM.map_or(0, |em| ((*em).interval_us() as f64 / 1000.0).ceil() as u32)
+        }
+    }
+
+}

components/profile_traits/lib.rs

@@ -13,6 +13,7 @@
 extern crate ipc_channel;
 extern crate serde;
 
+pub mod energy;
 pub mod mem;
 pub mod time;
 

components/profile_traits/time.rs

@@ -5,6 +5,7 @@
 extern crate time as std_time;
 extern crate url;
 
+use energy::read_energy_uj;
 use ipc_channel::ipc::IpcSender;
 use self::std_time::precise_time_ns;
 use self::url::Url;
@@ -29,7 +30,7 @@ impl ProfilerChan {
 #[derive(Clone, Deserialize, Serialize)]
 pub enum ProfilerMsg {
     /// Normal message used for reporting time
-    Time((ProfilerCategory, Option<TimerMetadata>), (u64, u64)),
+    Time((ProfilerCategory, Option<TimerMetadata>), (u64, u64), (u64, u64)),
     /// Message used to force print the profiling metrics
     Print,
     /// Tells the profiler to shut down.
@@ -72,6 +73,7 @@ pub enum ProfilerCategory {
     ScriptWebSocketEvent,
     ScriptWorkerEvent,
     ScriptXhrEvent,
+    ApplicationHeartbeat,
 }
 
 #[derive(Eq, PartialEq)]
@@ -96,15 +98,19 @@ pub fn profile<T, F>(category: ProfilerCategory,
                   -> T
     where F: FnOnce() -> T
 {
+    let start_energy = read_energy_uj();
     let start_time = precise_time_ns();
     let val = callback();
     let end_time = precise_time_ns();
+    let end_energy = read_energy_uj();
     let meta = meta.map(|(url, iframe, reflow_type)|
         TimerMetadata {
             url: url.serialize(),
             iframe: iframe == TimerMetadataFrameType::IFrame,
             incremental: reflow_type == TimerMetadataReflowType::Incremental,
         });
-    profiler_chan.send(ProfilerMsg::Time((category, meta), (start_time, end_time)));
+    profiler_chan.send(ProfilerMsg::Time((category, meta),
+                                         (start_time, end_time),
+                                         (start_energy, end_energy)));
     return val;
 }

components/servo/Cargo.lock

@@ -435,6 +435,40 @@ name = "encoding_index_tests"
 version = "0.1.4"
 source = "registry+https://github.com/rust-lang/crates.io-index"
 
+[[package]]
+name = "energy-monitor"
+version = "0.1.0"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+
+[[package]]
+name = "energymon"
+version = "0.1.0"
+source = "git+https://github.com/energymon/energymon-rust.git?rev=67f74732ac#67f74732ac0acc682659f7e81836155a32188fd0"
+dependencies = [
+ "energy-monitor 0.1.0 (registry+https://github.com/rust-lang/crates.io-index)",
+ "energymon-default-sys 0.1.0 (git+https://github.com/energymon/energymon-default-sys.git)",
+ "energymon-sys 0.1.0 (git+https://github.com/energymon/energymon-sys.git)",
+ "libc 0.1.8 (registry+https://github.com/rust-lang/crates.io-index)",
+]
+
+[[package]]
+name = "energymon-default-sys"
+version = "0.1.0"
+source = "git+https://github.com/energymon/energymon-default-sys.git#3e83c0ad72d9729f7f6b297e4c55dfa8b1db32ac"
+dependencies = [
+ "energymon-sys 0.1.0 (git+https://github.com/energymon/energymon-sys.git)",
+ "libc 0.1.8 (registry+https://github.com/rust-lang/crates.io-index)",
+ "pkg-config 0.3.5 (registry+https://github.com/rust-lang/crates.io-index)",
+]
+
+[[package]]
+name = "energymon-sys"
+version = "0.1.0"
+source = "git+https://github.com/energymon/energymon-sys.git#770d2cfe0373cf833992352b50dfdceb7a42b2e6"
+dependencies = [
+ "libc 0.1.8 (registry+https://github.com/rust-lang/crates.io-index)",
+]
+
 [[package]]
 name = "env_logger"
 version = "0.3.1"
@@ -1282,6 +1316,8 @@ dependencies = [
 name = "profile_traits"
 version = "0.0.1"
 dependencies = [
+ "energy-monitor 0.1.0 (registry+https://github.com/rust-lang/crates.io-index)",
+ "energymon 0.1.0 (git+https://github.com/energymon/energymon-rust.git?rev=67f74732ac)",
  "ipc-channel 0.1.0 (git+https://github.com/pcwalton/ipc-channel)",
  "serde 0.5.3 (registry+https://github.com/rust-lang/crates.io-index)",
  "serde_macros 0.5.1 (registry+https://github.com/rust-lang/crates.io-index)",

components/servo/Cargo.toml

@@ -45,6 +45,7 @@ default = ["glutin_app", "window", "webdriver"]
 window = ["glutin_app/window"]
 headless = ["glutin_app/headless"]
 webdriver = ["webdriver_server"]
+energy-profiling = ["profile_traits/energy-profiling"]
 
 # Uncomment to profile on Linux:
 #

tests/heartbeats/characterize.py

@@ -0,0 +1,247 @@
+#!/usr/bin/env python
+
+# This Source Code Form is subject to the terms of the Mozilla Public
+# License, v. 2.0. If a copy of the MPL was not distributed with this
+# file, You can obtain one at http://mozilla.org/MPL/2.0/.
+
+import sys
+import os
+from os import path
+import time
+import datetime
+import argparse
+import platform
+import subprocess
+
+TOP_DIR = path.join("..", "..")
+GUARD_TIME = 10
+HEARTBEAT_DEFAULT_WINDOW_SIZE = 20
+# Use a larger window sizes to reduce or prevent writing log files until benchmark completion
+# (profiler name, window size)
+HEARTBEAT_PROFILER_CATEGORIES = [
+    ("Compositing", HEARTBEAT_DEFAULT_WINDOW_SIZE),
+    ("LayoutPerform", HEARTBEAT_DEFAULT_WINDOW_SIZE),
+    ("LayoutStyleRecalc", HEARTBEAT_DEFAULT_WINDOW_SIZE),
+    ("LayoutRestyleDamagePropagation", HEARTBEAT_DEFAULT_WINDOW_SIZE),
+    ("LayoutNonIncrementalReset", HEARTBEAT_DEFAULT_WINDOW_SIZE),
+    ("LayoutSelectorMatch", HEARTBEAT_DEFAULT_WINDOW_SIZE),
+    ("LayoutTreeBuilder", HEARTBEAT_DEFAULT_WINDOW_SIZE),
+    ("LayoutDamagePropagate", HEARTBEAT_DEFAULT_WINDOW_SIZE),
+    ("LayoutGeneratedContent", HEARTBEAT_DEFAULT_WINDOW_SIZE),
+    ("LayoutMain", HEARTBEAT_DEFAULT_WINDOW_SIZE),
+    ("LayoutParallelWarmup", HEARTBEAT_DEFAULT_WINDOW_SIZE),
+    ("LayoutShaping", HEARTBEAT_DEFAULT_WINDOW_SIZE),
+    ("LayoutDispListBuild", HEARTBEAT_DEFAULT_WINDOW_SIZE),
+    ("PaintingPerTile", 50),
+    ("PaintingPrepBuff", HEARTBEAT_DEFAULT_WINDOW_SIZE),
+    ("Painting", HEARTBEAT_DEFAULT_WINDOW_SIZE),
+    ("ImageDecoding", HEARTBEAT_DEFAULT_WINDOW_SIZE),
+    ("ScriptAttachLayout", HEARTBEAT_DEFAULT_WINDOW_SIZE),
+    ("ScriptConstellationMsg", HEARTBEAT_DEFAULT_WINDOW_SIZE),
+    ("ScriptDevtoolsMsg", HEARTBEAT_DEFAULT_WINDOW_SIZE),
+    ("ScriptDocumentEvent", HEARTBEAT_DEFAULT_WINDOW_SIZE),
+    ("ScriptDomEvent", HEARTBEAT_DEFAULT_WINDOW_SIZE),
+    ("ScriptFileRead", HEARTBEAT_DEFAULT_WINDOW_SIZE),
+    ("ScriptImageCacheMsg", HEARTBEAT_DEFAULT_WINDOW_SIZE),
+    ("ScriptInputEvent", HEARTBEAT_DEFAULT_WINDOW_SIZE),
+    ("ScriptNetworkEvent", 200),
+    ("ScriptResize", HEARTBEAT_DEFAULT_WINDOW_SIZE),
+    ("ScriptEvent", HEARTBEAT_DEFAULT_WINDOW_SIZE),
+    ("ScriptUpdateReplacedElement", HEARTBEAT_DEFAULT_WINDOW_SIZE),
+    ("ScriptSetViewport", HEARTBEAT_DEFAULT_WINDOW_SIZE),
+    ("ScriptWebSocketEvent", HEARTBEAT_DEFAULT_WINDOW_SIZE),
+    ("ScriptWorkerEvent", HEARTBEAT_DEFAULT_WINDOW_SIZE),
+    ("ScriptXhrEvent", HEARTBEAT_DEFAULT_WINDOW_SIZE),
+    ("ApplicationHeartbeat", 100)
+]
+ENERGY_READER_BIN = "energymon"
+ENERGY_READER_TEMP_OUTPUT = "energymon.txt"
+SUMMARY_OUTPUT = "summary.txt"
+
+
+def get_command(build_target, layout_thread_count, renderer, page, profile):
+    """Get the command to execute.
+    """
+    return path.join(TOP_DIR, "target", build_target, "servo") + \
+        " -p %d -x -y %d %s -Z profile-script-events '%s'" % \
+        (profile, layout_thread_count, renderer, page)
+
+
+def set_app_environment(log_dir):
+    """Set environment variables to enable heartbeats.
+    """
+    prefix = "heartbeat-"
+    for (profiler, window) in HEARTBEAT_PROFILER_CATEGORIES:
+        os.environ["SERVO_HEARTBEAT_ENABLE_" + profiler] = ""
+        os.environ["SERVO_HEARTBEAT_LOG_" + profiler] = path.join(log_dir, prefix + profiler + ".log")
+        os.environ["SERVO_HEARTBEAT_WINDOW_" + profiler] = str(window)
+
+
+def start_energy_reader():
+    """Energy reader writes to a file that we will poll.
+    """
+    os.system(ENERGY_READER_BIN + " " + ENERGY_READER_TEMP_OUTPUT + "&")
+
+
+def stop_energy_reader():
+    """Stop the energy reader and remove its temp file.
+    """
+    os.system("pkill -x " + ENERGY_READER_BIN)
+    os.remove(ENERGY_READER_TEMP_OUTPUT)
+
+
+def read_energy():
+    """Poll the energy reader's temp file.
+    """
+    data = 0
+    with open(ENERGY_READER_TEMP_OUTPUT, "r") as em:
+        data = int(em.read().replace('\n', ''))
+    return data
+
+
+def git_rev_hash():
+    """Get the git revision hash.
+    """
+    return subprocess.check_output(['git', 'rev-parse', 'HEAD']).rstrip()
+
+
+def git_rev_hash_short():
+    """Get the git revision short hash.
+    """
+    return subprocess.check_output(['git', 'rev-parse', '--short', 'HEAD']).rstrip()
+
+
+def execute(base_dir, build_target, renderer, page, profile, trial, layout_thread_count):
+    """Run a single execution.
+    """
+    log_dir = path.join(base_dir, "logs_l" + str(layout_thread_count),
+                        "trial_" + str(trial))
+    if os.path.exists(log_dir):
+        print "Log directory already exists: " + log_dir
+        sys.exit(1)
+    os.makedirs(log_dir)
+
+    set_app_environment(log_dir)
+    cmd = get_command(build_target, layout_thread_count, renderer, page, profile)
+
+    # Execute
+    start_energy_reader()
+    print 'sleep ' + str(GUARD_TIME)
+    time.sleep(GUARD_TIME)
+    time_start = time.time()
+    energy_start = read_energy()
+    print cmd
+    os.system(cmd)
+    energy_end = read_energy()
+    time_end = time.time()
+    stop_energy_reader()
+    print 'sleep ' + str(GUARD_TIME)
+    time.sleep(GUARD_TIME)
+
+    uj = energy_end - energy_start
+    latency = time_end - time_start
+    watts = uj / 1000000.0 / latency
+    # Write a file that describes this execution
+    with open(path.join(log_dir, SUMMARY_OUTPUT), "w") as f:
+        f.write("Datetime (UTC): " + datetime.datetime.utcnow().isoformat())
+        f.write("\nPlatform: " + platform.platform())
+        f.write("\nGit hash: " + git_rev_hash())
+        f.write("\nGit short hash: " + git_rev_hash_short())
+        f.write("\nRelease: " + build_target)
+        f.write("\nLayout threads: " + str(layout_thread_count))
+        f.write("\nTrial: " + str(trial))
+        f.write("\nCommand: " + cmd)
+        f.write("\nTime (sec): " + str(latency))
+        f.write("\nEnergy (uJ): " + str(uj))
+        f.write("\nPower (W): " + str(watts))
+
+
+def characterize(build_target, base_dir, (min_layout_threads, max_layout_threads), renderer, page, profile, trials):
+    """Run all configurations and capture results.
+    """
+    for layout_thread_count in xrange(min_layout_threads, max_layout_threads + 1):
+        for trial in xrange(1, trials + 1):
+            execute(base_dir, build_target, renderer, page, profile, trial, layout_thread_count)
+
+
+def main():
+    """For this script to be useful, the following conditions are needed:
+    - HEARTBEAT_PROFILER_CATEGORIES should be aligned with the profiler categories in the source code.
+    - The "energymon" project needs to be installed to the system (libraries and the "energymon" binary).
+     - The "default" energymon library will be used - make sure you choose one that is useful for your system setup
+       when installing energymon.
+    - Build servo in release mode with the "energy-profiling" feature enabled (this links with the energymon lib).
+    """
+    # Default max number of layout threads
+    max_layout_threads = 1
+    # Default benchmark
+    benchmark = path.join(TOP_DIR, "tests", "html", "perf-rainbow.html")
+    # Default renderer
+    renderer = "-c"
+    # Default output directory
+    output_dir = "heartbeat_logs"
+    # Default build target
+    build_target = "release"
+    # Default profile interval
+    profile = 60
+    # Default single argument
+    single = False
+    # Default number of trials
+    trials = 1
+
+    # Parsing the input of the script
+    parser = argparse.ArgumentParser(description="Characterize Servo timing and energy behavior")
+    parser.add_argument("-b", "--benchmark",
+                        default=benchmark,
+                        help="Gets the benchmark, for example \"-b http://www.example.com\"")
+    parser.add_argument("-d", "--debug",
+                        action='store_true',
+                        help="Use debug build instead of release build")
+    parser.add_argument("-g", "--gpu",
+                        action='store_true',
+                        help="Rendering with GPU instead of CPU")
+    parser.add_argument("-l", "--max_layout_threads",
+                        help="Specify the maximum number of threads for layout, for example \"-l 5\"")
+    parser.add_argument("-o", "--output",
+                        help="Specify the log output directory, for example \"-o heartbeat_logs\"")
+    parser.add_argument("-p", "--profile",
+                        default=60,
+                        help="Profiler output interval, for example \"-p 60\"")
+    parser.add_argument("-s", "--single",
+                        action='store_true',
+                        help="Just run a single trial of the config provided, for example \"-s\"")
+    parser.add_argument("-t", "--trials",
+                        default=1,
+                        type=int,
+                        help="Number of trials to run for each configuration, for example \"-t 1\"")
+
+    args = parser.parse_args()
+    if args.benchmark:
+        benchmark = args.benchmark
+    if args.debug:
+        build_target = "debug"
+    if args.gpu:
+        renderer = "-g"
+    if args.max_layout_threads:
+        max_layout_threads = int(args.max_layout_threads)
+    if args.output:
+        output_dir = args.output
+    if args.profile:
+        profile = args.profile
+    if args.single:
+        single = True
+    if args.trials:
+        trials = args.trials
+
+    if os.path.exists(output_dir):
+        print "Output directory already exists: " + output_dir
+        sys.exit(1)
+    os.makedirs(output_dir)
+
+    if single:
+        execute(output_dir, build_target, renderer, benchmark, profile, trials, max_layout_threads)
+    else:
+        characterize(build_target, output_dir, (1, max_layout_threads), renderer, benchmark, profile, trials)
+
+if __name__ == "__main__":
+    main()

tests/heartbeats/process_logs.py

@@ -0,0 +1,398 @@
+#!/usr/bin/env python
+
+# This Source Code Form is subject to the terms of the Mozilla Public
+# License, v. 2.0. If a copy of the MPL was not distributed with this
+# file, You can obtain one at http://mozilla.org/MPL/2.0/.
+
+import argparse
+import matplotlib.pyplot as plt
+import numpy as np
+import os
+from os import path
+import sys
+import warnings
+
+HB_LOG_IDX_START_TIME = 7
+HB_LOG_IDX_END_TIME = HB_LOG_IDX_START_TIME + 1
+HB_LOG_IDX_START_ENERGY = 14
+HB_LOG_IDX_END_ENERGY = HB_LOG_IDX_START_ENERGY + 1
+
+ENERGY_PROFILER_NAME = 'ApplicationHeartbeat'
+SUMMARY_OUTPUT = "summary.txt"
+SUMMARY_TIME_IDX = 8
+SUMMARY_ENERGY_IDX = SUMMARY_TIME_IDX + 1
+SUMMARY_POWER_IDX = SUMMARY_ENERGY_IDX + 1
+
+
+def autolabel(rects, ax):
+    """Attach some text labels.
+    """
+    for rect in rects:
+        ax.text(rect.get_x() + rect.get_width() / 2., 1.05 * rect.get_height(), '', ha='center', va='bottom')
+
+
+def plot_raw_totals(config, plot_data, max_time, max_time_std, max_energy, max_energy_std, output_dir, normalize):
+    """Plot the raw totals for a configuration.
+
+    Keyword arguments:
+    config -- configuration name
+    plot_data -- (profiler name, total_time, total_time_std, total_energy, total_energy_std)
+    max_time, max_time_std, max_energy, max_energy_std -- single values
+    normalize -- True/False
+    """
+    plot_data = sorted(plot_data)
+    keys = [p for (p, tt, tts, te, tes) in plot_data]
+    total_times = [tt for (p, tt, tts, te, tes) in plot_data]
+    total_times_std = [tts for (p, tt, tts, te, tes) in plot_data]
+    total_energies = [te for (p, tt, tts, te, tes) in plot_data]
+    total_energies_std = [tes for (p, tt, tts, te, tes) in plot_data]
+
+    fig, ax1 = plt.subplots()
+    ind = np.arange(len(keys))  # the x locations for the groups
+    width = 0.35  # the width of the bars
+    # add some text for labels, title and axes ticks
+    ax1.set_title('Time/Energy Data for Configuration ' + config)
+    ax1.set_xticks(ind + width)
+    ax1.set_xticklabels(keys, rotation=45)
+    fig.set_tight_layout(True)
+    fig.set_size_inches(len(plot_data) / 1.5, 8)
+
+    ax2 = ax1.twinx()
+
+    # Normalize
+    if normalize:
+        total_times_std /= np.sum(total_times)
+        total_times /= np.sum(total_times)
+        total_energies_std /= np.sum(total_energies)
+        total_energies /= np.sum(total_energies)
+        ax1.set_ylabel('Time (Normalized)')
+        ax2.set_ylabel('Energy (Normalized)')
+    else:
+        # set time in us instead of ns
+        total_times_std /= np.array(1000000.0)
+        total_times /= np.array(1000000.0)
+        total_energies_std /= np.array(1000000.0)
+        total_energies /= np.array(1000000.0)
+        ax1.set_ylabel('Time (ms)')
+        ax2.set_ylabel('Energy (Joules)')
+
+    rects1 = ax1.bar(ind, total_times, width, color='r', yerr=total_times_std)
+    rects2 = ax2.bar(ind + width, total_energies, width, color='y', yerr=total_energies_std)
+    ax1.legend([rects1[0], rects2[0]], ['Time', 'Energy'])
+
+    # set axis
+    x1, x2, y1, y2 = plt.axis()
+    if normalize:
+        ax1.set_ylim(ymin=0, ymax=1)
+        ax2.set_ylim(ymin=0, ymax=1)
+    else:
+        ax1.set_ylim(ymin=0, ymax=((max_time + max_time_std) * 1.25 / 1000000.0))
+        ax2.set_ylim(ymin=0, ymax=((max_energy + max_energy_std) * 1.25 / 1000000.0))
+
+    autolabel(rects1, ax1)
+    autolabel(rects2, ax2)
+
+    # plt.show()
+    plt.savefig(path.join(output_dir, config + ".png"))
+    plt.close(fig)
+
+
+def create_raw_total_data(config_data):
+    """Get the raw data to plot for a configuration
+    Return: [(profiler, time_mean, time_stddev, energy_mean, energy_stddev)]
+
+    Keyword arguments:
+    config_data -- (trial, trial_data)
+    """
+    # We can't assume that the same number of heartbeats are always issued across trials
+    # key: profiler name; value: list of timing sums for each trial
+    profiler_total_times = {}
+    # key: profiler name; value: list of energy sums for each trial
+    profiler_total_energies = {}
+    for (t, td) in config_data:
+        for (profiler, ts, te, es, ee) in td:
+            # sum the total times and energies for each profiler in this trial
+            total_time = np.sum(te - ts)
+            total_energy = np.sum(ee - es)
+            # add to list to be averaged later
+            time_list = profiler_total_times.get(profiler, [])
+            time_list.append(total_time)
+            profiler_total_times[profiler] = time_list
+            energy_list = profiler_total_energies.get(profiler, [])
+            energy_list.append(total_energy)
+            profiler_total_energies[profiler] = energy_list
+
+    # Get mean and stddev for time and energy totals
+    return [(profiler,
+             np.mean(profiler_total_times[profiler]),
+             np.std(profiler_total_times[profiler]),
+             np.mean(profiler_total_energies[profiler]),
+             np.std(profiler_total_energies[profiler]))
+            for profiler in profiler_total_times.keys()]
+
+
+def plot_all_raw_totals(config_list, output_dir):
+    """Plot column charts of the raw total time/energy spent in each profiler category.
+
+    Keyword arguments:
+    config_list -- [(config, result of process_config_dir(...))]
+    output_dir -- where to write plots to
+    """
+    raw_total_norm_out_dir = path.join(output_dir, 'raw_totals_normalized')
+    os.makedirs(raw_total_norm_out_dir)
+    raw_total_out_dir = path.join(output_dir, 'raw_totals')
+    os.makedirs(raw_total_out_dir)
+
+    # (name, (profiler, (time_mean, time_stddev, energy_mean, energy_stddev)))
+    raw_totals_data = [(config, create_raw_total_data(config_data)) for (config, config_data) in config_list]
+
+    mean_times = []
+    mean_times_std = []
+    mean_energies = []
+    mean_energies_std = []
+    for profiler_tup in [config_tup[1] for config_tup in raw_totals_data]:
+        for (p, tt, tts, te, tes) in profiler_tup:
+            mean_times.append(tt)
+            mean_times_std.append(tts)
+            mean_energies.append(te)
+            mean_energies_std.append(tes)
+    # get consistent max time/energy values across plots
+    max_t = np.max(mean_times)
+    max_t_std = np.max(mean_times_std)
+    max_e = np.max(mean_energies)
+    max_e_std = np.max(mean_energies_std)
+    [plot_raw_totals(data[0], data[1], max_t, max_t_std, max_e, max_e_std, raw_total_norm_out_dir, True)
+        for data in raw_totals_data]
+    [plot_raw_totals(data[0], data[1], max_t, max_t_std, max_e, max_e_std, raw_total_out_dir, False)
+        for data in raw_totals_data]
+
+
+def plot_trial_time_series(config, trial, trial_data, max_end_time, max_power, output_dir):
+    """Plot time series for a single trial.
+
+    Keyword arguments:
+    config -- the config name
+    trial -- the trial name
+    trial_data -- [(profiler, [start times], [end times], [start energies], [end energies])]
+    max_end_time -- single value to use as max X axis value (for consistency across trials)
+    output_dir -- the output directory
+    """
+    # TODO: Some profilers may have parallel tasks - need to identify this on plots
+    max_end_time = max_end_time / 1000000.0
+    trial_data = sorted(trial_data)
+    fig, ax1 = plt.subplots()
+    keys = [p for (p, ts, te, es, ee) in trial_data]
+    # add some text for labels, title and axes ticks
+    ax1.set_title('Profiler Activity for ' + config + ', ' + trial)
+    ax1.set_xlabel('Time (ms)')
+    ax1.grid(True)
+    width = 8  # the width of the bars
+    ax1.set_yticks(10 * np.arange(1, len(keys) + 2))
+    ax1.set_yticklabels(keys)
+    ax1.set_ylim(ymin=0, ymax=((len(trial_data) + 1) * 10))
+    ax1.set_xlim(xmin=0, xmax=max_end_time)
+    fig.set_tight_layout(True)
+    fig.set_size_inches(16, len(trial_data) / 3)
+
+    i = 10
+    for (p, ts, te, es, ee) in trial_data:
+        xranges = [(ts[j] / 1000000.0, (te[j] - ts[j]) / 1000000.0) for j in xrange(len(ts))]
+        ax1.broken_barh(xranges, (i - 0.5 * width, width))
+        i += 10
+    # place a vbar at the final time for this trial
+    last_profiler_times = map(np.nanmax, filter(lambda x: len(x) > 0, [te for (p, ts, te, es, ee) in trial_data]))
+    plt.axvline(np.max(last_profiler_times) / 1000000.0, color='black')
+
+    power_times = []
+    power_values = []
+    for (p, ts, te, es, ee) in trial_data:
+        if p == ENERGY_PROFILER_NAME:
+            power_times = te / 1000000.0
+            power_values = (ee - es) / ((te - ts) / 1000.0)
+    ax2 = ax1.twinx()
+    ax2.set_xlim(xmin=0, xmax=max_end_time)
+    ax2.set_ylim(ymin=0, ymax=max_power)
+    ax2.set_ylabel('Power (Watts)')
+    ax2.plot(power_times, power_values, color='r')
+
+    # plt.show()
+    plt.savefig(path.join(output_dir, "ts_" + config + "_" + trial + ".png"))
+    plt.close(fig)
+
+
+def hb_energy_times_to_power(es, ee, ts, te):
+    """Compute power from start and end energy and times.
+    Return: power values
+    """
+    return (ee - es) / ((te - ts) / 1000.0)
+
+
+def plot_all_time_series(config_list, output_dir):
+    """Plot column charts of the raw total time/energy spent in each profiler category.
+
+    Keyword arguments:
+    config_list -- [(config, result of process_config_dir(...))]
+    output_dir -- where to write plots to
+    """
+    time_series_out_dir = path.join(output_dir, 'time_series')
+    os.makedirs(time_series_out_dir)
+
+    max_end_times = []
+    max_power_values = []
+    for (c, cd) in config_list:
+        for (t, td) in cd:
+            trial_max_end_times = map(np.nanmax, filter(lambda x: len(x) > 0, [te for (p, ts, te, es, ee) in td]))
+            max_end_times.append(np.nanmax(trial_max_end_times))
+            for (p, ts, te, es, ee) in td:
+                # We only care about the energy profiler (others aren't reliable for instant power anyway)
+                if p == ENERGY_PROFILER_NAME and len(te) > 0:
+                    max_power_values.append(np.nanmax(hb_energy_times_to_power(es, ee, ts, te)))
+    max_time = np.nanmax(max_end_times)
+    max_power = np.nanmax(np.array(max_power_values)) * 1.2  # leave a little space at the top
+
+    for (config, config_data) in config_list:
+        [plot_trial_time_series(config, trial, trial_data, max_time, max_power, time_series_out_dir)
+            for (trial, trial_data) in config_data]
+
+
+def read_heartbeat_log(profiler_hb_log):
+    """Read a heartbeat log file.
+    Return: (profiler name, [start times], [end times], [start energies], [end energies], [instant powers])
+
+    Keyword arguments:
+    profiler_hb_log -- the file to read
+    """
+    with warnings.catch_warnings():
+        try:
+            warnings.simplefilter("ignore")
+            time_start, time_end, energy_start, energy_end = \
+                np.loadtxt(profiler_hb_log,
+                           dtype=np.dtype('uint64'),
+                           skiprows=1,
+                           usecols=(HB_LOG_IDX_START_TIME,
+                                    HB_LOG_IDX_END_TIME,
+                                    HB_LOG_IDX_START_ENERGY,
+                                    HB_LOG_IDX_END_ENERGY),
+                           unpack=True,
+                           ndmin=1)
+        except ValueError:
+            time_start, time_end, energy_start, energy_end = [], [], [], []
+    name = path.split(profiler_hb_log)[1].split('-')[1].split('.')[0]
+    return (name,
+            np.atleast_1d(time_start),
+            np.atleast_1d(time_end),
+            np.atleast_1d(energy_start),
+            np.atleast_1d(energy_end))
+
+
+def process_trial_dir(trial_dir):
+    """Process trial directory.
+    Return: [(profiler name, [start times], [end times], [start energies], [end energies])]
+    Time and energy are normalized to 0 start values.
+
+    Keyword arguments:
+    trial_dir -- the directory for this trial
+    """
+    log_data = map(lambda h: read_heartbeat_log(path.join(trial_dir, h)),
+                   filter(lambda f: f.endswith(".log"), os.listdir(trial_dir)))
+
+    # Find the earliest timestamps and energy readings
+    min_t = np.nanmin(map(np.nanmin, filter(lambda x: len(x) > 0, [ts for (profiler, ts, te, es, ee) in log_data])))
+    min_e = np.nanmin(map(np.nanmin, filter(lambda x: len(x) > 0, [es for (profiler, ts, te, es, ee) in log_data])))
+
+    # Normalize timing/energy data to start values of 0
+    return [(profiler, ts - min_t, te - min_t, es - min_e, ee - min_e) for (profiler, ts, te, es, ee) in log_data]
+
+
+def process_config_dir(config_dir):
+    """Process a configuration directory.
+    Return: [(trial, [(profiler name, [start times], [end times], [start energies], [end energies])])]
+
+    Keyword arguments:
+    config_dir -- the directory for this configuration - contains subdirectories for each trial
+    """
+    return [(trial_dir, process_trial_dir(path.join(config_dir, trial_dir))) for trial_dir in os.listdir(config_dir)]
+
+
+def process_logs(log_dir):
+    """Process log directory.
+    Return: [(config, [(trial, [(profiler name, [start times], [end times], [start energies], [end energies])])])]
+
+    Keyword arguments:
+    log_dir -- the log directory to process - contains subdirectories for each configuration
+    """
+    return [((config_dir.split('_')[1], process_config_dir(path.join(log_dir, config_dir))))
+            for config_dir in os.listdir(log_dir)]
+
+
+def find_best_executions(log_dir):
+    """Get the best time, energy, and power from the characterization summaries.
+    Return: ((config, trial, min_time), (config, trial, min_energy), (config, trial, min_power))
+
+    Keyword arguments:
+    results -- the results from process_logs(...).
+    """
+    DEFAULT = ('', '', 1000000000.0)
+    min_time = DEFAULT
+    min_energy = DEFAULT
+    min_power = DEFAULT
+    for config_dir in os.listdir(log_dir):
+        for trial_dir in os.listdir(path.join(log_dir, config_dir)):
+            with open(path.join(log_dir, config_dir, trial_dir, SUMMARY_OUTPUT), "r") as s:
+                lines = s.readlines()
+                time = float(lines[SUMMARY_TIME_IDX].split(':')[1])
+                energy = int(lines[SUMMARY_ENERGY_IDX].split(':')[1])
+                power = float(lines[SUMMARY_POWER_IDX].split(':')[1])
+                if time < min_time[2]:
+                    min_time = (config_dir, trial_dir, time)
+                if energy < min_energy[2]:
+                    min_energy = (config_dir, trial_dir, energy)
+                if power < min_power:
+                    min_power = (config_dir, trial_dir, power)
+    return (min_time, min_energy, min_power)
+
+
+def main():
+    """This script processes the log files from the "characterize.py" script and produces visualizations.
+    """
+    # Default log directory
+    directory = 'heartbeat_logs'
+    # Default output directory
+    output_dir = 'plots'
+
+    # Parsing the input of the script
+    parser = argparse.ArgumentParser(description="Process Heartbeat log files from characterization")
+    parser.add_argument("-d", "--directory",
+                        default=directory,
+                        help="Heartbeat log directory \"-d heartbeat_logs\"")
+    parser.add_argument("-o", "--output",
+                        default=output_dir,
+                        help="Specify the log output directory, for example \"-o plots\"")
+
+    args = parser.parse_args()
+    if args.directory:
+        directory = args.directory
+    if args.output:
+        output_dir = args.output
+
+    if not os.path.exists(directory):
+        print "Input directory does not exist: " + directory
+        sys.exit(1)
+
+    if os.path.exists(output_dir):
+        print "Output directory already exists: " + output_dir
+        sys.exit(1)
+
+    res = process_logs(directory)
+
+    best = find_best_executions(directory)
+    print 'Best time:', best[0]
+    print 'Best energy:', best[1]
+    print 'Best power:', best[2]
+
+    os.makedirs(output_dir)
+    plot_all_raw_totals(res, output_dir)
+    plot_all_time_series(res, output_dir)
+
+if __name__ == "__main__":
+    main()