chess_vector_engine/utils/
profiler.rs

1use std::collections::HashMap;
2use std::sync::{Arc, RwLock};
3use std::time::{Duration, Instant};
4
5/// High-performance profiler for chess engine operations
6pub struct Profiler {
7    timers: RwLock<HashMap<String, TimerData>>,
8    counters: RwLock<HashMap<String, CounterData>>,
9    memory_snapshots: RwLock<Vec<MemorySnapshot>>,
10    start_time: Instant,
11    enabled: bool,
12}
13
14/// Timer measurement data
15#[derive(Debug, Clone)]
16struct TimerData {
17    total_time: Duration,
18    count: u64,
19    min_time: Duration,
20    max_time: Duration,
21    current_start: Option<Instant>,
22}
23
24/// Counter data
25#[derive(Debug, Clone)]
26struct CounterData {
27    value: i64,
28    min_value: i64,
29    max_value: i64,
30    total_increments: u64,
31}
32
33/// Memory usage snapshot
34#[derive(Debug, Clone)]
35pub struct MemorySnapshot {
36    pub timestamp: Instant,
37    pub allocated_bytes: usize,
38    pub peak_bytes: usize,
39    pub active_allocations: usize,
40}
41
42impl Profiler {
43    /// Create a new profiler
44    pub fn new() -> Self {
45        Self {
46            timers: RwLock::new(HashMap::new()),
47            counters: RwLock::new(HashMap::new()),
48            memory_snapshots: RwLock::new(Vec::new()),
49            start_time: Instant::now(),
50            enabled: true,
51        }
52    }
53
54    /// Enable or disable profiling
55    pub fn set_enabled(&mut self, enabled: bool) {
56        self.enabled = enabled;
57    }
58
59    /// Start timing an operation
60    pub fn start_timer(&self, name: &str) {
61        if !self.enabled {
62            return;
63        }
64
65        let mut timers = self.timers.write().unwrap();
66        let timer = timers.entry(name.to_string()).or_insert_with(|| TimerData {
67            total_time: Duration::ZERO,
68            count: 0,
69            min_time: Duration::MAX,
70            max_time: Duration::ZERO,
71            current_start: None,
72        });
73
74        timer.current_start = Some(Instant::now());
75    }
76
77    /// End timing an operation
78    pub fn end_timer(&self, name: &str) {
79        if !self.enabled {
80            return;
81        }
82
83        let end_time = Instant::now();
84        let mut timers = self.timers.write().unwrap();
85
86        if let Some(timer) = timers.get_mut(name) {
87            if let Some(start_time) = timer.current_start.take() {
88                let elapsed = end_time.duration_since(start_time);
89
90                timer.total_time += elapsed;
91                timer.count += 1;
92                timer.min_time = timer.min_time.min(elapsed);
93                timer.max_time = timer.max_time.max(elapsed);
94            }
95        }
96    }
97
98    /// Time a closure
99    pub fn time<F, R>(&self, name: &str, f: F) -> R
100    where
101        F: FnOnce() -> R,
102    {
103        self.start_timer(name);
104        let result = f();
105        self.end_timer(name);
106        result
107    }
108
109    /// Increment a counter
110    pub fn increment_counter(&self, name: &str, value: i64) {
111        if !self.enabled {
112            return;
113        }
114
115        let mut counters = self.counters.write().unwrap();
116        let counter = counters
117            .entry(name.to_string())
118            .or_insert_with(|| CounterData {
119                value: 0,
120                min_value: i64::MAX,
121                max_value: i64::MIN,
122                total_increments: 0,
123            });
124
125        counter.value += value;
126        counter.min_value = counter.min_value.min(counter.value);
127        counter.max_value = counter.max_value.max(counter.value);
128        counter.total_increments += 1;
129    }
130
131    /// Set a counter to a specific value
132    pub fn set_counter(&self, name: &str, value: i64) {
133        if !self.enabled {
134            return;
135        }
136
137        let mut counters = self.counters.write().unwrap();
138        let counter = counters
139            .entry(name.to_string())
140            .or_insert_with(|| CounterData {
141                value: 0,
142                min_value: i64::MAX,
143                max_value: i64::MIN,
144                total_increments: 0,
145            });
146
147        counter.value = value;
148        counter.min_value = counter.min_value.min(value);
149        counter.max_value = counter.max_value.max(value);
150    }
151
152    /// Take a memory snapshot
153    pub fn memory_snapshot(
154        &self,
155        allocated_bytes: usize,
156        peak_bytes: usize,
157        active_allocations: usize,
158    ) {
159        if !self.enabled {
160            return;
161        }
162
163        let mut snapshots = self.memory_snapshots.write().unwrap();
164        snapshots.push(MemorySnapshot {
165            timestamp: Instant::now(),
166            allocated_bytes,
167            peak_bytes,
168            active_allocations,
169        });
170
171        // Keep only last 1000 snapshots
172        if snapshots.len() > 1000 {
173            let len = snapshots.len();
174            snapshots.drain(0..len - 1000);
175        }
176    }
177
178    /// Get timer statistics
179    pub fn get_timer_stats(&self, name: &str) -> Option<TimerStats> {
180        let timers = self.timers.read().unwrap();
181        timers.get(name).map(|timer| TimerStats {
182            name: name.to_string(),
183            total_time: timer.total_time,
184            count: timer.count,
185            average_time: if timer.count > 0 {
186                timer.total_time / timer.count as u32
187            } else {
188                Duration::ZERO
189            },
190            min_time: if timer.min_time == Duration::MAX {
191                Duration::ZERO
192            } else {
193                timer.min_time
194            },
195            max_time: timer.max_time,
196        })
197    }
198
199    /// Get all timer statistics
200    pub fn get_all_timer_stats(&self) -> Vec<TimerStats> {
201        let timers = self.timers.read().unwrap();
202        timers
203            .iter()
204            .map(|(name, timer)| TimerStats {
205                name: name.clone(),
206                total_time: timer.total_time,
207                count: timer.count,
208                average_time: if timer.count > 0 {
209                    timer.total_time / timer.count as u32
210                } else {
211                    Duration::ZERO
212                },
213                min_time: if timer.min_time == Duration::MAX {
214                    Duration::ZERO
215                } else {
216                    timer.min_time
217                },
218                max_time: timer.max_time,
219            })
220            .collect()
221    }
222
223    /// Get counter statistics
224    pub fn get_counter_stats(&self, name: &str) -> Option<CounterStats> {
225        let counters = self.counters.read().unwrap();
226        counters.get(name).map(|counter| CounterStats {
227            name: name.to_string(),
228            current_value: counter.value,
229            min_value: if counter.min_value == i64::MAX {
230                0
231            } else {
232                counter.min_value
233            },
234            max_value: if counter.max_value == i64::MIN {
235                0
236            } else {
237                counter.max_value
238            },
239            total_increments: counter.total_increments,
240        })
241    }
242
243    /// Get all counter statistics
244    pub fn get_all_counter_stats(&self) -> Vec<CounterStats> {
245        let counters = self.counters.read().unwrap();
246        counters
247            .iter()
248            .map(|(name, counter)| CounterStats {
249                name: name.clone(),
250                current_value: counter.value,
251                min_value: if counter.min_value == i64::MAX {
252                    0
253                } else {
254                    counter.min_value
255                },
256                max_value: if counter.max_value == i64::MIN {
257                    0
258                } else {
259                    counter.max_value
260                },
261                total_increments: counter.total_increments,
262            })
263            .collect()
264    }
265
266    /// Get recent memory snapshots
267    pub fn get_memory_snapshots(&self, last_n: Option<usize>) -> Vec<MemorySnapshot> {
268        let snapshots = self.memory_snapshots.read().unwrap();
269        if let Some(n) = last_n {
270            if snapshots.len() > n {
271                snapshots[snapshots.len() - n..].to_vec()
272            } else {
273                snapshots.clone()
274            }
275        } else {
276            snapshots.clone()
277        }
278    }
279
280    /// Generate a performance report
281    pub fn generate_report(&self) -> PerformanceReport {
282        let uptime = self.start_time.elapsed();
283        let timer_stats = self.get_all_timer_stats();
284        let counter_stats = self.get_all_counter_stats();
285        let memory_snapshots = self.get_memory_snapshots(Some(100));
286
287        PerformanceReport {
288            uptime,
289            timer_stats,
290            counter_stats,
291            memory_snapshots,
292            report_time: Instant::now(),
293        }
294    }
295
296    /// Reset all statistics
297    pub fn reset(&self) {
298        self.timers.write().unwrap().clear();
299        self.counters.write().unwrap().clear();
300        self.memory_snapshots.write().unwrap().clear();
301    }
302}
303
304impl Default for Profiler {
305    fn default() -> Self {
306        Self::new()
307    }
308}
309
310/// Timer statistics
311#[derive(Debug, Clone)]
312pub struct TimerStats {
313    pub name: String,
314    pub total_time: Duration,
315    pub count: u64,
316    pub average_time: Duration,
317    pub min_time: Duration,
318    pub max_time: Duration,
319}
320
321/// Counter statistics
322#[derive(Debug, Clone)]
323pub struct CounterStats {
324    pub name: String,
325    pub current_value: i64,
326    pub min_value: i64,
327    pub max_value: i64,
328    pub total_increments: u64,
329}
330
331/// Performance report
332#[derive(Debug, Clone)]
333pub struct PerformanceReport {
334    pub uptime: Duration,
335    pub timer_stats: Vec<TimerStats>,
336    pub counter_stats: Vec<CounterStats>,
337    pub memory_snapshots: Vec<MemorySnapshot>,
338    pub report_time: Instant,
339}
340
341/// RAII timer for automatic timing
342pub struct ScopedTimer<'a> {
343    profiler: &'a Profiler,
344    name: String,
345}
346
347impl<'a> ScopedTimer<'a> {
348    /// Create a new scoped timer
349    pub fn new(profiler: &'a Profiler, name: &str) -> Self {
350        profiler.start_timer(name);
351        Self {
352            profiler,
353            name: name.to_string(),
354        }
355    }
356}
357
358impl<'a> Drop for ScopedTimer<'a> {
359    fn drop(&mut self) {
360        self.profiler.end_timer(&self.name);
361    }
362}
363
364/// Macro for easy scoped timing
365#[macro_export]
366macro_rules! profile_scope {
367    ($profiler:expr, $name:expr) => {
368        let _timer = $crate::utils::profiler::ScopedTimer::new($profiler, $name);
369    };
370}
371
372/// Performance monitoring for specific chess engine operations
373pub struct ChessEngineProfiler {
374    profiler: Profiler,
375    search_metrics: RwLock<SearchMetrics>,
376    evaluation_metrics: RwLock<EvaluationMetrics>,
377}
378
379#[derive(Debug, Clone, Default)]
380struct SearchMetrics {
381    nodes_searched: u64,
382    positions_evaluated: u64,
383    cache_hits: u64,
384    cache_misses: u64,
385    pruned_branches: u64,
386    transposition_hits: u64,
387}
388
389#[derive(Debug, Clone, Default)]
390struct EvaluationMetrics {
391    nnue_evaluations: u64,
392    pattern_evaluations: u64,
393    hybrid_evaluations: u64,
394    similarity_searches: u64,
395    vector_operations: u64,
396}
397
398impl ChessEngineProfiler {
399    /// Create a new chess engine profiler
400    pub fn new() -> Self {
401        Self {
402            profiler: Profiler::new(),
403            search_metrics: RwLock::new(SearchMetrics::default()),
404            evaluation_metrics: RwLock::new(EvaluationMetrics::default()),
405        }
406    }
407
408    /// Record search metrics
409    pub fn record_search(&self, nodes: u64, positions: u64, cache_hits: u64, cache_misses: u64) {
410        let mut metrics = self.search_metrics.write().unwrap();
411        metrics.nodes_searched += nodes;
412        metrics.positions_evaluated += positions;
413        metrics.cache_hits += cache_hits;
414        metrics.cache_misses += cache_misses;
415
416        self.profiler
417            .increment_counter("search.nodes_total", nodes as i64);
418        self.profiler
419            .increment_counter("search.positions_total", positions as i64);
420        self.profiler.set_counter(
421            "search.cache_hit_ratio",
422            if cache_hits + cache_misses > 0 {
423                (cache_hits * 100 / (cache_hits + cache_misses)) as i64
424            } else {
425                0
426            },
427        );
428    }
429
430    /// Record evaluation metrics
431    pub fn record_evaluation(&self, eval_type: &str) {
432        let mut metrics = self.evaluation_metrics.write().unwrap();
433        match eval_type {
434            "nnue" => metrics.nnue_evaluations += 1,
435            "pattern" => metrics.pattern_evaluations += 1,
436            "hybrid" => metrics.hybrid_evaluations += 1,
437            "similarity" => metrics.similarity_searches += 1,
438            "vector" => metrics.vector_operations += 1,
439            _ => {}
440        }
441
442        self.profiler
443            .increment_counter(&format!("eval.{}", eval_type), 1);
444    }
445
446    /// Time a search operation
447    pub fn time_search<F, R>(&self, operation: &str, f: F) -> R
448    where
449        F: FnOnce() -> R,
450    {
451        self.profiler.time(&format!("search.{}", operation), f)
452    }
453
454    /// Time an evaluation operation
455    pub fn time_evaluation<F, R>(&self, operation: &str, f: F) -> R
456    where
457        F: FnOnce() -> R,
458    {
459        self.profiler.time(&format!("eval.{}", operation), f)
460    }
461
462    /// Get chess-specific performance metrics
463    pub fn get_chess_metrics(&self) -> ChessMetrics {
464        let search_metrics = self.search_metrics.read().unwrap().clone();
465        let evaluation_metrics = self.evaluation_metrics.read().unwrap().clone();
466
467        ChessMetrics {
468            search_metrics,
469            evaluation_metrics,
470            nodes_per_second: self.calculate_nodes_per_second(),
471            evaluations_per_second: self.calculate_evaluations_per_second(),
472        }
473    }
474
475    /// Calculate nodes per second
476    fn calculate_nodes_per_second(&self) -> f64 {
477        if let Some(timer_stats) = self.profiler.get_timer_stats("search.tactical") {
478            if timer_stats.total_time.as_secs_f64() > 0.0 {
479                let search_metrics = self.search_metrics.read().unwrap();
480                return search_metrics.nodes_searched as f64 / timer_stats.total_time.as_secs_f64();
481            }
482        }
483        0.0
484    }
485
486    /// Calculate evaluations per second
487    fn calculate_evaluations_per_second(&self) -> f64 {
488        if let Some(timer_stats) = self.profiler.get_timer_stats("eval.total") {
489            if timer_stats.total_time.as_secs_f64() > 0.0 {
490                let eval_metrics = self.evaluation_metrics.read().unwrap();
491                let total_evals = eval_metrics.nnue_evaluations
492                    + eval_metrics.pattern_evaluations
493                    + eval_metrics.hybrid_evaluations;
494                return total_evals as f64 / timer_stats.total_time.as_secs_f64();
495            }
496        }
497        0.0
498    }
499
500    /// Generate comprehensive chess engine report
501    pub fn generate_chess_report(&self) -> ChessEngineReport {
502        let base_report = self.profiler.generate_report();
503        let chess_metrics = self.get_chess_metrics();
504
505        ChessEngineReport {
506            base_report,
507            chess_metrics,
508        }
509    }
510
511    /// Get the underlying profiler
512    pub fn profiler(&self) -> &Profiler {
513        &self.profiler
514    }
515}
516
517impl Default for ChessEngineProfiler {
518    fn default() -> Self {
519        Self::new()
520    }
521}
522
523/// Chess-specific performance metrics
524#[derive(Debug, Clone)]
525pub struct ChessMetrics {
526    pub search_metrics: SearchMetrics,
527    pub evaluation_metrics: EvaluationMetrics,
528    pub nodes_per_second: f64,
529    pub evaluations_per_second: f64,
530}
531
532/// Comprehensive chess engine performance report
533#[derive(Debug, Clone)]
534pub struct ChessEngineReport {
535    pub base_report: PerformanceReport,
536    pub chess_metrics: ChessMetrics,
537}
538
539/// Global profiler instance
540static GLOBAL_PROFILER: std::sync::OnceLock<Arc<ChessEngineProfiler>> = std::sync::OnceLock::new();
541
542/// Get the global profiler
543pub fn global_profiler() -> &'static Arc<ChessEngineProfiler> {
544    GLOBAL_PROFILER.get_or_init(|| Arc::new(ChessEngineProfiler::new()))
545}
546
547/// Simple benchmark utility
548pub struct Benchmark {
549    name: String,
550    start_time: Instant,
551    iterations: u64,
552}
553
554impl Benchmark {
555    /// Start a new benchmark
556    pub fn start(name: &str) -> Self {
557        Self {
558            name: name.to_string(),
559            start_time: Instant::now(),
560            iterations: 0,
561        }
562    }
563
564    /// Record an iteration
565    pub fn iteration(&mut self) {
566        self.iterations += 1;
567    }
568
569    /// Finish the benchmark and return results
570    pub fn finish(self) -> BenchmarkResult {
571        let elapsed = self.start_time.elapsed();
572        let iterations_per_second = if elapsed.as_secs_f64() > 0.0 {
573            self.iterations as f64 / elapsed.as_secs_f64()
574        } else {
575            0.0
576        };
577
578        BenchmarkResult {
579            name: self.name,
580            total_time: elapsed,
581            iterations: self.iterations,
582            iterations_per_second,
583            time_per_iteration: if self.iterations > 0 {
584                elapsed / self.iterations as u32
585            } else {
586                Duration::ZERO
587            },
588        }
589    }
590}
591
592/// Benchmark result
593#[derive(Debug, Clone)]
594pub struct BenchmarkResult {
595    pub name: String,
596    pub total_time: Duration,
597    pub iterations: u64,
598    pub iterations_per_second: f64,
599    pub time_per_iteration: Duration,
600}
601
602impl BenchmarkResult {
603    /// Print benchmark results
604    pub fn print(&self) {
605        println!("Benchmark: {}", self.name);
606        println!("  Total time: {:?}", self.total_time);
607        println!("  Iterations: {}", self.iterations);
608        println!("  Iterations/sec: {:.2}", self.iterations_per_second);
609        println!("  Time/iteration: {:?}", self.time_per_iteration);
610    }
611}
612
613#[cfg(test)]
614mod tests {
615    use super::*;
616    use std::thread;
617    use std::time::Duration;
618
619    #[test]
620    fn test_profiler_timers() {
621        let profiler = Profiler::new();
622
623        profiler.start_timer("test_operation");
624        thread::sleep(Duration::from_millis(10));
625        profiler.end_timer("test_operation");
626
627        let stats = profiler.get_timer_stats("test_operation").unwrap();
628        assert_eq!(stats.count, 1);
629        assert!(stats.total_time >= Duration::from_millis(10));
630        assert!(stats.average_time >= Duration::from_millis(10));
631    }
632
633    #[test]
634    fn test_profiler_counters() {
635        let profiler = Profiler::new();
636
637        profiler.increment_counter("test_counter", 5);
638        profiler.increment_counter("test_counter", 3);
639        profiler.set_counter("test_counter", 10);
640
641        let stats = profiler.get_counter_stats("test_counter").unwrap();
642        assert_eq!(stats.current_value, 10);
643        assert_eq!(stats.max_value, 10);
644        assert_eq!(stats.total_increments, 2);
645    }
646
647    #[test]
648    fn test_scoped_timer() {
649        let profiler = Profiler::new();
650
651        {
652            let _timer = ScopedTimer::new(&profiler, "scoped_test");
653            thread::sleep(Duration::from_millis(5));
654        }
655
656        let stats = profiler.get_timer_stats("scoped_test").unwrap();
657        assert_eq!(stats.count, 1);
658        assert!(stats.total_time >= Duration::from_millis(5));
659    }
660
661    #[test]
662    fn test_chess_engine_profiler() {
663        let profiler = ChessEngineProfiler::new();
664
665        profiler.record_search(1000, 500, 300, 200);
666        profiler.record_evaluation("nnue");
667        profiler.record_evaluation("pattern");
668
669        let metrics = profiler.get_chess_metrics();
670        assert_eq!(metrics.search_metrics.nodes_searched, 1000);
671        assert_eq!(metrics.search_metrics.positions_evaluated, 500);
672        assert_eq!(metrics.evaluation_metrics.nnue_evaluations, 1);
673        assert_eq!(metrics.evaluation_metrics.pattern_evaluations, 1);
674    }
675
676    #[test]
677    fn test_benchmark() {
678        let mut bench = Benchmark::start("test_benchmark");
679
680        for _ in 0..100 {
681            bench.iteration();
682            // Simulate some work
683            thread::sleep(Duration::from_micros(100));
684        }
685
686        let result = bench.finish();
687        assert_eq!(result.iterations, 100);
688        assert!(result.total_time > Duration::from_millis(10));
689        assert!(result.iterations_per_second > 0.0);
690    }
691
692    #[test]
693    fn test_memory_snapshots() {
694        let profiler = Profiler::new();
695
696        profiler.memory_snapshot(1024, 2048, 10);
697        profiler.memory_snapshot(1536, 2048, 15);
698
699        let snapshots = profiler.get_memory_snapshots(Some(2));
700        assert_eq!(snapshots.len(), 2);
701        assert_eq!(snapshots[0].allocated_bytes, 1024);
702        assert_eq!(snapshots[1].allocated_bytes, 1536);
703    }
704
705    #[test]
706    fn test_performance_report() {
707        let profiler = Profiler::new();
708
709        profiler.start_timer("operation1");
710        thread::sleep(Duration::from_millis(5));
711        profiler.end_timer("operation1");
712
713        profiler.increment_counter("counter1", 42);
714        profiler.memory_snapshot(1024, 1024, 5);
715
716        let report = profiler.generate_report();
717        assert!(!report.timer_stats.is_empty());
718        assert!(!report.counter_stats.is_empty());
719        assert!(!report.memory_snapshots.is_empty());
720    }
721}