/home/noah/src/trueno/src/brick/profiler.rs
Line | Count | Source |
1 | | //! BrickProfiler: Token-Centric Profiling System |
2 | | //! |
3 | | //! TILING-SPEC-001: Tile-Level Profiling Support |
4 | | //! |
5 | | //! This module provides hierarchical profiling for compute bricks: |
6 | | //! - Per-brick timing and throughput (PAR-073) |
7 | | //! - O(1) hot path with BrickId enum (PAR-200) |
8 | | //! - Tile-level profiling for cache-blocked operations (TILING-SPEC-001) |
9 | | //! - Kernel checksum capture for divergence detection (CORRECTNESS-011) |
10 | | |
11 | | use std::fmt; |
12 | | use std::time::Instant; |
13 | | |
14 | | use super::exec_graph::{ |
15 | | BrickBottleneck, BrickCategory, BrickId, BrickStats, CategoryStats, ExecutionGraph, |
16 | | ExecutionNode, ExecutionNodeId, SyncMode, |
17 | | }; |
18 | | |
19 | | // ============================================================================ |
20 | | // TILING-SPEC-001: Tile-Level Profiling Support |
21 | | // ============================================================================ |
22 | | |
23 | | /// Tile-level profiling statistics. |
24 | | /// |
25 | | /// Tracks per-tile performance metrics for hierarchical cache-blocked operations. |
26 | | /// Used in conjunction with `TcbGeometry` and `TilingConfig` from the tiling module. |
27 | | /// |
28 | | /// # Example |
29 | | /// |
30 | | /// ```ignore |
31 | | /// let mut profiler = BrickProfiler::new(); |
32 | | /// profiler.enable(); |
33 | | /// |
34 | | /// let tile_timer = profiler.start_tile(TileLevel::Macro, 0, 0); |
35 | | /// // ... execute tile ... |
36 | | /// profiler.stop_tile(tile_timer, 1024 * 1024); |
37 | | /// ``` |
38 | | #[derive(Debug, Clone, Default)] |
39 | | pub struct TileStats { |
40 | | /// Tile level (Macro/Midi/Micro) |
41 | | pub level: TileLevel, |
42 | | /// Total samples collected |
43 | | pub count: u64, |
44 | | /// Total elapsed time (nanoseconds) |
45 | | pub total_ns: u64, |
46 | | /// Min elapsed time (nanoseconds) |
47 | | pub min_ns: u64, |
48 | | /// Max elapsed time (nanoseconds) |
49 | | pub max_ns: u64, |
50 | | /// Total elements processed |
51 | | pub total_elements: u64, |
52 | | /// Total cache misses (estimated) |
53 | | pub cache_misses: u64, |
54 | | /// Total arithmetic operations |
55 | | pub total_flops: u64, |
56 | | } |
57 | | |
58 | | /// Tile hierarchy level for profiling. |
59 | | #[derive(Debug, Clone, Copy, PartialEq, Eq, Default)] |
60 | | pub enum TileLevel { |
61 | | /// Macro-tile: L3 cache / GPU global memory |
62 | | #[default] |
63 | | Macro, |
64 | | /// Midi-tile: L2 cache / GPU shared memory |
65 | | Midi, |
66 | | /// Micro-tile: Registers / SIMD lanes |
67 | | Micro, |
68 | | } |
69 | | |
70 | | impl TileLevel { |
71 | | /// Get the name of this tile level. |
72 | | #[must_use] |
73 | 0 | pub const fn name(&self) -> &'static str { |
74 | 0 | match self { |
75 | 0 | TileLevel::Macro => "macro", |
76 | 0 | TileLevel::Midi => "midi", |
77 | 0 | TileLevel::Micro => "micro", |
78 | | } |
79 | 0 | } |
80 | | } |
81 | | |
82 | | impl TileStats { |
83 | | /// Create new tile stats for a given level. |
84 | 0 | pub fn new(level: TileLevel) -> Self { |
85 | 0 | Self { |
86 | 0 | level, |
87 | 0 | count: 0, |
88 | 0 | total_ns: 0, |
89 | 0 | min_ns: u64::MAX, |
90 | 0 | max_ns: 0, |
91 | 0 | total_elements: 0, |
92 | 0 | cache_misses: 0, |
93 | 0 | total_flops: 0, |
94 | 0 | } |
95 | 0 | } |
96 | | |
97 | | /// Add a sample to statistics. |
98 | 0 | pub fn add_sample(&mut self, elapsed_ns: u64, elements: u64, flops: u64) { |
99 | 0 | self.count += 1; |
100 | 0 | self.total_ns += elapsed_ns; |
101 | 0 | self.min_ns = self.min_ns.min(elapsed_ns); |
102 | 0 | self.max_ns = self.max_ns.max(elapsed_ns); |
103 | 0 | self.total_elements += elements; |
104 | 0 | self.total_flops += flops; |
105 | 0 | } |
106 | | |
107 | | /// Average time in microseconds. |
108 | | #[must_use] |
109 | 0 | pub fn avg_us(&self) -> f64 { |
110 | 0 | if self.count == 0 { |
111 | 0 | 0.0 |
112 | | } else { |
113 | 0 | self.total_ns as f64 / self.count as f64 / 1000.0 |
114 | | } |
115 | 0 | } |
116 | | |
117 | | /// Throughput in elements/second. |
118 | | #[must_use] |
119 | 0 | pub fn throughput(&self) -> f64 { |
120 | 0 | if self.total_ns == 0 { |
121 | 0 | 0.0 |
122 | | } else { |
123 | 0 | self.total_elements as f64 / (self.total_ns as f64 / 1_000_000_000.0) |
124 | | } |
125 | 0 | } |
126 | | |
127 | | /// Compute throughput in GFLOP/s. |
128 | | #[must_use] |
129 | 0 | pub fn gflops(&self) -> f64 { |
130 | 0 | if self.total_ns == 0 { |
131 | 0 | 0.0 |
132 | | } else { |
133 | 0 | self.total_flops as f64 / (self.total_ns as f64 / 1_000_000_000.0) / 1e9 |
134 | | } |
135 | 0 | } |
136 | | |
137 | | /// Arithmetic intensity (FLOP/byte) estimate. |
138 | | /// |
139 | | /// Assumes 4 bytes per element (f32). |
140 | | #[must_use] |
141 | 0 | pub fn arithmetic_intensity(&self) -> f64 { |
142 | 0 | if self.total_elements == 0 { |
143 | 0 | 0.0 |
144 | | } else { |
145 | 0 | self.total_flops as f64 / (self.total_elements as f64 * 4.0) |
146 | | } |
147 | 0 | } |
148 | | |
149 | | /// Estimated cache efficiency (0.0-1.0). |
150 | | /// |
151 | | /// Based on ratio of actual throughput vs theoretical peak. |
152 | | #[must_use] |
153 | 0 | pub fn cache_efficiency(&self, peak_gflops: f64) -> f64 { |
154 | 0 | if peak_gflops <= 0.0 { |
155 | 0 | 0.0 |
156 | | } else { |
157 | 0 | (self.gflops() / peak_gflops).min(1.0) |
158 | | } |
159 | 0 | } |
160 | | } |
161 | | |
162 | | /// Timer handle for tile-level profiling. |
163 | | #[derive(Debug)] |
164 | | pub struct TileTimer { |
165 | | /// Tile level |
166 | | level: TileLevel, |
167 | | /// Row index within parent tile (reserved for spatial analysis) |
168 | | _row: u32, |
169 | | /// Column index within parent tile (reserved for spatial analysis) |
170 | | _col: u32, |
171 | | /// Start time |
172 | | start: Instant, |
173 | | } |
174 | | |
175 | | /// Pending measurement for deferred sync mode. |
176 | | #[derive(Debug, Clone)] |
177 | | struct PendingMeasurement { |
178 | | /// Brick ID (if known) |
179 | | brick_id: Option<BrickId>, |
180 | | /// Brick name (for dynamic bricks) |
181 | | name: Option<String>, |
182 | | /// Start time in nanoseconds (from Instant::now()) |
183 | | start_ns: u64, |
184 | | /// Number of elements processed |
185 | | elements: u64, |
186 | | } |
187 | | |
188 | | /// Per-brick profiler using pure Rust timing. |
189 | | /// |
190 | | /// # Design (PAR-073, PAR-200) |
191 | | /// |
192 | | /// - Uses `std::time::Instant` for timing (no CUDA event FFI) |
193 | | /// - PAR-200: O(1) hot path with `BrickId` enum + array storage |
194 | | /// - GPU operations require explicit sync before timing point |
195 | | /// - Supports deferred sync mode for low-overhead production profiling |
196 | | /// - Aggregates statistics per brick name |
197 | | /// |
198 | | /// # Usage |
199 | | /// |
200 | | /// ```rust,ignore |
201 | | /// use trueno::brick::{BrickProfiler, BrickId, SyncMode}; |
202 | | /// |
203 | | /// let mut profiler = BrickProfiler::new(); |
204 | | /// profiler.enable(); |
205 | | /// |
206 | | /// // Fast path: use BrickId for known bricks (PAR-200) |
207 | | /// let timer = profiler.start_brick(BrickId::RmsNorm); |
208 | | /// // ... do work ... |
209 | | /// // For GPU: cuda_stream.synchronize() HERE |
210 | | /// profiler.stop_brick(timer, 1); |
211 | | /// |
212 | | /// // Legacy path: string-based (slower, for unknown bricks) |
213 | | /// let timer = profiler.start("CustomBrick"); |
214 | | /// profiler.stop(timer, 1); |
215 | | /// |
216 | | /// // Deferred sync mode (production) |
217 | | /// profiler.set_sync_mode(SyncMode::Deferred); |
218 | | /// profiler.record_deferred(BrickId::RmsNorm, start_ns, 1); |
219 | | /// // ... more operations ... |
220 | | /// cuda_stream.synchronize(); |
221 | | /// profiler.finalize(end_ns); |
222 | | /// |
223 | | /// // Get statistics |
224 | | /// let stats = profiler.brick_stats(BrickId::RmsNorm); |
225 | | /// println!("RmsNorm avg: {:.2}µs", stats.avg_us()); |
226 | | /// |
227 | | /// // Get category breakdown |
228 | | /// let cats = profiler.category_stats(); |
229 | | /// println!("Attention: {:.1}%", cats[BrickCategory::Attention as usize].percentage(profiler.total_ns())); |
230 | | /// ``` |
231 | | #[derive(Debug)] |
232 | | pub struct BrickProfiler { |
233 | | // PAR-200: Fast path - pre-allocated array for known bricks |
234 | | /// Per-brick statistics for known BrickId types (O(1) lookup) |
235 | | brick_stats: [BrickStats; BrickId::COUNT], |
236 | | |
237 | | // Legacy path - HashMap for dynamic/unknown brick names |
238 | | /// Per-brick statistics for unknown brick names (slower, O(1) amortized) |
239 | | dynamic_stats: std::collections::HashMap<String, BrickStats>, |
240 | | |
241 | | // PAR-200: Deferred sync support |
242 | | /// Pending measurements awaiting GPU sync |
243 | | pending: Vec<PendingMeasurement>, |
244 | | /// Synchronization mode |
245 | | sync_mode: SyncMode, |
246 | | /// Reference instant for deferred timing |
247 | | epoch: Instant, |
248 | | |
249 | | /// Whether profiling is enabled |
250 | | enabled: bool, |
251 | | /// Total tokens processed |
252 | | total_tokens: u64, |
253 | | /// Total time (ns) across all bricks |
254 | | total_ns: u64, |
255 | | /// L2 cache hit rate (0.0-1.0) - v1.1.0 OBSERVE phase |
256 | | l2_cache_hit_rate: Option<f32>, |
257 | | /// Whether zero-copy memory transfers are enabled - v1.1.0 OBSERVE phase |
258 | | is_zero_copy: bool, |
259 | | /// CORRECTNESS-011: Per-kernel checksums for divergence detection |
260 | | kernel_checksums: Vec<KernelChecksum>, |
261 | | |
262 | | // PAR-201: Execution path graph |
263 | | /// Whether execution graph tracking is enabled |
264 | | graph_enabled: bool, |
265 | | /// Execution path graph for PTX→kernel→brick relationships |
266 | | execution_graph: ExecutionGraph, |
267 | | |
268 | | // TILING-SPEC-001: Tile-level profiling |
269 | | /// Per-level tile statistics (Macro, Midi, Micro) |
270 | | tile_stats: [TileStats; 3], |
271 | | /// Whether tile profiling is enabled |
272 | | tile_profiling_enabled: bool, |
273 | | } |
274 | | |
275 | | /// Timer handle returned by `start()` (legacy string-based API). |
276 | | #[derive(Debug)] |
277 | | pub struct BrickTimer { |
278 | | /// Brick name |
279 | | name: String, |
280 | | /// Start time |
281 | | start: Instant, |
282 | | } |
283 | | |
284 | | /// Timer handle returned by `start_brick()` (PAR-200 fast path). |
285 | | #[derive(Debug)] |
286 | | pub struct BrickIdTimer { |
287 | | /// Brick ID |
288 | | brick_id: BrickId, |
289 | | /// Start time |
290 | | start: Instant, |
291 | | } |
292 | | |
293 | | impl Default for BrickProfiler { |
294 | 0 | fn default() -> Self { |
295 | 0 | Self::new() |
296 | 0 | } |
297 | | } |
298 | | |
299 | | impl BrickProfiler { |
300 | | /// Create a new profiler (disabled by default for zero overhead). |
301 | 0 | pub fn new() -> Self { |
302 | | Self { |
303 | 0 | brick_stats: std::array::from_fn(|i| { |
304 | | // Safety: i < BrickId::COUNT by construction |
305 | 0 | let brick_id = unsafe { std::mem::transmute::<u8, BrickId>(i as u8) }; |
306 | 0 | BrickStats::new(brick_id.name()) |
307 | 0 | }), |
308 | 0 | dynamic_stats: std::collections::HashMap::new(), |
309 | 0 | pending: Vec::new(), |
310 | 0 | sync_mode: SyncMode::Deferred, |
311 | 0 | epoch: Instant::now(), |
312 | | enabled: false, |
313 | | total_tokens: 0, |
314 | | total_ns: 0, |
315 | 0 | l2_cache_hit_rate: None, |
316 | | is_zero_copy: false, |
317 | 0 | kernel_checksums: Vec::new(), |
318 | | graph_enabled: false, |
319 | 0 | execution_graph: ExecutionGraph::new(), |
320 | 0 | tile_stats: [ |
321 | 0 | TileStats::new(TileLevel::Macro), |
322 | 0 | TileStats::new(TileLevel::Midi), |
323 | 0 | TileStats::new(TileLevel::Micro), |
324 | 0 | ], |
325 | | tile_profiling_enabled: false, |
326 | | } |
327 | 0 | } |
328 | | |
329 | | /// Create an enabled profiler. |
330 | 0 | pub fn enabled() -> Self { |
331 | 0 | let mut profiler = Self::new(); |
332 | 0 | profiler.enabled = true; |
333 | 0 | profiler |
334 | 0 | } |
335 | | |
336 | | // ======================================================================== |
337 | | // PAR-200: Sync Mode Configuration |
338 | | // ======================================================================== |
339 | | |
340 | | /// Set the synchronization mode for GPU profiling. |
341 | | /// |
342 | | /// # Modes |
343 | | /// - `Immediate`: Sync after each kernel (accurate but slow) |
344 | | /// - `PerLayer`: Sync once per transformer layer |
345 | | /// - `Deferred`: Sync once per forward pass (default, fast) |
346 | | /// - `None`: No synchronization |
347 | 0 | pub fn set_sync_mode(&mut self, mode: SyncMode) { |
348 | 0 | self.sync_mode = mode; |
349 | 0 | } |
350 | | |
351 | | /// Get the current synchronization mode. |
352 | | #[must_use] |
353 | 0 | pub fn sync_mode(&self) -> SyncMode { |
354 | 0 | self.sync_mode |
355 | 0 | } |
356 | | |
357 | | /// Reset the epoch for deferred timing. |
358 | | /// Call this at the start of a forward pass. |
359 | 0 | pub fn reset_epoch(&mut self) { |
360 | 0 | self.epoch = Instant::now(); |
361 | 0 | } |
362 | | |
363 | | /// Get nanoseconds elapsed since epoch. |
364 | | #[inline] |
365 | 0 | pub fn elapsed_ns(&self) -> u64 { |
366 | 0 | self.epoch.elapsed().as_nanos() as u64 |
367 | 0 | } |
368 | | |
369 | | // ======================================================================== |
370 | | // PAR-200: Fast Path API (BrickId-based) |
371 | | // ======================================================================== |
372 | | |
373 | | /// Start timing a brick using BrickId (O(1) hot path). |
374 | | /// |
375 | | /// This is the preferred API for known brick types. |
376 | | /// For GPU operations, call `stream.synchronize()` before `stop_brick()`. |
377 | | #[inline] |
378 | | #[must_use] |
379 | 0 | pub fn start_brick(&self, brick_id: BrickId) -> BrickIdTimer { |
380 | 0 | BrickIdTimer { |
381 | 0 | brick_id, |
382 | 0 | start: Instant::now(), |
383 | 0 | } |
384 | 0 | } |
385 | | |
386 | | /// Stop timing and record the sample (O(1) hot path). |
387 | | #[inline] |
388 | 0 | pub fn stop_brick(&mut self, timer: BrickIdTimer, elements: u64) { |
389 | 0 | if !self.enabled { |
390 | 0 | return; |
391 | 0 | } |
392 | | |
393 | 0 | let elapsed = timer.start.elapsed(); |
394 | 0 | let elapsed_ns = elapsed.as_nanos() as u64; |
395 | | |
396 | | // O(1) array access |
397 | 0 | let stats = &mut self.brick_stats[timer.brick_id as usize]; |
398 | 0 | stats.add_sample(elapsed_ns, elements); |
399 | | |
400 | | // Update totals |
401 | 0 | self.total_tokens += elements; |
402 | 0 | self.total_ns += elapsed_ns; |
403 | 0 | } |
404 | | |
405 | | /// Get statistics for a known brick type (O(1)). |
406 | | #[inline] |
407 | | #[must_use] |
408 | 0 | pub fn brick_stats(&self, brick_id: BrickId) -> &BrickStats { |
409 | 0 | &self.brick_stats[brick_id as usize] |
410 | 0 | } |
411 | | |
412 | | /// Get mutable statistics for a known brick type (O(1)). |
413 | | #[inline] |
414 | 0 | pub fn brick_stats_mut(&mut self, brick_id: BrickId) -> &mut BrickStats { |
415 | 0 | &mut self.brick_stats[brick_id as usize] |
416 | 0 | } |
417 | | |
418 | | // ======================================================================== |
419 | | // PAR-200: Deferred Sync API |
420 | | // ======================================================================== |
421 | | |
422 | | /// Record a measurement without GPU sync (deferred mode). |
423 | | /// |
424 | | /// Call `finalize()` after GPU sync to apply all pending measurements. |
425 | | /// |
426 | | /// # Arguments |
427 | | /// - `brick_id`: The brick type |
428 | | /// - `start_ns`: Start time (from `elapsed_ns()` at operation start) |
429 | | /// - `elements`: Number of elements processed |
430 | | #[inline] |
431 | 0 | pub fn record_deferred(&mut self, brick_id: BrickId, start_ns: u64, elements: u64) { |
432 | 0 | if !self.enabled { |
433 | 0 | return; |
434 | 0 | } |
435 | 0 | self.pending.push(PendingMeasurement { |
436 | 0 | brick_id: Some(brick_id), |
437 | 0 | name: None, |
438 | 0 | start_ns, |
439 | 0 | elements, |
440 | 0 | }); |
441 | 0 | } |
442 | | |
443 | | /// Record a measurement for a dynamic brick (deferred mode). |
444 | | #[inline] |
445 | 0 | pub fn record_deferred_dynamic(&mut self, name: &str, start_ns: u64, elements: u64) { |
446 | 0 | if !self.enabled { |
447 | 0 | return; |
448 | 0 | } |
449 | 0 | self.pending.push(PendingMeasurement { |
450 | 0 | brick_id: BrickId::from_str(name), |
451 | 0 | name: Some(name.to_string()), |
452 | 0 | start_ns, |
453 | 0 | elements, |
454 | 0 | }); |
455 | 0 | } |
456 | | |
457 | | /// Finalize all pending measurements after GPU sync. |
458 | | /// |
459 | | /// Must be called after `stream.synchronize()` to get accurate timing. |
460 | | /// |
461 | | /// # Arguments |
462 | | /// - `end_ns`: End time (from `elapsed_ns()` after sync) |
463 | 0 | pub fn finalize(&mut self, end_ns: u64) { |
464 | 0 | if self.pending.is_empty() { |
465 | 0 | return; |
466 | 0 | } |
467 | | |
468 | | // Calculate elapsed time for each pending measurement |
469 | 0 | for m in self.pending.drain(..) { |
470 | 0 | let elapsed_ns = end_ns.saturating_sub(m.start_ns); |
471 | | |
472 | 0 | if let Some(brick_id) = m.brick_id { |
473 | 0 | // Fast path: known brick |
474 | 0 | let stats = &mut self.brick_stats[brick_id as usize]; |
475 | 0 | stats.add_sample(elapsed_ns, m.elements); |
476 | 0 | } else if let Some(name) = m.name { |
477 | | // Slow path: dynamic brick |
478 | 0 | let stats = self |
479 | 0 | .dynamic_stats |
480 | 0 | .entry(name.clone()) |
481 | 0 | .or_insert_with(|| BrickStats::new(&name)); |
482 | 0 | stats.add_sample(elapsed_ns, m.elements); |
483 | 0 | } |
484 | | |
485 | 0 | self.total_tokens += m.elements; |
486 | 0 | self.total_ns += elapsed_ns; |
487 | | } |
488 | 0 | } |
489 | | |
490 | | /// Check if there are pending measurements. |
491 | | #[inline] |
492 | | #[must_use] |
493 | 0 | pub fn has_pending(&self) -> bool { |
494 | 0 | !self.pending.is_empty() |
495 | 0 | } |
496 | | |
497 | | /// Get number of pending measurements. |
498 | | #[inline] |
499 | | #[must_use] |
500 | 0 | pub fn pending_count(&self) -> usize { |
501 | 0 | self.pending.len() |
502 | 0 | } |
503 | | |
504 | | // ======================================================================== |
505 | | // PAR-200: Category Aggregation |
506 | | // ======================================================================== |
507 | | |
508 | | /// Get aggregated statistics by category. |
509 | | /// |
510 | | /// Returns an array indexed by `BrickCategory as usize`. |
511 | | #[must_use] |
512 | 0 | pub fn category_stats(&self) -> [CategoryStats; BrickCategory::COUNT] { |
513 | 0 | let mut result = [CategoryStats::default(); BrickCategory::COUNT]; |
514 | | |
515 | 0 | for (i, stats) in self.brick_stats.iter().enumerate() { |
516 | 0 | // Safety: i < BrickId::COUNT by construction |
517 | 0 | let brick_id = unsafe { std::mem::transmute::<u8, BrickId>(i as u8) }; |
518 | 0 | let cat = brick_id.category() as usize; |
519 | 0 | result[cat].total_ns += stats.total_ns; |
520 | 0 | result[cat].total_elements += stats.total_elements; |
521 | 0 | result[cat].count += stats.count; |
522 | 0 | } |
523 | | |
524 | | // Include dynamic stats in "Other" category |
525 | 0 | for stats in self.dynamic_stats.values() { |
526 | 0 | let cat = BrickCategory::Other as usize; |
527 | 0 | result[cat].total_ns += stats.total_ns; |
528 | 0 | result[cat].total_elements += stats.total_elements; |
529 | 0 | result[cat].count += stats.count; |
530 | 0 | } |
531 | | |
532 | 0 | result |
533 | 0 | } |
534 | | |
535 | | /// Print category breakdown to console. |
536 | 0 | pub fn print_category_stats(&self) { |
537 | 0 | let cats = self.category_stats(); |
538 | 0 | let total = self.total_ns; |
539 | | |
540 | 0 | println!("╭─────────────────────────────────────────────────────────╮"); |
541 | 0 | println!("│ Category Breakdown (PAR-200) │"); |
542 | 0 | println!("├─────────────────────────────────────────────────────────┤"); |
543 | 0 | for (i, cat_stats) in cats.iter().enumerate() { |
544 | | // Safety: i < BrickCategory::COUNT |
545 | 0 | let cat = unsafe { std::mem::transmute::<u8, BrickCategory>(i as u8) }; |
546 | 0 | if cat_stats.count > 0 { |
547 | 0 | println!( |
548 | 0 | "│ {:12} {:8.2}µs avg {:6.1}% [{:5} samples] │", |
549 | 0 | cat.name(), |
550 | 0 | cat_stats.avg_us(), |
551 | 0 | cat_stats.percentage(total), |
552 | 0 | cat_stats.count |
553 | 0 | ); |
554 | 0 | } |
555 | | } |
556 | 0 | println!("╰─────────────────────────────────────────────────────────╯"); |
557 | 0 | } |
558 | | |
559 | | // ======================================================================== |
560 | | // PAR-201: Execution Path Graph |
561 | | // ======================================================================== |
562 | | |
563 | | /// Enable execution graph tracking. |
564 | | /// |
565 | | /// When enabled, the profiler records the execution hierarchy: |
566 | | /// - Layer → Brick → Kernel relationships |
567 | | /// - PTX hashes for kernel identity |
568 | | /// - Timing data per node |
569 | 0 | pub fn enable_graph(&mut self) { |
570 | 0 | self.graph_enabled = true; |
571 | 0 | } |
572 | | |
573 | | /// Disable execution graph tracking. |
574 | 0 | pub fn disable_graph(&mut self) { |
575 | 0 | self.graph_enabled = false; |
576 | 0 | } |
577 | | |
578 | | /// Check if execution graph tracking is enabled. |
579 | | #[must_use] |
580 | 0 | pub fn is_graph_enabled(&self) -> bool { |
581 | 0 | self.graph_enabled |
582 | 0 | } |
583 | | |
584 | | /// Get the execution graph (immutable). |
585 | | #[must_use] |
586 | 0 | pub fn execution_graph(&self) -> &ExecutionGraph { |
587 | 0 | &self.execution_graph |
588 | 0 | } |
589 | | |
590 | | /// Get the execution graph (mutable). |
591 | 0 | pub fn execution_graph_mut(&mut self) -> &mut ExecutionGraph { |
592 | 0 | &mut self.execution_graph |
593 | 0 | } |
594 | | |
595 | | /// Push a scope for hierarchical graph recording. |
596 | | /// |
597 | | /// # Example |
598 | | /// |
599 | | /// ```rust,ignore |
600 | | /// profiler.enable_graph(); |
601 | | /// profiler.graph_push_scope(ExecutionNode::Layer { index: 0 }); |
602 | | /// // ... record bricks and kernels ... |
603 | | /// profiler.graph_pop_scope(); |
604 | | /// ``` |
605 | 0 | pub fn graph_push_scope(&mut self, node: ExecutionNode) -> Option<ExecutionNodeId> { |
606 | 0 | if !self.graph_enabled { |
607 | 0 | return None; |
608 | 0 | } |
609 | 0 | Some(self.execution_graph.push_scope(node)) |
610 | 0 | } |
611 | | |
612 | | /// Pop the current scope. |
613 | 0 | pub fn graph_pop_scope(&mut self) -> Option<ExecutionNodeId> { |
614 | 0 | if !self.graph_enabled { |
615 | 0 | return None; |
616 | 0 | } |
617 | 0 | self.execution_graph.pop_scope() |
618 | 0 | } |
619 | | |
620 | | /// Record a brick in the execution graph. |
621 | | /// |
622 | | /// This should be called after `stop_brick()` with the timing data. |
623 | 0 | pub fn graph_record_brick( |
624 | 0 | &mut self, |
625 | 0 | brick_id: BrickId, |
626 | 0 | timing_ns: u64, |
627 | 0 | elements: u64, |
628 | 0 | ) -> Option<ExecutionNodeId> { |
629 | 0 | if !self.graph_enabled { |
630 | 0 | return None; |
631 | 0 | } |
632 | 0 | let node = ExecutionNode::Brick { |
633 | 0 | id: brick_id, |
634 | 0 | timing_ns, |
635 | 0 | elements, |
636 | 0 | }; |
637 | 0 | Some(self.execution_graph.add_node_in_scope(node)) |
638 | 0 | } |
639 | | |
640 | | /// Record a kernel launch in the execution graph. |
641 | | /// |
642 | | /// # Arguments |
643 | | /// - `name`: Kernel name (e.g., "batched_q4k_gemv") |
644 | | /// - `ptx_hash`: FNV-1a hash of PTX source for identity |
645 | | /// - `grid`: Grid dimensions (blocks) |
646 | | /// - `block`: Block dimensions (threads) |
647 | | /// - `shared_mem`: Shared memory bytes |
648 | 0 | pub fn graph_record_kernel( |
649 | 0 | &mut self, |
650 | 0 | name: &str, |
651 | 0 | ptx_hash: u64, |
652 | 0 | grid: (u32, u32, u32), |
653 | 0 | block: (u32, u32, u32), |
654 | 0 | shared_mem: u32, |
655 | 0 | ) -> Option<ExecutionNodeId> { |
656 | 0 | if !self.graph_enabled { |
657 | 0 | return None; |
658 | 0 | } |
659 | 0 | Some( |
660 | 0 | self.execution_graph |
661 | 0 | .record_kernel_launch(name, ptx_hash, grid, block, shared_mem), |
662 | 0 | ) |
663 | 0 | } |
664 | | |
665 | | /// Export execution graph to DOT format for visualization. |
666 | | /// |
667 | | /// Use with Graphviz: `dot -Tsvg output.dot -o graph.svg` |
668 | | #[must_use] |
669 | 0 | pub fn graph_to_dot(&self) -> String { |
670 | 0 | self.execution_graph.to_dot() |
671 | 0 | } |
672 | | |
673 | | /// Export execution graph to trueno-graph CsrGraph. |
674 | | #[cfg(feature = "execution-graph")] |
675 | | #[must_use] |
676 | | pub fn graph_to_csr(&self) -> trueno_graph::CsrGraph { |
677 | | self.execution_graph.to_csr() |
678 | | } |
679 | | |
680 | | /// Clear the execution graph. |
681 | 0 | pub fn graph_clear(&mut self) { |
682 | 0 | self.execution_graph.clear(); |
683 | 0 | } |
684 | | |
685 | | /// Check if the execution graph scope stack is balanced. |
686 | | #[must_use] |
687 | 0 | pub fn graph_is_scope_balanced(&self) -> bool { |
688 | 0 | self.execution_graph.is_scope_balanced() |
689 | 0 | } |
690 | | |
691 | | /// Set L2 cache hit rate (v1.1.0 OBSERVE phase) |
692 | 0 | pub fn set_l2_cache_hit_rate(&mut self, rate: f32) { |
693 | 0 | self.l2_cache_hit_rate = Some(rate.clamp(0.0, 1.0)); |
694 | 0 | } |
695 | | |
696 | | /// Get L2 cache hit rate |
697 | 0 | pub fn l2_cache_hit_rate(&self) -> Option<f32> { |
698 | 0 | self.l2_cache_hit_rate |
699 | 0 | } |
700 | | |
701 | | /// Set zero-copy mode (v1.1.0 OBSERVE phase) |
702 | 0 | pub fn set_zero_copy(&mut self, enabled: bool) { |
703 | 0 | self.is_zero_copy = enabled; |
704 | 0 | } |
705 | | |
706 | | /// Check if zero-copy is enabled |
707 | 0 | pub fn is_zero_copy(&self) -> bool { |
708 | 0 | self.is_zero_copy |
709 | 0 | } |
710 | | |
711 | | /// Enable profiling. |
712 | 0 | pub fn enable(&mut self) { |
713 | 0 | self.enabled = true; |
714 | 0 | } |
715 | | |
716 | | /// Disable profiling. |
717 | 0 | pub fn disable(&mut self) { |
718 | 0 | self.enabled = false; |
719 | 0 | } |
720 | | |
721 | | /// Check if profiling is enabled. |
722 | | #[must_use] |
723 | 0 | pub fn is_enabled(&self) -> bool { |
724 | 0 | self.enabled |
725 | 0 | } |
726 | | |
727 | | /// Start timing a brick. Returns timer handle. |
728 | | /// |
729 | | /// IMPORTANT: For GPU operations, call sync AFTER the operation |
730 | | /// completes but BEFORE calling stop(). |
731 | | #[must_use] |
732 | 0 | pub fn start(&self, name: &str) -> BrickTimer { |
733 | 0 | BrickTimer { |
734 | 0 | name: name.to_string(), |
735 | 0 | start: Instant::now(), |
736 | 0 | } |
737 | 0 | } |
738 | | |
739 | | /// Stop timing and record the sample. |
740 | | /// |
741 | | /// # Arguments |
742 | | /// - `timer`: Timer handle from `start()` |
743 | | /// - `elements`: Number of elements (tokens) processed |
744 | 0 | pub fn stop(&mut self, timer: BrickTimer, elements: u64) { |
745 | 0 | if !self.enabled { |
746 | 0 | return; |
747 | 0 | } |
748 | | |
749 | 0 | let elapsed = timer.start.elapsed(); |
750 | 0 | let elapsed_ns = elapsed.as_nanos() as u64; |
751 | | |
752 | | // PAR-200: Try fast path first if name matches a known BrickId |
753 | 0 | if let Some(brick_id) = BrickId::from_str(&timer.name) { |
754 | 0 | let stats = &mut self.brick_stats[brick_id as usize]; |
755 | 0 | stats.add_sample(elapsed_ns, elements); |
756 | 0 | } else { |
757 | | // Fall back to dynamic stats |
758 | 0 | let name = timer.name; |
759 | 0 | let stats = self |
760 | 0 | .dynamic_stats |
761 | 0 | .entry(name.clone()) |
762 | 0 | .or_insert_with(|| BrickStats::new(&name)); |
763 | 0 | stats.add_sample(elapsed_ns, elements); |
764 | | } |
765 | | |
766 | | // Update totals |
767 | 0 | self.total_tokens += elements; |
768 | 0 | self.total_ns += elapsed_ns; |
769 | 0 | } |
770 | | |
771 | | /// Record a pre-measured duration for a brick. |
772 | | /// |
773 | | /// PAR-073: This method allows timing with raw `Instant` calls, avoiding |
774 | | /// borrow conflicts when profiling CUDA operations that also need `&mut self`. |
775 | | /// |
776 | | /// # Arguments |
777 | | /// - `name`: Brick name |
778 | | /// - `elapsed`: Duration of the operation (from `Instant::elapsed()`) |
779 | | /// - `elements`: Number of elements (tokens) processed |
780 | | /// |
781 | | /// # Example |
782 | | /// ```rust,ignore |
783 | | /// let start = std::time::Instant::now(); |
784 | | /// cuda_stream.synchronize()?; |
785 | | /// self.some_cuda_operation()?; |
786 | | /// cuda_stream.synchronize()?; |
787 | | /// let elapsed = start.elapsed(); |
788 | | /// self.profiler.record_elapsed("SomeBrick", elapsed, 1); |
789 | | /// ``` |
790 | 0 | pub fn record_elapsed(&mut self, name: &str, elapsed: std::time::Duration, elements: u64) { |
791 | 0 | if !self.enabled { |
792 | 0 | return; |
793 | 0 | } |
794 | | |
795 | 0 | let elapsed_ns = elapsed.as_nanos() as u64; |
796 | | |
797 | | // PAR-200: Try fast path first if name matches a known BrickId |
798 | 0 | if let Some(brick_id) = BrickId::from_str(name) { |
799 | 0 | let stats = &mut self.brick_stats[brick_id as usize]; |
800 | 0 | stats.add_sample(elapsed_ns, elements); |
801 | 0 | } else { |
802 | | // Fall back to dynamic stats |
803 | 0 | let stats = self |
804 | 0 | .dynamic_stats |
805 | 0 | .entry(name.to_string()) |
806 | 0 | .or_insert_with(|| BrickStats::new(name)); |
807 | 0 | stats.add_sample(elapsed_ns, elements); |
808 | | } |
809 | | |
810 | | // Update totals |
811 | 0 | self.total_tokens += elements; |
812 | 0 | self.total_ns += elapsed_ns; |
813 | 0 | } |
814 | | |
815 | | /// PMAT-451: Record elapsed time with byte metrics for compression workloads. |
816 | | /// |
817 | | /// # Arguments |
818 | | /// - `name`: Brick name |
819 | | /// - `elapsed`: Duration of the operation |
820 | | /// - `elements`: Number of elements (pages) processed |
821 | | /// - `input_bytes`: Original uncompressed size |
822 | | /// - `output_bytes`: Compressed output size |
823 | | /// |
824 | | /// # Example |
825 | | /// ```rust,ignore |
826 | | /// let start = std::time::Instant::now(); |
827 | | /// let compressed = zstd_compress(&page_data); |
828 | | /// let elapsed = start.elapsed(); |
829 | | /// profiler.record_elapsed_with_bytes( |
830 | | /// "ZstdCompress", |
831 | | /// elapsed, |
832 | | /// 1, |
833 | | /// page_data.len() as u64, |
834 | | /// compressed.len() as u64, |
835 | | /// ); |
836 | | /// ``` |
837 | 0 | pub fn record_elapsed_with_bytes( |
838 | 0 | &mut self, |
839 | 0 | name: &str, |
840 | 0 | elapsed: std::time::Duration, |
841 | 0 | elements: u64, |
842 | 0 | input_bytes: u64, |
843 | 0 | output_bytes: u64, |
844 | 0 | ) { |
845 | 0 | if !self.enabled { |
846 | 0 | return; |
847 | 0 | } |
848 | | |
849 | 0 | let elapsed_ns = elapsed.as_nanos() as u64; |
850 | | |
851 | | // PAR-200: Try fast path first if name matches a known BrickId |
852 | 0 | if let Some(brick_id) = BrickId::from_str(name) { |
853 | 0 | let stats = &mut self.brick_stats[brick_id as usize]; |
854 | 0 | stats.add_sample_with_bytes(elapsed_ns, elements, input_bytes, output_bytes); |
855 | 0 | } else { |
856 | | // Fall back to dynamic stats |
857 | 0 | let stats = self |
858 | 0 | .dynamic_stats |
859 | 0 | .entry(name.to_string()) |
860 | 0 | .or_insert_with(|| BrickStats::new(name)); |
861 | 0 | stats.add_sample_with_bytes(elapsed_ns, elements, input_bytes, output_bytes); |
862 | | } |
863 | | |
864 | | // Update totals |
865 | 0 | self.total_tokens += elements; |
866 | 0 | self.total_ns += elapsed_ns; |
867 | 0 | } |
868 | | |
869 | | /// PMAT-451: Set bottleneck classification for a brick. |
870 | 0 | pub fn set_brick_bottleneck(&mut self, name: &str, bottleneck: BrickBottleneck) { |
871 | | // PAR-200: Try fast path first |
872 | 0 | if let Some(brick_id) = BrickId::from_str(name) { |
873 | 0 | self.brick_stats[brick_id as usize].set_bottleneck(bottleneck); |
874 | 0 | } else if let Some(stats) = self.dynamic_stats.get_mut(name) { |
875 | 0 | stats.set_bottleneck(bottleneck); |
876 | 0 | } |
877 | 0 | } |
878 | | |
879 | | /// Get statistics for a specific brick by name. |
880 | | /// |
881 | | /// First checks known BrickId types (O(1)), then falls back to dynamic stats. |
882 | | #[must_use] |
883 | 0 | pub fn stats(&self, name: &str) -> Option<&BrickStats> { |
884 | | // Try fast path first |
885 | 0 | if let Some(brick_id) = BrickId::from_str(name) { |
886 | 0 | let stats = &self.brick_stats[brick_id as usize]; |
887 | 0 | if stats.count > 0 { |
888 | 0 | return Some(stats); |
889 | 0 | } |
890 | 0 | } |
891 | | // Fall back to dynamic stats |
892 | 0 | self.dynamic_stats.get(name) |
893 | 0 | } |
894 | | |
895 | | /// Get all brick statistics (legacy API, returns dynamic stats only). |
896 | | /// |
897 | | /// For full statistics including known bricks, use `all_brick_stats()` instead. |
898 | | #[must_use] |
899 | | #[deprecated( |
900 | | since = "0.12.0", |
901 | | note = "Use all_brick_stats() for complete statistics" |
902 | | )] |
903 | 0 | pub fn all_stats(&self) -> &std::collections::HashMap<String, BrickStats> { |
904 | 0 | &self.dynamic_stats |
905 | 0 | } |
906 | | |
907 | | /// Get all brick statistics including both known and dynamic bricks. |
908 | 0 | pub fn all_brick_stats(&self) -> impl Iterator<Item = &BrickStats> { |
909 | 0 | self.brick_stats |
910 | 0 | .iter() |
911 | 0 | .filter(|s| s.count > 0) |
912 | 0 | .chain(self.dynamic_stats.values()) |
913 | 0 | } |
914 | | |
915 | | /// Get total throughput across all bricks. |
916 | | #[must_use] |
917 | 0 | pub fn total_throughput(&self) -> f64 { |
918 | 0 | if self.total_ns == 0 { |
919 | 0 | 0.0 |
920 | | } else { |
921 | 0 | self.total_tokens as f64 / (self.total_ns as f64 / 1_000_000_000.0) |
922 | | } |
923 | 0 | } |
924 | | |
925 | | /// Get total tokens processed. |
926 | | #[must_use] |
927 | 0 | pub fn total_tokens(&self) -> u64 { |
928 | 0 | self.total_tokens |
929 | 0 | } |
930 | | |
931 | | /// Get total time in nanoseconds. |
932 | | #[must_use] |
933 | 0 | pub fn total_ns(&self) -> u64 { |
934 | 0 | self.total_ns |
935 | 0 | } |
936 | | |
937 | | /// Get all brick names. |
938 | | #[must_use] |
939 | 0 | pub fn brick_names(&self) -> Vec<String> { |
940 | 0 | let mut names: Vec<String> = self |
941 | 0 | .brick_stats |
942 | 0 | .iter() |
943 | 0 | .enumerate() |
944 | 0 | .filter(|(_, s)| s.count > 0) |
945 | 0 | .map(|(i, _)| { |
946 | | // Safety: i < BrickId::COUNT |
947 | 0 | let brick_id = unsafe { std::mem::transmute::<u8, BrickId>(i as u8) }; |
948 | 0 | brick_id.name().to_string() |
949 | 0 | }) |
950 | 0 | .collect(); |
951 | 0 | names.extend(self.dynamic_stats.keys().cloned()); |
952 | 0 | names |
953 | 0 | } |
954 | | |
955 | | /// Reset all statistics. |
956 | 0 | pub fn reset(&mut self) { |
957 | 0 | for stats in &mut self.brick_stats { |
958 | 0 | stats.count = 0; |
959 | 0 | stats.total_ns = 0; |
960 | 0 | stats.min_ns = u64::MAX; |
961 | 0 | stats.max_ns = 0; |
962 | 0 | stats.total_elements = 0; |
963 | 0 | stats.total_bytes = 0; |
964 | 0 | stats.total_compressed_bytes = 0; |
965 | 0 | } |
966 | 0 | self.dynamic_stats.clear(); |
967 | 0 | self.pending.clear(); |
968 | 0 | self.total_tokens = 0; |
969 | 0 | self.total_ns = 0; |
970 | 0 | } |
971 | | |
972 | | /// Generate a summary report. |
973 | | #[must_use] |
974 | 0 | pub fn summary(&self) -> String { |
975 | 0 | let mut report = String::new(); |
976 | 0 | report.push_str("=== Brick Profiler Summary (PAR-200) ===\n"); |
977 | 0 | report.push_str(&format!( |
978 | 0 | "Total: {} tokens, {:.2}µs, {:.1} tok/s\n", |
979 | 0 | self.total_tokens, |
980 | 0 | self.total_ns as f64 / 1000.0, |
981 | 0 | self.total_throughput() |
982 | 0 | )); |
983 | 0 | report.push_str("\nPer-Brick Breakdown:\n"); |
984 | | |
985 | | // Collect all stats (known + dynamic) |
986 | 0 | let mut all_stats: Vec<(&str, &BrickStats)> = Vec::new(); |
987 | | |
988 | | // Add known bricks with non-zero counts |
989 | 0 | for (i, stats) in self.brick_stats.iter().enumerate() { |
990 | 0 | if stats.count > 0 { |
991 | 0 | // Safety: i < BrickId::COUNT |
992 | 0 | let brick_id = unsafe { std::mem::transmute::<u8, BrickId>(i as u8) }; |
993 | 0 | all_stats.push((brick_id.name(), stats)); |
994 | 0 | } |
995 | | } |
996 | | |
997 | | // Add dynamic bricks |
998 | 0 | for (name, stats) in &self.dynamic_stats { |
999 | 0 | all_stats.push((name.as_str(), stats)); |
1000 | 0 | } |
1001 | | |
1002 | | // Sort by total time descending |
1003 | 0 | all_stats.sort_by(|a, b| b.1.total_ns.cmp(&a.1.total_ns)); |
1004 | | |
1005 | 0 | for (name, stats) in all_stats { |
1006 | 0 | let pct = if self.total_ns > 0 { |
1007 | 0 | 100.0 * stats.total_ns as f64 / self.total_ns as f64 |
1008 | | } else { |
1009 | 0 | 0.0 |
1010 | | }; |
1011 | 0 | report.push_str(&format!( |
1012 | 0 | " {:20} {:8.2}µs avg ({:5.1}%) [{} samples]\n", |
1013 | 0 | name, |
1014 | 0 | stats.avg_us(), |
1015 | 0 | pct, |
1016 | 0 | stats.count |
1017 | 0 | )); |
1018 | | } |
1019 | | |
1020 | | // Add category breakdown |
1021 | 0 | report.push_str("\nCategory Breakdown:\n"); |
1022 | 0 | let cats = self.category_stats(); |
1023 | 0 | for (i, cat_stats) in cats.iter().enumerate() { |
1024 | 0 | if cat_stats.count > 0 { |
1025 | 0 | // Safety: i < BrickCategory::COUNT |
1026 | 0 | let cat = unsafe { std::mem::transmute::<u8, BrickCategory>(i as u8) }; |
1027 | 0 | report.push_str(&format!( |
1028 | 0 | " {:12} {:8.2}µs avg ({:5.1}%)\n", |
1029 | 0 | cat.name(), |
1030 | 0 | cat_stats.avg_us(), |
1031 | 0 | cat_stats.percentage(self.total_ns) |
1032 | 0 | )); |
1033 | 0 | } |
1034 | | } |
1035 | | |
1036 | 0 | report |
1037 | 0 | } |
1038 | | |
1039 | | /// Export profiling data as JSON for pmat metrics integration. |
1040 | | /// |
1041 | | /// Format compatible with `.pmat-metrics/trends/` structure: |
1042 | | /// ```json |
1043 | | /// { |
1044 | | /// "total_tokens": 1000, |
1045 | | /// "total_ns": 5000000, |
1046 | | /// "total_throughput": 200000.0, |
1047 | | /// "bricks": [ |
1048 | | /// { |
1049 | | /// "name": "RmsNorm", |
1050 | | /// "count": 10, |
1051 | | /// "total_ns": 1000000, |
1052 | | /// "avg_us": 100.0, |
1053 | | /// "min_us": 90.0, |
1054 | | /// "max_us": 120.0, |
1055 | | /// "throughput": 10000.0, |
1056 | | /// "pct": 20.0 |
1057 | | /// } |
1058 | | /// ] |
1059 | | /// } |
1060 | | /// ``` |
1061 | | #[must_use] |
1062 | 0 | pub fn to_json(&self) -> String { |
1063 | 0 | let mut bricks = Vec::new(); |
1064 | | |
1065 | | // Collect all stats (known + dynamic) |
1066 | 0 | let mut all_stats: Vec<(&str, &BrickStats)> = Vec::new(); |
1067 | | |
1068 | | // Add known bricks with non-zero counts |
1069 | 0 | for (i, stats) in self.brick_stats.iter().enumerate() { |
1070 | 0 | if stats.count > 0 { |
1071 | 0 | // Safety: i < BrickId::COUNT |
1072 | 0 | let brick_id = unsafe { std::mem::transmute::<u8, BrickId>(i as u8) }; |
1073 | 0 | all_stats.push((brick_id.name(), stats)); |
1074 | 0 | } |
1075 | | } |
1076 | | |
1077 | | // Add dynamic bricks |
1078 | 0 | for (name, stats) in &self.dynamic_stats { |
1079 | 0 | all_stats.push((name.as_str(), stats)); |
1080 | 0 | } |
1081 | | |
1082 | | // Sort by total time descending |
1083 | 0 | all_stats.sort_by(|a, b| b.1.total_ns.cmp(&a.1.total_ns)); |
1084 | | |
1085 | 0 | for (name, stats) in all_stats { |
1086 | 0 | let pct = if self.total_ns > 0 { |
1087 | 0 | 100.0 * stats.total_ns as f64 / self.total_ns as f64 |
1088 | | } else { |
1089 | 0 | 0.0 |
1090 | | }; |
1091 | | // PMAT-451: Include compression_ratio, throughput_gbps, and bottleneck |
1092 | 0 | let compression = stats.compression_ratio(); |
1093 | 0 | let throughput_gbps = stats.throughput_gbps(); |
1094 | 0 | let bottleneck = stats.get_bottleneck(); |
1095 | 0 | bricks.push(format!( |
1096 | 0 | r#"{{"name":"{}","count":{},"total_ns":{},"avg_us":{:.2},"min_us":{:.2},"max_us":{:.2},"throughput":{:.1},"pct":{:.1},"total_bytes":{},"compression_ratio":{:.2},"throughput_gbps":{:.2},"bottleneck":"{}"}}"#, |
1097 | | name, |
1098 | | stats.count, |
1099 | | stats.total_ns, |
1100 | 0 | stats.avg_us(), |
1101 | 0 | stats.min_us(), |
1102 | 0 | stats.max_us(), |
1103 | 0 | stats.throughput(), |
1104 | | pct, |
1105 | | stats.total_bytes, |
1106 | | compression, |
1107 | | throughput_gbps, |
1108 | | bottleneck |
1109 | | )); |
1110 | | } |
1111 | | |
1112 | 0 | format!( |
1113 | 0 | r#"{{"total_tokens":{},"total_ns":{},"total_throughput":{:.1},"bricks":[{}]}}"#, |
1114 | | self.total_tokens, |
1115 | | self.total_ns, |
1116 | 0 | self.total_throughput(), |
1117 | 0 | bricks.join(",") |
1118 | | ) |
1119 | 0 | } |
1120 | | |
1121 | | /// Write profiling data to a JSON file for pmat tracking. |
1122 | | /// |
1123 | | /// # Errors |
1124 | | /// Returns error if file cannot be written. |
1125 | 0 | pub fn write_json(&self, path: &std::path::Path) -> std::io::Result<()> { |
1126 | 0 | std::fs::write(path, self.to_json()) |
1127 | 0 | } |
1128 | | |
1129 | | // ======================================================================= |
1130 | | // CORRECTNESS-011: Per-kernel checksum capture for divergence detection |
1131 | | // ======================================================================= |
1132 | | |
1133 | | /// Record a kernel trace with output checksum for divergence detection. |
1134 | | /// |
1135 | | /// This enables automated CPU/GPU divergence detection by capturing |
1136 | | /// output checksums alongside timing data. When GPU produces wrong output, |
1137 | | /// this identifies WHICH kernel diverged without hours of manual debugging. |
1138 | | /// |
1139 | | /// Five-Whys Root Cause: Hours of manual "let me check X in Y" debugging |
1140 | | /// → No automated tool identified which kernel diverged |
1141 | | /// → BrickProfiler only captured timing, not checksums |
1142 | | /// → Missing feature: per-kernel checksum capture |
1143 | | /// |
1144 | | /// # Arguments |
1145 | | /// - `name`: Brick/kernel name |
1146 | | /// - `layer_idx`: Layer index (0-N for transformer layers) |
1147 | | /// - `position`: Position in sequence |
1148 | | /// - `output`: Output tensor data (first 64 floats checksummed) |
1149 | | /// |
1150 | | /// # Example |
1151 | | /// ```rust,ignore |
1152 | | /// // After RoPE kernel |
1153 | | /// profiler.record_checksum("RopeNeox", layer_idx, position, &q_rotated); |
1154 | | /// ``` |
1155 | 0 | pub fn record_checksum(&mut self, name: &str, layer_idx: usize, position: u32, output: &[f32]) { |
1156 | 0 | if !self.enabled { |
1157 | 0 | return; |
1158 | 0 | } |
1159 | 0 | let checksum = fnv1a_f32_checksum(output); |
1160 | 0 | let trace = KernelChecksum { |
1161 | 0 | name: name.to_string(), |
1162 | 0 | layer_idx, |
1163 | 0 | position, |
1164 | 0 | checksum, |
1165 | 0 | }; |
1166 | 0 | self.kernel_checksums.push(trace); |
1167 | 0 | } |
1168 | | |
1169 | | /// Get all kernel checksums for divergence comparison. |
1170 | | #[must_use] |
1171 | 0 | pub fn get_checksums(&self) -> &[KernelChecksum] { |
1172 | 0 | &self.kernel_checksums |
1173 | 0 | } |
1174 | | |
1175 | | /// Compare checksums with a reference profiler (e.g., CPU baseline). |
1176 | | /// |
1177 | | /// Returns None if all checksums match, or the first divergent kernel. |
1178 | | #[must_use] |
1179 | 0 | pub fn find_divergence(&self, reference: &BrickProfiler) -> Option<DivergenceInfo> { |
1180 | | use std::collections::HashMap; |
1181 | | |
1182 | | // Index reference checksums by (name, layer_idx, position) |
1183 | 0 | let ref_index: HashMap<(&str, usize, u32), u64> = reference |
1184 | 0 | .kernel_checksums |
1185 | 0 | .iter() |
1186 | 0 | .map(|t| ((t.name.as_str(), t.layer_idx, t.position), t.checksum)) |
1187 | 0 | .collect(); |
1188 | | |
1189 | | // Check each of our checksums against reference |
1190 | 0 | for trace in &self.kernel_checksums { |
1191 | 0 | let key = (trace.name.as_str(), trace.layer_idx, trace.position); |
1192 | 0 | if let Some(&expected) = ref_index.get(&key) { |
1193 | 0 | if trace.checksum != expected { |
1194 | 0 | return Some(DivergenceInfo { |
1195 | 0 | kernel_name: trace.name.clone(), |
1196 | 0 | layer_idx: trace.layer_idx, |
1197 | 0 | position: trace.position, |
1198 | 0 | expected_checksum: expected, |
1199 | 0 | actual_checksum: trace.checksum, |
1200 | 0 | }); |
1201 | 0 | } |
1202 | 0 | } |
1203 | | } |
1204 | 0 | None |
1205 | 0 | } |
1206 | | |
1207 | | /// Reset checksum tracking (call before new forward pass). |
1208 | 0 | pub fn reset_checksums(&mut self) { |
1209 | 0 | self.kernel_checksums.clear(); |
1210 | 0 | } |
1211 | | |
1212 | | // ======================================================================== |
1213 | | // TILING-SPEC-001: Tile-Level Profiling (Phase 15) |
1214 | | // ======================================================================== |
1215 | | |
1216 | | /// Enable tile-level profiling. |
1217 | | /// |
1218 | | /// When enabled, `start_tile()`/`stop_tile()` record per-tile statistics |
1219 | | /// for Macro/Midi/Micro tile hierarchy. |
1220 | 0 | pub fn enable_tile_profiling(&mut self) { |
1221 | 0 | self.tile_profiling_enabled = true; |
1222 | 0 | } |
1223 | | |
1224 | | /// Disable tile-level profiling. |
1225 | 0 | pub fn disable_tile_profiling(&mut self) { |
1226 | 0 | self.tile_profiling_enabled = false; |
1227 | 0 | } |
1228 | | |
1229 | | /// Check if tile profiling is enabled. |
1230 | | #[must_use] |
1231 | 0 | pub fn is_tile_profiling_enabled(&self) -> bool { |
1232 | 0 | self.tile_profiling_enabled |
1233 | 0 | } |
1234 | | |
1235 | | /// Start timing a tile execution. |
1236 | | /// |
1237 | | /// Returns a `TileTimer` that should be passed to `stop_tile()` after |
1238 | | /// the tile computation completes. |
1239 | | /// |
1240 | | /// # Arguments |
1241 | | /// - `level`: Tile hierarchy level (Macro/Midi/Micro) |
1242 | | /// - `row`: Row index within parent tile |
1243 | | /// - `col`: Column index within parent tile |
1244 | | /// |
1245 | | /// # Example |
1246 | | /// ```rust,ignore |
1247 | | /// let timer = profiler.start_tile(TileLevel::Macro, 0, 0); |
1248 | | /// // ... execute tile computation ... |
1249 | | /// profiler.stop_tile(timer, 256 * 256, 2 * 256 * 256 * 256); |
1250 | | /// ``` |
1251 | | #[must_use] |
1252 | 0 | pub fn start_tile(&self, level: TileLevel, row: u32, col: u32) -> TileTimer { |
1253 | 0 | TileTimer { |
1254 | 0 | level, |
1255 | 0 | _row: row, |
1256 | 0 | _col: col, |
1257 | 0 | start: Instant::now(), |
1258 | 0 | } |
1259 | 0 | } |
1260 | | |
1261 | | /// Stop timing and record tile statistics. |
1262 | | /// |
1263 | | /// # Arguments |
1264 | | /// - `timer`: Timer handle from `start_tile()` |
1265 | | /// - `elements`: Number of elements processed by this tile |
1266 | | /// - `flops`: Number of floating-point operations performed |
1267 | 0 | pub fn stop_tile(&mut self, timer: TileTimer, elements: u64, flops: u64) { |
1268 | 0 | if !self.tile_profiling_enabled { |
1269 | 0 | return; |
1270 | 0 | } |
1271 | | |
1272 | 0 | let elapsed_ns = timer.start.elapsed().as_nanos() as u64; |
1273 | 0 | let idx = timer.level as usize; |
1274 | 0 | self.tile_stats[idx].add_sample(elapsed_ns, elements, flops); |
1275 | 0 | } |
1276 | | |
1277 | | /// Get tile statistics for a given level. |
1278 | | #[must_use] |
1279 | 0 | pub fn tile_stats(&self, level: TileLevel) -> &TileStats { |
1280 | 0 | &self.tile_stats[level as usize] |
1281 | 0 | } |
1282 | | |
1283 | | /// Get mutable tile statistics for a given level. |
1284 | 0 | pub fn tile_stats_mut(&mut self, level: TileLevel) -> &mut TileStats { |
1285 | 0 | &mut self.tile_stats[level as usize] |
1286 | 0 | } |
1287 | | |
1288 | | /// Get all tile statistics as a slice. |
1289 | | #[must_use] |
1290 | 0 | pub fn all_tile_stats(&self) -> &[TileStats; 3] { |
1291 | 0 | &self.tile_stats |
1292 | 0 | } |
1293 | | |
1294 | | /// Reset tile statistics for all levels. |
1295 | 0 | pub fn reset_tile_stats(&mut self) { |
1296 | 0 | self.tile_stats = [ |
1297 | 0 | TileStats::new(TileLevel::Macro), |
1298 | 0 | TileStats::new(TileLevel::Midi), |
1299 | 0 | TileStats::new(TileLevel::Micro), |
1300 | 0 | ]; |
1301 | 0 | } |
1302 | | |
1303 | | /// Generate tile profiling summary report. |
1304 | | /// |
1305 | | /// # Example Output |
1306 | | /// ```text |
1307 | | /// === Tile Profiling Summary (TILING-SPEC-001) === |
1308 | | /// Level Samples Avg µs GFLOP/s AI Elements |
1309 | | /// Macro 128 1234.5 12.34 0.50 1048576 |
1310 | | /// Midi 2048 78.2 45.67 2.00 65536 |
1311 | | /// Micro 32768 4.9 89.12 4.00 4096 |
1312 | | /// ``` |
1313 | | #[must_use] |
1314 | 0 | pub fn tile_summary(&self) -> String { |
1315 | 0 | let mut report = String::new(); |
1316 | 0 | report.push_str("=== Tile Profiling Summary (TILING-SPEC-001) ===\n"); |
1317 | 0 | report.push_str("Level Samples Avg µs GFLOP/s AI Elements\n"); |
1318 | | |
1319 | 0 | for stats in &self.tile_stats { |
1320 | 0 | if stats.count > 0 { |
1321 | 0 | report.push_str(&format!( |
1322 | 0 | "{:8} {:9} {:8.1} {:8.2} {:4.2} {:10}\n", |
1323 | 0 | stats.level.name(), |
1324 | 0 | stats.count, |
1325 | 0 | stats.avg_us(), |
1326 | 0 | stats.gflops(), |
1327 | 0 | stats.arithmetic_intensity(), |
1328 | 0 | stats.total_elements / stats.count.max(1) |
1329 | 0 | )); |
1330 | 0 | } |
1331 | | } |
1332 | | |
1333 | 0 | report |
1334 | 0 | } |
1335 | | |
1336 | | /// Export tile statistics as JSON. |
1337 | | /// |
1338 | | /// Compatible with pmat metrics integration. |
1339 | | #[must_use] |
1340 | 0 | pub fn tile_stats_to_json(&self) -> String { |
1341 | 0 | let tiles: Vec<String> = self |
1342 | 0 | .tile_stats |
1343 | 0 | .iter() |
1344 | 0 | .filter(|s| s.count > 0) |
1345 | 0 | .map(|s| { |
1346 | 0 | format!( |
1347 | 0 | r#"{{"level":"{}","count":{},"total_ns":{},"avg_us":{:.2},"min_us":{:.2},"max_us":{:.2},"gflops":{:.2},"arithmetic_intensity":{:.2},"total_elements":{},"total_flops":{}}}"#, |
1348 | 0 | s.level.name(), |
1349 | | s.count, |
1350 | | s.total_ns, |
1351 | 0 | s.avg_us(), |
1352 | 0 | s.min_ns as f64 / 1000.0, |
1353 | 0 | s.max_ns as f64 / 1000.0, |
1354 | 0 | s.gflops(), |
1355 | 0 | s.arithmetic_intensity(), |
1356 | | s.total_elements, |
1357 | | s.total_flops |
1358 | | ) |
1359 | 0 | }) |
1360 | 0 | .collect(); |
1361 | | |
1362 | 0 | format!( |
1363 | 0 | r#"{{"tile_profiling_enabled":{},"tiles":[{}]}}"#, |
1364 | | self.tile_profiling_enabled, |
1365 | 0 | tiles.join(",") |
1366 | | ) |
1367 | 0 | } |
1368 | | } |
1369 | | |
1370 | | /// Kernel checksum for divergence detection. |
1371 | | /// |
1372 | | /// CORRECTNESS-011: Captures output checksum per kernel invocation. |
1373 | | #[derive(Debug, Clone)] |
1374 | | pub struct KernelChecksum { |
1375 | | /// Kernel/brick name |
1376 | | pub name: String, |
1377 | | /// Layer index |
1378 | | pub layer_idx: usize, |
1379 | | /// Sequence position |
1380 | | pub position: u32, |
1381 | | /// FNV-1a checksum of first 64 output floats |
1382 | | pub checksum: u64, |
1383 | | } |
1384 | | |
1385 | | /// Information about a detected divergence between CPU and GPU. |
1386 | | #[derive(Debug, Clone)] |
1387 | | pub struct DivergenceInfo { |
1388 | | /// Name of the divergent kernel |
1389 | | pub kernel_name: String, |
1390 | | /// Layer where divergence occurred |
1391 | | pub layer_idx: usize, |
1392 | | /// Position where divergence occurred |
1393 | | pub position: u32, |
1394 | | /// Expected checksum (from CPU/reference) |
1395 | | pub expected_checksum: u64, |
1396 | | /// Actual checksum (from GPU/test) |
1397 | | pub actual_checksum: u64, |
1398 | | } |
1399 | | |
1400 | | impl fmt::Display for DivergenceInfo { |
1401 | 0 | fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { |
1402 | 0 | write!( |
1403 | 0 | f, |
1404 | 0 | "DIVERGENCE at '{}' (layer {}, pos {}): expected 0x{:016X}, got 0x{:016X}", |
1405 | | self.kernel_name, |
1406 | | self.layer_idx, |
1407 | | self.position, |
1408 | | self.expected_checksum, |
1409 | | self.actual_checksum |
1410 | | ) |
1411 | 0 | } |
1412 | | } |
1413 | | |
1414 | | /// FNV-1a hash of f32 slice (first 64 elements for efficiency). |
1415 | | /// |
1416 | | /// Used for quick divergence detection between CPU and GPU outputs. |
1417 | | #[inline] |
1418 | 0 | pub fn fnv1a_f32_checksum(data: &[f32]) -> u64 { |
1419 | | const FNV_OFFSET: u64 = 0xcbf29ce484222325; |
1420 | | const FNV_PRIME: u64 = 0x100000001b3; |
1421 | | |
1422 | 0 | let mut hash = FNV_OFFSET; |
1423 | 0 | let len = data.len().min(64); |
1424 | 0 | for &val in &data[..len] { |
1425 | 0 | let bytes = val.to_le_bytes(); |
1426 | 0 | for byte in bytes { |
1427 | 0 | hash ^= u64::from(byte); |
1428 | 0 | hash = hash.wrapping_mul(FNV_PRIME); |
1429 | 0 | } |
1430 | | } |
1431 | 0 | hash |
1432 | 0 | } |
1433 | | |
1434 | | /// Macro for convenient brick timing with automatic sync. |
1435 | | /// |
1436 | | /// # Usage |
1437 | | /// |
1438 | | /// ```rust,ignore |
1439 | | /// time_brick!(profiler, "RmsNorm", 1, { |
1440 | | /// rmsnorm_kernel.launch(); |
1441 | | /// stream.synchronize(); // REQUIRED for GPU |
1442 | | /// }); |
1443 | | /// ``` |
1444 | | #[macro_export] |
1445 | | macro_rules! time_brick { |
1446 | | ($profiler:expr, $name:expr, $elements:expr, $body:block) => {{ |
1447 | | let timer = $profiler.start($name); |
1448 | | let result = $body; |
1449 | | $profiler.stop(timer, $elements); |
1450 | | result |
1451 | | }}; |
1452 | | } |
1453 | | |
1454 | | #[cfg(test)] |
1455 | | mod tests { |
1456 | | use super::*; |
1457 | | |
1458 | | // ======================================================================== |
1459 | | // TileStats Tests |
1460 | | // ======================================================================== |
1461 | | |
1462 | | #[test] |
1463 | | fn test_tile_stats_new() { |
1464 | | let stats = TileStats::new(TileLevel::Macro); |
1465 | | assert_eq!(stats.level, TileLevel::Macro); |
1466 | | assert_eq!(stats.count, 0); |
1467 | | assert_eq!(stats.total_ns, 0); |
1468 | | assert_eq!(stats.min_ns, u64::MAX); |
1469 | | assert_eq!(stats.max_ns, 0); |
1470 | | } |
1471 | | |
1472 | | #[test] |
1473 | | fn test_tile_stats_add_sample() { |
1474 | | let mut stats = TileStats::new(TileLevel::Midi); |
1475 | | stats.add_sample(1000, 100, 200); |
1476 | | assert_eq!(stats.count, 1); |
1477 | | assert_eq!(stats.total_ns, 1000); |
1478 | | assert_eq!(stats.min_ns, 1000); |
1479 | | assert_eq!(stats.max_ns, 1000); |
1480 | | assert_eq!(stats.total_elements, 100); |
1481 | | assert_eq!(stats.total_flops, 200); |
1482 | | |
1483 | | stats.add_sample(2000, 150, 300); |
1484 | | assert_eq!(stats.count, 2); |
1485 | | assert_eq!(stats.total_ns, 3000); |
1486 | | assert_eq!(stats.min_ns, 1000); |
1487 | | assert_eq!(stats.max_ns, 2000); |
1488 | | } |
1489 | | |
1490 | | #[test] |
1491 | | fn test_tile_stats_avg_us() { |
1492 | | let mut stats = TileStats::new(TileLevel::Micro); |
1493 | | assert_eq!(stats.avg_us(), 0.0); |
1494 | | |
1495 | | stats.add_sample(2000_000, 100, 200); // 2000 µs |
1496 | | assert!((stats.avg_us() - 2000.0).abs() < 0.01); |
1497 | | |
1498 | | stats.add_sample(4000_000, 100, 200); // 4000 µs |
1499 | | assert!((stats.avg_us() - 3000.0).abs() < 0.01); // (2000 + 4000) / 2 |
1500 | | } |
1501 | | |
1502 | | #[test] |
1503 | | fn test_tile_stats_throughput() { |
1504 | | let mut stats = TileStats::new(TileLevel::Macro); |
1505 | | assert_eq!(stats.throughput(), 0.0); |
1506 | | |
1507 | | // 1 billion ns = 1 second, 1000 elements = 1000 elem/s |
1508 | | stats.add_sample(1_000_000_000, 1000, 0); |
1509 | | assert!((stats.throughput() - 1000.0).abs() < 1.0); |
1510 | | } |
1511 | | |
1512 | | #[test] |
1513 | | fn test_tile_stats_gflops() { |
1514 | | let mut stats = TileStats::new(TileLevel::Macro); |
1515 | | assert_eq!(stats.gflops(), 0.0); |
1516 | | |
1517 | | // 1 second, 1 billion FLOPs = 1 GFLOP/s |
1518 | | stats.add_sample(1_000_000_000, 100, 1_000_000_000); |
1519 | | assert!((stats.gflops() - 1.0).abs() < 0.01); |
1520 | | } |
1521 | | |
1522 | | #[test] |
1523 | | fn test_tile_stats_arithmetic_intensity() { |
1524 | | let mut stats = TileStats::new(TileLevel::Midi); |
1525 | | assert_eq!(stats.arithmetic_intensity(), 0.0); |
1526 | | |
1527 | | // 1000 elements * 4 bytes = 4000 bytes, 4000 flops = 1.0 AI |
1528 | | stats.add_sample(1000, 1000, 4000); |
1529 | | assert!((stats.arithmetic_intensity() - 1.0).abs() < 0.01); |
1530 | | } |
1531 | | |
1532 | | #[test] |
1533 | | fn test_tile_level_name() { |
1534 | | assert_eq!(TileLevel::Macro.name(), "macro"); |
1535 | | assert_eq!(TileLevel::Midi.name(), "midi"); |
1536 | | assert_eq!(TileLevel::Micro.name(), "micro"); |
1537 | | } |
1538 | | |
1539 | | // ======================================================================== |
1540 | | // BrickProfiler Tests |
1541 | | // ======================================================================== |
1542 | | |
1543 | | #[test] |
1544 | | fn test_brick_profiler_new() { |
1545 | | let profiler = BrickProfiler::new(); |
1546 | | assert!(!profiler.is_enabled()); |
1547 | | assert_eq!(profiler.total_tokens(), 0); |
1548 | | assert_eq!(profiler.total_ns(), 0); |
1549 | | } |
1550 | | |
1551 | | #[test] |
1552 | | fn test_brick_profiler_enabled() { |
1553 | | let profiler = BrickProfiler::enabled(); |
1554 | | assert!(profiler.is_enabled()); |
1555 | | } |
1556 | | |
1557 | | #[test] |
1558 | | fn test_brick_profiler_enable_disable() { |
1559 | | let mut profiler = BrickProfiler::new(); |
1560 | | assert!(!profiler.is_enabled()); |
1561 | | |
1562 | | profiler.enable(); |
1563 | | assert!(profiler.is_enabled()); |
1564 | | |
1565 | | profiler.disable(); |
1566 | | assert!(!profiler.is_enabled()); |
1567 | | } |
1568 | | |
1569 | | #[test] |
1570 | | fn test_brick_profiler_sync_mode() { |
1571 | | let mut profiler = BrickProfiler::new(); |
1572 | | assert_eq!(profiler.sync_mode(), SyncMode::Deferred); |
1573 | | |
1574 | | profiler.set_sync_mode(SyncMode::Immediate); |
1575 | | assert_eq!(profiler.sync_mode(), SyncMode::Immediate); |
1576 | | } |
1577 | | |
1578 | | #[test] |
1579 | | fn test_brick_profiler_start_stop() { |
1580 | | let mut profiler = BrickProfiler::new(); |
1581 | | profiler.enable(); |
1582 | | |
1583 | | let timer = profiler.start("TestBrick"); |
1584 | | std::thread::sleep(std::time::Duration::from_micros(100)); |
1585 | | profiler.stop(timer, 10); |
1586 | | |
1587 | | // Should have recorded something |
1588 | | assert!(profiler.total_tokens() >= 10); |
1589 | | assert!(profiler.total_ns() > 0); |
1590 | | } |
1591 | | |
1592 | | #[test] |
1593 | | fn test_brick_profiler_start_stop_disabled() { |
1594 | | let mut profiler = BrickProfiler::new(); |
1595 | | // profiler is disabled by default |
1596 | | |
1597 | | let timer = profiler.start("TestBrick"); |
1598 | | profiler.stop(timer, 10); |
1599 | | |
1600 | | // Should NOT have recorded anything |
1601 | | assert_eq!(profiler.total_tokens(), 0); |
1602 | | assert_eq!(profiler.total_ns(), 0); |
1603 | | } |
1604 | | |
1605 | | #[test] |
1606 | | fn test_brick_profiler_brick_id_api() { |
1607 | | let mut profiler = BrickProfiler::new(); |
1608 | | profiler.enable(); |
1609 | | |
1610 | | let timer = profiler.start_brick(BrickId::RmsNorm); |
1611 | | std::thread::sleep(std::time::Duration::from_micros(50)); |
1612 | | profiler.stop_brick(timer, 5); |
1613 | | |
1614 | | let stats = profiler.brick_stats(BrickId::RmsNorm); |
1615 | | assert_eq!(stats.count, 1); |
1616 | | assert!(stats.total_ns > 0); |
1617 | | } |
1618 | | |
1619 | | #[test] |
1620 | | fn test_brick_profiler_deferred_api() { |
1621 | | let mut profiler = BrickProfiler::new(); |
1622 | | profiler.enable(); |
1623 | | |
1624 | | let start_ns = profiler.elapsed_ns(); |
1625 | | std::thread::sleep(std::time::Duration::from_micros(100)); |
1626 | | profiler.record_deferred(BrickId::QkvProjection, start_ns, 100); |
1627 | | |
1628 | | assert!(profiler.has_pending()); |
1629 | | assert_eq!(profiler.pending_count(), 1); |
1630 | | |
1631 | | let end_ns = profiler.elapsed_ns(); |
1632 | | profiler.finalize(end_ns); |
1633 | | |
1634 | | assert!(!profiler.has_pending()); |
1635 | | assert_eq!(profiler.pending_count(), 0); |
1636 | | |
1637 | | let stats = profiler.brick_stats(BrickId::QkvProjection); |
1638 | | assert_eq!(stats.count, 1); |
1639 | | } |
1640 | | |
1641 | | #[test] |
1642 | | fn test_brick_profiler_reset() { |
1643 | | let mut profiler = BrickProfiler::new(); |
1644 | | profiler.enable(); |
1645 | | |
1646 | | let timer = profiler.start_brick(BrickId::AttentionSoftmax); |
1647 | | profiler.stop_brick(timer, 10); |
1648 | | |
1649 | | assert!(profiler.total_tokens() > 0); |
1650 | | |
1651 | | profiler.reset(); |
1652 | | |
1653 | | assert_eq!(profiler.total_tokens(), 0); |
1654 | | assert_eq!(profiler.total_ns(), 0); |
1655 | | } |
1656 | | |
1657 | | #[test] |
1658 | | fn test_brick_profiler_tile_profiling() { |
1659 | | let mut profiler = BrickProfiler::new(); |
1660 | | assert!(!profiler.is_tile_profiling_enabled()); |
1661 | | |
1662 | | profiler.enable_tile_profiling(); |
1663 | | assert!(profiler.is_tile_profiling_enabled()); |
1664 | | |
1665 | | let timer = profiler.start_tile(TileLevel::Macro, 0, 0); |
1666 | | std::thread::sleep(std::time::Duration::from_micros(50)); |
1667 | | profiler.stop_tile(timer, 1024, 2048); |
1668 | | |
1669 | | let stats = profiler.tile_stats(TileLevel::Macro); |
1670 | | assert_eq!(stats.count, 1); |
1671 | | assert!(stats.total_ns > 0); |
1672 | | } |
1673 | | |
1674 | | #[test] |
1675 | | fn test_brick_profiler_tile_profiling_disabled() { |
1676 | | let mut profiler = BrickProfiler::new(); |
1677 | | // Tile profiling disabled by default |
1678 | | |
1679 | | let timer = profiler.start_tile(TileLevel::Midi, 1, 1); |
1680 | | profiler.stop_tile(timer, 512, 1024); |
1681 | | |
1682 | | let stats = profiler.tile_stats(TileLevel::Midi); |
1683 | | assert_eq!(stats.count, 0); |
1684 | | } |
1685 | | |
1686 | | // ======================================================================== |
1687 | | // Checksum Tests (CORRECTNESS-011) |
1688 | | // ======================================================================== |
1689 | | |
1690 | | #[test] |
1691 | | fn test_fnv1a_checksum_empty() { |
1692 | | let data: [f32; 0] = []; |
1693 | | let checksum = fnv1a_f32_checksum(&data); |
1694 | | // Should return offset basis for empty input |
1695 | | assert_eq!(checksum, 0xcbf29ce484222325); |
1696 | | } |
1697 | | |
1698 | | #[test] |
1699 | | fn test_fnv1a_checksum_deterministic() { |
1700 | | let data = [1.0f32, 2.0, 3.0, 4.0]; |
1701 | | let c1 = fnv1a_f32_checksum(&data); |
1702 | | let c2 = fnv1a_f32_checksum(&data); |
1703 | | assert_eq!(c1, c2); |
1704 | | } |
1705 | | |
1706 | | #[test] |
1707 | | fn test_fnv1a_checksum_different_inputs() { |
1708 | | let data1 = [1.0f32, 2.0, 3.0]; |
1709 | | let data2 = [1.0f32, 2.0, 4.0]; |
1710 | | let c1 = fnv1a_f32_checksum(&data1); |
1711 | | let c2 = fnv1a_f32_checksum(&data2); |
1712 | | assert_ne!(c1, c2); |
1713 | | } |
1714 | | |
1715 | | #[test] |
1716 | | fn test_fnv1a_checksum_truncates_at_64() { |
1717 | | let data_short: Vec<f32> = (0..64).map(|i| i as f32).collect(); |
1718 | | let data_long: Vec<f32> = (0..100).map(|i| i as f32).collect(); |
1719 | | |
1720 | | let c1 = fnv1a_f32_checksum(&data_short); |
1721 | | let c2 = fnv1a_f32_checksum(&data_long); |
1722 | | // Both should hash only first 64 elements |
1723 | | assert_eq!(c1, c2); |
1724 | | } |
1725 | | |
1726 | | #[test] |
1727 | | fn test_brick_profiler_divergence_detection() { |
1728 | | let mut cpu_profiler = BrickProfiler::new(); |
1729 | | let mut gpu_profiler = BrickProfiler::new(); |
1730 | | cpu_profiler.enable(); |
1731 | | gpu_profiler.enable(); |
1732 | | |
1733 | | // Record same checksum on both |
1734 | | let data = [1.0f32, 2.0, 3.0, 4.0]; |
1735 | | cpu_profiler.record_checksum("TestKernel", 0, 0, &data); |
1736 | | gpu_profiler.record_checksum("TestKernel", 0, 0, &data); |
1737 | | |
1738 | | // No divergence |
1739 | | assert!(gpu_profiler.find_divergence(&cpu_profiler).is_none()); |
1740 | | |
1741 | | // Now record different checksum |
1742 | | let different_data = [1.0f32, 2.0, 3.0, 5.0]; // Changed last element |
1743 | | gpu_profiler.reset_checksums(); |
1744 | | gpu_profiler.record_checksum("TestKernel", 0, 0, &different_data); |
1745 | | |
1746 | | // Should find divergence |
1747 | | let div = gpu_profiler.find_divergence(&cpu_profiler); |
1748 | | assert!(div.is_some()); |
1749 | | let div = div.unwrap(); |
1750 | | assert_eq!(div.kernel_name, "TestKernel"); |
1751 | | assert_eq!(div.layer_idx, 0); |
1752 | | assert_eq!(div.position, 0); |
1753 | | } |
1754 | | |
1755 | | // ======================================================================== |
1756 | | // Falsification Tests |
1757 | | // ======================================================================== |
1758 | | |
1759 | | /// FALSIFICATION TEST: TileStats min/max monotonicity |
1760 | | /// |
1761 | | /// After any sequence of add_sample calls, min_ns <= max_ns must hold. |
1762 | | #[test] |
1763 | | fn test_falsify_tile_stats_min_max_monotonicity() { |
1764 | | let mut stats = TileStats::new(TileLevel::Macro); |
1765 | | |
1766 | | // Add samples with varying elapsed times |
1767 | | for ns in [1000, 500, 2000, 100, 5000, 50] { |
1768 | | stats.add_sample(ns, 10, 20); |
1769 | | assert!( |
1770 | | stats.min_ns <= stats.max_ns, |
1771 | | "FALSIFICATION FAILED: min {} > max {} after adding {}", |
1772 | | stats.min_ns, |
1773 | | stats.max_ns, |
1774 | | ns |
1775 | | ); |
1776 | | } |
1777 | | |
1778 | | assert_eq!(stats.min_ns, 50); |
1779 | | assert_eq!(stats.max_ns, 5000); |
1780 | | } |
1781 | | |
1782 | | /// FALSIFICATION TEST: BrickProfiler total_tokens accumulation |
1783 | | /// |
1784 | | /// total_tokens must equal sum of all elements passed to stop/stop_brick. |
1785 | | #[test] |
1786 | | fn test_falsify_total_tokens_accumulation() { |
1787 | | let mut profiler = BrickProfiler::new(); |
1788 | | profiler.enable(); |
1789 | | |
1790 | | let mut expected_total = 0u64; |
1791 | | let element_counts = [10, 20, 30, 15, 25]; |
1792 | | |
1793 | | for &count in &element_counts { |
1794 | | let timer = profiler.start_brick(BrickId::RmsNorm); |
1795 | | profiler.stop_brick(timer, count); |
1796 | | expected_total += count; |
1797 | | } |
1798 | | |
1799 | | assert_eq!( |
1800 | | profiler.total_tokens(), |
1801 | | expected_total, |
1802 | | "FALSIFICATION FAILED: total_tokens {} != expected {}", |
1803 | | profiler.total_tokens(), |
1804 | | expected_total |
1805 | | ); |
1806 | | } |
1807 | | |
1808 | | /// FALSIFICATION TEST: Checksum collision resistance |
1809 | | /// |
1810 | | /// Different float patterns should produce different checksums. |
1811 | | #[test] |
1812 | | fn test_falsify_checksum_collision_resistance() { |
1813 | | // Generate various patterns that might collide in weak hashes |
1814 | | let patterns: Vec<Vec<f32>> = vec![ |
1815 | | vec![0.0; 10], |
1816 | | vec![1.0; 10], |
1817 | | vec![-1.0; 10], |
1818 | | (0..10).map(|i| i as f32).collect(), |
1819 | | (0..10).map(|i| -(i as f32)).collect(), |
1820 | | vec![f32::MIN_POSITIVE; 10], |
1821 | | vec![f32::MAX; 10], |
1822 | | ]; |
1823 | | |
1824 | | let checksums: Vec<u64> = patterns.iter().map(|p| fnv1a_f32_checksum(p)).collect(); |
1825 | | |
1826 | | // Check all pairs for uniqueness |
1827 | | for i in 0..checksums.len() { |
1828 | | for j in (i + 1)..checksums.len() { |
1829 | | assert_ne!( |
1830 | | checksums[i], checksums[j], |
1831 | | "FALSIFICATION FAILED: patterns {} and {} collide with checksum {:016X}", |
1832 | | i, j, checksums[i] |
1833 | | ); |
1834 | | } |
1835 | | } |
1836 | | } |
1837 | | |
1838 | | // ======================================================================== |
1839 | | // Additional Coverage Tests |
1840 | | // ======================================================================== |
1841 | | |
1842 | | #[test] |
1843 | | fn test_tile_stats_cache_efficiency() { |
1844 | | let mut stats = TileStats::new(TileLevel::Macro); |
1845 | | |
1846 | | // Zero peak_gflops should return 0.0 |
1847 | | assert_eq!(stats.cache_efficiency(0.0), 0.0); |
1848 | | assert_eq!(stats.cache_efficiency(-1.0), 0.0); |
1849 | | |
1850 | | // 1 second, 1 billion FLOPs = 1 GFLOP/s |
1851 | | stats.add_sample(1_000_000_000, 100, 1_000_000_000); |
1852 | | let efficiency = stats.cache_efficiency(10.0); // 10 GFLOP/s peak |
1853 | | assert!((efficiency - 0.1).abs() < 0.01); |
1854 | | |
1855 | | // Efficiency capped at 1.0 |
1856 | | let capped = stats.cache_efficiency(0.5); // Lower peak than actual |
1857 | | assert!((capped - 1.0).abs() < 0.001); |
1858 | | } |
1859 | | |
1860 | | #[test] |
1861 | | fn test_brick_profiler_record_elapsed() { |
1862 | | let mut profiler = BrickProfiler::new(); |
1863 | | profiler.enable(); |
1864 | | |
1865 | | let duration = std::time::Duration::from_micros(1000); |
1866 | | profiler.record_elapsed("MyBrick", duration, 100); |
1867 | | |
1868 | | assert!(profiler.total_tokens() >= 100); |
1869 | | assert!(profiler.total_ns() > 0); |
1870 | | } |
1871 | | |
1872 | | #[test] |
1873 | | fn test_brick_profiler_record_elapsed_disabled() { |
1874 | | let mut profiler = BrickProfiler::new(); |
1875 | | // profiler is disabled |
1876 | | |
1877 | | let duration = std::time::Duration::from_micros(1000); |
1878 | | profiler.record_elapsed("MyBrick", duration, 100); |
1879 | | |
1880 | | // Should not record when disabled |
1881 | | assert_eq!(profiler.total_tokens(), 0); |
1882 | | } |
1883 | | |
1884 | | #[test] |
1885 | | fn test_brick_profiler_record_elapsed_with_bytes() { |
1886 | | let mut profiler = BrickProfiler::new(); |
1887 | | profiler.enable(); |
1888 | | |
1889 | | let duration = std::time::Duration::from_micros(500); |
1890 | | profiler.record_elapsed_with_bytes("ByteBrick", duration, 200, 4096, 2048); |
1891 | | |
1892 | | assert!(profiler.total_tokens() >= 200); |
1893 | | } |
1894 | | |
1895 | | #[test] |
1896 | | fn test_brick_profiler_set_brick_bottleneck() { |
1897 | | let mut profiler = BrickProfiler::new(); |
1898 | | profiler.enable(); |
1899 | | |
1900 | | // Record something first |
1901 | | let timer = profiler.start("TestBrick"); |
1902 | | profiler.stop(timer, 10); |
1903 | | |
1904 | | profiler.set_brick_bottleneck("TestBrick", BrickBottleneck::Memory); |
1905 | | // Should not panic |
1906 | | } |
1907 | | |
1908 | | #[test] |
1909 | | fn test_brick_profiler_category_stats() { |
1910 | | let mut profiler = BrickProfiler::new(); |
1911 | | profiler.enable(); |
1912 | | |
1913 | | // Record normalization brick |
1914 | | let timer = profiler.start_brick(BrickId::RmsNorm); |
1915 | | std::thread::sleep(std::time::Duration::from_micros(10)); |
1916 | | profiler.stop_brick(timer, 100); |
1917 | | |
1918 | | let category_stats = profiler.category_stats(); |
1919 | | // Should have accumulated in Norm category |
1920 | | let norm_stats = &category_stats[BrickCategory::Norm as usize]; |
1921 | | assert!(norm_stats.count >= 1); |
1922 | | } |
1923 | | |
1924 | | #[test] |
1925 | | fn test_brick_profiler_graph_operations() { |
1926 | | let mut profiler = BrickProfiler::new(); |
1927 | | profiler.enable(); |
1928 | | |
1929 | | // Graph disabled by default |
1930 | | assert!(!profiler.is_graph_enabled()); |
1931 | | |
1932 | | profiler.enable_graph(); |
1933 | | assert!(profiler.is_graph_enabled()); |
1934 | | |
1935 | | // Push a scope using Layer variant |
1936 | | let node = ExecutionNode::Layer { index: 0 }; |
1937 | | let scope_id = profiler.graph_push_scope(node); |
1938 | | assert!(scope_id.is_some()); |
1939 | | |
1940 | | // Record a brick |
1941 | | profiler.graph_record_brick(BrickId::RmsNorm, 1000, 100); |
1942 | | |
1943 | | // Pop the scope |
1944 | | let popped_id = profiler.graph_pop_scope(); |
1945 | | assert!(popped_id.is_some()); |
1946 | | |
1947 | | assert!(profiler.graph_is_scope_balanced()); |
1948 | | |
1949 | | profiler.disable_graph(); |
1950 | | assert!(!profiler.is_graph_enabled()); |
1951 | | } |
1952 | | |
1953 | | #[test] |
1954 | | fn test_brick_profiler_graph_to_dot() { |
1955 | | let mut profiler = BrickProfiler::new(); |
1956 | | profiler.enable(); |
1957 | | profiler.enable_graph(); |
1958 | | |
1959 | | let node = ExecutionNode::Layer { index: 1 }; |
1960 | | profiler.graph_push_scope(node); |
1961 | | profiler.graph_record_brick(BrickId::RmsNorm, 500, 50); |
1962 | | profiler.graph_pop_scope(); |
1963 | | |
1964 | | let dot = profiler.graph_to_dot(); |
1965 | | assert!(dot.contains("digraph")); |
1966 | | } |
1967 | | |
1968 | | #[test] |
1969 | | fn test_brick_profiler_graph_clear() { |
1970 | | let mut profiler = BrickProfiler::new(); |
1971 | | profiler.enable(); |
1972 | | profiler.enable_graph(); |
1973 | | |
1974 | | let node = ExecutionNode::Layer { index: 2 }; |
1975 | | profiler.graph_push_scope(node); |
1976 | | profiler.graph_pop_scope(); |
1977 | | |
1978 | | profiler.graph_clear(); |
1979 | | // Should be balanced after clear |
1980 | | assert!(profiler.graph_is_scope_balanced()); |
1981 | | } |
1982 | | |
1983 | | #[test] |
1984 | | fn test_brick_profiler_l2_cache_hit_rate() { |
1985 | | let mut profiler = BrickProfiler::new(); |
1986 | | |
1987 | | // Default is None |
1988 | | assert!(profiler.l2_cache_hit_rate().is_none()); |
1989 | | |
1990 | | profiler.set_l2_cache_hit_rate(0.95); |
1991 | | assert_eq!(profiler.l2_cache_hit_rate(), Some(0.95)); |
1992 | | } |
1993 | | |
1994 | | #[test] |
1995 | | fn test_brick_profiler_zero_copy() { |
1996 | | let mut profiler = BrickProfiler::new(); |
1997 | | |
1998 | | // Default is false |
1999 | | assert!(!profiler.is_zero_copy()); |
2000 | | |
2001 | | profiler.set_zero_copy(true); |
2002 | | assert!(profiler.is_zero_copy()); |
2003 | | |
2004 | | profiler.set_zero_copy(false); |
2005 | | assert!(!profiler.is_zero_copy()); |
2006 | | } |
2007 | | |
2008 | | #[test] |
2009 | | fn test_brick_profiler_reset_epoch() { |
2010 | | let mut profiler = BrickProfiler::new(); |
2011 | | profiler.enable(); |
2012 | | |
2013 | | // Let some time pass |
2014 | | std::thread::sleep(std::time::Duration::from_micros(100)); |
2015 | | let ns1 = profiler.elapsed_ns(); |
2016 | | assert!(ns1 > 0); |
2017 | | |
2018 | | profiler.reset_epoch(); |
2019 | | let ns2 = profiler.elapsed_ns(); |
2020 | | // After reset, elapsed should be close to zero |
2021 | | assert!(ns2 < ns1); |
2022 | | } |
2023 | | |
2024 | | #[test] |
2025 | | fn test_brick_profiler_brick_stats_mut() { |
2026 | | let mut profiler = BrickProfiler::new(); |
2027 | | profiler.enable(); |
2028 | | |
2029 | | // Get mutable stats and modify |
2030 | | let stats = profiler.brick_stats_mut(BrickId::RmsNorm); |
2031 | | stats.count = 42; |
2032 | | |
2033 | | // Verify modification persisted |
2034 | | let stats = profiler.brick_stats(BrickId::RmsNorm); |
2035 | | assert_eq!(stats.count, 42); |
2036 | | } |
2037 | | |
2038 | | #[test] |
2039 | | fn test_brick_profiler_record_deferred_dynamic() { |
2040 | | let mut profiler = BrickProfiler::new(); |
2041 | | profiler.enable(); |
2042 | | |
2043 | | let start_ns = profiler.elapsed_ns(); |
2044 | | std::thread::sleep(std::time::Duration::from_micros(50)); |
2045 | | profiler.record_deferred_dynamic("DynamicBrick", start_ns, 75); |
2046 | | |
2047 | | assert!(profiler.has_pending()); |
2048 | | assert_eq!(profiler.pending_count(), 1); |
2049 | | |
2050 | | let end_ns = profiler.elapsed_ns(); |
2051 | | profiler.finalize(end_ns); |
2052 | | |
2053 | | assert!(!profiler.has_pending()); |
2054 | | } |
2055 | | |
2056 | | #[test] |
2057 | | fn test_tile_stats_default() { |
2058 | | let stats = TileStats::default(); |
2059 | | assert_eq!(stats.level, TileLevel::Macro); // Default is Macro |
2060 | | assert_eq!(stats.count, 0); |
2061 | | } |
2062 | | |
2063 | | #[test] |
2064 | | fn test_tile_level_default() { |
2065 | | let level = TileLevel::default(); |
2066 | | assert_eq!(level, TileLevel::Macro); |
2067 | | } |
2068 | | |
2069 | | #[test] |
2070 | | fn test_brick_profiler_execution_graph_accessors() { |
2071 | | let mut profiler = BrickProfiler::new(); |
2072 | | |
2073 | | // Read-only access |
2074 | | let _graph = profiler.execution_graph(); |
2075 | | |
2076 | | // Mutable access |
2077 | | let _graph_mut = profiler.execution_graph_mut(); |
2078 | | } |
2079 | | |
2080 | | #[test] |
2081 | | fn test_brick_profiler_graph_record_kernel() { |
2082 | | let mut profiler = BrickProfiler::new(); |
2083 | | profiler.enable(); |
2084 | | profiler.enable_graph(); |
2085 | | |
2086 | | let node = ExecutionNode::Layer { index: 3 }; |
2087 | | profiler.graph_push_scope(node); |
2088 | | // graph_record_kernel(name, ptx_hash, grid, block, shared_mem) |
2089 | | profiler.graph_record_kernel("my_kernel", 0x12345678, (1, 1, 1), (256, 1, 1), 4096); |
2090 | | profiler.graph_pop_scope(); |
2091 | | |
2092 | | // Should be able to convert to DOT |
2093 | | let dot = profiler.graph_to_dot(); |
2094 | | assert!(!dot.is_empty()); |
2095 | | } |
2096 | | |
2097 | | #[test] |
2098 | | fn test_brick_profiler_graph_disabled_operations() { |
2099 | | let mut profiler = BrickProfiler::new(); |
2100 | | profiler.enable(); |
2101 | | // Graph is NOT enabled |
2102 | | |
2103 | | // Operations should be no-ops when graph disabled |
2104 | | let node = ExecutionNode::Layer { index: 4 }; |
2105 | | let scope_id = profiler.graph_push_scope(node); |
2106 | | assert!(scope_id.is_none()); // Returns None when disabled |
2107 | | |
2108 | | let popped = profiler.graph_pop_scope(); |
2109 | | assert!(popped.is_none()); |
2110 | | } |
2111 | | } |