use crate::function_trace::*;
use indexmap::set::IndexSet;
use serde::Serialize;
use serde_repr::Serialize_repr;
use std::collections::HashMap;
use std::fs::File;
use std::io::Write;
use std::path::PathBuf;
use std::time::{Duration, SystemTime};
use fnv::{FnvHashMap, FnvHashSet};
type FirefoxTime = f64;
#[derive(Serialize, Debug)]
enum Unused {}
type StringIndex = usize;
pub struct FirefoxProfileThreadId {
pub tid: usize,
start_duration: Duration,
}
#[derive(Serialize, Debug)]
pub struct FirefoxProfile {
meta: Metadata,
counters: Vec<Unused>,
threads: Vec<FirefoxThread>,
#[serde(skip_serializing)]
thread_count: usize,
}
#[derive(Serialize, Debug)]
#[serde(rename_all = "lowercase")]
#[allow(dead_code)]
enum Color {
Transparent,
Purple,
Green,
Orange,
Yellow,
LightBlue,
Grey,
Blue,
Brown,
}
#[derive(Serialize, Debug)]
struct Category {
name: &'static str,
color: Color,
subcategories: [&'static str; 1],
}
#[derive(Serialize_repr, Debug, Clone, Copy)]
#[repr(usize)]
enum CategoryIndex {
Logs,
Python,
Native,
Exceptions,
Imports,
GarbageCollection,
Length,
}
const CATEGORIES: [Category; CategoryIndex::Length as usize] = [
Category {
name: "Logs",
color: Color::Grey,
subcategories: ["Unused"],
},
Category {
name: "Python",
color: Color::Orange,
subcategories: ["Code"],
},
Category {
name: "Native",
color: Color::LightBlue,
subcategories: ["Code"],
},
Category {
name: "Exceptions",
color: Color::Brown,
subcategories: ["Unused"],
},
Category {
name: "Imports",
color: Color::Grey,
subcategories: ["Unused"],
},
Category {
name: "GarbageCollection",
color: Color::Purple,
subcategories: ["Unused"],
},
];
macro_rules! struct_table {
(struct $struct_name: ident {
$($element: ident: $ty: ty),+
} $($additional_field:ident: $additional_type: ty),*) => {
paste::item! {
#[derive(Serialize, Debug, Copy, Clone, PartialEq, Eq, Hash)]
struct [<$struct_name Index>] (usize);
#[derive(Serialize, Debug)]
#[serde(rename_all = "camelCase")]
struct [<$struct_name Table>] {
$($element: Vec<$ty>,)*
$($additional_field: $additional_type,)*
length: usize
}
struct $struct_name {
$($element: $ty),*,
}
impl [<$struct_name Table>] {
fn new($([<$additional_field _arg>]: $additional_type,)*) -> Self {
Self {
$($element: Vec::new()),*,
$($additional_field: [<$additional_field _arg>],)*
length: 0
}
}
#[allow(dead_code)]
fn add(&mut self, arg: $struct_name) -> [<$struct_name Index>] {
let length = self.length;
$(self.$element.push(arg.$element);)*
self.length += 1;
[<$struct_name Index>](length)
}
#[allow(dead_code)]
fn is_empty(&self) -> bool {
self.length == 0
}
$(
#[allow(dead_code)]
fn [<get_ $element>](&self, index: [<$struct_name Index>]) -> &$ty {
&self.$element[index.0]
})*
}
}
}
}
struct_table! {
struct Sample {
event_delay: Option<u32>,
stack: StackIndex,
time: FirefoxTime,
weight: Option<FirefoxTime>
}
weight_type: &'static str
}
struct_table! {
struct Stack {
frame: FrameIndex,
category: CategoryIndex,
subcategory: u32,
prefix: Option<StackIndex>
}
}
struct_table! {
struct Frame {
address: Option<u32>,
category: CategoryIndex,
subcategory: u32,
func: FunctionIndex,
innerWindowID: Option<Unused>,
implementation: Option<Unused>,
line: Option<u32>,
column: Option<u32>,
optimizations: Option<Unused>
}
}
struct_table! {
struct Function {
address: Option<Unused>,
isJS: bool,
name: StringIndex,
resource: i32,
relevantForJS: bool,
file_name: StringIndex,
line_number: Option<u32>,
column_number: Option<u32>
}
}
struct_table! {
struct NativeAllocation {
time: FirefoxTime,
weight: isize,
stack: Option<StackIndex>,
memory_address: usize,
thread_id: usize
}
weight_type: &'static str
}
struct_table! {
struct Marker {
data: serde_json::Value,
name: StringIndex,
startTime: FirefoxTime,
endTime: Option<FirefoxTime>,
phase: u64,
category: CategoryIndex
}
}
struct_table! {
struct Resource {
lib: Unused,
name: Unused,
host: Unused,
r#type: Unused
}
}
#[derive(Serialize, Debug)]
#[serde(rename_all = "camelCase")]
struct MarkerSchema {
name: &'static str,
tooltip_label: &'static str,
table_label: &'static str,
chart_label: &'static str,
display: &'static [&'static str],
data: &'static [MarkerDataSchema],
}
#[derive(Serialize, Debug)]
struct MarkerDataSchema {
key: &'static str,
label: &'static str,
format: &'static str,
searchable: bool
}
const MARKER_DISPLAYS_ALL: &'static [&'static str] = &[
"marker-chart",
"marker-table",
"timeline-overview",
"stack-chart"
];
const MARKER_SCHEMAS_SUPPORTED: &'static [MarkerSchema] = &[
MarkerSchema {
name: "Log",
tooltip_label: "Log event from {marker.data.origin}",
chart_label: "{marker.data.origin}",
table_label: "{marker.data.origin}: {marker.data.value}",
display: MARKER_DISPLAYS_ALL,
data: &[
MarkerDataSchema {
key: "origin",
label: "Log Origin",
format: "string",
searchable: true,
},
MarkerDataSchema {
key: "value",
label: "Value",
format: "string",
searchable: true,
},
]
},
MarkerSchema {
name: "Import",
tooltip_label: "Imported {marker.data.module}",
chart_label: "{marker.data.module}",
table_label: "imported {marker.data.module}",
display: &MARKER_DISPLAYS_ALL,
data: &[
MarkerDataSchema {
key: "module",
label: "Imported Module",
format: "string",
searchable: true,
},
]
},
MarkerSchema {
name: "Exception",
tooltip_label: "Exception {marker.data.exception} in {marker.data.module}",
chart_label: "{marker.data.exception}",
table_label: "Exception {marker.data.exception}: {marker.data.value}",
display: &MARKER_DISPLAYS_ALL,
data: &[
MarkerDataSchema {
key: "exception",
label: "Exception Type",
format: "string",
searchable: true,
},
MarkerDataSchema {
key: "value",
label: "Exception Data",
format: "string",
searchable: true,
},
MarkerDataSchema {
key: "module",
label: "Module",
format: "string",
searchable: true,
},
]
},
];
#[derive(Serialize, Debug)]
#[serde(rename_all = "camelCase")]
struct Metadata {
interval: f32,
start_time: f64,
process_type: u32,
categories: &'static [Category],
stackwalk: u32,
debug: bool,
version: u32,
preprocessed_profile_version: u32,
symbolicated: bool,
product: String,
#[serde(rename = "appBuildID")]
app_build_id: String,
abi: String,
platform: String,
misc: String,
#[serde(rename = "physicalCPUs")]
physical_cpus: usize,
#[serde(rename = "logicalCPUs")]
logical_cpus: usize,
marker_schema: &'static [MarkerSchema],
#[serde(skip_serializing)]
start_duration: Duration,
}
#[derive(Serialize, Debug)]
#[serde(rename_all = "camelCase")]
pub struct FirefoxThread {
process_type: &'static str,
process_startup_time: FirefoxTime,
process_shutdown_time: FirefoxTime,
register_time: FirefoxTime,
unregister_time: Option<FirefoxTime>,
paused_ranges: Vec<Unused>,
name: &'static str,
process_name: String,
is_js_tracer: bool,
pid: usize,
tid: usize,
samples: SampleTable,
markers: MarkerTable,
stack_table: StackTable,
frame_table: FrameTable,
func_table: FunctionTable,
string_array: IndexSet<String>,
#[serde(skip_serializing_if = "NativeAllocationTable::is_empty")]
native_allocations: NativeAllocationTable,
libs: Vec<Unused>,
resource_table: ResourceTable,
#[serde(skip_serializing)]
calls: Vec<SampleIndex>,
#[serde(skip_serializing)]
functions: HashMap<String, FunctionIndex>,
#[serde(skip_serializing)]
start_duration: Duration,
#[serde(skip_serializing)]
allocations: FnvHashMap<usize, usize>,
#[serde(skip_serializing)]
existing_stacks: FnvHashMap<(FunctionIndex, Option<StackIndex>), StackIndex>,
}
impl FirefoxProfile {
pub fn new(info: TraceInitialization) -> FirefoxProfile {
FirefoxProfile {
meta: Metadata {
start_time: SystemTime::now()
.duration_since(SystemTime::UNIX_EPOCH)
.map_or(0.0, |n| n.as_secs_f64() * 1000.0),
start_duration: info.time,
interval: 0.000_001,
process_type: 0,
categories: &CATEGORIES,
stackwalk: 0,
version: 22,
preprocessed_profile_version: 33,
debug: false,
symbolicated: true,
physical_cpus: num_cpus::get_physical(),
logical_cpus: num_cpus::get(),
product: info.program_name,
app_build_id: info.program_version,
abi: info.lang_version,
platform: info.platform,
misc: "<git revision>".to_string(),
marker_schema: MARKER_SCHEMAS_SUPPORTED,
},
counters: Vec::new(),
threads: Vec::new(),
thread_count: 0,
}
}
pub fn register_thread(&mut self) -> FirefoxProfileThreadId {
self.thread_count += 1;
FirefoxProfileThreadId {
tid: self.thread_count,
start_duration: self.meta.start_duration,
}
}
pub fn finalize_thread(&mut self, thread: FirefoxThread) {
self.threads.push(thread);
}
pub fn export(&mut self, mut output_dir: PathBuf) -> std::io::Result<()> {
self.threads.sort_by(|x, y| {
x.register_time
.partial_cmp(&y.register_time)
.expect("Registration time is reasonable")
});
let end_time = self
.threads
.iter()
.map(|x| x.process_shutdown_time)
.fold(0.0, f64::max);
let mut registered_pids = FnvHashSet::default();
for thread in self.threads.iter_mut() {
thread.name = if registered_pids.contains(&thread.pid) {
"thread"
} else {
"GeckoMain"
};
registered_pids.insert(thread.pid);
if thread.functions.is_empty() {
let message = "[WARNING] FunctionTrace didn't log any data for this thread. This may be because the thread crashed or otherwise exited before flushing its trace buffer.";
thread.emit_call(
message,
thread.start_duration + Duration::from_secs_f64(thread.register_time / 1000.0),
"FunctionTrace",
None,
);
thread.emit_return(message, end_time);
thread.process_shutdown_time = end_time;
}
}
let output_file = {
let mut dir = output_dir.clone();
let now = chrono::Local::now();
dir.push(format!("functiontrace.{}.json", now.format("%F-%T.%3f")));
dir
};
let json = serde_json::to_string(&self)?;
let bytes = json.as_bytes();
File::create(&output_file)?.write_all(bytes)?;
output_dir.push("functiontrace.latest.json");
let _ = std::fs::remove_file(&output_dir);
std::os::unix::fs::symlink(&output_file, &output_dir)?;
println!(
"\n[FunctionTrace] Wrote profile data to {} ({})\n",
output_file.display(),
bytesize::to_string(bytes.len() as u64, false)
);
Ok(())
}
}
impl FirefoxThread {
pub fn new(registration: ThreadRegistration, thread: FirefoxProfileThreadId) -> FirefoxThread {
FirefoxThread {
process_type: "default",
process_startup_time: 0.0,
process_shutdown_time: 0.0,
register_time: (registration.time - thread.start_duration).as_secs_f64() * 1000.0,
unregister_time: None,
paused_ranges: Vec::new(),
name: "<filled in at export>",
process_name: registration.program_name,
is_js_tracer: true,
pid: registration.pid,
tid: thread.tid,
samples: SampleTable::new("tracing-ms"),
markers: MarkerTable::new(),
stack_table: StackTable::new(),
frame_table: FrameTable::new(),
func_table: FunctionTable::new(),
string_array: IndexSet::new(),
native_allocations: NativeAllocationTable::new("bytes"),
libs: Vec::new(),
resource_table: ResourceTable::new(),
calls: Vec::new(),
functions: HashMap::new(),
start_duration: thread.start_duration,
allocations: FnvHashMap::default(),
existing_stacks: FnvHashMap::default(),
}
}
fn offset_time(&self, time: Duration) -> FirefoxTime {
(time - self.start_duration).as_secs_f64() * 1000.0
}
fn unique_string(&mut self, string: &str) -> StringIndex {
match self.string_array.get_full(string) {
Some((index, _)) => index,
None => self.string_array.insert_full(string.to_string()).0,
}
}
fn emit_call(
&mut self,
name: &str,
time: Duration,
file_or_module: &str,
linenumber: Option<u32>,
) -> FirefoxTime {
let (func_uid, category) = match linenumber {
None => (
format!("{}:{}:native", name, file_or_module),
CategoryIndex::Native,
),
Some(line) => (
format!("{} ({}:{})", name, file_or_module, line),
CategoryIndex::Python,
),
};
let function_id = match self.functions.get(&func_uid) {
Some(&x) => x,
None => {
let funcname_id = self.unique_string(name);
let filename_id = self.unique_string(file_or_module);
let function_id = self.func_table.add(Function {
address: None,
isJS: false,
name: funcname_id,
resource: -1,
relevantForJS: false,
file_name: filename_id,
line_number: linenumber,
column_number: None,
});
self.frame_table.add(Frame {
address: None,
category: category,
subcategory: 0,
func: function_id,
innerWindowID: None,
implementation: None,
line: linenumber,
column: None,
optimizations: None,
});
self.functions.insert(func_uid, function_id);
function_id
}
};
let frame_id = FrameIndex(function_id.0);
let prefix = self.calls.last().map(|&x| *self.samples.get_stack(x));
let stack_id = match self.existing_stacks.get(&(function_id, prefix)) {
Some(&id) => id,
None => {
let stack_id = self.stack_table.add(Stack {
frame: frame_id,
category: category,
subcategory: 0,
prefix: prefix,
});
self.existing_stacks.insert((function_id, prefix), stack_id);
stack_id
}
};
let time = self.offset_time(time);
let samples_id = self.samples.add(Sample {
event_delay: Some(0),
stack: stack_id,
time,
weight: None,
});
self.calls.push(samples_id);
time
}
fn emit_return(&mut self, func_name: &str, time: FirefoxTime) -> FirefoxTime {
while let Some(call_id) = self.calls.pop() {
let matches = {
let caller_id = *self.func_table.get_name(
*self
.frame_table
.get_func(*self.stack_table.get_frame(*self.samples.get_stack(call_id))),
);
self.string_array
.get_full(func_name)
.map_or(false, |(id, _)| id == caller_id)
};
self.samples.weight[call_id.0] = Some(time - self.samples.get_time(call_id));
if matches {
break;
}
log::trace!(
"Returning from `{}` which was not the most recently called function",
func_name
);
}
time
}
pub fn add_trace(&mut self, trace: FunctionTrace) {
let event_time = match trace {
FunctionTrace::Call {
time,
func_name,
filename,
linenumber,
} => self.emit_call(&func_name, time, &filename, Some(linenumber)),
FunctionTrace::NativeCall {
time,
func_name,
module_name,
} => self.emit_call(&func_name, time, &module_name, None),
FunctionTrace::Return { time, func_name } => {
self.emit_return(&func_name, self.offset_time(time))
}
FunctionTrace::NativeReturn { time, func_name } => {
self.emit_return(&func_name, self.offset_time(time))
}
FunctionTrace::Exception {
time,
exception_type,
exception_value,
filename,
linenumber,
} => {
let unique_type = self.unique_string(&exception_type);
let time = self.offset_time(time);
self.markers.add(Marker {
data: serde_json::json!({
"type": "Exception",
"exeption": exception_type,
"value": exception_value,
"module": format!("{}:{}", filename, linenumber)
}),
name: unique_type,
startTime: time,
endTime: None,
phase: 0,
category: CategoryIndex::Exceptions,
});
time
}
FunctionTrace::Log {
time,
log_type,
log_value,
} => {
let time = self.offset_time(time);
let unique_type = self.unique_string(&log_type);
self.markers.add(Marker {
data: serde_json::json!({
"type": "Log",
"origin": log_type,
"value": log_value,
}),
name: unique_type,
startTime: time,
endTime: None,
phase: 0,
category: CategoryIndex::Logs,
});
time
}
FunctionTrace::Import { time, module_name } => {
let time = self.offset_time(time);
let unique_type = self.unique_string("Import");
self.markers.add(Marker {
data: serde_json::json!({
"type": "Import",
"module": module_name,
}),
name: unique_type,
startTime: time,
endTime: None,
phase: 0,
category: CategoryIndex::Imports,
});
time
}
FunctionTrace::Allocation { time, details } => {
let time = self.offset_time(time);
let stack = self.calls.last().map(|&x| *self.samples.get_stack(x));
match details {
AllocationDetails::Alloc { bytes, addr } => {
self.allocations.insert(addr, bytes);
self.native_allocations.add(NativeAllocation {
time,
weight: bytes as isize,
stack,
memory_address: addr,
thread_id: self.tid,
});
}
AllocationDetails::Realloc {
bytes,
old_addr,
new_addr,
} => {
let old_bytes = self.allocations.remove(&old_addr).unwrap_or(0);
self.native_allocations.add(NativeAllocation {
time,
weight: -(old_bytes as isize),
stack,
memory_address: old_addr,
thread_id: self.tid,
});
self.allocations.insert(new_addr, bytes);
self.native_allocations.add(NativeAllocation {
time,
weight: bytes as isize,
stack,
memory_address: new_addr,
thread_id: self.tid,
});
}
AllocationDetails::Free { old_addr } => {
let bytes = self.allocations.remove(&old_addr).unwrap_or(0);
self.native_allocations.add(NativeAllocation {
time,
weight: -(bytes as isize),
stack,
memory_address: old_addr,
thread_id: self.tid,
});
}
}
time
}
msg => panic!("Invalid message variant: {:?}", msg),
};
self.process_shutdown_time = self.process_shutdown_time.max(event_time);
}
}