diff --git a/etw-reader/src/custom_schemas.rs b/etw-reader/src/custom_schemas.rs index 0db0d0c8..72f46e9e 100644 --- a/etw-reader/src/custom_schemas.rs +++ b/etw-reader/src/custom_schemas.rs @@ -434,6 +434,249 @@ impl EventSchema for ThreadStart { } } +pub struct SampledProfile {} + +/// The schema for the SampledProfile event, version 2. +/// +/// This schema is hardcoded because, for a brief time +/// at the end of 2024, Windows was missing the schema +/// definition for this event type, so our queries to +/// look up the schema failed. One of the affected Windows +/// versions was 10.0.26100 24H2. +const SampledProfile_PROPS: [PropDesc; 4] = [ + PropDesc { + name: "InstructionPointer", + in_type: TdhInType::InTypePointer, + out_type: TdhOutType::OutTypeCodePointer, + }, + PropDesc { + name: "ThreadId", + in_type: TdhInType::InTypeUInt32, + out_type: TdhOutType::OutTypeUInt32, + }, + PropDesc { + name: "Count", + in_type: TdhInType::InTypeUInt16, + out_type: TdhOutType::OutTypeUInt16, + }, + PropDesc { + name: "Reserved", + in_type: TdhInType::InTypeUInt16, + out_type: TdhOutType::OutTypeUInt16, + }, +]; + +impl EventSchema for SampledProfile { + fn provider_guid(&self) -> GUID { + GUID::from("ce1dbfb4-137e-4da6-87b0-3f59aa102cbc") + } + + fn event_id(&self) -> u16 { + 0 + } + + fn opcode(&self) -> u8 { + 46 + } + + fn event_version(&self) -> u8 { + 2 + } + + fn level(&self) -> u8 { + 0 + } + + fn decoding_source(&self) -> DecodingSource { + panic!() + } + + fn provider_name(&self) -> String { + "MSNT_SystemTrace".to_owned() + } + + fn task_name(&self) -> String { + "PerfInfo".to_owned() + } + + fn opcode_name(&self) -> String { + "SampleProf".to_string() + } + + fn property_count(&self) -> u32 { + SampledProfile_PROPS.len() as u32 + } + + fn property(&self, index: u32) -> Property { + let prop = &SampledProfile_PROPS[index as usize]; + Property { + name: prop.name.to_owned(), + desc: PropertyDesc::Primitive(PrimitiveDesc { + in_type: prop.in_type, + out_type: prop.out_type, + }), + count: 1, + length: PropertyLength::Length(0), + map_info: None, + flags: PropertyFlags::empty(), + } + } +} + +pub struct CSwitch {} + +/// The schema for the CSwitch event, version 4. +/// +/// This schema is hardcoded because, for a brief time +/// at the end of 2024, Windows was missing the schema +/// definition for this event type, so our queries to +/// look up the schema failed. One of the affected Windows +/// versions was 10.0.26100 24H2. +// +// ```mof +// [dynamic: ToInstance, EventType(36)] +// class CSwitch_V4 : Thread_V4 +// { +// [WmiDataId(1), format("x"), read] uint32 NewThreadId; +// [WmiDataId(2), format("x"), read] uint32 OldThreadId; +// [WmiDataId(3), read] sint8 NewThreadPriority; +// [WmiDataId(4), read] sint8 OldThreadPriority; +// [WmiDataId(5), read] uint8 PreviousCState; +// [WmiDataId(6), read] sint8 SpareByte; +// [WmiDataId(7), read] sint8 OldThreadWaitReason; +// [WmiDataId(8), read] sint8 ThreadFlags; +// [WmiDataId(9), read] sint8 OldThreadState; +// [WmiDataId(10), read] sint8 OldThreadWaitIdealProcessor; +// [WmiDataId(11), format("x"), read] uint32 NewThreadWaitTime; +// [WmiDataId(12), read] uint32 Reserved; +// }; +// ``` +const CSwitch_V4_PROPS: [PropDesc; 12] = [ + PropDesc { + name: "NewThreadId", + in_type: TdhInType::InTypeUInt32, + out_type: TdhOutType::OutTypeUInt32, + }, + PropDesc { + name: "OldThreadId", + in_type: TdhInType::InTypeUInt32, + out_type: TdhOutType::OutTypeUInt32, + }, + PropDesc { + name: "NewThreadPriority", + in_type: TdhInType::InTypeInt8, + out_type: TdhOutType::OutTypeInt8, + }, + PropDesc { + name: "OldThreadPriority", + in_type: TdhInType::InTypeInt8, + out_type: TdhOutType::OutTypeInt8, + }, + PropDesc { + name: "PreviousCState", + in_type: TdhInType::InTypeUInt8, + out_type: TdhOutType::OutTypeUInt8, + }, + PropDesc { + name: "SpareByte", + in_type: TdhInType::InTypeInt8, + out_type: TdhOutType::OutTypeInt8, + }, + PropDesc { + name: "OldThreadWaitReason", + in_type: TdhInType::InTypeInt8, + out_type: TdhOutType::OutTypeInt8, + }, + PropDesc { + name: "ThreadFlags", + in_type: TdhInType::InTypeInt8, + out_type: TdhOutType::OutTypeInt8, + }, + PropDesc { + name: "OldThreadState", + in_type: TdhInType::InTypeInt8, + out_type: TdhOutType::OutTypeInt8, + }, + PropDesc { + name: "OldThreadWaitIdealProcessor", + in_type: TdhInType::InTypeInt8, + out_type: TdhOutType::OutTypeInt8, + }, + PropDesc { + name: "NewThreadWaitTime", + in_type: TdhInType::InTypeUInt32, + out_type: TdhOutType::OutTypeUInt32, + }, + PropDesc { + name: "Reserved", + in_type: TdhInType::InTypeUInt32, + out_type: TdhOutType::OutTypeUInt32, + }, +]; + +impl EventSchema for CSwitch { + fn provider_guid(&self) -> GUID { + GUID::from("3d6fa8d1-fe05-11d0-9dda-00c04fd7ba7c") // class Thread_V4 : MSNT_SystemTrace + } + + fn event_id(&self) -> u16 { + 0 + } + + fn opcode(&self) -> u8 { + 36 + } + + fn event_version(&self) -> u8 { + // Warning: We are pretending to be version 5, because that's + // what matches the events observed on Windows 10.0.26100 Build 26100, + // which is the Windows version where the schema was missing. + // But we don't actually know the correct V5 schema! There are likely + // one or two fields added at the end which our hardcoded V4 schema + // doesn't have. + 5 + } + + fn level(&self) -> u8 { + 0 + } + + fn decoding_source(&self) -> DecodingSource { + panic!() + } + + fn provider_name(&self) -> String { + "MSNT_SystemTrace".to_owned() + } + + fn task_name(&self) -> String { + "Thread".to_owned() + } + + fn opcode_name(&self) -> String { + "CSwitch".to_string() + } + + fn property_count(&self) -> u32 { + CSwitch_V4_PROPS.len() as u32 + } + + fn property(&self, index: u32) -> Property { + let prop = &CSwitch_V4_PROPS[index as usize]; + Property { + name: prop.name.to_owned(), + desc: PropertyDesc::Primitive(PrimitiveDesc { + in_type: prop.in_type, + out_type: prop.out_type, + }), + count: 1, + length: PropertyLength::Length(0), + map_info: None, + flags: PropertyFlags::empty(), + } + } +} + // from umdprovider.h pub struct D3DUmdLogging_MapAllocation {} diff --git a/etw-reader/src/lib.rs b/etw-reader/src/lib.rs index ce6fe0a2..388050fd 100644 --- a/etw-reader/src/lib.rs +++ b/etw-reader/src/lib.rs @@ -502,6 +502,8 @@ pub fn add_custom_schemas(locator: &mut SchemaLocator) { locator.add_custom_schema(Box::new(custom_schemas::DbgID {})); locator.add_custom_schema(Box::new(custom_schemas::EventInfo {})); locator.add_custom_schema(Box::new(custom_schemas::ThreadStart {})); + locator.add_custom_schema(Box::new(custom_schemas::CSwitch {})); + locator.add_custom_schema(Box::new(custom_schemas::SampledProfile {})); locator.add_custom_schema(Box::new(custom_schemas::D3DUmdLogging_MapAllocation {})); locator.add_custom_schema(Box::new(custom_schemas::D3DUmdLogging_RundownAllocation {})); locator.add_custom_schema(Box::new(custom_schemas::D3DUmdLogging_UnmapAllocation {})); diff --git a/samply/src/windows/elevated_helper.rs b/samply/src/windows/elevated_helper.rs index c512e888..2ccbfa77 100644 --- a/samply/src/windows/elevated_helper.rs +++ b/samply/src/windows/elevated_helper.rs @@ -161,7 +161,16 @@ impl UtilityProcessParent for ElevatedHelperParent { // Don't show a new Console window for this process. cmd.show(false); - let _ = cmd.status().expect("Failed to execute elevated helper"); + let exit_status = cmd.status().expect("Failed to execute elevated helper"); + if !exit_status.success() { + eprintln!( + "Failed to run elevated helper, exit status {}", + exit_status.code().unwrap() + ); + use crate::name::SAMPLY_NAME_PRINT_STRING; + eprintln!("{SAMPLY_NAME_PRINT_STRING} requires Administrator privileges for profiling on Windows."); + std::process::exit(1); + } } } diff --git a/samply/src/windows/elevated_helper.rs.orig b/samply/src/windows/elevated_helper.rs.orig new file mode 100644 index 00000000..c512e888 --- /dev/null +++ b/samply/src/windows/elevated_helper.rs.orig @@ -0,0 +1,214 @@ +use std::error::Error; +use std::path::{Path, PathBuf}; + +use serde_derive::{Deserialize, Serialize}; + +use super::utility_process::{ + run_child, UtilityProcess, UtilityProcessChild, UtilityProcessParent, UtilityProcessSession, +}; +use super::xperf::Xperf; +use crate::shared::recording_props::{ + CoreClrProfileProps, ProfileCreationProps, RecordingMode, RecordingProps, +}; + +#[derive(Debug, Clone, Serialize, Deserialize)] +#[serde(tag = "t", content = "c")] +enum ElevatedHelperRequestMsg { + StartXperf(ElevatedRecordingProps), + StopXperf, + GetKernelModules, +} + +#[derive(Debug, Clone, Serialize, Deserialize)] +pub struct ElevatedRecordingProps { + pub time_limit_seconds: Option, + pub interval_nanos: u64, + pub coreclr: CoreClrProfileProps, + pub vm_hack: bool, + pub is_attach: bool, + pub gfx: bool, + pub browsers: bool, +} + +impl ElevatedRecordingProps { + pub fn from_recording_props( + recording_props: &RecordingProps, + profile_creation_props: &ProfileCreationProps, + recording_mode: &RecordingMode, + ) -> Self { + Self { + time_limit_seconds: recording_props.time_limit.map(|l| l.as_secs_f64()), + interval_nanos: recording_props.interval.as_nanos().try_into().unwrap(), + coreclr: profile_creation_props.coreclr, + vm_hack: recording_props.vm_hack, + is_attach: recording_mode.is_attach_mode(), + gfx: recording_props.gfx, + browsers: recording_props.browsers, + } + } +} + +#[derive(Debug, Clone, Serialize, Deserialize)] +#[serde(tag = "t", content = "c")] +#[allow(clippy::enum_variant_names)] +enum ElevatedHelperReplyMsg { + AckStartXperf, + AckStopXperf { + kernel_output_file: PathBuf, + user_output_file: Option, + }, + AckGetKernelModules, +} + +// Runs in the helper process which has Administrator privileges. +pub fn run_elevated_helper(ipc_directory: &Path, output_path: PathBuf) { + let child = ElevatedHelperChild::new(output_path); + run_child::(ipc_directory, child) +} + +pub struct ElevatedHelperSession { + elevated_session: UtilityProcessSession, +} + +impl ElevatedHelperSession { + pub fn new(output_path: PathBuf) -> Result> { + let parent = ElevatedHelperParent { output_path }; + let elevated_session = UtilityProcessSession::spawn_process(parent)?; + Ok(Self { elevated_session }) + } + + pub fn start_xperf( + &mut self, + recording_props: &RecordingProps, + profile_creation_props: &ProfileCreationProps, + recording_mode: &RecordingMode, + ) -> Result<(), Box> { + let xperf_args = ElevatedRecordingProps::from_recording_props( + recording_props, + profile_creation_props, + recording_mode, + ); + match self + .elevated_session + .send_msg_and_wait_for_response(ElevatedHelperRequestMsg::StartXperf(xperf_args)) + { + Ok(reply) => match reply { + ElevatedHelperReplyMsg::AckStartXperf => Ok(()), + other_msg => { + Err(format!("Unexpected reply to StartXperf msg: {other_msg:?}").into()) + } + }, + Err(err) => { + eprintln!("Could not start xperf: {err}"); + std::process::exit(1); + } + } + } + + pub fn stop_xperf( + &mut self, + ) -> Result<(PathBuf, Option), Box> { + let reply = self + .elevated_session + .send_msg_and_wait_for_response(ElevatedHelperRequestMsg::StopXperf)?; + match reply { + ElevatedHelperReplyMsg::AckStopXperf { + kernel_output_file, + user_output_file, + } => Ok((kernel_output_file, user_output_file)), + other_msg => Err(format!("Unexpected reply to StartXperf msg: {other_msg:?}").into()), + } + } + + pub fn shutdown(self) { + self.elevated_session.shutdown() + } +} + +struct ElevatedHelper; + +impl UtilityProcess for ElevatedHelper { + const PROCESS_TYPE: &'static str = "windows-elevated-helper"; + type Child = ElevatedHelperChild; + type Parent = ElevatedHelperParent; + type ParentToChildMsg = ElevatedHelperRequestMsg; + type ChildToParentMsg = ElevatedHelperReplyMsg; +} + +struct ElevatedHelperParent { + output_path: PathBuf, +} + +impl UtilityProcessParent for ElevatedHelperParent { + fn spawn_child(self, ipc_directory: &Path) { + let self_path = std::env::current_exe().expect("Couldn't obtain path of this binary"); + // eprintln!( + // "Run this: {} run-elevated-helper --ipc-directory {} --output-path {}", + // self_path.to_string_lossy(), + // ipc_directory.to_string_lossy(), + // self.output_path.to_string_lossy() + // ); + + // let mut cmd = std::process::Command::new(&self_path); + let mut cmd = runas::Command::new(self_path); + cmd.arg("run-elevated-helper"); + + cmd.arg("--ipc-directory"); + cmd.arg(ipc_directory); + cmd.arg("--output-path"); + cmd.arg(expand_full_filename_with_cwd(&self.output_path)); + + // Don't show a new Console window for this process. + cmd.show(false); + + let _ = cmd.status().expect("Failed to execute elevated helper"); + } +} + +pub fn expand_full_filename_with_cwd(filename: &Path) -> PathBuf { + if filename.is_absolute() { + filename.to_path_buf() + } else { + let mut fullpath = std::env::current_dir().unwrap(); + fullpath.push(filename); + fullpath + } +} + +struct ElevatedHelperChild { + output_path: PathBuf, + xperf: Xperf, +} + +impl ElevatedHelperChild { + // Runs in the helper process which has Administrator privileges. + pub fn new(output_path: PathBuf) -> Self { + Self { + xperf: Xperf::new(), + output_path, + } + } +} + +impl UtilityProcessChild for ElevatedHelperChild { + // Runs in the helper process which has Administrator privileges. + fn handle_message( + &mut self, + msg: ElevatedHelperRequestMsg, + ) -> Result> { + match msg { + ElevatedHelperRequestMsg::StartXperf(props) => { + self.xperf.start_xperf(&self.output_path, &props)?; + Ok(ElevatedHelperReplyMsg::AckStartXperf) + } + ElevatedHelperRequestMsg::StopXperf => { + let (kernel_output_file, user_output_file) = self.xperf.stop_xperf()?; + Ok(ElevatedHelperReplyMsg::AckStopXperf { + kernel_output_file, + user_output_file, + }) + } + ElevatedHelperRequestMsg::GetKernelModules => Err("todo".into()), + } + } +} diff --git a/samply/src/windows/etw_gecko.rs b/samply/src/windows/etw_gecko.rs index 7f41e9aa..f213f04e 100644 --- a/samply/src/windows/etw_gecko.rs +++ b/samply/src/windows/etw_gecko.rs @@ -35,6 +35,7 @@ pub fn process_etl_files( &mut core_clr_context, ); if result.is_err() { + dbg!(etl_file); dbg!(&result); std::process::exit(1); } @@ -47,6 +48,7 @@ pub fn process_etl_files( &mut core_clr_context, ); if result.is_err() { + dbg!(extra_etl_file); dbg!(&result); std::process::exit(1); } @@ -58,6 +60,11 @@ pub fn process_etl_files( ); } +struct PendingImageInfo { + image_timestamp: u32, + pdb_path_and_debug_id: Option<(String, DebugId)>, +} + fn process_trace( etl_file: &Path, context: &mut ProfileContext, @@ -66,7 +73,7 @@ fn process_trace( ) -> Result<(), std::io::Error> { let is_arm64 = context.is_arm64(); let demand_zero_faults = false; //pargs.contains("--demand-zero-faults"); - let mut pending_image_info: Option<((u32, u64), PeInfo)> = None; + let mut pending_image_info: Option<((u32, u64), PendingImageInfo)> = None; open_trace(etl_file, |e| { let Ok(s) = schema_locator.event_schema(e) else { @@ -254,10 +261,10 @@ fn process_trace( let pid = s.process_id(); // there isn't a ProcessId field here let image_base: u64 = parser.try_parse("ImageBase").unwrap(); let image_timestamp: u32 = parser.try_parse("TimeDateStamp").unwrap(); - let image_checksum: u32 = parser.try_parse("ImageChecksum").unwrap(); - let image_size: u32 = parser.try_parse("ImageSize").unwrap(); - let mut info = PeInfo::new_with_size_and_checksum(image_size, image_checksum); - info.image_timestamp = Some(image_timestamp); + let info = PendingImageInfo { + image_timestamp, + pdb_path_and_debug_id: None, + }; pending_image_info = Some(((pid, image_base), info)); } "KernelTraceControl/ImageID/DbgID_RSDS" => { @@ -272,8 +279,7 @@ fn process_trace( Uuid::from_fields(guid.data1, guid.data2, guid.data3, &guid.data4), age, ); - info.debug_id = Some(debug_id); - info.pdb_path = Some(pdb_path); + info.pdb_path_and_debug_id = Some((pdb_path, debug_id)); } }; } @@ -288,17 +294,26 @@ fn process_trace( let image_checksum: u32 = parser.try_parse("ImageChecksum").unwrap(); let path: String = parser.try_parse("FileName").unwrap(); + let mut info = + PeInfo::new_with_size_and_checksum(image_size as u32, image_checksum); + // Supplement the information from this event with the information from // KernelTraceControl/ImageID events, if available. Those events come right // before this one (they were inserted by xperf during merging, if this is // a merged file). - let mut info = match pending_image_info.take() { - Some((pid_and_base, info)) if pid_and_base == (pid, image_base) => info, - _ => PeInfo::new_with_size_and_checksum(image_size as u32, image_checksum), - }; - - if info.image_timestamp.is_none() && image_timestamp_maybe_zero != 0 { - info.image_timestamp = Some(image_timestamp_maybe_zero); + match pending_image_info.take() { + Some((pid_and_base, pending_info)) if pid_and_base == (pid, image_base) => { + info.image_timestamp = Some(pending_info.image_timestamp); + if let Some((pdb_path, debug_id)) = pending_info.pdb_path_and_debug_id { + info.pdb_path = Some(pdb_path); + info.debug_id = Some(debug_id); + } + } + _ => { + if image_timestamp_maybe_zero != 0 { + info.image_timestamp = Some(image_timestamp_maybe_zero); + } + } } context.handle_image_load(timestamp_raw, pid, image_base, path, info);