diff --git a/etw-reader/Cargo.toml b/etw-reader/Cargo.toml new file mode 100644 index 00000000..6635ca1a --- /dev/null +++ b/etw-reader/Cargo.toml @@ -0,0 +1,30 @@ +[package] +name = "etw-reader" +version = "0.1.0" +edition = "2021" +license = "MIT" +repository = "https://github.com/jrmuizel/etw-profiler" +documentation = "https://docs.rs/etw-reader" +description = "library for reading ETW etl files" +category = "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.3" +once_cell = "1.8.0" +fxhash = "0.2.1" +memoffset = "0.6" + + +[dependencies.windows] +version = "0.51" +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..b5ac0390 --- /dev/null +++ b/etw-reader/examples/dump.rs @@ -0,0 +1,221 @@ +use etw_reader::{ + open_trace, + parser::{Parser, TryParse}, + print_property, + schema::SchemaLocator, + GUID, +}; +use std::{collections::HashMap, path::Path}; +use windows::Win32::System::{ + Diagnostics::Etw::{ + self, EtwProviderTraitDecodeGuid, EtwProviderTraitTypeGroup, ETW_PROVIDER_TRAIT_TYPE, + }, + SystemInformation::PRODUCT_CORE_COUNTRYSPECIFIC, +}; + +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 mut metadata_end = metadata_start; + 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 + ); + } + } + }); +} diff --git a/etw-reader/examples/event-types.rs b/etw-reader/examples/event-types.rs new file mode 100644 index 00000000..81b7e736 --- /dev/null +++ b/etw-reader/examples/event-types.rs @@ -0,0 +1,76 @@ +use etw_reader::{open_trace, schema::SchemaLocator, GUID}; +use std::{cmp::Reverse, collections::HashMap, path::Path}; + +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; + } + }); + 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..b4867b0e --- /dev/null +++ b/etw-reader/examples/list-processes.rs @@ -0,0 +1,29 @@ +use etw_reader::{ + open_trace, + parser::{Parser, TryParse}, + schema::SchemaLocator, +}; +use std::path::Path; + +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); + } + } + }); +} 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..57d49da3 --- /dev/null +++ b/etw-reader/examples/list-threads.rs @@ -0,0 +1,86 @@ +use etw_reader::{ + open_trace, + parser::{Parser, TryParse}, + schema::SchemaLocator, +}; +use std::{collections::HashMap, path::Path}; + +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..ba63a54c --- /dev/null +++ b/etw-reader/examples/log-js-stacks.rs @@ -0,0 +1,225 @@ +use etw_reader::{ + open_trace, + parser::{Address, Parser, TryParse}, + print_property, + schema::SchemaLocator, +}; +use std::collections::Bound::{Included, Unbounded}; +use std::{ + cell::Cell, + collections::{hash_map::Entry, BTreeMap, HashMap}, + convert::TryInto, + path::Path, +}; +use windows::Win32::System::Diagnostics::Etw; + +/// 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 mut 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); + 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 mut 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 = sym.1 .1.clone(); + child_addr = *sym.0; + return; + } + } + } + //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_insert(BTreeMap::new()); + //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.len() > 0 { + 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..69ecc1f5 --- /dev/null +++ b/etw-reader/examples/log-stacks.rs @@ -0,0 +1,242 @@ +use etw_reader::{ + open_trace, + parser::{Parser, TryParse}, + print_property, + schema::SchemaLocator, +}; +use std::{ + cell::Cell, + collections::{hash_map::Entry, HashMap}, + convert::TryInto, + path::Path, +}; +use windows::Win32::System::Diagnostics::Etw; + +fn is_kernel_address(ip: u64, pointer_size: u32) -> bool { + if pointer_size == 4 { + return ip >= 0x80000000; + } + return 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 mut 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.len() > 0 { + 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..e95bb94a --- /dev/null +++ b/etw-reader/examples/record.rs @@ -0,0 +1,42 @@ +use etw_reader::{parser::Parser, print_property, schema::SchemaLocator, 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..3951716b 100644 --- a/samply/src/windows/etw_reader/etw_types.rs +++ b/etw-reader/src/etw_types.rs @@ -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 95% rename from samply/src/windows/etw_reader/mod.rs rename to etw-reader/src/lib.rs index cd397992..0517fdb6 100644 --- a/samply/src/windows/etw_reader/mod.rs +++ b/etw-reader/src/lib.rs @@ -1,29 +1,39 @@ -#![allow(warnings)] +extern crate num_traits; -use std::borrow::Cow; -use std::collections::HashMap; -use std::hash::BuildHasherDefault; -use std::mem; -use std::path::Path; +#[macro_use] +extern crate bitflags; + +#[macro_use] +extern crate num_derive; + +use crate::{ + parser::{Parser, ParserError, TryParse}, + schema::SchemaLocator, + tdh_types::{PrimitiveDesc, PropertyDesc, TdhInType}, + traits::EncodeUtf16, +}; +use windows::{ + core::{h, Error, HRESULT, HSTRING, PWSTR}, + Win32::{ + Foundation::{ + GetLastError, ERROR_INSUFFICIENT_BUFFER, ERROR_MORE_DATA, ERROR_SUCCESS, MAX_PATH, + }, + System::Diagnostics::Etw::{ + EnumerateTraceGuids, EnumerateTraceGuidsEx, TraceGuidQueryInfo, TraceGuidQueryList, + CONTROLTRACE_HANDLE, EVENT_TRACE_FLAG, TRACE_GUID_INFO, TRACE_GUID_PROPERTIES, + TRACE_PROVIDER_INSTANCE_INFO, + }, + }, +}; + +#[macro_use] +extern crate memoffset; -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 std::{borrow::Cow, collections::HashMap, hash::BuildHasherDefault, mem, path::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; @@ -93,9 +103,7 @@ pub fn open_trace( let session_handle = unsafe { Etw::OpenTraceW(&mut *log_file) }; let result = unsafe { Etw::ProcessTrace(&[session_handle], None, None) }; - result - .ok() - .map_err(|e| std::io::Error::from_raw_os_error(e.code().0)) + result.map_err(|e| std::io::Error::from_raw_os_error(e.code().0)) } /// Complete Trace Properties struct @@ -508,7 +516,7 @@ pub fn enumerate_trace_guids() { } let result = unsafe { EnumerateTraceGuids(&mut ptrs.as_mut_slice(), &mut count) }; - match result.ok() { + match result { Ok(()) => { for guid in guids[..count as usize].iter() { println!("{:?}", guid.Guid); @@ -544,7 +552,7 @@ pub fn enumerate_trace_guids_ex(print_instances: bool) { &mut required_size as *mut _, ) }; - match result.ok() { + match result { Ok(()) => { for guid in guids.iter() { println!("{:?}", guid); @@ -601,7 +609,7 @@ pub fn get_provider_info(guid: &GUID) -> Vec { &mut required_size as *mut _, ) }; - match result.ok() { + match result { Ok(()) => { return info; } diff --git a/samply/src/windows/etw_reader/parser.rs b/etw-reader/src/parser.rs similarity index 100% rename from samply/src/windows/etw_reader/parser.rs rename to etw-reader/src/parser.rs diff --git a/samply/src/windows/etw_reader/property.rs b/etw-reader/src/property.rs similarity index 100% rename from samply/src/windows/etw_reader/property.rs rename to etw-reader/src/property.rs diff --git a/samply/src/windows/etw_reader/schema.rs b/etw-reader/src/schema.rs similarity index 100% rename from samply/src/windows/etw_reader/schema.rs rename to etw-reader/src/schema.rs diff --git a/samply/src/windows/etw_reader/sddl.rs b/etw-reader/src/sddl.rs similarity index 100% rename from samply/src/windows/etw_reader/sddl.rs rename to etw-reader/src/sddl.rs diff --git a/samply/src/windows/etw_reader/tdh.rs b/etw-reader/src/tdh.rs similarity index 100% rename from samply/src/windows/etw_reader/tdh.rs rename to etw-reader/src/tdh.rs diff --git a/samply/src/windows/etw_reader/tdh_types.rs b/etw-reader/src/tdh_types.rs similarity index 100% rename from samply/src/windows/etw_reader/tdh_types.rs rename to etw-reader/src/tdh_types.rs diff --git a/samply/src/windows/etw_reader/traits.rs b/etw-reader/src/traits.rs similarity index 100% rename from samply/src/windows/etw_reader/traits.rs rename to etw-reader/src/traits.rs diff --git a/samply/src/windows/etw_reader/utils.rs b/etw-reader/src/utils.rs similarity index 100% rename from samply/src/windows/etw_reader/utils.rs rename to etw-reader/src/utils.rs 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..3a308b33 100644 --- a/samply/src/windows/etw_gecko.rs +++ b/samply/src/windows/etw_gecko.rs @@ -15,9 +15,9 @@ 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::{ +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 super::profile_context::ProfileContext; @@ -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::{PendingStack, PendingMarker, 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..493da6b1 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,