profile/
time.rs

1/* This Source Code Form is subject to the terms of the Mozilla Public
2 * License, v. 2.0. If a copy of the MPL was not distributed with this
3 * file, You can obtain one at https://mozilla.org/MPL/2.0/. */
4
5//! Timing functions.
6
7use std::borrow::ToOwned;
8use std::collections::{BTreeMap, HashMap};
9use std::fs::File;
10use std::io::{self, Write};
11use std::path::Path;
12use std::thread;
13
14use ipc_channel::ipc::{self, IpcReceiver};
15use profile_traits::time::{
16    ProfilerCategory, ProfilerChan, ProfilerData, ProfilerMsg, TimerMetadata,
17    TimerMetadataFrameType, TimerMetadataReflowType,
18};
19use servo_config::opts::OutputOptions;
20use time::Duration;
21
22use crate::trace_dump::TraceDump;
23
24pub trait Formattable {
25    fn format(&self, output: &Option<OutputOptions>) -> String;
26}
27
28impl Formattable for Option<TimerMetadata> {
29    fn format(&self, output: &Option<OutputOptions>) -> String {
30        match *self {
31            // TODO(cgaebel): Center-align in the format strings as soon as rustc supports it.
32            Some(ref meta) => {
33                let url = &*meta.url;
34                match *output {
35                    Some(OutputOptions::FileName(_)) => {
36                        /* The profiling output is a CSV file */
37                        let incremental = match meta.incremental {
38                            TimerMetadataReflowType::Incremental => "yes",
39                            TimerMetadataReflowType::FirstReflow => "no",
40                        };
41                        let iframe = match meta.iframe {
42                            TimerMetadataFrameType::RootWindow => "yes",
43                            TimerMetadataFrameType::IFrame => "no",
44                        };
45                        format!(" {}\t{}\t{}", incremental, iframe, url)
46                    },
47                    _ => {
48                        /* The profiling output is the terminal */
49                        let url = if url.len() > 30 { &url[..30] } else { url };
50                        let incremental = match meta.incremental {
51                            TimerMetadataReflowType::Incremental => "    yes",
52                            TimerMetadataReflowType::FirstReflow => "    no ",
53                        };
54                        let iframe = match meta.iframe {
55                            TimerMetadataFrameType::RootWindow => "  yes",
56                            TimerMetadataFrameType::IFrame => "  no ",
57                        };
58                        format!(" {:14} {:9} {:30}", incremental, iframe, url)
59                    },
60                }
61            },
62            None => match *output {
63                Some(OutputOptions::FileName(_)) => {
64                    format!(" {}\t{}\t{}", "    N/A", "  N/A", "             N/A")
65                },
66                _ => format!(" {:14} {:9} {:30}", "    N/A", "  N/A", "             N/A"),
67            },
68        }
69    }
70}
71
72type ProfilerBuckets = BTreeMap<(ProfilerCategory, Option<TimerMetadata>), Vec<Duration>>;
73
74// back end of the profiler that handles data aggregation and performance metrics
75pub struct Profiler {
76    pub port: IpcReceiver<ProfilerMsg>,
77    buckets: ProfilerBuckets,
78    output: Option<OutputOptions>,
79    pub last_msg: Option<ProfilerMsg>,
80    trace: Option<TraceDump>,
81    blocked_layout_queries: HashMap<String, u32>,
82}
83
84impl Profiler {
85    pub fn create(output: &Option<OutputOptions>, file_path: Option<String>) -> ProfilerChan {
86        let (chan, port) = ipc::channel().unwrap();
87        match *output {
88            Some(ref option) => {
89                // Spawn the time profiler thread
90                let outputoption = option.clone();
91                thread::Builder::new()
92                    .name("TimeProfiler".to_owned())
93                    .spawn(move || {
94                        let trace = file_path.as_ref().and_then(|p| TraceDump::new(p).ok());
95                        let mut profiler = Profiler::new(port, trace, Some(outputoption));
96                        profiler.start();
97                    })
98                    .expect("Thread spawning failed");
99                // decide if we need to spawn the timer thread
100                match *option {
101                    OutputOptions::FileName(_) => { /* no timer thread needed */ },
102                    OutputOptions::Stdout(period) => {
103                        // Spawn a timer thread
104                        let chan = chan.clone();
105                        thread::Builder::new()
106                            .name("TimeProfTimer".to_owned())
107                            .spawn(move || {
108                                loop {
109                                    thread::sleep(std::time::Duration::from_secs_f64(period));
110                                    if chan.send(ProfilerMsg::Print).is_err() {
111                                        break;
112                                    }
113                                }
114                            })
115                            .expect("Thread spawning failed");
116                    },
117                }
118            },
119            None => {
120                // this is when the -p option hasn't been specified
121                if file_path.is_some() {
122                    // Spawn the time profiler
123                    thread::Builder::new()
124                        .name("TimeProfiler".to_owned())
125                        .spawn(move || {
126                            let trace = file_path.as_ref().and_then(|p| TraceDump::new(p).ok());
127                            let mut profiler = Profiler::new(port, trace, None);
128                            profiler.start();
129                        })
130                        .expect("Thread spawning failed");
131                } else {
132                    // No-op to handle messages when the time profiler is not printing:
133                    thread::Builder::new()
134                        .name("TimeProfiler".to_owned())
135                        .spawn(move || {
136                            loop {
137                                match port.recv() {
138                                    Err(_) => break,
139                                    Ok(ProfilerMsg::Exit(chan)) => {
140                                        let _ = chan.send(());
141                                        break;
142                                    },
143                                    _ => {},
144                                }
145                            }
146                        })
147                        .expect("Thread spawning failed");
148                }
149            },
150        }
151
152        ProfilerChan(chan)
153    }
154
155    pub fn new(
156        port: IpcReceiver<ProfilerMsg>,
157        trace: Option<TraceDump>,
158        output: Option<OutputOptions>,
159    ) -> Profiler {
160        Profiler {
161            port,
162            buckets: BTreeMap::new(),
163            output,
164            last_msg: None,
165            trace,
166            blocked_layout_queries: HashMap::new(),
167        }
168    }
169
170    pub fn start(&mut self) {
171        while let Ok(msg) = self.port.recv() {
172            if !self.handle_msg(msg) {
173                break;
174            }
175        }
176    }
177
178    fn find_or_insert(&mut self, k: (ProfilerCategory, Option<TimerMetadata>), duration: Duration) {
179        self.buckets.entry(k).or_default().push(duration);
180    }
181
182    fn handle_msg(&mut self, msg: ProfilerMsg) -> bool {
183        match msg.clone() {
184            ProfilerMsg::Time(category_and_metadata, (start_time, end_time)) => {
185                if let Some(ref mut trace) = self.trace {
186                    trace.write_one(&category_and_metadata, start_time, end_time);
187                }
188                self.find_or_insert(category_and_metadata, end_time - start_time);
189            },
190            ProfilerMsg::Print => {
191                if let Some(ProfilerMsg::Time(..)) = self.last_msg {
192                    // only print if more data has arrived since the last printout
193                    self.print_buckets();
194                }
195            },
196            ProfilerMsg::Get(k, sender) => {
197                let vec_option = self.buckets.get(&k);
198                match vec_option {
199                    Some(vec_entry) => sender
200                        .send(ProfilerData::Record(vec_entry.to_vec()))
201                        .unwrap(),
202                    None => sender.send(ProfilerData::NoRecords).unwrap(),
203                };
204            },
205            ProfilerMsg::BlockedLayoutQuery(url) => {
206                *self.blocked_layout_queries.entry(url).or_insert(0) += 1;
207            },
208            ProfilerMsg::Exit(chan) => {
209                self.print_buckets();
210                let _ = chan.send(());
211                return false;
212            },
213        };
214        self.last_msg = Some(msg);
215        true
216    }
217
218    /// Get tuple (mean, median, min, max) for profiler statistics.
219    pub fn get_statistics(data: &[Duration]) -> (Duration, Duration, Duration, Duration) {
220        debug_assert!(
221            data.windows(2).all(|window| window[0] <= window[1]),
222            "Data must be sorted"
223        );
224
225        let data_len = data.len();
226        debug_assert!(data_len > 0);
227        let (mean, median, min, max) = (
228            data.iter().sum::<Duration>() / data_len as u32,
229            data[data_len / 2],
230            data[0],
231            data[data_len - 1],
232        );
233        (mean, median, min, max)
234    }
235
236    fn print_buckets(&mut self) {
237        match self.output {
238            Some(OutputOptions::FileName(ref filename)) => {
239                let path = Path::new(&filename);
240                let mut file = match File::create(path) {
241                    Err(e) => panic!("Couldn't create {}: {}", path.display(), e),
242                    Ok(file) => file,
243                };
244                writeln!(
245                    file,
246                    "_category_\t_incremental?_\t_iframe?_\t_url_\t_mean (ms)_\t\
247                     _median (ms)_\t_min (ms)_\t_max (ms)_\t_events_"
248                )
249                .unwrap();
250                for ((category, meta), ref mut data) in &mut self.buckets {
251                    data.sort_by(|a, b| a.partial_cmp(b).expect("No NaN values in profiles"));
252                    let data_len = data.len();
253                    if data_len > 0 {
254                        let (mean, median, min, max) = Self::get_statistics(data);
255                        writeln!(
256                            file,
257                            "{}\t{}\t{:15.4}\t{:15.4}\t{:15.4}\t{:15.4}\t{:15}",
258                            category.variant_name(),
259                            meta.format(&self.output),
260                            mean.as_seconds_f64() * 1000.,
261                            median.as_seconds_f64() * 1000.,
262                            min.as_seconds_f64() * 1000.,
263                            max.as_seconds_f64() * 1000.,
264                            data_len
265                        )
266                        .unwrap();
267                    }
268                }
269
270                writeln!(file, "_url\t_blocked layout queries_").unwrap();
271                for (url, count) in &self.blocked_layout_queries {
272                    writeln!(file, "{}\t{}", url, count).unwrap();
273                }
274            },
275            Some(OutputOptions::Stdout(_)) => {
276                let stdout = io::stdout();
277                let mut lock = stdout.lock();
278
279                writeln!(
280                    &mut lock,
281                    "{:35} {:14} {:9} {:30} {:15} {:15} {:-15} {:-15} {:-15}",
282                    "_category_",
283                    "_incremental?_",
284                    "_iframe?_",
285                    "            _url_",
286                    "    _mean (ms)_",
287                    "  _median (ms)_",
288                    "     _min (ms)_",
289                    "     _max (ms)_",
290                    "      _events_"
291                )
292                .unwrap();
293                for ((category, meta), ref mut data) in &mut self.buckets {
294                    data.sort_by(|a, b| a.partial_cmp(b).expect("No NaN values in profiles"));
295                    let data_len = data.len();
296                    if data_len > 0 {
297                        let (mean, median, min, max) = Self::get_statistics(data);
298                        writeln!(
299                            &mut lock,
300                            "{:-35}{} {:15.4} {:15.4} {:15.4} {:15.4} {:15}",
301                            category.variant_name(),
302                            meta.format(&self.output),
303                            mean.as_seconds_f64() * 1000.,
304                            median.as_seconds_f64() * 1000.,
305                            min.as_seconds_f64() * 1000.,
306                            max.as_seconds_f64() * 1000.,
307                            data_len
308                        )
309                        .unwrap();
310                    }
311                }
312                writeln!(&mut lock).unwrap();
313
314                writeln!(&mut lock, "_url_\t_blocked layout queries_").unwrap();
315                for (url, count) in &self.blocked_layout_queries {
316                    writeln!(&mut lock, "{}\t{}", url, count).unwrap();
317                }
318                writeln!(&mut lock).unwrap();
319            },
320            None => { /* Do nothing if no output option has been set */ },
321        };
322    }
323}
profile/time.rs

profile/
time.rs
