From f072c0ce533782f44729e6de279815f6fda8f553 Mon Sep 17 00:00:00 2001 From: David Venhoff Date: Thu, 4 Sep 2025 18:11:20 +0200 Subject: [PATCH] Use correct conversion for time values Two errors I made: * cycle durations are not constant, their value relies on the cbr * tsc frequency was not exactly 2.7Ghz, now calculated at runtime --- Cargo.lock | 10 +++++++ client/src/main.rs | 1 + pt-dump-decoder/Cargo.toml | 1 + pt-dump-decoder/src/lib.rs | 56 ++++++++++++++++++++++++-------------- 4 files changed, 47 insertions(+), 21 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index aa9ab02..85b1fc2 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -639,6 +639,7 @@ version = "0.1.0" dependencies = [ "libipt", "memmap2", + "raw-cpuid", ] [[package]] @@ -711,6 +712,15 @@ dependencies = [ "rand_core", ] +[[package]] +name = "raw-cpuid" +version = "11.5.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "c6df7ab838ed27997ba19a4664507e6f82b41fe6e20be42929332156e5e85146" +dependencies = [ + "bitflags 2.9.1", +] + [[package]] name = "regex" version = "1.11.1" diff --git a/client/src/main.rs b/client/src/main.rs index ba56b35..1696a16 100644 --- a/client/src/main.rs +++ b/client/src/main.rs @@ -10,6 +10,7 @@ fn main() { let start = std::time::Instant::now(); ptwrite(42); loop { + // ptwrite(69); if start.elapsed().as_secs() >= 2 { break; } diff --git a/pt-dump-decoder/Cargo.toml b/pt-dump-decoder/Cargo.toml index 738990f..9443a4a 100644 --- a/pt-dump-decoder/Cargo.toml +++ b/pt-dump-decoder/Cargo.toml @@ -9,3 +9,4 @@ edition = "2024" [dependencies] libipt = { version = "0.4.0", features = ["libipt_master"] } memmap2 = "0.9.7" +raw-cpuid = "11.5.0" diff --git a/pt-dump-decoder/src/lib.rs b/pt-dump-decoder/src/lib.rs index 09f8000..6d2c493 100644 --- a/pt-dump-decoder/src/lib.rs +++ b/pt-dump-decoder/src/lib.rs @@ -1,15 +1,16 @@ use libipt::enc_dec_builder::EncoderDecoderBuilder; use libipt::packet::{Packet, PacketDecoder}; use memmap2::Mmap; +use std::collections::HashMap; use std::error::Error; use std::fs::File; use std::path::Path; use std::time::Duration; +use raw_cpuid::CpuId; #[derive(Debug)] pub struct AnalyzeData { pub packets: u64, - pub cycles: u64, pub time_tsc: Duration, pub time_cyc: Duration, pub time_main: Duration, @@ -34,17 +35,30 @@ pub fn analyze_dump(path: impl AsRef) -> Result; let mut last_tsc = 0; + let mut seen_cbrs = HashMap::::new(); + for packet in decoder { total += 1; match packet { Ok(Packet::Cyc(cyc)) => { - segments.last_mut().unwrap().1 += cyc.value(); + // Ignore cycle packets when there was no cbr packet yet. + if current_cbr == 0 { + println!("Ignoring {} cycles, because cbr is still unknown!", cyc.value()); + continue; + } + let f_core = f_bus * current_cbr as f64; + let duration = Duration::from_secs_f64(cyc.value() as f64 / f_core); + segments.last_mut().unwrap().1 += duration; } Ok(Packet::Tsc(tsc)) => { if first_tsc.is_none() { @@ -52,15 +66,19 @@ pub fn analyze_dump(path: impl AsRef) -> Result { + current_cbr = cbr.ratio(); + *seen_cbrs.entry(cbr.ratio()).or_default() += 1; + } Ok(Packet::Ptw(ptwrite)) => { if ptwrite.payload() == 42 { // Main enter - segments.push((Scope::Main, 0)); + segments.push((Scope::Main, Duration::ZERO)); } else if ptwrite.payload() == 43 { // Main exit - segments.push((Scope::PostRun, 0)); + segments.push((Scope::PostRun, Duration::ZERO)); } else { - println!("GOT PTWRITE!!!!!: {ptwrite:?}"); + // println!("GOT PTWRITE!!!!!: {ptwrite:?}"); } } Ok(Packet::Ovf(overflow)) => { @@ -70,29 +88,25 @@ pub fn analyze_dump(path: impl AsRef) -> Result println!("Got error: {error:?}"), } } - // dbg!(&segments); - let cycles_total = segments.iter().map(|(_, cycles)| cycles).sum(); - let total_seconds = cycles_total as f64 / 2_700_000_000.0; - - let total_seconds_tsc = (last_tsc - first_tsc.unwrap()) as f64 / 2_700_000_000.0; - + dbg!(seen_cbrs); + let duration_total = segments.iter().map(|(_, duration)| *duration).sum(); let main_duration = duration_in_mode(&segments, Scope::Main); + let f_tsc = CpuId::new().get_tsc_info().unwrap().tsc_frequency().unwrap(); + let total_seconds_tsc = (last_tsc - first_tsc.unwrap()) as f64 / f_tsc as f64; + Ok(AnalyzeData { packets: total, - cycles: cycles_total, - time_cyc: Duration::from_secs_f64(total_seconds), + time_cyc: duration_total, time_main: main_duration, - time_tsc: Duration::from_secs_f64(total_seconds_tsc) + time_tsc: Duration::from_secs_f64(total_seconds_tsc), }) } -fn duration_in_mode(segments: &[(Scope, u64)], scope: Scope) -> Duration { - let total_cycles = segments +fn duration_in_mode(segments: &[(Scope, Duration)], scope: Scope) -> Duration { + segments .into_iter() .filter(|(it, _)| *it == scope) - .map(|(_, cycles)| *cycles) - .sum::(); - let total_seconds = total_cycles as f64 / 2_700_000_000.0; - Duration::from_secs_f64(total_seconds) + .map(|(_, duration)| *duration) + .sum::() }