1use std::{
2 alloc::Layout,
3 collections::{BTreeMap, HashMap},
4 time::Duration,
5};
6
7use ndarray::Array1;
8use ndarray_stats::QuantileExt;
9use twizzler::object::ObjID;
10use twizzler_abi::{
11 syscall::ThreadControl,
12 thread::ExecutionState,
13 trace::{
14 CONTEXT_INVALIDATION, CONTEXT_SHOOTDOWN, ContextFaultEvent, FaultFlags, KERNEL_ALLOC,
15 KernelAllocationEvent, RUNTIME_ALLOC, RuntimeAllocationEvent, SwitchFlags,
16 SyscallExitEvent, THREAD_BLOCK, THREAD_CONTEXT_SWITCH, THREAD_MIGRATE, THREAD_RESUME,
17 THREAD_SAMPLE, THREAD_SYSCALL_EXIT, ThreadCtxSwitch, ThreadSamplingEvent, TraceKind,
18 },
19};
20
21use crate::tracer::TracingState;
22
23struct PfEvent {
24 data: ContextFaultEvent,
25}
26
27pub fn stat(state: TracingState) {
28 println!(
29 "statistics for {}, executed over {} seconds",
30 state.name,
31 (state.end_time - state.start_time).as_secs_f32()
32 );
33 let data = state.data();
34
35 let mut pfs = Vec::new();
36 for entry in data.filter(|p| p.0.kind == TraceKind::Context) {
37 if let Some(data) = entry
38 .1
39 .and_then(|data| data.try_cast::<ContextFaultEvent>(entry.0.event))
40 {
41 let pfe = PfEvent { data: data.data };
42 pfs.push(pfe);
43 }
44 }
45
46 if pfs.len() > 0 {
47 let durations = pfs
48 .iter()
49 .map(|p| p.data.processing_time.as_nanos() as f64)
50 .collect::<ndarray::Array1<_>>();
51
52 let mean = durations.mean().unwrap();
53 let _max = durations.max().unwrap();
54 let _min = durations.min().unwrap();
55 let stddev = durations.std(1.);
56 let total = durations.sum() / 1_000_000_000.;
57
58 println!(
59 "{} pages faults, costing {}s, mean = {:5.5}us, stddev = {:5.5}us",
60 pfs.len(),
61 total,
62 mean / 1000.,
63 stddev / 1000.
64 );
65
66 let num_pager = pfs
67 .iter()
68 .filter(|p| p.data.flags.contains(FaultFlags::PAGER))
69 .count();
70 let num_large = pfs
71 .iter()
72 .filter(|p| p.data.flags.contains(FaultFlags::LARGE))
73 .count();
74 println!("{} used large pages, {} used pager", num_large, num_pager);
75
76 let mut map = HashMap::<_, usize>::new();
77 for pf in pfs {
78 *map.entry(pf.data.obj).or_default() += 1;
79 }
80
81 let mut coll = map.into_iter().collect::<Vec<_>>();
82 coll.sort_by_key(|c| c.1);
83
84 let mut banner = false;
85 for (k, v) in coll.iter().rev() {
86 if !banner {
87 banner = true;
88 println!(" OBJECT COUNT")
89 }
90 println!(" {:0>32x} {:10}", k.raw(), v);
91 }
92 }
93 let tlbs = state
94 .data()
95 .filter(|p| {
96 p.0.kind == TraceKind::Context
97 && p.0.event & (CONTEXT_INVALIDATION | CONTEXT_SHOOTDOWN) != 0
98 })
99 .collect::<Vec<_>>();
100
101 if tlbs.len() > 0 {
102 let invalidations = tlbs
103 .iter()
104 .filter(|t| t.0.event & CONTEXT_INVALIDATION != 0)
105 .count();
106 let shootdowns = tlbs
107 .iter()
108 .filter(|t| t.0.event & CONTEXT_SHOOTDOWN != 0)
109 .count();
110
111 println!(
112 "collected {} TLB events: {} invalidations, {} shootdowns",
113 tlbs.len(),
114 invalidations,
115 shootdowns
116 );
117 }
118
119 let syscalls = state
120 .data()
121 .filter(|p| p.0.kind == TraceKind::Thread && p.0.event & THREAD_SYSCALL_EXIT != 0)
122 .collect::<Vec<_>>();
123
124 if syscalls.len() > 0 {
125 let mut map = BTreeMap::<_, BTreeMap<u64, (Option<String>, Vec<Duration>)>>::new();
126
127 for syscall in &syscalls {
128 if let Some(data) = syscall
129 .1
130 .and_then(|data| data.try_cast::<SyscallExitEvent>(THREAD_SYSCALL_EXIT))
131 {
132 let entry = match data.data.entry.num {
133 twizzler_abi::syscall::Syscall::ThreadCtrl => map
134 .entry(data.data.entry.num)
135 .or_default()
136 .entry(data.data.entry.args[2])
137 .or_insert_with(|| {
138 (
139 ThreadControl::try_from(data.data.entry.args[2])
140 .ok()
141 .map(|x| format!("{:?}", x)),
142 Vec::new(),
143 )
144 }),
145 twizzler_abi::syscall::Syscall::ThreadSync => map
146 .entry(data.data.entry.num)
147 .or_default()
148 .entry(data.data.entry.args[1])
149 .or_insert_with(|| {
150 (Some(format!("len={}", data.data.entry.args[1])), Vec::new())
151 }),
152 twizzler_abi::syscall::Syscall::ObjectCtrl => map
153 .entry(data.data.entry.num)
154 .or_default()
155 .entry(data.data.entry.args[2])
156 .or_insert_with(|| {
157 (
158 match data.data.entry.args[2] {
159 0 => Some("CreateCommit".to_string()),
160 1 => Some("Delete".to_string()),
161 2 => Some("Sync".to_string()),
162 3 => Some("Preload".to_string()),
163 _ => Some("???".to_string()),
164 },
165 Vec::new(),
166 )
167 }),
168 twizzler_abi::syscall::Syscall::MapCtrl => map
169 .entry(data.data.entry.num)
170 .or_default()
171 .entry(data.data.entry.args[2])
172 .or_insert_with(|| {
173 (
174 match data.data.entry.args[2] {
175 0 => Some("Sync".to_string()),
176 1 => Some("Discard".to_string()),
177 2 => Some("Invalidate".to_string()),
178 3 => Some("Update".to_string()),
179 _ => Some("???".to_string()),
180 },
181 Vec::new(),
182 )
183 }),
184 _ => {
185 let entry = map
186 .entry(data.data.entry.num)
187 .or_default()
188 .entry(0)
189 .or_default();
190 entry
191 }
192 };
193 entry.1.push(data.data.duration.into());
194 }
195 }
196
197 println!("collected {} syscalls", syscalls.len(),);
198
199 let mut coll = map.into_iter().collect::<Vec<_>>();
200 coll.sort_by_cached_key(|c| c.1.values().fold(0, |a, v| a + v.1.len()));
201
202 let mut banner = false;
203 for (k, v) in coll.iter().rev() {
204 if !banner {
205 banner = true;
206 println!(
207 " SYSCALL SUBTYPE COUNT MEAN STDDEV TOTAL"
208 )
209 }
210 let sys = format!("{:?}", k);
211
212 let mut coll = v.values().collect::<Vec<_>>();
213 coll.sort_by_key(|c| c.1.len());
214 for v in coll.iter().rev() {
215 let durations = Array1::from_iter(v.1.iter().map(|d| d.as_nanos() as f64));
216 let mut unit = "us";
217 let mut mean = durations.mean().unwrap();
218 let mut stddev = durations.std(1.);
219 let total = durations.sum() / 1_000_000_000.;
220
221 if mean <= 1000. {
222 unit = "ns";
223 mean *= 1000.;
224 stddev *= 1000.;
225 } else if mean >= 1_000_000. {
226 unit = "ms";
227 mean /= 1000.;
228 stddev /= 1000.;
229 }
230
231 if durations.len() > 1 {
232 println!(
233 " {:>20} {:>20} {:7} {:8.2}{} {:8.2}{} {:10.2}ms",
234 sys,
235 match v.0 {
236 Some(ref st) => st.as_str(),
237 None => "",
238 },
239 durations.len(),
240 mean / 1000.,
241 unit,
242 stddev / 1000.,
243 unit,
244 total * 1000.
245 );
246 } else {
247 println!(
248 " {:>20} {:>20} {:7} {:8.2}{} - {:10.2}ms",
249 sys,
250 match v.0 {
251 Some(ref st) => st.as_str(),
252 None => "",
253 },
254 durations.len(),
255 mean / 1000.,
256 unit,
257 total * 1000.
258 );
259 }
260 }
261 }
262 }
263
264 #[derive(Debug, Clone, Default)]
265 struct PerThreadData {
266 migrations: usize,
267 switches: usize,
268 switches_to_collector: usize,
269 switches_to_ktrace_kthread: usize,
270 cpu_map: HashMap<u64, usize>,
271 }
272 let mut threads = HashMap::<ObjID, PerThreadData>::new();
273
274 let thread_events = state.data().filter(|p| {
275 p.0.kind == TraceKind::Thread
276 && (p.0.event & (THREAD_CONTEXT_SWITCH | THREAD_BLOCK | THREAD_RESUME | THREAD_MIGRATE))
277 != 0
278 });
279
280 for event in thread_events {
281 let entry = threads.entry(event.0.thread).or_default();
282 if event.0.event & THREAD_MIGRATE != 0 {
283 entry.migrations += 1;
284 }
285 if event.0.event & THREAD_CONTEXT_SWITCH != 0 {
286 entry.switches += 1;
287 *entry.cpu_map.entry(event.0.cpuid).or_default() += 1;
288 if let Some(data) = event
289 .1
290 .and_then(|d| d.try_cast::<ThreadCtxSwitch>(THREAD_CONTEXT_SWITCH))
291 .map(|d| d.data)
292 {
293 if data.to.is_some_and(|target| target == state.collector_id) {
294 entry.switches_to_collector += 1;
295 }
296 if data.flags.contains(SwitchFlags::IS_TRACE) {
297 entry.switches_to_ktrace_kthread += 1;
298 }
299 }
300 }
301 }
302
303 if !threads.is_empty() {
304 println!(" THREAD ID MIGRATIONS CONTEXT SWITCHES");
305 println!(" ON CPUs");
306 for thread in &threads {
307 println!(
308 " {:0>32x} {:7} {:7} ({:7} to tracing system)",
309 thread.0.raw(),
310 thread.1.migrations,
311 thread.1.switches,
312 thread.1.switches_to_collector + thread.1.switches_to_ktrace_kthread,
313 );
314
315 let mut cpumap = thread.1.cpu_map.iter().collect::<Vec<_>>();
316 cpumap.sort_by_key(|x| *x.0);
317 print!(" [",);
318 for (i, cpu) in cpumap.iter().enumerate() {
319 if i != 0 {
320 print!(", ")
321 }
322 print!("{}:{}", cpu.0, cpu.1);
323 }
324 println!("]");
325 }
326 }
327
328 let samples = state
329 .data()
330 .filter_map(|p| {
331 if p.0.kind == TraceKind::Thread && p.0.event & THREAD_SAMPLE != 0 {
332 Some((
333 p.0,
334 p.1.and_then(|d| d.try_cast::<ThreadSamplingEvent>(THREAD_SAMPLE))
335 .map(|d| d.data)?,
336 ))
337 } else {
338 None
339 }
340 })
341 .collect::<Vec<_>>();
342
343 if samples.len() > 0 {
344 println!("collected {} samples", samples.len());
345
346 let mut map = HashMap::<_, usize>::new();
347 let mut thread_map = HashMap::<_, usize>::new();
348 for (head, sample) in samples {
349 if sample.state == ExecutionState::Running {
350 *map.entry(sample.ip).or_default() += 1usize;
351 *thread_map.entry(head.thread).or_default() += 1usize;
352 }
353 }
354 let mut coll = thread_map.into_iter().collect::<Vec<_>>();
355 coll.sort_by_key(|x| x.1);
356
357 let mut banner = false;
358 for (thread, count) in coll.iter().rev() {
359 if *count > 1 {
360 if !banner {
361 banner = true;
362 println!(" THREAD ID COUNT");
363 }
364 println!(" {:0>32x} {:7}", thread.raw(), count);
365 }
366 }
367
368 let mut coll = map.into_iter().collect::<Vec<_>>();
369 coll.sort_by_key(|x| x.1);
370
371 let mut banner = false;
372 for (ip, count) in coll.iter().rev() {
373 if *count > 1 {
374 if !banner {
375 banner = true;
376 println!("PROGRAM COUNTER ADDRESS COUNT")
377 }
378 println!(" {:0>18x} {:7}", ip, count);
379 }
380 }
381 }
382
383 let rt_events = state.data().filter(|e| e.0.kind == TraceKind::Runtime);
384
385 let mut rtalloc_map = HashMap::<Layout, Vec<Duration>>::new();
386 let mut rtfree_map = HashMap::<Layout, Vec<Duration>>::new();
387 for rte in rt_events {
388 if rte.0.event & RUNTIME_ALLOC != 0 {
389 if let Some(data) = rte
390 .1
391 .and_then(|d| d.try_cast::<RuntimeAllocationEvent>(RUNTIME_ALLOC))
392 .map(|d| d.data)
393 {
394 let entry = if data.is_free {
395 rtfree_map.entry(data.layout).or_default()
396 } else {
397 rtalloc_map.entry(data.layout).or_default()
398 };
399 entry.push(data.duration.into());
400 }
401 }
402 }
403
404 let mut coll = rtalloc_map.into_iter().collect::<Vec<_>>();
405 coll.sort_by_key(|x| x.1.len());
406
407 let mut banner = false;
408 for rtalloc in coll.iter().rev() {
409 if !banner {
410 banner = true;
411 println!("Runtime Allocation Statistics");
412 println!("ALLOCATION SIZE COUNT MEAN STDDEV TOTAL")
413 }
414 let arr = Array1::from_iter(rtalloc.1.iter().map(|d| d.as_nanos() as f64));
415 println!(
416 " {:8} {:8} {:8.1}ns {:8.1}ns {:12.4}ms",
417 rtalloc.0.size(),
418 arr.len(),
419 arr.mean().unwrap_or(0.),
420 if arr.len() == 1 { 0. } else { arr.std(1.) },
421 arr.sum() / 1_000_000.
422 );
423 }
424
425 let kalloc_events = state
426 .data()
427 .filter(|e| e.0.kind == TraceKind::Kernel && e.0.event & KERNEL_ALLOC != 0);
428
429 let mut kalloc_map = HashMap::<Layout, Vec<Duration>>::new();
430 let mut kfree_map = HashMap::<Layout, Vec<Duration>>::new();
431 for kae in kalloc_events {
432 if let Some(data) = kae
433 .1
434 .and_then(|d| d.try_cast::<KernelAllocationEvent>(KERNEL_ALLOC))
435 .map(|d| d.data)
436 {
437 let entry = if data.is_free {
438 kfree_map.entry(data.layout).or_default()
439 } else {
440 kalloc_map.entry(data.layout).or_default()
441 };
442 entry.push(data.duration.into());
443 }
444 }
445
446 let mut coll = kalloc_map.into_iter().collect::<Vec<_>>();
447 coll.sort_by_key(|x| x.1.len());
448
449 let mut banner = false;
450 for kalloc in coll.iter().rev() {
451 if !banner {
452 banner = true;
453 println!("Kernel Allocation Statistics");
454 println!("ALLOCATION SIZE COUNT MEAN STDDEV TOTAL")
455 }
456 let arr = Array1::from_iter(kalloc.1.iter().map(|d| d.as_nanos() as f64));
457 println!(
458 " {:8} {:8} {:8.1}ns {:8.1}ns {:12.4}ms",
459 kalloc.0.size(),
460 arr.len(),
461 arr.mean().unwrap_or(0.),
462 if arr.len() == 1 { 0. } else { arr.std(1.) },
463 arr.sum() / 1_000_000.
464 );
465 }
466}