Mirrors/servo
1
0
Fork 0
mirror of https://github.com/servo/servo.git synced 2025-08-05 05:30:08 +01:00
Code Issues Projects Releases Packages Wiki Activity

Auto merge of #21651 - AnshulMalik:format-profile, r=jdm

Browse source 
format components/profile

Issue #21373

<!-- Reviewable:start -->
---
This change is [<img src="https://reviewable.io/review_button.svg" height="34" align="absmiddle" alt="Reviewable"/>](https://reviewable.io/reviews/servo/servo/21651)
<!-- Reviewable:end -->
This commit is contained in:
bors-servo 2018-09-10 11:49:56 -04:00 • committed by GitHub
commit e122341a1d
No known key found for this signature in database
GPG key ID: 4AEE18F83AFDEB23
4 changed files with 276 additions and 189 deletions
Download patch file Download diff file Expand all files Collapse all files

63
components/profile/heartbeats.rs
View file

@ -14,24 +14,22 @@ use std::path::Path;
/// Initialize heartbeats /// Initialize heartbeats
pub fn init() { pub fn init() {
lock_and_work(|hbs_opt| lock_and_work(|hbs_opt| {
if hbs_opt.is_none() { if hbs_opt.is_none() {
let mut hbs: Box<HashMap<ProfilerCategory, Heartbeat>> = Box::new(HashMap::new()); let mut hbs: Box<HashMap<ProfilerCategory, Heartbeat>> = Box::new(HashMap::new());
maybe_create_heartbeat(&mut hbs, ProfilerCategory::ApplicationHeartbeat); maybe_create_heartbeat(&mut hbs, ProfilerCategory::ApplicationHeartbeat);
*hbs_opt = Some(Box::into_raw(hbs)) *hbs_opt = Some(Box::into_raw(hbs))
} }
); });
} }
/// Log regmaining buffer data and cleanup heartbeats /// Log regmaining buffer data and cleanup heartbeats
pub fn cleanup() { pub fn cleanup() {
let hbs_opt_box: Option<Box<HashMap<ProfilerCategory, Heartbeat>>> = lock_and_work(|hbs_opt| let hbs_opt_box: Option<Box<HashMap<ProfilerCategory, Heartbeat>>> = lock_and_work(|hbs_opt| {
hbs_opt.take().map(|hbs_ptr| hbs_opt
unsafe { .take()
Box::from_raw(hbs_ptr) .map(|hbs_ptr| unsafe { Box::from_raw(hbs_ptr) })
} });
)
);
if let Some(mut hbs) = hbs_opt_box { if let Some(mut hbs) = hbs_opt_box {
for (_, v) in hbs.iter_mut() { for (_, v) in hbs.iter_mut() {
// log any remaining heartbeat records before dropping // log any remaining heartbeat records before dropping
@ -43,23 +41,23 @@ pub fn cleanup() {
/// Check if a heartbeat exists for the given category /// Check if a heartbeat exists for the given category
pub fn is_heartbeat_enabled(category: &ProfilerCategory) -> bool { pub fn is_heartbeat_enabled(category: &ProfilerCategory) -> bool {
let is_enabled = lock_and_work(|hbs_opt| let is_enabled = lock_and_work(|hbs_opt| {
hbs_opt.map_or(false, |hbs_ptr| hbs_opt.map_or(false, |hbs_ptr| unsafe {
unsafe { (*hbs_ptr).contains_key(category)
(*hbs_ptr).contains_key(category) })
} });
)
);
is_enabled || is_create_heartbeat(category) is_enabled || is_create_heartbeat(category)
} }
/// Issue a heartbeat (if one exists) for the given category /// Issue a heartbeat (if one exists) for the given category
pub fn maybe_heartbeat(category: &ProfilerCategory, pub fn maybe_heartbeat(
start_time: u64, category: &ProfilerCategory,
end_time: u64, start_time: u64,
start_energy: u64, end_time: u64,
end_energy: u64) { start_energy: u64,
lock_and_work(|hbs_opt| end_energy: u64,
) {
lock_and_work(|hbs_opt| {
if let Some(hbs_ptr) = *hbs_opt { if let Some(hbs_ptr) = *hbs_opt {
unsafe { unsafe {
if !(*hbs_ptr).contains_key(category) { if !(*hbs_ptr).contains_key(category) {
@ -70,13 +68,14 @@ pub fn maybe_heartbeat(category: &ProfilerCategory,
} }
} }
} }
); });
} }
// TODO(cimes): Android doesn't really do environment variables. Need a better way to configure dynamically. // TODO(cimes): Android doesn't really do environment variables. Need a better way to configure dynamically.
fn is_create_heartbeat(category: &ProfilerCategory) -> bool { fn is_create_heartbeat(category: &ProfilerCategory) -> bool {
opts::get().profile_heartbeats || var_os(format!("SERVO_HEARTBEAT_ENABLE_{:?}", category)).is_some() opts::get().profile_heartbeats ||
var_os(format!("SERVO_HEARTBEAT_ENABLE_{:?}", category)).is_some()
} }
fn open_heartbeat_log<P: AsRef<Path>>(name: P) -> Option<File> { fn open_heartbeat_log<P: AsRef<Path>>(name: P) -> Option<File> {
@ -111,8 +110,10 @@ fn get_heartbeat_window_size(category: &ProfilerCategory) -> usize {
} }
/// Possibly create a heartbeat /// Possibly create a heartbeat
fn maybe_create_heartbeat(hbs: &mut HashMap<ProfilerCategory, Heartbeat>, fn maybe_create_heartbeat(
category: ProfilerCategory) { hbs: &mut HashMap<ProfilerCategory, Heartbeat>,
category: ProfilerCategory,
) {
if is_create_heartbeat(&category) { if is_create_heartbeat(&category) {
// get optional log file // get optional log file
let logfile: Option<File> = get_heartbeat_log(&category); let logfile: Option<File> = get_heartbeat_log(&category);
@ -151,11 +152,11 @@ mod synchronized_heartbeat {
static HBS_SPINLOCK: AtomicBool = ATOMIC_BOOL_INIT; static HBS_SPINLOCK: AtomicBool = ATOMIC_BOOL_INIT;
pub fn lock_and_work<F, R>(work: F) -> R pub fn lock_and_work<F, R>(work: F) -> R
where F: FnOnce(&mut Option<*mut HashMap<ProfilerCategory, Heartbeat>>) -> R { where
F: FnOnce(&mut Option<*mut HashMap<ProfilerCategory, Heartbeat>>) -> R,
{
while HBS_SPINLOCK.compare_and_swap(false, true, Ordering::SeqCst) {} while HBS_SPINLOCK.compare_and_swap(false, true, Ordering::SeqCst) {}
let result = unsafe { let result = unsafe { work(&mut HBS) };
work(&mut HBS)
};
HBS_SPINLOCK.store(false, Ordering::SeqCst); HBS_SPINLOCK.store(false, Ordering::SeqCst);
result result
} }
@ -163,7 +164,7 @@ mod synchronized_heartbeat {
/// Callback function used to log the window buffer. /// Callback function used to log the window buffer.
/// When this is called from native C, the heartbeat is safely locked internally and the global lock is held. /// When this is called from native C, the heartbeat is safely locked internally and the global lock is held.
/// If calling from this file, you must already hold the global lock! /// If calling from this file, you must already hold the global lock!
pub extern fn heartbeat_window_callback(hb: *const HeartbeatContext) { pub extern "C" fn heartbeat_window_callback(hb: *const HeartbeatContext) {
unsafe { unsafe {
if let Some(hbs_ptr) = HBS { if let Some(hbs_ptr) = HBS {
for (_, v) in (*hbs_ptr).iter_mut() { for (_, v) in (*hbs_ptr).iter_mut() {

155
components/profile/mem.rs
View file

@ -36,22 +36,24 @@ impl Profiler {
// Create the timer thread if a period was provided. // Create the timer thread if a period was provided.
if let Some(period) = period { if let Some(period) = period {
let chan = chan.clone(); let chan = chan.clone();
thread::Builder::new().name("Memory profiler timer".to_owned()).spawn(move || { thread::Builder::new()
loop { .name("Memory profiler timer".to_owned())
.spawn(move || loop {
thread::sleep(duration_from_seconds(period)); thread::sleep(duration_from_seconds(period));
if chan.send(ProfilerMsg::Print).is_err() { if chan.send(ProfilerMsg::Print).is_err() {
break; break;
} }
} }).expect("Thread spawning failed");
}).expect("Thread spawning failed");
} }
// Always spawn the memory profiler. If there is no timer thread it won't receive regular // Always spawn the memory profiler. If there is no timer thread it won't receive regular
// `Print` events, but it will still receive the other events. // `Print` events, but it will still receive the other events.
thread::Builder::new().name("Memory profiler".to_owned()).spawn(move || { thread::Builder::new()
let mut mem_profiler = Profiler::new(port); .name("Memory profiler".to_owned())
mem_profiler.start(); .spawn(move || {
}).expect("Thread spawning failed"); let mut mem_profiler = Profiler::new(port);
mem_profiler.start();
}).expect("Thread spawning failed");
let mem_profiler_chan = ProfilerChan(chan); let mem_profiler_chan = ProfilerChan(chan);
@ -59,12 +61,17 @@ impl Profiler {
// be unregistered, because as long as the memory profiler is running the system memory // be unregistered, because as long as the memory profiler is running the system memory
// reporter can make measurements. // reporter can make measurements.
let (system_reporter_sender, system_reporter_receiver) = ipc::channel().unwrap(); let (system_reporter_sender, system_reporter_receiver) = ipc::channel().unwrap();
ROUTER.add_route(system_reporter_receiver.to_opaque(), Box::new(|message| { ROUTER.add_route(
let request: ReporterRequest = message.to().unwrap(); system_reporter_receiver.to_opaque(),
system_reporter::collect_reports(request) Box::new(|message| {
})); let request: ReporterRequest = message.to().unwrap();
mem_profiler_chan.send(ProfilerMsg::RegisterReporter("system".to_owned(), system_reporter::collect_reports(request)
Reporter(system_reporter_sender))); }),
);
mem_profiler_chan.send(ProfilerMsg::RegisterReporter(
"system".to_owned(),
Reporter(system_reporter_sender),
));
mem_profiler_chan mem_profiler_chan
} }
@ -79,9 +86,9 @@ impl Profiler {
pub fn start(&mut self) { pub fn start(&mut self) {
while let Ok(msg) = self.port.recv() { while let Ok(msg) = self.port.recv() {
if !self.handle_msg(msg) { if !self.handle_msg(msg) {
break break;
} }
} }
} }
@ -92,8 +99,10 @@ impl Profiler {
let name_clone = name.clone(); let name_clone = name.clone();
match self.reporters.insert(name, reporter) { match self.reporters.insert(name, reporter) {
None => true, None => true,
Some(_) => panic!(format!("RegisterReporter: '{}' name is already in use", Some(_) => panic!(format!(
name_clone)), "RegisterReporter: '{}' name is already in use",
name_clone
)),
} }
}, },
@ -101,8 +110,7 @@ impl Profiler {
// Panic if it hasn't previously been registered. // Panic if it hasn't previously been registered.
match self.reporters.remove(&name) { match self.reporters.remove(&name) {
Some(_) => true, Some(_) => true,
None => None => panic!(format!("UnregisterReporter: '{}' name is unknown", &name)),
panic!(format!("UnregisterReporter: '{}' name is unknown", &name)),
} }
}, },
@ -111,7 +119,7 @@ impl Profiler {
true true
}, },
ProfilerMsg::Exit => false ProfilerMsg::Exit => false,
} }
} }
@ -149,17 +157,20 @@ impl Profiler {
ReportKind::ExplicitJemallocHeapSize | ReportKind::ExplicitJemallocHeapSize |
ReportKind::ExplicitSystemHeapSize | ReportKind::ExplicitSystemHeapSize |
ReportKind::ExplicitNonHeapSize | ReportKind::ExplicitNonHeapSize |
ReportKind::ExplicitUnknownLocationSize => ReportKind::ExplicitUnknownLocationSize => {
report.path.insert(0, String::from("explicit")), report.path.insert(0, String::from("explicit"))
},
ReportKind::NonExplicitSize => {}, ReportKind::NonExplicitSize => {},
} }
// Update the reported fractions of the heaps, when appropriate. // Update the reported fractions of the heaps, when appropriate.
match report.kind { match report.kind {
ReportKind::ExplicitJemallocHeapSize => ReportKind::ExplicitJemallocHeapSize => {
jemalloc_heap_reported_size += report.size, jemalloc_heap_reported_size += report.size
ReportKind::ExplicitSystemHeapSize => },
system_heap_reported_size += report.size, ReportKind::ExplicitSystemHeapSize => {
system_heap_reported_size += report.size
},
_ => {}, _ => {},
} }
@ -182,12 +193,16 @@ impl Profiler {
// Compute and insert the heap-unclassified values. // Compute and insert the heap-unclassified values.
if let Some(jemalloc_heap_allocated_size) = jemalloc_heap_allocated_size { if let Some(jemalloc_heap_allocated_size) = jemalloc_heap_allocated_size {
forest.insert(&path!["explicit", "jemalloc-heap-unclassified"], forest.insert(
jemalloc_heap_allocated_size - jemalloc_heap_reported_size); &path!["explicit", "jemalloc-heap-unclassified"],
jemalloc_heap_allocated_size - jemalloc_heap_reported_size,
);
} }
if let Some(system_heap_allocated_size) = system_heap_allocated_size { if let Some(system_heap_allocated_size) = system_heap_allocated_size {
forest.insert(&path!["explicit", "system-heap-unclassified"], forest.insert(
system_heap_allocated_size - system_heap_reported_size); &path!["explicit", "system-heap-unclassified"],
system_heap_allocated_size - system_heap_reported_size,
);
} }
forest.print(); forest.print();
@ -222,7 +237,7 @@ impl ReportsTree {
size: 0, size: 0,
count: 0, count: 0,
path_seg: path_seg, path_seg: path_seg,
children: vec![] children: vec![],
} }
} }
@ -249,7 +264,7 @@ impl ReportsTree {
t.children.len() - 1 t.children.len() - 1
}, },
}; };
let tmp = t; // this temporary is needed to satisfy the borrow checker let tmp = t; // this temporary is needed to satisfy the borrow checker
t = &mut tmp.children[i]; t = &mut tmp.children[i];
} }
@ -286,9 +301,18 @@ impl ReportsTree {
} }
let mebi = 1024f64 * 1024f64; let mebi = 1024f64 * 1024f64;
let count_str = if self.count > 1 { format!(" [{}]", self.count) } else { "".to_owned() }; let count_str = if self.count > 1 {
println!("|{}{:8.2} MiB -- {}{}", format!(" [{}]", self.count)
indent_str, (self.size as f64) / mebi, self.path_seg, count_str); } else {
"".to_owned()
};
println!(
"|{}{:8.2} MiB -- {}{}",
indent_str,
(self.size as f64) / mebi,
self.path_seg,
count_str
);
for child in &self.children { for child in &self.children {
child.print(depth + 1); child.print(depth + 1);
@ -314,7 +338,8 @@ impl ReportsForest {
let (head, tail) = path.split_first().unwrap(); let (head, tail) = path.split_first().unwrap();
// Get the right tree, creating it if necessary. // Get the right tree, creating it if necessary.
if !self.trees.contains_key(head) { if !self.trees.contains_key(head) {
self.trees.insert(head.clone(), ReportsTree::new(head.clone())); self.trees
.insert(head.clone(), ReportsTree::new(head.clone()));
} }
let t = self.trees.get_mut(head).unwrap(); let t = self.trees.get_mut(head).unwrap();
@ -405,7 +430,10 @@ mod system_reporter {
// directly from the jemalloc documentation. // directly from the jemalloc documentation.
// "Total number of bytes allocated by the application." // "Total number of bytes allocated by the application."
report(path![JEMALLOC_HEAP_ALLOCATED_STR], jemalloc_stat("stats.allocated")); report(
path![JEMALLOC_HEAP_ALLOCATED_STR],
jemalloc_stat("stats.allocated"),
);
// "Total number of bytes in active pages allocated by the application. // "Total number of bytes in active pages allocated by the application.
// This is a multiple of the page size, and greater than or equal to // This is a multiple of the page size, and greater than or equal to
@ -422,20 +450,20 @@ mod system_reporter {
} }
#[cfg(target_os = "linux")] #[cfg(target_os = "linux")]
extern { extern "C" {
fn mallinfo() -> struct_mallinfo; fn mallinfo() -> struct_mallinfo;
} }
#[cfg(target_os = "linux")] #[cfg(target_os = "linux")]
#[repr(C)] #[repr(C)]
pub struct struct_mallinfo { pub struct struct_mallinfo {
arena: c_int, arena: c_int,
ordblks: c_int, ordblks: c_int,
smblks: c_int, smblks: c_int,
hblks: c_int, hblks: c_int,
hblkhd: c_int, hblkhd: c_int,
usmblks: c_int, usmblks: c_int,
fsmblks: c_int, fsmblks: c_int,
uordblks: c_int, uordblks: c_int,
fordblks: c_int, fordblks: c_int,
keepcost: c_int, keepcost: c_int,
@ -487,15 +515,26 @@ mod system_reporter {
// Using the same values for the `old` and `new` parameters is enough // Using the same values for the `old` and `new` parameters is enough
// to get the statistics updated. // to get the statistics updated.
let rv = unsafe { let rv = unsafe {
mallctl(epoch_c_name.as_ptr(), epoch_ptr, &mut epoch_len, epoch_ptr, mallctl(
epoch_len) epoch_c_name.as_ptr(),
epoch_ptr,
&mut epoch_len,
epoch_ptr,
epoch_len,
)
}; };
if rv != 0 { if rv != 0 {
return None; return None;
} }
let rv = unsafe { let rv = unsafe {
mallctl(value_c_name.as_ptr(), value_ptr, &mut value_len, null_mut(), 0) mallctl(
value_c_name.as_ptr(),
value_ptr,
&mut value_len,
null_mut(),
0,
)
}; };
if rv != 0 { if rv != 0 {
return None; return None;
@ -511,9 +550,7 @@ mod system_reporter {
#[cfg(target_os = "linux")] #[cfg(target_os = "linux")]
fn page_size() -> usize { fn page_size() -> usize {
unsafe { unsafe { ::libc::sysconf(::libc::_SC_PAGESIZE) as usize }
::libc::sysconf(::libc::_SC_PAGESIZE) as usize
}
} }
#[cfg(target_os = "linux")] #[cfg(target_os = "linux")]
@ -585,14 +622,18 @@ mod system_reporter {
}; };
let seg_re = Regex::new( let seg_re = Regex::new(
r"^[:xdigit:]+-[:xdigit:]+ (....) [:xdigit:]+ [:xdigit:]+:[:xdigit:]+ \d+ +(.*)").unwrap(); r"^[:xdigit:]+-[:xdigit:]+ (....) [:xdigit:]+ [:xdigit:]+:[:xdigit:]+ \d+ +(.*)",
).unwrap();
let rss_re = Regex::new(r"^Rss: +(\d+) kB").unwrap(); let rss_re = Regex::new(r"^Rss: +(\d+) kB").unwrap();
// We record each segment's resident size. // We record each segment's resident size.
let mut seg_map: HashMap<String, usize> = HashMap::new(); let mut seg_map: HashMap<String, usize> = HashMap::new();
#[derive(PartialEq)] #[derive(PartialEq)]
enum LookingFor { Segment, Rss } enum LookingFor {
Segment,
Rss,
}
let mut looking_for = LookingFor::Segment; let mut looking_for = LookingFor::Segment;
let mut curr_seg_name = String::new(); let mut curr_seg_name = String::new();
@ -644,7 +685,9 @@ mod system_reporter {
curr_seg_name.clone() curr_seg_name.clone()
}; };
match seg_map.entry(seg_name) { match seg_map.entry(seg_name) {
Entry::Vacant(entry) => { entry.insert(rss); }, Entry::Vacant(entry) => {
entry.insert(rss);
},
Entry::Occupied(mut entry) => *entry.get_mut() += rss, Entry::Occupied(mut entry) => *entry.get_mut() += rss,
} }
} }

234
components/profile/time.rs
View file

@ -50,11 +50,7 @@ impl Formattable for Option<TimerMetadata> {
}, },
_ => { _ => {
/* The profiling output is the terminal */ /* The profiling output is the terminal */
let url = if url.len() > 30 { let url = if url.len() > 30 { &url[..30] } else { url };
&url[..30]
} else {
url
};
let incremental = match meta.incremental { let incremental = match meta.incremental {
TimerMetadataReflowType::Incremental => " yes", TimerMetadataReflowType::Incremental => " yes",
TimerMetadataReflowType::FirstReflow => " no ", TimerMetadataReflowType::FirstReflow => " no ",
@ -67,16 +63,12 @@ impl Formattable for Option<TimerMetadata> {
}, },
} }
}, },
None => { None => match *output {
match *output { Some(OutputOptions::FileName(_)) => {
Some(OutputOptions::FileName(_)) => { format!(" {}\t{}\t{}", " N/A", " N/A", " N/A")
format!(" {}\t{}\t{}", " N/A", " N/A", " N/A") },
}, _ => format!(" {:14} {:9} {:30}", " N/A", " N/A", " N/A"),
_ => { },
format!(" {:14} {:9} {:30}", " N/A", " N/A", " N/A")
}
}
}
} }
} }
} }
@ -102,7 +94,7 @@ impl Formattable for ProfilerCategory {
ProfilerCategory::LayoutSelectorMatch | ProfilerCategory::LayoutSelectorMatch |
ProfilerCategory::LayoutTreeBuilder | ProfilerCategory::LayoutTreeBuilder |
ProfilerCategory::LayoutTextShaping => "| + ", ProfilerCategory::LayoutTextShaping => "| + ",
_ => "" _ => "",
}; };
let name = match *self { let name = match *self {
ProfilerCategory::Compositing => "Compositing", ProfilerCategory::Compositing => "Compositing",
@ -183,27 +175,29 @@ impl Profiler {
Some(ref option) => { Some(ref option) => {
// Spawn the time profiler thread // Spawn the time profiler thread
let outputoption = option.clone(); let outputoption = option.clone();
thread::Builder::new().name("Time profiler".to_owned()).spawn(move || { thread::Builder::new()
let trace = file_path.as_ref() .name("Time profiler".to_owned())
.and_then(|p| TraceDump::new(p).ok()); .spawn(move || {
let mut profiler = Profiler::new(port, trace, Some(outputoption)); let trace = file_path.as_ref().and_then(|p| TraceDump::new(p).ok());
profiler.start(); let mut profiler = Profiler::new(port, trace, Some(outputoption));
}).expect("Thread spawning failed"); profiler.start();
}).expect("Thread spawning failed");
// decide if we need to spawn the timer thread // decide if we need to spawn the timer thread
match option { match option {
&OutputOptions::FileName(_) | &OutputOptions::FileName(_) | &OutputOptions::DB(_, _, _, _) => {
&OutputOptions::DB(_, _, _, _) => { /* no timer thread needed */ }, /* no timer thread needed */
},
&OutputOptions::Stdout(period) => { &OutputOptions::Stdout(period) => {
// Spawn a timer thread // Spawn a timer thread
let chan = chan.clone(); let chan = chan.clone();
thread::Builder::new().name("Time profiler timer".to_owned()).spawn(move || { thread::Builder::new()
loop { .name("Time profiler timer".to_owned())
.spawn(move || loop {
thread::sleep(duration_from_seconds(period)); thread::sleep(duration_from_seconds(period));
if chan.send(ProfilerMsg::Print).is_err() { if chan.send(ProfilerMsg::Print).is_err() {
break; break;
} }
} }).expect("Thread spawning failed");
}).expect("Thread spawning failed");
}, },
} }
}, },
@ -211,37 +205,37 @@ impl Profiler {
// this is when the -p option hasn't been specified // this is when the -p option hasn't been specified
if file_path.is_some() { if file_path.is_some() {
// Spawn the time profiler // Spawn the time profiler
thread::Builder::new().name("Time profiler".to_owned()).spawn(move || { thread::Builder::new()
let trace = file_path.as_ref() .name("Time profiler".to_owned())
.and_then(|p| TraceDump::new(p).ok()); .spawn(move || {
let mut profiler = Profiler::new(port, trace, None); let trace = file_path.as_ref().and_then(|p| TraceDump::new(p).ok());
profiler.start(); let mut profiler = Profiler::new(port, trace, None);
}).expect("Thread spawning failed"); profiler.start();
}).expect("Thread spawning failed");
} else { } else {
// No-op to handle messages when the time profiler is not printing: // No-op to handle messages when the time profiler is not printing:
thread::Builder::new().name("Time profiler".to_owned()).spawn(move || { thread::Builder::new()
loop { .name("Time profiler".to_owned())
.spawn(move || loop {
match port.recv() { match port.recv() {
Err(_) => break, Err(_) => break,
Ok(ProfilerMsg::Exit(chan)) => { Ok(ProfilerMsg::Exit(chan)) => {
let _ = chan.send(()); let _ = chan.send(());
break; break;
}, },
_ => {} _ => {},
} }
} }).expect("Thread spawning failed");
}).expect("Thread spawning failed");
} }
} },
} }
heartbeats::init(); heartbeats::init();
let profiler_chan = ProfilerChan(chan); let profiler_chan = ProfilerChan(chan);
// only spawn the application-level profiler thread if its heartbeat is enabled // only spawn the application-level profiler thread if its heartbeat is enabled
let run_ap_thread = || { let run_ap_thread =
heartbeats::is_heartbeat_enabled(&ProfilerCategory::ApplicationHeartbeat) || heartbeats::is_heartbeat_enabled(&ProfilerCategory::ApplicationHeartbeat);
};
if run_ap_thread() { if run_ap_thread() {
let profiler_chan = profiler_chan.clone(); let profiler_chan = profiler_chan.clone();
// min of 1 heartbeat/sec, max of 20 should provide accurate enough power/energy readings // min of 1 heartbeat/sec, max of 20 should provide accurate enough power/energy readings
@ -249,39 +243,52 @@ impl Profiler {
const SLEEP_MS: u32 = 10; const SLEEP_MS: u32 = 10;
const MIN_ENERGY_INTERVAL_MS: u32 = 50; const MIN_ENERGY_INTERVAL_MS: u32 = 50;
const MAX_ENERGY_INTERVAL_MS: u32 = 1000; const MAX_ENERGY_INTERVAL_MS: u32 = 1000;
let interval_ms = enforce_range(MIN_ENERGY_INTERVAL_MS, MAX_ENERGY_INTERVAL_MS, energy_interval_ms()); 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; let loop_count: u32 = (interval_ms as f32 / SLEEP_MS as f32).ceil() as u32;
thread::Builder::new().name("Application heartbeat profiler".to_owned()).spawn(move || { thread::Builder::new()
let mut start_time = precise_time_ns(); .name("Application heartbeat profiler".to_owned())
let mut start_energy = read_energy_uj(); .spawn(move || {
loop { let mut start_time = precise_time_ns();
for _ in 0..loop_count { let mut start_energy = read_energy_uj();
if run_ap_thread() { loop {
thread::sleep(Duration::from_millis(SLEEP_MS as u64)) for _ in 0..loop_count {
} else { if run_ap_thread() {
return thread::sleep(Duration::from_millis(SLEEP_MS as u64))
} else {
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;
if let Err(_) = c.send(ProfilerMsg::Time(
(ProfilerCategory::ApplicationHeartbeat, None),
(start_time, end_time),
(start_energy, end_energy),
)) {
return;
}
start_time = end_time;
start_energy = end_energy;
} }
let end_time = precise_time_ns(); }).expect("Thread spawning failed");
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;
if let Err(_) = c.send(ProfilerMsg::Time((ProfilerCategory::ApplicationHeartbeat, None),
(start_time, end_time),
(start_energy, end_energy))) {
return;
}
start_time = end_time;
start_energy = end_energy;
}
}).expect("Thread spawning failed");
} }
profiler_chan profiler_chan
} }
pub fn new(port: IpcReceiver<ProfilerMsg>, trace: Option<TraceDump>, output: Option<OutputOptions>) -> Profiler { pub fn new(
port: IpcReceiver<ProfilerMsg>,
trace: Option<TraceDump>,
output: Option<OutputOptions>,
) -> Profiler {
Profiler { Profiler {
port: port, port: port,
buckets: BTreeMap::new(), buckets: BTreeMap::new(),
@ -293,9 +300,9 @@ impl Profiler {
pub fn start(&mut self) { pub fn start(&mut self) {
while let Ok(msg) = self.port.recv() { while let Ok(msg) = self.port.recv() {
if !self.handle_msg(msg) { if !self.handle_msg(msg) {
break break;
} }
} }
} }
@ -320,7 +327,9 @@ impl Profiler {
ProfilerMsg::Get(k, sender) => { ProfilerMsg::Get(k, sender) => {
let vec_option = self.buckets.get(&k); let vec_option = self.buckets.get(&k);
match vec_option { match vec_option {
Some(vec_entry) => sender.send(ProfilerData::Record(vec_entry.to_vec())).unwrap(), Some(vec_entry) => sender
.send(ProfilerData::Record(vec_entry.to_vec()))
.unwrap(),
None => sender.send(ProfilerData::NoRecords).unwrap(), None => sender.send(ProfilerData::NoRecords).unwrap(),
}; };
}, },
@ -344,11 +353,12 @@ impl Profiler {
let data_len = data.len(); let data_len = data.len();
debug_assert!(data_len > 0); debug_assert!(data_len > 0);
let (mean, median, min, max) = let (mean, median, min, max) = (
(data.iter().sum::<f64>() / (data_len as f64), data.iter().sum::<f64>() / (data_len as f64),
data[data_len / 2], data[data_len / 2],
data[0], data[0],
data[data_len - 1]); data[data_len - 1],
);
(mean, median, min, max) (mean, median, min, max)
} }
@ -357,21 +367,34 @@ impl Profiler {
Some(OutputOptions::FileName(ref filename)) => { Some(OutputOptions::FileName(ref filename)) => {
let path = Path::new(&filename); let path = Path::new(&filename);
let mut file = match File::create(&path) { let mut file = match File::create(&path) {
Err(e) => panic!("Couldn't create {}: {}", Err(e) => panic!(
path.display(), "Couldn't create {}: {}",
Error::description(&e)), path.display(),
Error::description(&e)
),
Ok(file) => file, Ok(file) => file,
}; };
write!(file, "_category_\t_incremental?_\t_iframe?_\t_url_\t_mean (ms)_\t\ write!(
_median (ms)_\t_min (ms)_\t_max (ms)_\t_events_\n").unwrap(); file,
"_category_\t_incremental?_\t_iframe?_\t_url_\t_mean (ms)_\t\
_median (ms)_\t_min (ms)_\t_max (ms)_\t_events_\n"
).unwrap();
for (&(ref category, ref meta), ref mut data) in &mut self.buckets { for (&(ref category, ref meta), ref mut data) in &mut self.buckets {
data.sort_by(|a, b| a.partial_cmp(b).expect("No NaN values in profiles")); data.sort_by(|a, b| a.partial_cmp(b).expect("No NaN values in profiles"));
let data_len = data.len(); let data_len = data.len();
if data_len > 0 { if data_len > 0 {
let (mean, median, min, max) = Self::get_statistics(data); let (mean, median, min, max) = Self::get_statistics(data);
write!(file, "{}\t{}\t{:15.4}\t{:15.4}\t{:15.4}\t{:15.4}\t{:15}\n", write!(
category.format(&self.output), meta.format(&self.output), file,
mean, median, min, max, data_len).unwrap(); "{}\t{}\t{:15.4}\t{:15.4}\t{:15.4}\t{:15.4}\t{:15}\n",
category.format(&self.output),
meta.format(&self.output),
mean,
median,
min,
max,
data_len
).unwrap();
} }
} }
}, },
@ -379,18 +402,35 @@ impl Profiler {
let stdout = io::stdout(); let stdout = io::stdout();
let mut lock = stdout.lock(); let mut lock = stdout.lock();
writeln!(&mut lock, "{:35} {:14} {:9} {:30} {:15} {:15} {:-15} {:-15} {:-15}", writeln!(
"_category_", "_incremental?_", "_iframe?_", &mut lock,
" _url_", " _mean (ms)_", " _median (ms)_", "{:35} {:14} {:9} {:30} {:15} {:15} {:-15} {:-15} {:-15}",
" _min (ms)_", " _max (ms)_", " _events_").unwrap(); "_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 { for (&(ref category, ref meta), ref mut data) in &mut self.buckets {
data.sort_by(|a, b| a.partial_cmp(b).expect("No NaN values in profiles")); data.sort_by(|a, b| a.partial_cmp(b).expect("No NaN values in profiles"));
let data_len = data.len(); let data_len = data.len();
if data_len > 0 { if data_len > 0 {
let (mean, median, min, max) = Self::get_statistics(data); let (mean, median, min, max) = Self::get_statistics(data);
writeln!(&mut lock, "{:-35}{} {:15.4} {:15.4} {:15.4} {:15.4} {:15}", writeln!(
category.format(&self.output), meta.format(&self.output), mean, median, min, max, &mut lock,
data_len).unwrap(); "{:-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(); writeln!(&mut lock, "").unwrap();
@ -434,22 +474,22 @@ impl Profiler {
} }
} }
} }
}, },
None => { /* Do nothing if no output option has been set */ }, None => { /* Do nothing if no output option has been set */ },
}; };
} }
} }
fn enforce_range<T>(min: T, max: T, value: T) -> T where T: Ord { fn enforce_range<T>(min: T, max: T, value: T) -> T
where
T: Ord,
{
assert!(min <= max); assert!(min <= max);
match value.cmp(&max) { match value.cmp(&max) {
Ordering::Equal | Ordering::Greater => max, Ordering::Equal | Ordering::Greater => max,
Ordering::Less => { Ordering::Less => match value.cmp(&min) {
match value.cmp(&min) { Ordering::Equal | Ordering::Less => min,
Ordering::Equal | Ordering::Less => min, Ordering::Greater => value,
Ordering::Greater => value,
}
}, },
} }
} }

13
components/profile/trace_dump.rs
View file

@ -38,7 +38,8 @@ impl TraceDump {
/// Create a new TraceDump and write the prologue of the HTML file out to /// Create a new TraceDump and write the prologue of the HTML file out to
/// disk. /// disk.
pub fn new<P>(trace_file_path: P) -> io::Result<TraceDump> pub fn new<P>(trace_file_path: P) -> io::Result<TraceDump>
where P: AsRef<path::Path> where
P: AsRef<path::Path>,
{ {
let mut file = fs::File::create(trace_file_path)?; let mut file = fs::File::create(trace_file_path)?;
write_prologue(&mut file)?; write_prologue(&mut file)?;
@ -46,10 +47,12 @@ impl TraceDump {
} }
/// Write one trace to the trace dump file. /// Write one trace to the trace dump file.
pub fn write_one(&mut self, pub fn write_one(
category: &(ProfilerCategory, Option<TimerMetadata>), &mut self,
time: (u64, u64), category: &(ProfilerCategory, Option<TimerMetadata>),
energy: (u64, u64)) { time: (u64, u64),
energy: (u64, u64),
) {
let entry = TraceEntry { let entry = TraceEntry {
category: category.0, category: category.0,
metadata: category.1.clone(), metadata: category.1.clone(),