diff --git a/Cargo.lock b/Cargo.lock index bb8d1dc6..2b26f7ae 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -555,6 +555,19 @@ dependencies = [ "windows-sys 0.52.0", ] +[[package]] +name = "etw-reader" +version = "0.1.0" +dependencies = [ + "bitflags 2.5.0", + "fxhash", + "memoffset 0.9.1", + "num-derive", + "num-traits", + "once_cell", + "windows", +] + [[package]] name = "fallible-iterator" version = "0.2.0" @@ -1158,6 +1171,15 @@ dependencies = [ "autocfg", ] +[[package]] +name = "memoffset" +version = "0.9.1" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "488016bfae457b036d996092f6cb448677611ce4449e970ceaf42695203f218a" +dependencies = [ + "autocfg", +] + [[package]] name = "mime" version = "0.3.17" @@ -1763,6 +1785,7 @@ dependencies = [ "ctrlc", "debugid", "dirs", + "etw-reader", "flate2", "framehop", "futures-util", @@ -1777,7 +1800,7 @@ dependencies = [ "mach", "memchr", "memmap2", - "memoffset", + "memoffset 0.6.5", "mio", "nix", "nix-base32", diff --git a/Cargo.toml b/Cargo.toml index 3783e5da..29a5de00 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -1,4 +1,6 @@ [workspace] +resolver = "2" +default-members = ["samply"] members = [ "fxprof-processed-profile", "gecko_profile", @@ -11,8 +13,7 @@ members = [ "tools/dump_table", "tools/query_api" ] -resolver = "2" -default-members = ["samply"] +exclude = ["etw-reader"] # Should not be compiled on non-Windows # Config for 'cargo dist' [workspace.metadata.dist] diff --git a/etw-reader/Cargo.toml b/etw-reader/Cargo.toml new file mode 100644 index 00000000..10cb6ff8 --- /dev/null +++ b/etw-reader/Cargo.toml @@ -0,0 +1,29 @@ +[package] +name = "etw-reader" +version = "0.1.0" +edition = "2021" +license = "MIT" +repository = "https://github.com/mstange/samply" +documentation = "https://docs.rs/etw-reader" +description = "library for reading ETW etl files" +categories = ["os::windows-apis"] + +# See more keys and their definitions at https://doc.rust-lang.org/cargo/reference/manifest.html + +[dependencies] +bitflags = "2.4.2" +num-traits = "0.2" +num-derive = "0.4" +once_cell = "1.8.0" +fxhash = "0.2.1" +memoffset = "0.9" + +[dependencies.windows] +version = "0.56" +features = ["Win32_System_Diagnostics_Etw", + "Win32_System_Diagnostics_Debug", + "Win32_System_SystemInformation", + "Win32_Security_Authorization", + "Win32_System_Memory", + "Win32_System_Time", + "Win32_Foundation"] diff --git a/samply/src/windows/etw_reader/README.md b/etw-reader/README.md similarity index 100% rename from samply/src/windows/etw_reader/README.md rename to etw-reader/README.md diff --git a/etw-reader/examples/dump.rs b/etw-reader/examples/dump.rs new file mode 100644 index 00000000..faa8aa24 --- /dev/null +++ b/etw-reader/examples/dump.rs @@ -0,0 +1,212 @@ +use std::collections::HashMap; +use std::path::Path; + +use etw_reader::parser::{Parser, TryParse}; +use etw_reader::schema::SchemaLocator; +use etw_reader::{open_trace, print_property, GUID}; +use windows::Win32::System::Diagnostics::Etw::{ + self, EtwProviderTraitDecodeGuid, EtwProviderTraitTypeGroup, +}; + +fn main() { + let mut schema_locator = SchemaLocator::new(); + etw_reader::add_custom_schemas(&mut schema_locator); + let pattern = std::env::args().nth(2); + let mut processes = HashMap::new(); + open_trace(Path::new(&std::env::args().nth(1).unwrap()), |e| { + //dbg!(e.EventHeader.TimeStamp); + + let s = schema_locator.event_schema(e); + if let Ok(s) = s { + if let "MSNT_SystemTrace/Process/Start" + | "MSNT_SystemTrace/Process/DCStart" + | "MSNT_SystemTrace/Process/DCEnd" = s.name() + { + let mut parser = Parser::create(&s); + + let image_file_name: String = parser.parse("ImageFileName"); + let process_id: u32 = parser.parse("ProcessId"); + processes.insert(process_id, image_file_name); + } + + if let Some(pattern) = &pattern { + if !s.name().contains(pattern) { + return; + } + } + println!( + "{:?} {} {} {}-{} {} {}", + e.EventHeader.ProviderId, + s.name(), + s.provider_name(), + e.EventHeader.EventDescriptor.Opcode, + e.EventHeader.EventDescriptor.Id, + s.property_count(), + e.EventHeader.TimeStamp + ); + println!( + "pid: {} {:?}", + s.process_id(), + processes.get(&s.process_id()) + ); + if e.EventHeader.ActivityId != GUID::zeroed() { + println!("ActivityId: {:?}", e.EventHeader.ActivityId); + } + if e.ExtendedDataCount > 0 { + let items = unsafe { + std::slice::from_raw_parts(e.ExtendedData, e.ExtendedDataCount as usize) + }; + for i in items { + match i.ExtType as u32 { + Etw::EVENT_HEADER_EXT_TYPE_EVENT_SCHEMA_TL => { + println!("extended: SCHEMA_TL"); + let data: &[u8] = unsafe { + std::slice::from_raw_parts( + i.DataPtr as *const u8, + i.DataSize as usize, + ) + }; + + // from TraceLoggingProvider.h + let size = + u16::from_ne_bytes(<[u8; 2]>::try_from(&data[0..2]).unwrap()); + println!(" size: {}", size); + let mut extension_size = 1; + while data[2 + extension_size] & 0x80 != 0 { + extension_size += 1; + } + println!(" extension: {:?}", &data[2..2 + extension_size]); + let name_start = 2 + extension_size; + let mut name_end = name_start; + while data[name_end] != 0 { + name_end += 1; + } + let name = + String::from_utf8(data[name_start..name_end].to_owned()).unwrap(); + println!(" name: {}", name); + + let mut field_start = name_end + 1; + + while field_start < data.len() { + let field_name_start = field_start; + let mut field_name_end = field_name_start; + while data[field_name_end] != 0 { + field_name_end += 1; + } + let field_name = String::from_utf8( + data[field_name_start..field_name_end].to_owned(), + ) + .unwrap(); + println!(" field_name: {}", field_name); + let mut field_pos = field_name_end + 1; + let field_in_type = data[field_pos]; + dbg!(field_in_type); + field_pos += 1; + if field_in_type & 128 == 128 { + let field_out_type = data[field_pos]; + field_pos += 1; + dbg!(field_out_type); + if field_out_type & 128 == 128 { + // field extension + println!(" field extension"); + while data[field_pos] & 0x80 != 0 { + field_pos += 1; + } + field_pos += 1; + } + } + let c_count = 32; + let v_count = 64; + let custom = v_count | c_count; + let count_mask = v_count | c_count; + if field_in_type & count_mask == c_count { + // value count + field_pos += 2 + } + if field_in_type & count_mask == custom { + let type_info_size = u16::from_ne_bytes( + <[u8; 2]>::try_from(&data[field_pos..field_pos + 2]) + .unwrap(), + ); + field_pos += 2; + field_pos += type_info_size as usize; + } + field_start = field_pos; + } + } + Etw::EVENT_HEADER_EXT_TYPE_PROV_TRAITS => { + println!("extended: PROV_TRAITS"); + let data: &[u8] = unsafe { + std::slice::from_raw_parts( + i.DataPtr as *const u8, + i.DataSize as usize, + ) + }; + // ProviderMetadata + let size = + u16::from_ne_bytes(<[u8; 2]>::try_from(&data[0..2]).unwrap()); + println!(" size: {}", size); + let name_start = 2; + let mut name_end = name_start; + while data[name_end] != 0 { + name_end += 1; + } + let name = + String::from_utf8(data[name_start..name_end].to_owned()).unwrap(); + println!(" name: {}", name); + let mut metadata_start = name_end + 1; + // ProviderMetadataChunk + while metadata_start < data.len() { + let metadata_size = u16::from_ne_bytes( + <[u8; 2]>::try_from(&data[metadata_start..metadata_start + 2]) + .unwrap(), + ); + let metadata_type = data[metadata_start + 2]; + println!(" metadata_size: {}", metadata_size); + if metadata_type as i32 == EtwProviderTraitTypeGroup.0 { + println!(" EtwProviderTraitTypeGroup"); + // read GUID + let guid = &data[(metadata_start + 3)..]; + let guid = GUID::from_values( + u32::from_ne_bytes((&guid[0..4]).try_into().unwrap()), + u16::from_ne_bytes((&guid[4..6]).try_into().unwrap()), + u16::from_ne_bytes((&guid[6..8]).try_into().unwrap()), + [ + guid[8], guid[9], guid[10], guid[11], guid[12], + guid[13], guid[14], guid[15], + ], + ); + println!(" GUID {:?}", guid); + } else if metadata_type as i32 == EtwProviderTraitDecodeGuid.0 { + println!(" EtwProviderTraitDecodeGuid"); + } else { + println!(" Unexpected {}", metadata_type); + } + metadata_start += metadata_size as usize; + } + } + _ => { + println!("extended: {:?}", i); + } + } + } + } + let formatted_message = s.event_message(); + if let Some(message) = formatted_message { + println!("message: {}", message); + } + let mut parser = Parser::create(&s); + for i in 0..s.property_count() { + let property = s.property(i); + //dbg!(&property); + print_property(&mut parser, &property, true); + } + } else if pattern.is_none() { + println!( + "unknown event {:x?}:{} size: {}", + e.EventHeader.ProviderId, e.EventHeader.EventDescriptor.Opcode, e.UserDataLength + ); + } + }) + .unwrap(); +} diff --git a/etw-reader/examples/event-types.rs b/etw-reader/examples/event-types.rs new file mode 100644 index 00000000..9634dd1d --- /dev/null +++ b/etw-reader/examples/event-types.rs @@ -0,0 +1,81 @@ +use std::cmp::Reverse; +use std::collections::HashMap; +use std::path::Path; + +use etw_reader::schema::SchemaLocator; +use etw_reader::{open_trace, GUID}; + +fn main() { + let mut schema_locator = SchemaLocator::new(); + etw_reader::add_custom_schemas(&mut schema_locator); + let mut event_counts = HashMap::new(); + open_trace(Path::new(&std::env::args().nth(1).unwrap()), |e| { + let s = schema_locator.event_schema(e); + if let Ok(s) = s { + let name = format!( + "{} {:?}/{}/{}", + s.name(), + e.EventHeader.ProviderId, + e.EventHeader.EventDescriptor.Id, + e.EventHeader.EventDescriptor.Opcode + ); + if let Some(count) = event_counts.get_mut(&name) { + *count += 1; + } else { + event_counts.insert(name, 1); + } + } else { + let provider_name = match e.EventHeader.ProviderId { + GUID { + data1: 0x9B79EE91, + data2: 0xB5FD, + data3: 0x41C0, + data4: [0xA2, 0x43, 0x42, 0x48, 0xE2, 0x66, 0xE9, 0xD0], + } => "SysConfig ", + GUID { + data1: 0xB3E675D7, + data2: 0x2554, + data3: 0x4F18, + data4: [0x83, 0x0B, 0x27, 0x62, 0x73, 0x25, 0x60, 0xDE], + } => "KernelTraceControl ", + GUID { + data1: 0xED54DFF8, + data2: 0xC409, + data3: 0x4CF6, + data4: [0xBF, 0x83, 0x05, 0xE1, 0xE6, 0x1A, 0x09, 0xC4], + } => "WinSat ", + // see https://docs.microsoft.com/en-us/windows-hardware/drivers/ddi/umdprovider/nf-umdprovider-umdetwregister + GUID { + data1: 0xa688ee40, + data2: 0xd8d9, + data3: 0x4736, + data4: [0xb6, 0xf9, 0x6b, 0x74, 0x93, 0x5b, 0xa3, 0xb1], + } => "D3DUmdLogging ", + GUID { + data1: 0x3d6fa8d3, + data2: 0xfe05, + data3: 0x11d0, + data4: [0x9d, 0xda, 0x00, 0xc0, 0x4f, 0xd7, 0xba, 0x7c], + } => "PageFault_V2 ", + _ => "", + }; + + let provider = format!( + "{}{:?}/{}-{}/{}", + provider_name, + e.EventHeader.ProviderId, + e.EventHeader.EventDescriptor.Id, + e.EventHeader.EventDescriptor.Version, + e.EventHeader.EventDescriptor.Task + ); + *event_counts.entry(provider).or_insert(0) += 1; + } + }) + .unwrap(); + let mut event_counts: Vec<_> = event_counts.into_iter().collect(); + // event_counts.sort_by_key(|x| x.0.clone()); //alphabetical + event_counts.sort_by_key(|x| Reverse(x.1)); + for (k, v) in event_counts { + println!("{} {}", k, v); + } +} diff --git a/etw-reader/examples/list-processes.rs b/etw-reader/examples/list-processes.rs new file mode 100644 index 00000000..11b7fe22 --- /dev/null +++ b/etw-reader/examples/list-processes.rs @@ -0,0 +1,29 @@ +use std::path::Path; + +use etw_reader::open_trace; +use etw_reader::parser::{Parser, TryParse}; +use etw_reader::schema::SchemaLocator; + +fn main() { + let mut schema_locator = SchemaLocator::new(); + etw_reader::add_custom_schemas(&mut schema_locator); + open_trace(Path::new(&std::env::args().nth(1).unwrap()), |e| { + let s = schema_locator.event_schema(e); + if let Ok(s) = s { + // DCEnd is used '-Buffering' traces + if let "MSNT_SystemTrace/Process/Start" + | "MSNT_SystemTrace/Process/DCStart" + | "MSNT_SystemTrace/Process/DCEnd" = s.name() + { + let mut parser = Parser::create(&s); + + let image_file_name: String = parser.parse("ImageFileName"); + let process_id: u32 = parser.parse("ProcessId"); + let command_line: String = parser.parse("CommandLine"); + + println!("{} {} {}", image_file_name, process_id, command_line); + } + } + }) + .unwrap(); +} diff --git a/etw-reader/examples/list-providers.rs b/etw-reader/examples/list-providers.rs new file mode 100644 index 00000000..a5ec4f1f --- /dev/null +++ b/etw-reader/examples/list-providers.rs @@ -0,0 +1,6 @@ +use etw_reader::{enumerate_trace_guids_ex, tdh}; + +pub fn main() { + tdh::list_etw_providers(); + enumerate_trace_guids_ex(false); +} diff --git a/etw-reader/examples/list-threads.rs b/etw-reader/examples/list-threads.rs new file mode 100644 index 00000000..a04cadf2 --- /dev/null +++ b/etw-reader/examples/list-threads.rs @@ -0,0 +1,86 @@ +use std::collections::HashMap; +use std::path::Path; + +use etw_reader::open_trace; +use etw_reader::parser::{Parser, TryParse}; +use etw_reader::schema::SchemaLocator; + +struct Process { + image_file_name: String, +} + +fn main() { + let mut schema_locator = SchemaLocator::new(); + etw_reader::add_custom_schemas(&mut schema_locator); + let mut processes = HashMap::new(); + open_trace(Path::new(&std::env::args().nth(1).unwrap()), |e| { + let s = schema_locator.event_schema(e); + if let Ok(s) = s { + // DCEnd is used '-Buffering' traces + match s.name() { + "MSNT_SystemTrace/Process/Start" + | "MSNT_SystemTrace/Process/DCStart" + | "MSNT_SystemTrace/Process/DCEnd" => { + let mut parser = Parser::create(&s); + + let image_file_name: String = parser.parse("ImageFileName"); + let process_id: u32 = parser.parse("ProcessId"); + let command_line: String = parser.parse("CommandLine"); + println!("{} {} {}", image_file_name, process_id, command_line); + + processes.insert(process_id, Process { image_file_name }); + } + "MSNT_SystemTrace/Thread/Start" | "MSNT_SystemTrace/Thread/DCStart" => { + let mut parser = Parser::create(&s); + + let thread_id: u32 = parser.parse("TThreadId"); + let process_id: u32 = parser.parse("ProcessId"); + println!( + "thread process {}({}) tid {}", + processes[&process_id].image_file_name, process_id, thread_id + ); + //assert_eq!(process_id,s.process_id()); + + let thread_name: Result = parser.try_parse("ThreadName"); + match thread_name { + Ok(thread_name) if !thread_name.is_empty() => { + println!( + "thread_name pid: {} tid: {} name: {:?}", + process_id, thread_id, thread_name + ); + } + _ => {} + } + } + "MSNT_SystemTrace/Thread/SetName" => { + /* + let mut parser = Parser::create(&s); + + let process_id: u32 = parser.parse("ProcessId"); + let thread_id: u32 = parser.parse("ThreadId"); + let thread_name: String = parser.parse("ThreadName"); + let thread = match threads.entry(thread_id) { + Entry::Occupied(e) => e.into_mut(), + Entry::Vacant(e) => { + let thread_start_instant = profile_start_instant; + let handle = match global_thread { + Some(global_thread) => global_thread, + None => { + let process = processes[&process_id].process_handle; + profile.add_thread(process, thread_id, thread_start_instant, false) + } + }; + let tb = e.insert( + ThreadState::new(handle, thread_id) + ); + thread_index += 1; + tb + } + };*/ + } + _ => {} + } + } + }) + .expect("failed"); +} diff --git a/etw-reader/examples/log-js-stacks.rs b/etw-reader/examples/log-js-stacks.rs new file mode 100644 index 00000000..03a3ed24 --- /dev/null +++ b/etw-reader/examples/log-js-stacks.rs @@ -0,0 +1,214 @@ +use std::collections::Bound::{Included, Unbounded}; +use std::collections::{BTreeMap, HashMap}; +use std::convert::TryInto; +use std::path::Path; + +use etw_reader::open_trace; +use etw_reader::parser::{Address, Parser, TryParse}; +use etw_reader::schema::SchemaLocator; + +/// A single symbol from a [`SymbolTable`]. +#[derive(Debug, Clone, PartialEq, Eq, PartialOrd, Ord, Hash)] +pub struct Symbol { + /// The symbol's address, as a "relative address", i.e. relative to the library's base address. + pub address: u32, + /// The symbol's size, if known. This is often just set based on the address of the next symbol. + pub size: Option, + /// The symbol name. + pub name: String, +} + +struct Event { + name: String, + timestamp: i64, + stack: Option>, +} + +// struct ThreadState { +// process_id: u32, +// unfinished_kernel_stacks: Vec, +// } +// impl ThreadState { +// fn new(process_id: u32) -> Self { +// ThreadState { +// process_id, +// unfinished_kernel_stacks: Vec::new(), +// } +// } +// } + +fn main() { + let mut schema_locator = SchemaLocator::new(); + etw_reader::add_custom_schemas(&mut schema_locator); + let pattern = std::env::args().nth(2); + let mut processes = HashMap::new(); + let mut events: Vec = Vec::new(); + // let mut threads = HashMap::new(); + let mut jscript_symbols: HashMap> = HashMap::new(); + // let jscript_sources: HashMap = HashMap::new(); + open_trace(Path::new(&std::env::args().nth(1).unwrap()), |e| { + //dbg!(e.EventHeader.TimeStamp); + + let s = schema_locator.event_schema(e); + #[allow(unused)] + let mut thread_id = e.EventHeader.ThreadId; + if let Ok(s) = s { + match s.name() { + "MSNT_SystemTrace/StackWalk/Stack" => { + let mut parser = Parser::create(&s); + + // let thread_id: u32 = parser.parse("StackThread"); + let process_id: u32 = parser.parse("StackProcess"); + + println!("Sample"); + // let thread = match threads.entry(thread_id) { + // Entry::Occupied(e) => e.into_mut(), + // Entry::Vacant(e) => e.insert(ThreadState::new(process_id)), + // }; + // let timestamp: u64 = parser.parse("EventTimeStamp"); + + let stack: Vec = parser + .buffer + .chunks_exact(8) + .map(|a| u64::from_ne_bytes(a.try_into().unwrap())) + .collect(); + + let mut js_stack = Vec::new(); + let mut child = String::new(); + let mut child_addr = 0; + + stack.iter().for_each(|addr| { + if let Some(syms) = jscript_symbols.get(&process_id) { + if let Some(sym) = syms.range((Unbounded, Included(addr))).last() { + if *addr < *sym.0 + sym.1 .0 { + js_stack.push((sym.1 .1.clone(), *addr)); + //println!("found match for {} calls {:x}:{}", sym.1.1, child_addr, child); + child.clone_from(&sym.1 .1); + child_addr = *sym.0; + } + } + } + //println!("{:x}", addr); + }); + + for i in 0..js_stack.len() { + if js_stack[i].0.contains("runSync") + && i > 2 + && js_stack[i - 2].0.contains("click") + { + println!( + "found match {} {:x}/{} {}", + js_stack[i].0, + js_stack[i - 1].1, + js_stack[i - 1].0, + js_stack[i - 2].0 + ); + } + } + } + "MSNT_SystemTrace/PerfInfo/SampleProf" => { + // let mut parser = Parser::create(&s); + // thread_id = parser.parse("ThreadId"); + } + "V8.js/MethodLoad/" + | "Microsoft-JScript/MethodRuntime/MethodDCStart" + | "Microsoft-JScript/MethodRuntime/MethodLoad" => { + let mut parser = Parser::create(&s); + let method_name: String = parser.parse("MethodName"); + let method_start_address: Address = parser.parse("MethodStartAddress"); + let method_size: u64 = parser.parse("MethodSize"); + if method_start_address.as_u64() <= 0x7ffde0297cc0 + && method_start_address.as_u64() + method_size >= 0x7ffde0297cc0 + { + println!( + "before: {} {:x} {}", + method_name, + method_start_address.as_u64(), + method_size + ); + } + + // let source_id: u64 = parser.parse("SourceID"); + // let process_id = s.process_id(); + if method_name.contains("getNearestLContainer") + || method_name.contains("277:53") + { + println!( + "load {} {} {:x}", + method_name, + method_size, + method_start_address.as_u64() + ); + } + let syms = jscript_symbols.entry(s.process_id()).or_default(); + //let name_and_file = format!("{} {}", method_name, jscript_sources.get(&source_id).map(|x| x.as_ref()).unwrap_or("?")); + let start_address = method_start_address.as_u64(); + let mut overlaps = Vec::new(); + for sym in syms.range_mut(( + Included(start_address), + Included(start_address + method_size), + )) { + if method_name != sym.1 .1 + || start_address != *sym.0 + || method_size != sym.1 .0 + { + println!( + "overlap {} {} {} - {:?}", + method_name, start_address, method_size, sym + ); + overlaps.push(*sym.0); + } else { + println!( + "overlap same {} {} {} - {:?}", + method_name, start_address, method_size, sym + ); + } + } + for sym in overlaps { + syms.remove(&sym); + } + + syms.insert(start_address, (method_size, method_name)); + //dbg!(s.process_id(), jscript_symbols.keys()); + } + _ => {} + } + if let "MSNT_SystemTrace/Process/Start" + | "MSNT_SystemTrace/Process/DCStart" + | "MSNT_SystemTrace/Process/DCEnd" = s.name() + { + let mut parser = Parser::create(&s); + + let image_file_name: String = parser.parse("ImageFileName"); + let process_id: u32 = parser.parse("ProcessId"); + processes.insert(process_id, image_file_name); + } + } else if pattern.is_none() { + /*println!( + "unknown event {:x?}:{}", + e.EventHeader.ProviderId, e.EventHeader.EventDescriptor.Opcode + );*/ + } + }) + .unwrap(); + for e in &mut events { + if let Some(stack) = &e.stack { + println!("{} {}", e.timestamp, e.name); + for addr in stack { + println!(" {:x}", addr); + } + } + } + // for (tid, state) in threads { + // if !state.unfinished_kernel_stacks.is_empty() { + // println!( + // "thread `{tid}` of {} has {} unfinished kernel stacks", + // state.process_id, + // state.unfinished_kernel_stacks.len() + // ); + // for stack in state.unfinished_kernel_stacks { + // println!(" {}", events[stack].timestamp); + // } + // } + // } +} diff --git a/etw-reader/examples/log-stacks.rs b/etw-reader/examples/log-stacks.rs new file mode 100644 index 00000000..2853ebcd --- /dev/null +++ b/etw-reader/examples/log-stacks.rs @@ -0,0 +1,235 @@ +use std::collections::hash_map::Entry; +use std::collections::HashMap; +use std::convert::TryInto; +use std::path::Path; + +use etw_reader::open_trace; +use etw_reader::parser::{Parser, TryParse}; +use etw_reader::schema::SchemaLocator; + +fn is_kernel_address(ip: u64, pointer_size: u32) -> bool { + if pointer_size == 4 { + return ip >= 0x80000000; + } + ip >= 0xFFFF000000000000 // TODO I don't know what the true cutoff is. +} + +struct Event { + name: String, + timestamp: i64, + thread_id: u32, + stack: Option>, + cpu: u16, + bad_stack: bool, +} + +struct ThreadState { + process_id: u32, + events_with_unfinished_kernel_stacks: Vec, +} +impl ThreadState { + fn new(process_id: u32) -> Self { + ThreadState { + process_id, + events_with_unfinished_kernel_stacks: Vec::new(), + } + } +} + +fn main() { + let mut schema_locator = SchemaLocator::new(); + etw_reader::add_custom_schemas(&mut schema_locator); + let pattern = std::env::args().nth(2); + let mut processes = HashMap::new(); + let mut events: Vec = Vec::new(); + let mut threads = HashMap::new(); + open_trace(Path::new(&std::env::args().nth(1).unwrap()), |e| { + //dbg!(e.EventHeader.TimeStamp); + + let s = schema_locator.event_schema(e); + let mut thread_id = e.EventHeader.ThreadId; + if let Ok(s) = s { + match s.name() { + "MSNT_SystemTrace/StackWalk/Stack" => { + let mut parser = Parser::create(&s); + + let thread_id: u32 = parser.parse("StackThread"); + let process_id: u32 = parser.parse("StackProcess"); + + let thread = match threads.entry(thread_id) { + Entry::Occupied(e) => e.into_mut(), + Entry::Vacant(e) => e.insert(ThreadState::new(process_id)), + }; + let timestamp: u64 = parser.parse("EventTimeStamp"); + + let stack: Vec = parser + .buffer + .chunks_exact(8) + .map(|a| u64::from_ne_bytes(a.try_into().unwrap())) + .collect(); + + let ends_in_kernel = is_kernel_address(*stack.last().unwrap(), 8); + let mut i = events.len() - 1; + let mut found_event: Option = None; + let cpu = unsafe { e.BufferContext.Anonymous.ProcessorIndex }; + while i > 0 { + if events[i].timestamp < timestamp as i64 { + break; + } + // sometimes the thread_id won't match (virtualalloc?) + // we adjust the thread_id of the SampleProf event to get this to work + // otherwise TraceLog will use the cpu index + if events[i].timestamp == timestamp as i64 + && events[i].thread_id == thread_id + { + if let Some(first_event) = found_event { + println!( + "more than one associated event {}/{}:{}@{} {}/{}:{}@{} {}/{}@{}", + first_event, + events[first_event].name, + events[first_event].thread_id, + events[first_event].cpu, + i, + events[i].name, + events[i].thread_id, + events[i].cpu, + timestamp, + thread_id, + cpu, + ); + } + if ends_in_kernel { + match &mut events[i].stack { + Some(existing_stack) => { + // Sometimes the kernel will call back into userspace (KeUserModeCallback) + // this can cause there to be multiple stacks that end in a kernel address. + // + // Microsoft's TraceLog library seems to discard the initial kernel stack replacing + // it with a subsequent one which seems wrong because the initial stack contains + // the address which matches the 'InstructionPointer' field in the SampleProf event. + // + // Instead of discarding, we concatenate the stacks + assert!(thread + .events_with_unfinished_kernel_stacks + .contains(&i)); + existing_stack.extend_from_slice(&stack[..]) + } + None => { + thread.events_with_unfinished_kernel_stacks.push(i); + events[i].stack = Some(stack.clone()); + } + }; + } else { + for e in &thread.events_with_unfinished_kernel_stacks { + events[*e] + .stack + .as_mut() + .unwrap() + .extend_from_slice(&stack[..]); + } + match &mut events[i].stack { + Some(_) => { + // any existing stacks should only have come from kernel stacks + assert!(thread + .events_with_unfinished_kernel_stacks + .contains(&i)); + } + None => { + events[i].stack = Some(stack.clone()); + } + }; + if let Some(event_index_with_last_unfinished_stack) = + thread.events_with_unfinished_kernel_stacks.last() + { + if events[*event_index_with_last_unfinished_stack].timestamp + < events[i].timestamp + { + // We had an event A with a kernel stack, then an event B without a kernel stack, and this user stack is for B. + // So we must have exited the kernel at some point in between. We would have expected the user stack for A + // to be captured during that exit. But we didn't get one! The user stack for B might be different from the + // (missing) user stack for A. + println!( + "missing userspace stack? {} < {}", + events[*event_index_with_last_unfinished_stack] + .timestamp, + events[i].timestamp + ); + events[*event_index_with_last_unfinished_stack].bad_stack = + true; + } + } + thread.events_with_unfinished_kernel_stacks.clear(); + } + + found_event = Some(i); + } + i -= 1; + } + + if found_event.is_none() { + println!("no matching event"); + } + } + "MSNT_SystemTrace/PerfInfo/SampleProf" => { + let mut parser = Parser::create(&s); + + thread_id = parser.parse("ThreadId"); + } + "MSNT_SystemTrace/Thread/CSwitch" => { + let mut parser = Parser::create(&s); + + thread_id = parser.parse("NewThreadId"); + } + _ => {} + } + if let "MSNT_SystemTrace/Process/Start" + | "MSNT_SystemTrace/Process/DCStart" + | "MSNT_SystemTrace/Process/DCEnd" = s.name() + { + let mut parser = Parser::create(&s); + + let image_file_name: String = parser.parse("ImageFileName"); + let process_id: u32 = parser.parse("ProcessId"); + processes.insert(process_id, image_file_name); + } + + events.push(Event { + name: s.name().to_owned(), + timestamp: e.EventHeader.TimeStamp, + thread_id, + cpu: unsafe { e.BufferContext.Anonymous.ProcessorIndex }, + stack: None, + bad_stack: false, + }); + } else if pattern.is_none() { + /*println!( + "unknown event {:x?}:{}", + e.EventHeader.ProviderId, e.EventHeader.EventDescriptor.Opcode + );*/ + } + }) + .unwrap(); + for e in &mut events { + if let Some(stack) = &e.stack { + println!("{} {}", e.timestamp, e.name); + if e.bad_stack { + println!("bad stack"); + } + for addr in stack { + println!(" {:x}", addr); + } + } + } + for (tid, state) in threads { + if !state.events_with_unfinished_kernel_stacks.is_empty() { + println!( + "thread `{tid}` of {} has {} unfinished kernel stacks", + state.process_id, + state.events_with_unfinished_kernel_stacks.len() + ); + for stack in state.events_with_unfinished_kernel_stacks { + println!(" {}", events[stack].timestamp); + } + } + } +} diff --git a/etw-reader/examples/record.rs b/etw-reader/examples/record.rs new file mode 100644 index 00000000..b9494f18 --- /dev/null +++ b/etw-reader/examples/record.rs @@ -0,0 +1,42 @@ +use etw_reader::parser::Parser; +use etw_reader::schema::SchemaLocator; +use etw_reader::{print_property, start_trace}; + +fn main() { + let mut schema_locator = SchemaLocator::new(); + etw_reader::add_custom_schemas(&mut schema_locator); + let pattern = std::env::args().nth(2); + start_trace(|e| { + let s = schema_locator.event_schema(e); + if let Ok(s) = s { + if !s.name().contains("VideoProcessorBltParameters") { + return; + } + println!( + "pid {} time {}", + e.EventHeader.ProcessId, e.EventHeader.TimeStamp + ); + println!( + "{:?} {} {}-{} {} {}", + e.EventHeader.ProviderId, + s.name(), + e.EventHeader.EventDescriptor.Opcode, + e.EventHeader.EventDescriptor.Id, + s.property_count(), + e.EventHeader.TimeStamp + ); + + let mut parser = Parser::create(&s); + for i in 0..s.property_count() { + let property = s.property(i); + //dbg!(&property); + print_property(&mut parser, &property, false); + } + } else if pattern.is_none() { + println!( + "unknown event {:x?}:{}", + e.EventHeader.ProviderId, e.EventHeader.EventDescriptor.Opcode + ); + } + }); +} diff --git a/samply/src/windows/etw_reader/custom_schemas.rs b/etw-reader/src/custom_schemas.rs similarity index 100% rename from samply/src/windows/etw_reader/custom_schemas.rs rename to etw-reader/src/custom_schemas.rs diff --git a/samply/src/windows/etw_reader/etw_types.rs b/etw-reader/src/etw_types.rs similarity index 97% rename from samply/src/windows/etw_reader/etw_types.rs rename to etw-reader/src/etw_types.rs index 729deb96..5c9e642c 100644 --- a/samply/src/windows/etw_reader/etw_types.rs +++ b/etw-reader/src/etw_types.rs @@ -219,7 +219,7 @@ impl TraceEventInfoRaw { } } } - return None; + None }); map.clone() } @@ -264,7 +264,14 @@ impl EventSchema for TraceEventInfoRaw { fn opcode_name(&self) -> String { let opcode_name_offset = TraceEventInfo::from(self).OpcodeNameOffset as usize; if opcode_name_offset == 0 { - return String::from(""); + return String::from(match self.opcode() { + 0 => "Info", + 1 => "Start", + 2 => "Stop", + 3 => "DCStart", + 4 => "DCStop", + _ => "", + }); } utils::parse_unk_size_null_utf16_string(&self.info[opcode_name_offset..]) } diff --git a/samply/src/windows/etw_reader/mod.rs b/etw-reader/src/lib.rs similarity index 93% rename from samply/src/windows/etw_reader/mod.rs rename to etw-reader/src/lib.rs index cd397992..ce6fe0a2 100644 --- a/samply/src/windows/etw_reader/mod.rs +++ b/etw-reader/src/lib.rs @@ -1,4 +1,20 @@ -#![allow(warnings)] +use windows::core::{h, HSTRING, PWSTR}; +use windows::Win32::Foundation::{ + GetLastError, ERROR_INSUFFICIENT_BUFFER, ERROR_MORE_DATA, MAX_PATH, +}; +use windows::Win32::System::Diagnostics::Etw::{ + EnumerateTraceGuids, EnumerateTraceGuidsEx, TraceGuidQueryInfo, TraceGuidQueryList, + CONTROLTRACE_HANDLE, EVENT_TRACE_FLAG, TRACE_GUID_INFO, TRACE_GUID_PROPERTIES, + TRACE_PROVIDER_INSTANCE_INFO, +}; + +use crate::parser::{Parser, ParserError, TryParse}; +use crate::schema::SchemaLocator; +use crate::tdh_types::{PrimitiveDesc, PropertyDesc, TdhInType}; +use crate::traits::EncodeUtf16; + +#[macro_use] +extern crate memoffset; use std::borrow::Cow; use std::collections::HashMap; @@ -6,30 +22,17 @@ use std::hash::BuildHasherDefault; use std::mem; use std::path::Path; -use bitflags::bitflags; use etw_types::EventRecord; use fxhash::FxHasher; -use memoffset::offset_of; -use parser::{Parser, ParserError, TryParse}; -use schema::SchemaLocator; -use tdh_types::{PrimitiveDesc, Property, PropertyDesc, TdhInType, TdhOutType}; -use traits::EncodeUtf16; -use windows::core::{h, Error, HRESULT, HSTRING, PWSTR}; -use windows::Win32::Foundation::{ - GetLastError, ERROR_INSUFFICIENT_BUFFER, ERROR_MORE_DATA, ERROR_SUCCESS, MAX_PATH, -}; +use tdh_types::{Property, TdhOutType}; use windows::Win32::System::Diagnostics::Etw; -use windows::Win32::System::Diagnostics::Etw::{ - EnumerateTraceGuids, EnumerateTraceGuidsEx, TraceGuidQueryInfo, TraceGuidQueryList, - CONTROLTRACE_HANDLE, EVENT_TRACE_FLAG, TRACE_GUID_INFO, TRACE_GUID_PROPERTIES, - TRACE_PROVIDER_INSTANCE_INFO, -}; // typedef ULONG64 TRACEHANDLE, *PTRACEHANDLE; pub(crate) type TraceHandle = u64; pub const INVALID_TRACE_HANDLE: TraceHandle = u64::MAX; //, WindowsProgramming}; +#[allow(non_upper_case_globals, non_camel_case_types)] pub mod custom_schemas; pub mod etw_types; pub mod parser; @@ -70,8 +73,9 @@ impl std::ops::DerefMut for EventTraceLogfile { } unsafe extern "system" fn trace_callback_thunk(event_record: *mut Etw::EVENT_RECORD) { - let f: &mut &mut dyn FnMut(&EventRecord) = std::mem::transmute((*event_record).UserContext); - f(std::mem::transmute(event_record)) + let f: &mut &mut dyn FnMut(&EventRecord) = &mut *((*event_record).UserContext + as *mut &mut dyn for<'a> std::ops::FnMut(&'a etw_types::EventRecord)); + f(&*(event_record as *const etw_types::EventRecord)) } pub fn open_trace( @@ -83,7 +87,7 @@ pub fn open_trace( #[cfg(windows)] let path = HSTRING::from(path.as_os_str()); #[cfg(not(windows))] - let path: HSTRING = panic!(); + let path = HSTRING::from(path.to_string_lossy().to_string()); log_file.0.LogFileName = PWSTR(path.as_wide().as_ptr() as *mut _); log_file.0.Anonymous1.ProcessTraceMode = Etw::PROCESS_TRACE_MODE_EVENT_RECORD | Etw::PROCESS_TRACE_MODE_RAW_TIMESTAMP; @@ -148,7 +152,7 @@ impl TraceInfo { // it doesn't seem like it matters if we fill in trace_name self.properties.LoggerNameOffset = offset_of!(TraceInfo, trace_name) as u32; self.properties.LogFileNameOffset = offset_of!(TraceInfo, log_file_name) as u32; - self.trace_name[..trace_name.len() + 1].copy_from_slice(&trace_name.as_utf16()) + self.trace_name[..trace_name.len() + 1].copy_from_slice(&trace_name.to_utf16()) } } @@ -186,6 +190,12 @@ impl std::ops::DerefMut for EnableTraceParameters { } } +impl Default for Provider { + fn default() -> Self { + Self::new() + } +} + impl Provider { /// Use the `new` function to create a Provider builder /// @@ -231,9 +241,9 @@ pub struct Provider { } pub fn start_trace(mut callback: F) { - let guid_str = "22fb2cd6-0e7b-422b-a0c7-2fad1fd0e716"; + // let guid_str = "22fb2cd6-0e7b-422b-a0c7-2fad1fd0e716"; let guid_str = "DB6F6DDB-AC77-4E88-8253-819DF9BBF140"; - let mut video_blt_guid = GUID::from(guid_str); //GUID::from("DB6F6DDB-AC77-4E88-8253-819DF9BBF140"); + let video_blt_guid = GUID::from(guid_str); //GUID::from("DB6F6DDB-AC77-4E88-8253-819DF9BBF140"); let session_name = h!("aaaaaa"); @@ -277,9 +287,9 @@ pub fn start_trace(mut callback: F) { println!("EnableTrace = {}", status); */ unsafe { - Etw::EnableTraceEx2( + let _ = Etw::EnableTraceEx2( handle, - &mut video_blt_guid, + &video_blt_guid, 1, // Fixme: EVENT_CONTROL_CODE_ENABLE_PROVIDER prov.level, prov.any, @@ -375,7 +385,7 @@ pub fn write_property( _ => panic!("{:?}", property.desc), }; if map_info.is_bitmap { - let mut remaining_bits_str = String::new(); + let remaining_bits_str; let mut matches: Vec<&str> = Vec::new(); let mut cleared_value = value; for (k, v) in &map_info.map { @@ -397,7 +407,7 @@ pub fn write_property( map_info .map .get(&value) - .map(|x| Cow::from(x)) + .map(Cow::from) .unwrap_or_else(|| Cow::from(format!("Unknown: {}", value))) ) .unwrap(); @@ -507,7 +517,7 @@ pub fn enumerate_trace_guids() { ptrs.push(guid) } - let result = unsafe { EnumerateTraceGuids(&mut ptrs.as_mut_slice(), &mut count) }; + let result = unsafe { EnumerateTraceGuids(ptrs.as_mut_slice(), &mut count) }; match result.ok() { Ok(()) => { for guid in guids[..count as usize].iter() { @@ -552,8 +562,8 @@ pub fn enumerate_trace_guids_ex(print_instances: bool) { let instance_count = unsafe { *(info.as_ptr() as *const TRACE_GUID_INFO) }.InstanceCount; let mut instance_ptr: *const TRACE_PROVIDER_INSTANCE_INFO = unsafe { - (info.as_ptr().add(mem::size_of::()) - as *const TRACE_PROVIDER_INSTANCE_INFO) + info.as_ptr().add(mem::size_of::()) + as *const TRACE_PROVIDER_INSTANCE_INFO }; for _ in 0..instance_count { @@ -565,9 +575,8 @@ pub fn enumerate_trace_guids_ex(print_instances: bool) { ) } instance_ptr = unsafe { - ((instance_ptr as *const TRACE_PROVIDER_INSTANCE_INFO as *const u8) - .add(instance.NextOffset as usize) - as *const TRACE_PROVIDER_INSTANCE_INFO) + (instance_ptr as *const u8).add(instance.NextOffset as usize) + as *const TRACE_PROVIDER_INSTANCE_INFO }; } } diff --git a/samply/src/windows/etw_reader/parser.rs b/etw-reader/src/parser.rs similarity index 95% rename from samply/src/windows/etw_reader/parser.rs rename to etw-reader/src/parser.rs index 047e46e6..9d8c754b 100644 --- a/samply/src/windows/etw_reader/parser.rs +++ b/etw-reader/src/parser.rs @@ -10,10 +10,8 @@ use windows::core::GUID; use super::etw_types::EVENT_HEADER_FLAG_32_BIT_HEADER; use super::property::{PropertyInfo, PropertyIter}; use super::schema::TypedEvent; -use super::tdh_types::{ - PrimitiveDesc, Property, PropertyDesc, PropertyFlags, PropertyLength, TdhInType, TdhOutType, -}; -use super::{sddl, tdh, utils}; +use super::tdh_types::{Property, PropertyDesc, PropertyLength, TdhInType, TdhOutType}; +use super::{tdh, utils}; #[derive(Debug, Clone, Copy)] pub enum Address { @@ -215,10 +213,10 @@ impl<'a> Parser<'a> { } TdhInType::InTypeGuid => return Ok(std::mem::size_of::()), TdhInType::InTypeUnicodeString => { - return Ok(utils::parse_unk_size_null_unicode_size(&self.buffer)) + return Ok(utils::parse_unk_size_null_unicode_size(self.buffer)) } TdhInType::InTypeAnsiString => { - return Ok(utils::parse_unk_size_null_ansi_size(&self.buffer)); + return Ok(utils::parse_unk_size_null_ansi_size(self.buffer)); } _ => {} } @@ -246,7 +244,7 @@ impl<'a> Parser<'a> { for i in self.cache.len()..=indx { let curr_prop = self.properties.property(i).unwrap(); - let prop_size = self.find_property_size(&curr_prop)?; + let prop_size = self.find_property_size(curr_prop)?; if self.buffer.len() < prop_size { return Err(ParserError::PropertyError(format!( @@ -348,7 +346,7 @@ impl TryParse for Parser<'_> { return Ok(u64::from_ne_bytes(prop_info.buffer.try_into()?)); } } - return Err(ParserError::InvalidType); + Err(ParserError::InvalidType) } } @@ -365,7 +363,7 @@ impl TryParse for Parser<'_> { return Ok(i64::from_ne_bytes(prop_info.buffer.try_into()?)); } } - return Err(ParserError::InvalidType); + Err(ParserError::InvalidType) } } @@ -382,7 +380,7 @@ impl TryParse for Parser<'_> { return Ok(i32::from_ne_bytes(prop_info.buffer.try_into()?)); } } - return Err(ParserError::InvalidType); + Err(ParserError::InvalidType) } } @@ -405,21 +403,19 @@ impl TryParse
for Parser<'_> { prop_info.buffer.try_into()?, ))); } - } else { - if desc.in_type == InTypeUInt32 - || desc.in_type == InTypePointer - || desc.in_type == InTypeHexInt32 - { - if std::mem::size_of::() != prop_info.buffer.len() { - return Err(ParserError::LengthMismatch); - } - return Ok(Address::Address32(u32::from_ne_bytes( - prop_info.buffer.try_into()?, - ))); + } else if desc.in_type == InTypeUInt32 + || desc.in_type == InTypePointer + || desc.in_type == InTypeHexInt32 + { + if std::mem::size_of::() != prop_info.buffer.len() { + return Err(ParserError::LengthMismatch); } + return Ok(Address::Address32(u32::from_ne_bytes( + prop_info.buffer.try_into()?, + ))); } } - return Err(ParserError::InvalidType); + Err(ParserError::InvalidType) } } @@ -458,7 +454,7 @@ impl TryParse for Parser<'_> { return Ok(f32::from_ne_bytes(prop_info.buffer.try_into()?)); } } - return Err(ParserError::InvalidType); + Err(ParserError::InvalidType) } } diff --git a/samply/src/windows/etw_reader/property.rs b/etw-reader/src/property.rs similarity index 94% rename from samply/src/windows/etw_reader/property.rs rename to etw-reader/src/property.rs index 997f1142..22b6dca9 100644 --- a/samply/src/windows/etw_reader/property.rs +++ b/etw-reader/src/property.rs @@ -51,8 +51,4 @@ impl PropertyIter { pub fn property(&self, index: usize) -> Option<&Property> { self.properties.get(index) } - - pub fn properties_iter(&self) -> &[Property] { - &self.properties - } } diff --git a/samply/src/windows/etw_reader/schema.rs b/etw-reader/src/schema.rs similarity index 96% rename from samply/src/windows/etw_reader/schema.rs rename to etw-reader/src/schema.rs index ea689a47..c6ed67bd 100644 --- a/samply/src/windows/etw_reader/schema.rs +++ b/etw-reader/src/schema.rs @@ -1,15 +1,13 @@ //! ETW Event Schema locator and handler //! //! This module contains the means needed to locate and interact with the Schema of an ETW event -use std::any::{Any, TypeId}; use std::collections::hash_map::Entry; -use std::sync::Arc; +use std::rc::Rc; use once_cell::unsync::OnceCell; use windows::core::GUID; use windows::Win32::System::Diagnostics::Etw::{self, EVENT_HEADER_FLAG_64_BIT_HEADER}; -use super::custom_schemas::EventInfo; use super::etw_types::{DecodingSource, EventRecord, TraceEventInfoRaw}; use super::property::PropertyIter; use super::tdh_types::Property; @@ -74,7 +72,7 @@ impl SchemaKey { }; for e in extended { if e.ExtType as u32 == Etw::EVENT_HEADER_EXT_TYPE_EVENT_SCHEMA_TL { - let mut provider = locator + let provider = locator .tracelogging_providers .entry(event.EventHeader.ProviderId) .or_insert(TraceLoggingProviderIds::new()); @@ -116,7 +114,7 @@ impl SchemaKey { /// Credits: [KrabsETW::schema_locator](https://github.com/microsoft/krabsetw/blob/master/krabs/krabs/schema_locator.hpp) #[derive(Default)] pub struct SchemaLocator { - schemas: FastHashMap>, + schemas: FastHashMap>, tracelogging_providers: FastHashMap, } @@ -136,10 +134,10 @@ pub trait EventSchema { fn property(&self, index: u32) -> Property; fn event_message(&self) -> Option { - return None; + None } fn is_event_metadata(&self) -> bool { - return false; + false } } @@ -165,7 +163,7 @@ impl SchemaLocator { version: schema.event_version(), level: schema.level(), }; - self.schemas.insert(key, Arc::new(Schema::new(schema))); + self.schemas.insert(key, Rc::new(Schema::new(schema))); } /// Use the `event_schema` function to retrieve the Schema of an ETW Event @@ -187,14 +185,14 @@ impl SchemaLocator { /// }; /// ``` pub fn event_schema<'a>(&mut self, event: &'a EventRecord) -> SchemaResult> { - let key = SchemaKey::new(&event, self); + let key = SchemaKey::new(event, self); let info = match self.schemas.entry(key) { Entry::Occupied(entry) => entry.into_mut(), Entry::Vacant(entry) => { - let info = Box::new(tdh::schema_from_tdh(event.clone())?); + let info = Box::new(tdh::schema_from_tdh(event)?); // dbg!(info.provider_guid(), info.provider_name(), info.decoding_source()); // TODO: Cloning for now, should be a reference at some point... - entry.insert(Arc::new(Schema::new(info))) + entry.insert(Rc::new(Schema::new(info))) } } .clone(); @@ -247,11 +245,11 @@ impl Schema { pub struct TypedEvent<'a> { record: &'a EventRecord, - pub(crate) schema: Arc, + pub(crate) schema: Rc, } impl<'a> TypedEvent<'a> { - pub fn new(record: &'a EventRecord, schema: Arc) -> Self { + pub fn new(record: &'a EventRecord, schema: Rc) -> Self { TypedEvent { record, schema } } diff --git a/samply/src/windows/etw_reader/sddl.rs b/etw-reader/src/sddl.rs similarity index 95% rename from samply/src/windows/etw_reader/sddl.rs rename to etw-reader/src/sddl.rs index cd2a7a2a..ab9097bd 100644 --- a/samply/src/windows/etw_reader/sddl.rs +++ b/etw-reader/src/sddl.rs @@ -33,11 +33,11 @@ pub(crate) type SddlResult = Result; pub fn convert_sid_to_string(sid: *const u8) -> SddlResult { let mut tmp = PSTR::null(); unsafe { - if !Security::Authorization::ConvertSidToStringSidA( + if Security::Authorization::ConvertSidToStringSidA( PSID(sid as *const _ as *mut _), &mut tmp, ) - .is_ok() + .is_err() { return Err(SddlNativeError::IoError(std::io::Error::last_os_error())); } diff --git a/samply/src/windows/etw_reader/tdh.rs b/etw-reader/src/tdh.rs similarity index 91% rename from samply/src/windows/etw_reader/tdh.rs rename to etw-reader/src/tdh.rs index f2f6af7b..44ebe379 100644 --- a/samply/src/windows/etw_reader/tdh.rs +++ b/etw-reader/src/tdh.rs @@ -1,10 +1,6 @@ -use std::ffi::OsString; use std::ops::Deref; -use std::os::windows::ffi::OsStringExt; -use std::ptr; -use windows::core::HRESULT; -use windows::Win32::Foundation::{ERROR_INSUFFICIENT_BUFFER, ERROR_SUCCESS, S_OK}; +use windows::Win32::Foundation::{ERROR_INSUFFICIENT_BUFFER, ERROR_SUCCESS}; use windows::Win32::System::Diagnostics::Etw; use windows::Win32::System::Diagnostics::Etw::{TdhEnumerateProviders, PROVIDER_ENUMERATION_INFO}; @@ -52,10 +48,12 @@ pub fn schema_from_tdh(event: &Etw::EVENT_RECORD) -> TdhNativeResult TdhNativeResult { let mut property_size = 0; - let mut desc = Etw::PROPERTY_DATA_DESCRIPTOR::default(); - desc.ArrayIndex = u32::MAX; - let utf16_name = name.as_utf16(); - desc.PropertyName = utf16_name.as_ptr() as u64; + let utf16_name = name.to_utf16(); + let desc = Etw::PROPERTY_DATA_DESCRIPTOR { + ArrayIndex: u32::MAX, + PropertyName: utf16_name.as_ptr() as u64, + ..Default::default() + }; unsafe { let status = Etw::TdhGetPropertySize(event.deref(), None, &[desc], &mut property_size); @@ -105,11 +103,10 @@ pub fn list_etw_providers() { len += 1; } let provider_name = unsafe { - OsString::from_wide(std::slice::from_raw_parts( + String::from_utf16(std::slice::from_raw_parts( provider_name_ptr as *const u16, len, )) - .into_string() .unwrap_or_else(|_| "Error converting to string".to_string()) }; diff --git a/samply/src/windows/etw_reader/tdh_types.rs b/etw-reader/src/tdh_types.rs similarity index 98% rename from samply/src/windows/etw_reader/tdh_types.rs rename to etw-reader/src/tdh_types.rs index aa78063f..45e84165 100644 --- a/samply/src/windows/etw_reader/tdh_types.rs +++ b/etw-reader/src/tdh_types.rs @@ -156,8 +156,9 @@ pub enum TdhInType { /// Represent a TDH_OUT_TYPE #[repr(u16)] -#[derive(Debug, Clone, Copy, FromPrimitive, ToPrimitive, PartialEq)] +#[derive(Debug, Clone, Copy, FromPrimitive, ToPrimitive, PartialEq, Default)] pub enum TdhOutType { + #[default] OutTypeNull, OutTypeString, OutTypeDateTime, @@ -193,12 +194,6 @@ pub enum TdhOutType { OutTypeDatetimeUtc = 38, } -impl Default for TdhOutType { - fn default() -> TdhOutType { - TdhOutType::OutTypeNull - } -} - bitflags! { /// Represents the Property flags /// diff --git a/samply/src/windows/etw_reader/traits.rs b/etw-reader/src/traits.rs similarity index 64% rename from samply/src/windows/etw_reader/traits.rs rename to etw-reader/src/traits.rs index 9a240d6f..946ba9ab 100644 --- a/samply/src/windows/etw_reader/traits.rs +++ b/etw-reader/src/traits.rs @@ -1,11 +1,11 @@ use std::iter; pub trait EncodeUtf16 { - fn as_utf16(self: Self) -> Vec; + fn to_utf16(self) -> Vec; } impl EncodeUtf16 for &str { - fn as_utf16(self: Self) -> Vec { + fn to_utf16(self) -> Vec { self.encode_utf16() // Make a UTF-16 iterator .chain(iter::once(0)) // Append a null .collect() // Collect the iterator into a vector @@ -13,7 +13,7 @@ impl EncodeUtf16 for &str { } impl EncodeUtf16 for String { - fn as_utf16(self: Self) -> Vec { - self.as_str().as_utf16() + fn to_utf16(self) -> Vec { + self.as_str().to_utf16() } } diff --git a/samply/src/windows/etw_reader/utils.rs b/etw-reader/src/utils.rs similarity index 81% rename from samply/src/windows/etw_reader/utils.rs rename to etw-reader/src/utils.rs index 8d96e8a9..be5c3164 100644 --- a/samply/src/windows/etw_reader/utils.rs +++ b/etw-reader/src/utils.rs @@ -17,7 +17,7 @@ pub fn parse_unk_size_null_utf16_string(v: &[u8]) -> String { } // safe because we not going past the end of the slice - let end: *const u16 = unsafe { v.as_ptr().offset(v.len() as isize) }.cast(); + let end: *const u16 = unsafe { v.as_ptr().add(v.len()) }.cast(); // find the null termination let mut len = 0; @@ -34,9 +34,7 @@ pub fn parse_unk_size_null_utf16_string(v: &[u8]) -> String { pub fn parse_unk_size_null_unicode_size(v: &[u8]) -> usize { // TODO: Make sure is aligned v.chunks_exact(2) - .into_iter() - .take_while(|&a| a != &[0, 0]) // Take until null terminator - .map(|a| u16::from_ne_bytes([a[0], a[1]])) + .take_while(|&a| a != [0, 0]) // Take until null terminator .count() * 2 + 2 @@ -45,30 +43,28 @@ pub fn parse_unk_size_null_unicode_size(v: &[u8]) -> usize { pub fn parse_unk_size_null_unicode_vec(v: &[u8]) -> Vec { // TODO: Make sure is aligned v.chunks_exact(2) - .into_iter() - .take_while(|&a| a != &[0, 0]) // Take until null terminator + .take_while(|&a| a != [0, 0]) // Take until null terminator .map(|a| u16::from_ne_bytes([a[0], a[1]])) .collect::>() } pub fn parse_unk_size_null_ansi_size(v: &[u8]) -> usize { - v.into_iter() + v.iter() .take_while(|&&a| a != 0) // Take until null terminator .count() + 1 } pub fn parse_unk_size_null_ansi_vec(v: &[u8]) -> Vec { - v.into_iter() - .take_while(|&&a| a != 0) // Take until null terminator - .map(|&a| a) + v.iter() + .take_while(|&&a| a != 0) + .copied() // Take until null terminator .collect::>() } pub fn parse_null_utf16_string(v: &[u8]) -> String { String::from_utf16_lossy( v.chunks_exact(2) - .into_iter() .map(|a| u16::from_ne_bytes([a[0], a[1]])) .collect::>() .as_slice(), @@ -80,7 +76,6 @@ pub fn parse_null_utf16_string(v: &[u8]) -> String { pub fn parse_utf16_guid(v: &[u8]) -> String { String::from_utf16_lossy( v.chunks_exact(2) - .into_iter() .map(|a| u16::from_ne_bytes([a[0], a[1]])) .collect::>() .as_slice(), diff --git a/samply/Cargo.toml b/samply/Cargo.toml index fc7ee460..b8bd0429 100644 --- a/samply/Cargo.toml +++ b/samply/Cargo.toml @@ -76,6 +76,8 @@ num-traits = "0.2" num-derive = "0.4" runas = "1.2.0" which = "6.0.1" +etw-reader = { path = "../etw-reader" } +# linux-perf-data = "0.10.1" [target.'cfg(windows)'.dependencies.windows] version = "0.56" diff --git a/samply/src/windows/etw_gecko.rs b/samply/src/windows/etw_gecko.rs index a3734e61..d072f938 100644 --- a/samply/src/windows/etw_gecko.rs +++ b/samply/src/windows/etw_gecko.rs @@ -7,6 +7,11 @@ use std::time::Instant; use bitflags::bitflags; use debugid::DebugId; +use etw_reader::parser::{Address, Parser, TryParse}; +use etw_reader::schema::SchemaLocator; +use etw_reader::{ + add_custom_schemas, event_properties_to_string, open_trace, print_property, GUID, +}; use fxprof_processed_profile::{ debugid, CategoryColor, CategoryHandle, CategoryPairHandle, CpuDelta, LibraryInfo, MarkerDynamicField, MarkerFieldFormat, MarkerLocation, MarkerSchema, MarkerSchemaField, @@ -15,11 +20,6 @@ use fxprof_processed_profile::{ use serde_json::{json, Value}; use uuid::Uuid; -use super::etw_reader::parser::{Address, Parser, TryParse}; -use super::etw_reader::schema::SchemaLocator; -use super::etw_reader::{ - add_custom_schemas, event_properties_to_string, open_trace, print_property, GUID, -}; use super::profile_context::ProfileContext; use crate::shared::context_switch::{ContextSwitchHandler, OffCpuSampleGroup}; use crate::shared::jit_category_manager::JitCategoryManager; @@ -31,7 +31,7 @@ use crate::shared::process_sample_data::{ }; use crate::shared::timestamp_converter::TimestampConverter; use crate::shared::types::{StackFrame, StackMode}; -use crate::windows::profile_context::{PendingStack, ProcessJitInfo}; +use crate::windows::profile_context::{PendingMarker, PendingStack, ProcessJitInfo}; pub fn profile_pid_from_etl_file(context: &mut ProfileContext, etl_file: &Path) { let profile_start_instant = Timestamp::from_nanos_since_reference(0); @@ -570,8 +570,38 @@ pub fn profile_pid_from_etl_file(context: &mut ProfileContext, etl_file: &Path) //dbg!(s.process_id(), jscript_symbols.keys()); } + "Microsoft-Windows-Direct3D11/ID3D11VideoContext_SubmitDecoderBuffers/win:Start" => { + let mut parser = Parser::create(&s); + let thread_id = s.thread_id(); + let Some(mut thread) = context.get_thread_mut(thread_id) else { return }; + let text = event_properties_to_string(&s, &mut parser, None); + thread.pending_markers.insert(s.name().to_owned(), PendingMarker { text, start: timestamp }); + } + "Microsoft-Windows-Direct3D11/ID3D11VideoContext_SubmitDecoderBuffers/win:Stop" => { + let mut parser = Parser::create(&s); + let thread_id = s.thread_id(); + let Some(mut thread) = context.get_thread_mut(thread_id) else { return }; + + let mut text = event_properties_to_string(&s, &mut parser, None); + let timing = if let Some(pending) = thread.pending_markers.remove("Microsoft-Windows-Direct3D11/ID3D11VideoContext_SubmitDecoderBuffers/win:Start") { + text = pending.text; + MarkerTiming::Interval(pending.start, timestamp) + } else { + MarkerTiming::IntervalEnd(timestamp) + }; + + let category = match categories.entry(s.provider_name()) { + Entry::Occupied(e) => *e.get(), + Entry::Vacant(e) => { + let category = context.profile.borrow_mut().add_category(e.key(), CategoryColor::Transparent); + *e.insert(category) + } + }; + + context.profile.borrow_mut().add_marker(thread.handle, category, s.name().split_once('/').unwrap().1, SimpleMarker(text), timing); + } marker_name if marker_name.starts_with("Mozilla.FirefoxTraceLogger/") => { - let Some(marker_name) = marker_name.strip_prefix("Mozilla.FirefoxTraceLogger/").and_then(|s| s.strip_suffix('/')) else { return }; + let Some(marker_name) = marker_name.strip_prefix("Mozilla.FirefoxTraceLogger/").and_then(|s| s.strip_suffix("/Info")) else { return }; let thread_id = e.EventHeader.ThreadId; let Some(thread) = context.get_thread(thread_id) else { return }; @@ -622,7 +652,7 @@ pub fn profile_pid_from_etl_file(context: &mut ProfileContext, etl_file: &Path) } } marker_name if marker_name.starts_with("Google.Chrome/") => { - let Some(marker_name) = marker_name.strip_prefix("Google.Chrome/").and_then(|s| s.strip_suffix('/')) else { return }; + let Some(marker_name) = marker_name.strip_prefix("Google.Chrome/").and_then(|s| s.strip_suffix("/Info")) else { return }; // a bitfield of keywords bitflags! { #[derive(PartialEq, Eq)] diff --git a/samply/src/windows/mod.rs b/samply/src/windows/mod.rs index 47396a69..b0bcfd76 100644 --- a/samply/src/windows/mod.rs +++ b/samply/src/windows/mod.rs @@ -1,5 +1,4 @@ mod etw_gecko; -mod etw_reader; pub mod import; mod profile_context; pub mod profiler; diff --git a/samply/src/windows/profile_context.rs b/samply/src/windows/profile_context.rs index 7d1254af..0bca43d7 100644 --- a/samply/src/windows/profile_context.rs +++ b/samply/src/windows/profile_context.rs @@ -44,6 +44,12 @@ pub struct ProcessJitInfo { pub symbols: Vec, } +#[derive(Debug)] +pub struct PendingMarker { + pub text: String, + pub start: Timestamp, +} + #[derive(Debug)] pub struct ThreadState { // When merging threads `handle` is the global thread handle and we use `merge_name` to store the name @@ -54,6 +60,7 @@ pub struct ThreadState { pub memory_usage: Option, pub thread_id: u32, pub process_id: u32, + pub pending_markers: HashMap, } impl ThreadState { @@ -63,6 +70,7 @@ impl ThreadState { merge_name: None, pending_stacks: VecDeque::new(), context_switch_data: Default::default(), + pending_markers: HashMap::new(), memory_usage: None, thread_id: tid, process_id: pid,