From 3c25f47dbcfd39396298fdd9f229305676836118 Mon Sep 17 00:00:00 2001 From: Connor Imes Date: Tue, 28 Jul 2015 15:23:57 -0500 Subject: [PATCH] Add energy monitoring and characterization scripts --- ORGANIZATION.md | 1 + components/profile/heartbeats.rs | 7 + components/profile/time.rs | 63 ++++- components/profile_traits/Cargo.toml | 12 + components/profile_traits/energy.rs | 63 +++++ components/profile_traits/lib.rs | 1 + components/profile_traits/time.rs | 10 +- components/servo/Cargo.lock | 36 +++ components/servo/Cargo.toml | 1 + tests/heartbeats/characterize.py | 247 +++++++++++++++++ tests/heartbeats/process_logs.py | 398 +++++++++++++++++++++++++++ 11 files changed, 834 insertions(+), 5 deletions(-) create mode 100644 components/profile_traits/energy.rs create mode 100644 tests/heartbeats/characterize.py create mode 100644 tests/heartbeats/process_logs.py diff --git a/ORGANIZATION.md b/ORGANIZATION.md index ca97aa0d625..b1169f2af3a 100644 --- a/ORGANIZATION.md +++ b/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 diff --git a/components/profile/heartbeats.rs b/components/profile/heartbeats.rs index e782067f8a6..6eaff00e79f 100644 --- a/components/profile/heartbeats.rs +++ b/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, diff --git a/components/profile/time.rs b/components/profile/time.rs index 8aafe92798d..e3c38827012 100644 --- a/components/profile/time.rs +++ b/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) -> Profiler { @@ -178,8 +222,8 @@ impl Profiler { fn handle_msg(&mut self, msg: ProfilerMsg) -> bool { match msg.clone() { - ProfilerMsg::Time(k, t) => { - heartbeats::maybe_heartbeat(&k.0, t.0, t.1, 0, 0); + ProfilerMsg::Time(k, t, e) => { + 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(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, + } + }, + } +} diff --git a/components/profile_traits/Cargo.toml b/components/profile_traits/Cargo.toml index 8be871bbc48..6af073d927c 100644 --- a/components/profile_traits/Cargo.toml +++ b/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" diff --git a/components/profile_traits/energy.rs b/components/profile_traits/energy.rs new file mode 100644 index 00000000000..a4b60e1316f --- /dev/null +++ b/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) + } + } + +} diff --git a/components/profile_traits/lib.rs b/components/profile_traits/lib.rs index 4ab9c55b6a7..abeec3bb1ad 100644 --- a/components/profile_traits/lib.rs +++ b/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; diff --git a/components/profile_traits/time.rs b/components/profile_traits/time.rs index 81eab5faacb..681c171d449 100644 --- a/components/profile_traits/time.rs +++ b/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), (u64, u64)), + Time((ProfilerCategory, Option), (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(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; } diff --git a/components/servo/Cargo.lock b/components/servo/Cargo.lock index 2a0d9a778e3..2ba4f60fb30 100644 --- a/components/servo/Cargo.lock +++ b/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)", diff --git a/components/servo/Cargo.toml b/components/servo/Cargo.toml index 8d454044d4e..95b70226b3d 100644 --- a/components/servo/Cargo.toml +++ b/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: # diff --git a/tests/heartbeats/characterize.py b/tests/heartbeats/characterize.py new file mode 100644 index 00000000000..4a0f3213c2c --- /dev/null +++ b/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() diff --git a/tests/heartbeats/process_logs.py b/tests/heartbeats/process_logs.py new file mode 100644 index 00000000000..b6f0f2a49d4 --- /dev/null +++ b/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()