Auto merge of #10995 - rzambre:master, r=larsbergstrom

Interval + CSV time-profiling

This PR fixes #10886. The -p option can be followed by either an interval number or a CSV filename.
* In the interval profiling, the profiler output would be spitted out to the terminal periodically.
Example usage: **./mach run -p 1 http://www.google.com** will print the time-profiling output to the terminal every second.

* In the CSV file profiling, a CSV file will be generate upon termination of servo.
Example usage: **./mach run -x -o out.png -p out.csv http://www.google.com** will generate out.csv upon termination of Servo.

<!-- Reviewable:start -->
---
This change is [<img src="https://reviewable.io/review_button.svg" height="35" align="absmiddle" alt="Reviewable"/>](https://reviewable.io/reviews/servo/servo/10995)
<!-- Reviewable:end -->

components/compositing/compositor.rs

@@ -509,7 +509,13 @@ impl<Window: WindowMethods> IOCompositor<Window> {
         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();
 

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<OutputOptions>) -> String;
 }
 
 impl Formattable for Option<TimerMetadata> {
-    fn format(&self) -> String {
+    fn format(&self, output: &Option<OutputOptions>) -> 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 {
+                match *output {
-                    &url[..30]
+                    Some(OutputOptions::FileName(_)) => {
-                } else {
+                        /* The profiling output is a CSV file */
-                    url
+                        let incremental = match meta.incremental {
-                };
+                            TimerMetadataReflowType::Incremental => "yes",
-                let incremental = match meta.incremental {
+                            TimerMetadataReflowType::FirstReflow => "no",
-                    TimerMetadataReflowType::Incremental => "    yes",
+                        };
-                    TimerMetadataReflowType::FirstReflow => "    no ",
+                        let iframe = match meta.iframe {
-                };
+                            TimerMetadataFrameType::RootWindow => "yes",
-                let iframe = match meta.iframe {
+                            TimerMetadataFrameType::IFrame => "no",
-                    TimerMetadataFrameType::RootWindow => "  yes",
+                        };
-                    TimerMetadataFrameType::IFrame => "  no ",
+                        format!(" {}, {}, {}", incremental, iframe, url)
-                };
+                    },
-                format!(" {:14} {:9} {:30}", 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 =>
+            None => {
-                format!(" {:14} {:9} {:30}", "    N/A", "  N/A", "             N/A")
+                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<TimerMetadata> {
 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<OutputOptions>) -> String {
         let padding = match *self {
             ProfilerCategory::LayoutStyleRecalc |
             ProfilerCategory::LayoutRestyleDamagePropagation |
@@ -128,45 +157,71 @@ type ProfilerBuckets = BTreeMap<(ProfilerCategory, Option<TimerMetadata>), Vec<f
 pub struct Profiler {
     pub port: IpcReceiver<ProfilerMsg>,
     buckets: ProfilerBuckets,
+    output: Option<OutputOptions>,
     pub last_msg: Option<ProfilerMsg>,
     trace: Option<TraceDump>,
 }
 
 impl Profiler {
-    pub fn create(period: Option<f64>, file_path: Option<String>) -> ProfilerChan {
+    pub fn create(output: &Option<OutputOptions>, file_path: Option<String>) -> ProfilerChan {
         let (chan, port) = ipc::channel().unwrap();
-        if let Some(period) = period {
+        match *output {
-            let chan = chan.clone();
+            Some(ref option) => {
-            spawn_named("Time profiler timer".to_owned(), move || {
+                // Spawn the time profiler thread
-                loop {
+                let outputoption = option.clone();
-                    thread::sleep(duration_from_seconds(period));
+                spawn_named("Time profiler".to_owned(), move || {
-                    if chan.send(ProfilerMsg::Print).is_err() {
+                    let trace = file_path.as_ref()
-                        break;
+                        .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;
+                                }
+                            }
+                        });
+                    },
                 }
-            });
+            },
-        }
+            None => {
-
+                // this is when the -p option hasn't been specified
-        if period.is_some() || file_path.is_some() {
+                if file_path.is_some() {
-            // Spawn the time profiler.
+                    // Spawn the time profiler
-            spawn_named("Time profiler".to_owned(), move || {
+                    spawn_named("Time profiler".to_owned(), move || {
-                let trace = file_path.as_ref()
+                        let trace = file_path.as_ref()
-                    .map(path::Path::new)
+                            .map(path::Path::new)
-                    .map(fs::File::create)
+                            .map(fs::File::create)
-                    .map(|res| TraceDump::new(res.unwrap()));
+                            .map(|res| TraceDump::new(res.unwrap()));
-                let mut profiler = Profiler::new(port, trace);
+                        let mut profiler = Profiler::new(port, trace, None);
-                profiler.start();
+                        profiler.start();
-            });
+                    });
-        } else {
+                } else {
-            // No-op to handle messages when the time profiler is inactive.
+                    // No-op to handle messages when the time profiler is not printing:
-            spawn_named("Time profiler".to_owned(), move || {
+                    spawn_named("Time profiler".to_owned(), move || {
-                loop {
+                        loop {
-                    match port.recv() {
+                            match port.recv() {
-                        Err(_) | Ok(ProfilerMsg::Exit) => break,
+                                Err(_) => break,
-                        _ => {}
+                                Ok(ProfilerMsg::Exit(chan)) => {
-                    }
+                                    chan.send(());
+                                    break;
+                                },
+                                _ => {}
+                            }
+                        }
+                    });
                 }
-            });
+            }
         }
 
         heartbeats::init();
@@ -216,10 +271,11 @@ impl Profiler {
         profiler_chan
     }
 
-    pub fn new(port: IpcReceiver<ProfilerMsg>, trace: Option<TraceDump>) -> Profiler {
+    pub fn new(port: IpcReceiver<ProfilerMsg>, trace: Option<TraceDump>, output: Option<OutputOptions>) -> 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();
+        match self.output {
-        let mut lock = stdout.lock();
+            Some(OutputOptions::FileName(ref filename)) => {
-
+                let path = Path::new(&filename);
-        writeln!(&mut lock, "{:35} {:14} {:9} {:30} {:15} {:15} {:-15} {:-15} {:-15}",
+                let mut file = match File::create(&path) {
-                 "_category_", "_incremental?_", "_iframe?_",
+                    Err(e) => panic!("Couldn't create {}: {}",
-                 "            _url_", "    _mean (ms)_", "  _median (ms)_",
+                                     path.display(),
-                 "     _min (ms)_", "     _max (ms)_", "      _events_").unwrap();
+                                     Error::description(&e)),
-        for (&(ref category, ref meta), ref mut data) in &mut self.buckets {
+                    Ok(file) => file,
-            data.sort_by(|a, b| {
+                };
-                if a < b {
+                write!(file, "_category_, _incremental?_, _iframe?_, _url_, _mean (ms)_, _median (ms)_, _min (ms)_, \
-                    Ordering::Less
+                _max (ms)_, _events_\n");
-                } else {
+                for (&(ref category, ref meta), ref mut data) in &mut self.buckets {
-                    Ordering::Greater
+                    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::<f64>() / (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();
+            Some(OutputOptions::Stdout(ref period)) => {
-            if data_len > 0 {
+                let stdout = io::stdout();
-                let (mean, median, min, max) =
+                let mut lock = stdout.lock();
-                    (data.iter().sum::<f64>() / (data_len as f64),
+
-                     data[data_len / 2],
+                writeln!(&mut lock, "{:35} {:14} {:9} {:30} {:15} {:15} {:-15} {:-15} {:-15}",
-                     data.iter().fold(f64::INFINITY, |a, &b| a.min(b)),
+                         "_category_", "_incremental?_", "_iframe?_",
-                     data.iter().fold(-f64::INFINITY, |a, &b| a.max(b)));
+                         "            _url_", "    _mean (ms)_", "  _median (ms)_",
-                writeln!(&mut lock, "{:-35}{} {:15.4} {:15.4} {:15.4} {:15.4} {:15}",
+                         "     _min (ms)_", "     _max (ms)_", "      _events_").unwrap();
-                         category.format(), meta.format(), mean, median, min, max,
+                for (&(ref category, ref meta), ref mut data) in &mut self.buckets {
-                         data_len).unwrap();
+                    data.sort_by(|a, b| {
-            }
+                        if a < b {
-        }
+                            Ordering::Less
-        writeln!(&mut lock, "").unwrap();
+                        } else {
+                            Ordering::Greater
+                        }
+                    });
+                    let data_len = data.len();
+                    if data_len > 0 {
+                        let (mean, median, min, max) =
+                            (data.iter().sum::<f64>() / (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 */},
+        };
     }
 }
 

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)]

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",
 ]

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| {

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<f64>,
+    pub time_profiling: Option<OutputOptions>,
 
     /// 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.
+    // 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| {
+    let time_profiling = if opt_match.opt_present("p") {
-        period.parse().unwrap_or_else(|err| args_fail(&format!("Error parsing option: -p ({})", err)))
+        match opt_match.opt_str("p") {
-    });
+            Some(argument) => match argument.parse::<f64>() {
+                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,

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"}

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;
 

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");
 }