From c06dffbf6576d340e09cc0e0132c61ea0934d5d4 Mon Sep 17 00:00:00 2001 From: Jeff Muizelaar Date: Thu, 16 Feb 2023 16:09:13 -0500 Subject: [PATCH] Emit JitFunctionAdd markers. When using `samply load perf.data` with perf.data files which have been processed by `perf inject --jit`, we will now emit profiler markers at the time at which the JIT code was "loaded", i.e. the time of the LOAD record from the JITDUMP file. This will let us see at which time the JIT compilation of which function was completed. --- samply/src/import/perf.rs | 6 ++-- samply/src/linux/profiler.rs | 51 +++++++++++++++++---------- samply/src/linux_shared/mod.rs | 63 +++++++++++++++++++++++++++++++--- 3 files changed, 94 insertions(+), 26 deletions(-) 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()?;