diff --git a/components/compositing/compositor.rs b/components/compositing/compositor.rs index e0d496c5652..ef47ffcb438 100644 --- a/components/compositing/compositor.rs +++ b/components/compositing/compositor.rs @@ -509,7 +509,13 @@ impl IOCompositor { while self.port.try_recv_compositor_msg().is_some() {} // Tell the profiler, memory profiler, and scrolling timer to shut down. - self.time_profiler_chan.send(time::ProfilerMsg::Exit); + match ipc::channel() { + Ok((sender, receiver)) => { + self.time_profiler_chan.send(time::ProfilerMsg::Exit(sender)); + receiver.recv(); + }, + Err(_) => {}, + } self.mem_profiler_chan.send(mem::ProfilerMsg::Exit); self.delayed_composition_timer.shutdown(); diff --git a/components/profile/time.rs b/components/profile/time.rs index db9ef2f0ac4..5661d07d57e 100644 --- a/components/profile/time.rs +++ b/components/profile/time.rs @@ -12,43 +12,72 @@ use profile_traits::time::{TimerMetadataReflowType, TimerMetadataFrameType}; use std::borrow::ToOwned; use std::cmp::Ordering; use std::collections::BTreeMap; +use std::error::Error; use std::fs; +use std::fs::File; use std::io::{self, Write}; use std::path; +use std::path::Path; use std::time::Duration; use std::{thread, f64}; use std_time::precise_time_ns; use trace_dump::TraceDump; +use util::opts::OutputOptions; use util::thread::spawn_named; use util::time::duration_from_seconds; pub trait Formattable { - fn format(&self) -> String; + fn format(&self, output: &Option) -> String; } impl Formattable for Option { - fn format(&self) -> String { + fn format(&self, output: &Option) -> String { match *self { // TODO(cgaebel): Center-align in the format strings as soon as rustc supports it. Some(ref meta) => { let url = &*meta.url; - let url = if url.len() > 30 { - &url[..30] - } else { - url - }; - let incremental = match meta.incremental { - TimerMetadataReflowType::Incremental => " yes", - TimerMetadataReflowType::FirstReflow => " no ", - }; - let iframe = match meta.iframe { - TimerMetadataFrameType::RootWindow => " yes", - TimerMetadataFrameType::IFrame => " no ", - }; - format!(" {:14} {:9} {:30}", incremental, iframe, url) + match *output { + Some(OutputOptions::FileName(_)) => { + /* The profiling output is a CSV file */ + let incremental = match meta.incremental { + TimerMetadataReflowType::Incremental => "yes", + TimerMetadataReflowType::FirstReflow => "no", + }; + let iframe = match meta.iframe { + TimerMetadataFrameType::RootWindow => "yes", + TimerMetadataFrameType::IFrame => "no", + }; + format!(" {}, {}, {}", incremental, iframe, url) + }, + _ => { + /* The profiling output is the terminal */ + let url = if url.len() > 30 { + &url[..30] + } else { + url + }; + let incremental = match meta.incremental { + TimerMetadataReflowType::Incremental => " yes", + TimerMetadataReflowType::FirstReflow => " no ", + }; + let iframe = match meta.iframe { + TimerMetadataFrameType::RootWindow => " yes", + TimerMetadataFrameType::IFrame => " no ", + }; + format!(" {:14} {:9} {:30}", incremental, iframe, url) + }, + } }, - None => - format!(" {:14} {:9} {:30}", " N/A", " N/A", " N/A") + None => { + match *output { + Some(OutputOptions::FileName(_)) => { + format!(" {}, {}, {}", " N/A", " N/A", " N/A") + }, + _ => { + format!(" {:14} {:9} {:30}", " N/A", " N/A", " N/A") + } + } + } } } } @@ -56,7 +85,7 @@ impl Formattable for Option { impl Formattable for ProfilerCategory { // some categories are subcategories of LayoutPerformCategory // and should be printed to indicate this - fn format(&self) -> String { + fn format(&self, output: &Option) -> String { let padding = match *self { ProfilerCategory::LayoutStyleRecalc | ProfilerCategory::LayoutRestyleDamagePropagation | @@ -128,45 +157,71 @@ type ProfilerBuckets = BTreeMap<(ProfilerCategory, Option), Vec, buckets: ProfilerBuckets, + output: Option, pub last_msg: Option, trace: Option, } impl Profiler { - pub fn create(period: Option, file_path: Option) -> ProfilerChan { + pub fn create(output: &Option, file_path: Option) -> ProfilerChan { let (chan, port) = ipc::channel().unwrap(); - if let Some(period) = period { - let chan = chan.clone(); - spawn_named("Time profiler timer".to_owned(), move || { - loop { - thread::sleep(duration_from_seconds(period)); - if chan.send(ProfilerMsg::Print).is_err() { - break; - } + match *output { + Some(ref option) => { + // Spawn the time profiler thread + let outputoption = option.clone(); + spawn_named("Time profiler".to_owned(), move || { + let trace = file_path.as_ref() + .map(path::Path::new) + .map(fs::File::create) + .map(|res| TraceDump::new(res.unwrap())); + let mut profiler = Profiler::new(port, trace, Some(outputoption)); + profiler.start(); + }); + // decide if we need to spawn the timer thread + match option { + &OutputOptions::FileName(_) => {/* no timer thread needed */}, + &OutputOptions::Stdout(period) => { + // Spawn a timer thread + let chan = chan.clone(); + spawn_named("Time profiler timer".to_owned(), move || { + loop { + thread::sleep(duration_from_seconds(period)); + if chan.send(ProfilerMsg::Print).is_err() { + break; + } + } + }); + }, } - }); - } - - if period.is_some() || file_path.is_some() { - // Spawn the time profiler. - spawn_named("Time profiler".to_owned(), move || { - let trace = file_path.as_ref() - .map(path::Path::new) - .map(fs::File::create) - .map(|res| TraceDump::new(res.unwrap())); - let mut profiler = Profiler::new(port, trace); - profiler.start(); - }); - } else { - // No-op to handle messages when the time profiler is inactive. - spawn_named("Time profiler".to_owned(), move || { - loop { - match port.recv() { - Err(_) | Ok(ProfilerMsg::Exit) => break, - _ => {} - } + }, + None => { + // this is when the -p option hasn't been specified + if file_path.is_some() { + // Spawn the time profiler + spawn_named("Time profiler".to_owned(), move || { + let trace = file_path.as_ref() + .map(path::Path::new) + .map(fs::File::create) + .map(|res| TraceDump::new(res.unwrap())); + let mut profiler = Profiler::new(port, trace, None); + profiler.start(); + }); + } else { + // No-op to handle messages when the time profiler is not printing: + spawn_named("Time profiler".to_owned(), move || { + loop { + match port.recv() { + Err(_) => break, + Ok(ProfilerMsg::Exit(chan)) => { + chan.send(()); + break; + }, + _ => {} + } + } + }); } - }); + } } heartbeats::init(); @@ -216,10 +271,11 @@ impl Profiler { profiler_chan } - pub fn new(port: IpcReceiver, trace: Option) -> Profiler { + pub fn new(port: IpcReceiver, trace: Option, output: Option) -> Profiler { Profiler { port: port, buckets: BTreeMap::new(), + output: output, last_msg: None, trace: trace, } @@ -256,8 +312,10 @@ impl Profiler { // only print if more data has arrived since the last printout self.print_buckets(); }, - ProfilerMsg::Exit => { + ProfilerMsg::Exit(chan) => { heartbeats::cleanup(); + self.print_buckets(); + chan.send(()); return false; }, }; @@ -266,34 +324,70 @@ impl Profiler { } fn print_buckets(&mut self) { - let stdout = io::stdout(); - let mut lock = stdout.lock(); - - writeln!(&mut lock, "{:35} {:14} {:9} {:30} {:15} {:15} {:-15} {:-15} {:-15}", - "_category_", "_incremental?_", "_iframe?_", - " _url_", " _mean (ms)_", " _median (ms)_", - " _min (ms)_", " _max (ms)_", " _events_").unwrap(); - for (&(ref category, ref meta), ref mut data) in &mut self.buckets { - data.sort_by(|a, b| { - if a < b { - Ordering::Less - } else { - Ordering::Greater + match self.output { + Some(OutputOptions::FileName(ref filename)) => { + let path = Path::new(&filename); + let mut file = match File::create(&path) { + Err(e) => panic!("Couldn't create {}: {}", + path.display(), + Error::description(&e)), + Ok(file) => file, + }; + write!(file, "_category_, _incremental?_, _iframe?_, _url_, _mean (ms)_, _median (ms)_, _min (ms)_, \ + _max (ms)_, _events_\n"); + for (&(ref category, ref meta), ref mut data) in &mut self.buckets { + data.sort_by(|a, b| { + if a < b { + Ordering::Less + } else { + Ordering::Greater + } + }); + let data_len = data.len(); + if data_len > 0 { + let (mean, median, min, max) = + (data.iter().sum::() / (data_len as f64), + data[data_len / 2], + data.iter().fold(f64::INFINITY, |a, &b| a.min(b)), + data.iter().fold(-f64::INFINITY, |a, &b| a.max(b))); + write!(file, "{}, {}, {:15.4}, {:15.4}, {:15.4}, {:15.4}, {:15}\n", + category.format(&self.output), meta.format(&self.output), + mean, median, min, max, data_len); + } } - }); - let data_len = data.len(); - if data_len > 0 { - let (mean, median, min, max) = - (data.iter().sum::() / (data_len as f64), - data[data_len / 2], - data.iter().fold(f64::INFINITY, |a, &b| a.min(b)), - data.iter().fold(-f64::INFINITY, |a, &b| a.max(b))); - writeln!(&mut lock, "{:-35}{} {:15.4} {:15.4} {:15.4} {:15.4} {:15}", - category.format(), meta.format(), mean, median, min, max, - data_len).unwrap(); - } - } - writeln!(&mut lock, "").unwrap(); + }, + Some(OutputOptions::Stdout(ref period)) => { + let stdout = io::stdout(); + let mut lock = stdout.lock(); + + writeln!(&mut lock, "{:35} {:14} {:9} {:30} {:15} {:15} {:-15} {:-15} {:-15}", + "_category_", "_incremental?_", "_iframe?_", + " _url_", " _mean (ms)_", " _median (ms)_", + " _min (ms)_", " _max (ms)_", " _events_").unwrap(); + for (&(ref category, ref meta), ref mut data) in &mut self.buckets { + data.sort_by(|a, b| { + if a < b { + Ordering::Less + } else { + Ordering::Greater + } + }); + let data_len = data.len(); + if data_len > 0 { + let (mean, median, min, max) = + (data.iter().sum::() / (data_len as f64), + data[data_len / 2], + data.iter().fold(f64::INFINITY, |a, &b| a.min(b)), + data.iter().fold(-f64::INFINITY, |a, &b| a.max(b))); + writeln!(&mut lock, "{:-35}{} {:15.4} {:15.4} {:15.4} {:15.4} {:15}", + category.format(&self.output), meta.format(&self.output), mean, median, min, max, + data_len).unwrap(); + } + } + writeln!(&mut lock, "").unwrap(); + }, + None => {/* Do nothing if not output option has been set */}, + }; } } diff --git a/components/profile_traits/time.rs b/components/profile_traits/time.rs index c9887e85409..0fe89ac99d3 100644 --- a/components/profile_traits/time.rs +++ b/components/profile_traits/time.rs @@ -31,7 +31,7 @@ pub enum ProfilerMsg { /// Message used to force print the profiling metrics Print, /// Tells the profiler to shut down. - Exit, + Exit(IpcSender<()>), } #[repr(u32)] diff --git a/components/servo/Cargo.lock b/components/servo/Cargo.lock index 16123ec93b6..9ee31354fd7 100644 --- a/components/servo/Cargo.lock +++ b/components/servo/Cargo.lock @@ -1706,6 +1706,7 @@ dependencies = [ name = "profile_tests" version = "0.0.1" dependencies = [ + "ipc-channel 0.2.2 (git+https://github.com/servo/ipc-channel)", "profile 0.0.1", "profile_traits 0.0.1", ] diff --git a/components/servo/lib.rs b/components/servo/lib.rs index 648e0ffb85b..416be542144 100644 --- a/components/servo/lib.rs +++ b/components/servo/lib.rs @@ -117,7 +117,7 @@ impl Browser { let (compositor_proxy, compositor_receiver) = window.create_compositor_channel(); let supports_clipboard = window.supports_clipboard(); - let time_profiler_chan = profile_time::Profiler::create(opts.time_profiler_period, + let time_profiler_chan = profile_time::Profiler::create(&opts.time_profiling, opts.time_profiler_trace_path.clone()); let mem_profiler_chan = profile_mem::Profiler::create(opts.mem_profiler_period); let devtools_chan = opts.devtools_port.map(|port| { diff --git a/components/util/opts.rs b/components/util/opts.rs index 8ca76e87a20..a412ae460c4 100644 --- a/components/util/opts.rs +++ b/components/util/opts.rs @@ -48,7 +48,7 @@ pub struct Opts { /// `None` to disable the time profiler or `Some` with an interval in seconds to enable it and /// cause it to produce output on that interval (`-p`). - pub time_profiler_period: Option, + pub time_profiling: Option, /// When the profiler is enabled, this is an optional path to dump a self-contained HTML file /// visualizing the traces as a timeline. @@ -383,6 +383,12 @@ pub fn print_debug_usage(app: &str) -> ! { process::exit(0) } +#[derive(Clone, Deserialize, Serialize)] +pub enum OutputOptions { + FileName(String), + Stdout(f64) +} + fn args_fail(msg: &str) -> ! { let mut stderr = io::stderr(); stderr.write_all(msg.as_bytes()).unwrap(); @@ -472,7 +478,7 @@ pub fn default_opts() -> Opts { gpu_painting: false, tile_size: 512, device_pixels_per_px: None, - time_profiler_period: None, + time_profiling: None, time_profiler_trace_path: None, mem_profiler_period: None, layout_threads: 1, @@ -533,7 +539,9 @@ pub fn from_cmdline_args(args: &[String]) -> ArgumentParsingResult { opts.optopt("s", "size", "Size of tiles", "512"); opts.optopt("", "device-pixel-ratio", "Device pixels per px", ""); opts.optopt("t", "threads", "Number of paint threads", "1"); - opts.optflagopt("p", "profile", "Profiler flag and output interval", "10"); + opts.optflagopt("p", "profile", "Time profiler flag and either a CSV output filename \ + OR an interval for output to Stdout (blank for Stdout with interval of 5s)", "10 \ + OR time.csv"); opts.optflagopt("", "profiler-trace-path", "Path to dump a self-contained HTML timeline of profiler traces", ""); @@ -659,10 +667,19 @@ pub fn from_cmdline_args(args: &[String]) -> ArgumentParsingResult { None => cmp::max(num_cpus::get() * 3 / 4, 1), }; - // If only the flag is present, default to a 5 second period for both profilers. - let time_profiler_period = opt_match.opt_default("p", "5").map(|period| { - period.parse().unwrap_or_else(|err| args_fail(&format!("Error parsing option: -p ({})", err))) - }); + // If only the flag is present, default to a 5 second period for both profilers + let time_profiling = if opt_match.opt_present("p") { + match opt_match.opt_str("p") { + Some(argument) => match argument.parse::() { + Ok(interval) => Some(OutputOptions::Stdout(interval)) , + Err(_) => Some(OutputOptions::FileName(argument)), + }, + None => Some(OutputOptions::Stdout(5 as f64)), + } + } else { + // if the p option doesn't exist: + None + }; if let Some(ref time_profiler_trace_path) = opt_match.opt_str("profiler-trace-path") { let mut path = PathBuf::from(time_profiler_trace_path); @@ -771,7 +788,7 @@ pub fn from_cmdline_args(args: &[String]) -> ArgumentParsingResult { gpu_painting: gpu_painting, tile_size: tile_size, device_pixels_per_px: device_pixels_per_px, - time_profiler_period: time_profiler_period, + time_profiling: time_profiling, time_profiler_trace_path: opt_match.opt_str("profiler-trace-path"), mem_profiler_period: mem_profiler_period, layout_threads: layout_threads, diff --git a/tests/unit/profile/Cargo.toml b/tests/unit/profile/Cargo.toml index bc84eee9c69..57f625b2e74 100644 --- a/tests/unit/profile/Cargo.toml +++ b/tests/unit/profile/Cargo.toml @@ -11,3 +11,4 @@ doctest = false [dependencies] profile = {path = "../../../components/profile"} profile_traits = {path = "../../../components/profile_traits"} +ipc-channel = {git = "https://github.com/servo/ipc-channel"} diff --git a/tests/unit/profile/lib.rs b/tests/unit/profile/lib.rs index f60883d4211..e07c4908c39 100644 --- a/tests/unit/profile/lib.rs +++ b/tests/unit/profile/lib.rs @@ -2,6 +2,7 @@ * 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/. */ +extern crate ipc_channel; extern crate profile; extern crate profile_traits; diff --git a/tests/unit/profile/time.rs b/tests/unit/profile/time.rs index b48e60dc423..6ee24ed3416 100644 --- a/tests/unit/profile/time.rs +++ b/tests/unit/profile/time.rs @@ -2,14 +2,16 @@ * 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/. */ +use ipc_channel::ipc; use profile::time; use profile_traits::time::ProfilerMsg; #[test] fn time_profiler_smoke_test() { - let chan = time::Profiler::create(None, None); + let chan = time::Profiler::create(&None, None); assert!(true, "Can create the profiler thread"); - chan.send(ProfilerMsg::Exit); + let (ipcchan, ipcport) = ipc::channel().unwrap(); + chan.send(ProfilerMsg::Exit(ipcchan)); assert!(true, "Can tell the profiler thread to exit"); }