diff --git a/samply/src/import/perf.rs b/samply/src/import/perf.rs index 2bcbce5f..0fe944eb 100644 --- a/samply/src/import/perf.rs +++ b/samply/src/import/perf.rs @@ -112,7 +112,7 @@ where }; if let Some(timestamp) = record.timestamp() { if timestamp < last_timestamp { - println!( + eprintln!( "bad timestamp ordering; {timestamp} is earlier but arrived after {last_timestamp}" ); } @@ -136,10 +136,10 @@ where converter.handle_thread_end(e); } EventRecord::Mmap(e) => { - converter.handle_mmap(e); + converter.handle_mmap(e, last_timestamp); } EventRecord::Mmap2(e) => { - converter.handle_mmap2(e); + converter.handle_mmap2(e, last_timestamp); } EventRecord::ContextSwitch(e) => { let common = match record.common_data() { diff --git a/samply/src/linux/profiler.rs b/samply/src/linux/profiler.rs index db1c4fb5..3a7dc4b6 100644 --- a/samply/src/linux/profiler.rs +++ b/samply/src/linux/profiler.rs @@ -328,23 +328,26 @@ fn init_profiler( flags |= libc::MAP_PRIVATE; } - converter.handle_mmap2(Mmap2Record { - pid: pid as i32, - tid: pid as i32, - address: region.start, - length: region.end - region.start, - page_offset: region.file_offset, - file_id: Mmap2FileId::InodeAndVersion(Mmap2InodeAndVersion { - major: region.major, - minor: region.minor, - inode: region.inode, - inode_generation: 0, - }), - protection: protection as _, - flags: flags as _, - path: RawData::Single(®ion.name.into_bytes()), - cpu_mode: CpuMode::User, - }); + converter.handle_mmap2( + Mmap2Record { + pid: pid as i32, + tid: pid as i32, + address: region.start, + length: region.end - region.start, + page_offset: region.file_offset, + file_id: Mmap2FileId::InodeAndVersion(Mmap2InodeAndVersion { + major: region.major, + minor: region.minor, + inode: region.inode, + inode_generation: 0, + }), + protection: protection as _, + flags: flags as _, + path: RawData::Single(®ion.name.into_bytes()), + cpu_mode: CpuMode::User, + }, + 0, + ); } // eprintln!("Enabling perf events..."); @@ -370,6 +373,7 @@ fn run_profiler( let mut wait = false; let mut pending_lost_events = 0; let mut total_lost_events = 0; + let mut last_timestamp = 0; loop { if stop.load(Ordering::SeqCst) || perf.is_empty() { break; @@ -391,6 +395,15 @@ fn run_profiler( let parsed_record = record.parse().unwrap(); // debug!("Recording parsed_record: {:#?}", parsed_record); + if let Some(timestamp) = record.timestamp() { + if timestamp < last_timestamp { + // eprintln!( + // "bad timestamp ordering; {timestamp} is earlier but arrived after {last_timestamp}" + // ); + } + last_timestamp = timestamp; + } + match parsed_record { EventRecord::Sample(e) => { converter.handle_sample::(e); @@ -409,10 +422,10 @@ fn run_profiler( converter.handle_thread_end(e); } EventRecord::Mmap(e) => { - converter.handle_mmap(e); + converter.handle_mmap(e, last_timestamp); } EventRecord::Mmap2(e) => { - converter.handle_mmap2(e); + converter.handle_mmap2(e, last_timestamp); } EventRecord::ContextSwitch(e) => { let common = match record.common_data() { diff --git a/samply/src/linux_shared/mod.rs b/samply/src/linux_shared/mod.rs index 81d1f376..db246e4f 100644 --- a/samply/src/linux_shared/mod.rs +++ b/samply/src/linux_shared/mod.rs @@ -10,8 +10,10 @@ use framehop::aarch64::UnwindRegsAarch64; use framehop::x86_64::UnwindRegsX86_64; use framehop::{FrameAddress, Module, ModuleSvmaInfo, ModuleUnwindData, TextByteData, Unwinder}; use fxprof_processed_profile::{ - CategoryColor, CategoryPairHandle, CpuDelta, Frame, LibraryInfo, ProcessHandle, Profile, - ReferenceTimestamp, SamplingInterval, ThreadHandle, Timestamp, + CategoryColor, CategoryPairHandle, CpuDelta, Frame, LibraryInfo, MarkerDynamicField, + MarkerFieldFormat, MarkerLocation, MarkerSchema, MarkerSchemaField, MarkerTiming, + ProcessHandle, Profile, ProfilerMarker, ReferenceTimestamp, SamplingInterval, ThreadHandle, + Timestamp, }; use linux_perf_data::linux_perf_event_reader; use linux_perf_data::{AttributeDescription, DsoInfo, DsoKey}; @@ -32,6 +34,7 @@ use object::{ FileKind, Object, ObjectSection, ObjectSegment, ObjectSymbol, SectionKind, SymbolKind, }; use samply_symbols::{debug_id_for_object, DebugIdExt}; +use serde_json::json; use wholesym::samply_symbols; use std::collections::{BTreeMap, HashMap}; @@ -483,7 +486,7 @@ where } } - pub fn handle_mmap(&mut self, e: MmapRecord) { + pub fn handle_mmap(&mut self, e: MmapRecord, timestamp: u64) { if e.page_offset == 0 { self.check_for_pe_mapping(&e.path.as_slice(), e.address); } @@ -520,11 +523,12 @@ where e.address, e.length, build_id.as_deref(), + timestamp, ); } } - pub fn handle_mmap2(&mut self, e: Mmap2Record) { + pub fn handle_mmap2(&mut self, e: Mmap2Record, timestamp: u64) { if e.page_offset == 0 { self.check_for_pe_mapping(&e.path.as_slice(), e.address); } @@ -556,6 +560,7 @@ where e.address, e.length, build_id.as_deref(), + timestamp, ); } @@ -790,6 +795,7 @@ where /// The profile needs to know about this module so that it can assign /// addresses in the stack to the right module and so that symbolication /// knows where to get symbols for this module. + #[allow(clippy::too_many_arguments)] fn add_module_to_process( &mut self, process_pid: i32, @@ -798,6 +804,7 @@ where mapping_start_avma: u64, mapping_size: u64, build_id: Option<&[u8]>, + timestamp: u64, ) { let process = self.processes.get_by_pid(process_pid, &mut self.profile); @@ -1002,6 +1009,24 @@ where end_address: mapping_end_avma, category, }); + + let main_thread = self + .threads + .get_by_tid( + process_pid, + process.profile_process, + true, + &mut self.profile, + ) + .profile_thread; + let timing = + MarkerTiming::Instant(self.timestamp_converter.convert_time(timestamp)); + self.profile.add_marker( + main_thread, + "JitFunctionAdd", + JitFunctionAddMarker(symbol_name.unwrap_or("").to_owned()), + timing, + ); }; } else { // Without access to the binary file, make some guesses. We can't really @@ -1035,6 +1060,36 @@ where } } +#[derive(Debug, Clone)] +pub struct JitFunctionAddMarker(pub String); + +impl ProfilerMarker for JitFunctionAddMarker { + const MARKER_TYPE_NAME: &'static str = "JitFunctionAdd"; + + fn json_marker_data(&self) -> serde_json::Value { + json!({ + "type": Self::MARKER_TYPE_NAME, + "functionName": self.0 + }) + } + + fn schema() -> MarkerSchema { + MarkerSchema { + type_name: Self::MARKER_TYPE_NAME, + locations: vec![MarkerLocation::MarkerChart, MarkerLocation::MarkerTable], + chart_label: Some("{marker.data.name}"), + tooltip_label: None, + table_label: Some("{marker.name} - {marker.data.name}"), + fields: vec![MarkerSchemaField::Dynamic(MarkerDynamicField { + key: "functionName", + label: "Name of the JIT function", + format: MarkerFieldFormat::String, + searchable: None, + })], + } + } +} + fn jit_function_name<'data>(obj: &object::File<'data>) -> Option<&'data str> { let mut text_symbols = obj.symbols().filter(|s| s.kind() == SymbolKind::Text); let symbol = text_symbols.next()?;