|
| 1 | +# -*- coding: ascii -*- |
| 2 | +""" |
| 3 | +Logging utilities for benchmark execution. |
| 4 | +""" |
| 5 | + |
| 6 | +import logging |
| 7 | +from typing import Any |
| 8 | + |
| 9 | +__author__ = "PySATL contributors" |
| 10 | +__copyright__ = "Copyright (c) 2026 PySATL project" |
| 11 | +__license__ = "SPDX-License-Identifier: MIT" |
| 12 | + |
| 13 | + |
| 14 | +class BenchmarkLogger: |
| 15 | + """Dedicated logger for benchmark execution with structured logging.""" |
| 16 | + |
| 17 | + def __init__(self, name: str = "pysatl.benchmark"): |
| 18 | + self.logger = logging.getLogger(name) |
| 19 | + self._setup_logger() |
| 20 | + |
| 21 | + def _setup_logger(self) -> None: |
| 22 | + """Setup logger if not already configured.""" |
| 23 | + if not self.logger.handlers: |
| 24 | + handler = logging.StreamHandler() |
| 25 | + formatter = logging.Formatter( |
| 26 | + "[%(asctime)s] %(levelname)-8s | %(message)s", |
| 27 | + datefmt="%H:%M:%S", |
| 28 | + ) |
| 29 | + handler.setFormatter(formatter) |
| 30 | + self.logger.addHandler(handler) |
| 31 | + self.logger.setLevel(logging.INFO) |
| 32 | + |
| 33 | + def info(self, msg: str, **kwargs: Any) -> None: |
| 34 | + """Log info message with optional context.""" |
| 35 | + if kwargs: |
| 36 | + msg = f"{msg} | {' | '.join(f'{k}={v}' for k, v in kwargs.items())}" |
| 37 | + self.logger.info(msg) |
| 38 | + |
| 39 | + def debug(self, msg: str, **kwargs: Any) -> None: |
| 40 | + """Log debug message with optional context.""" |
| 41 | + if kwargs: |
| 42 | + msg = f"{msg} | {' | '.join(f'{k}={v}' for k, v in kwargs.items())}" |
| 43 | + self.logger.debug(msg) |
| 44 | + |
| 45 | + def warning(self, msg: str, **kwargs: Any) -> None: |
| 46 | + """Log warning message.""" |
| 47 | + if kwargs: |
| 48 | + msg = f"{msg} | {' | '.join(f'{k}={v}' for k, v in kwargs.items())}" |
| 49 | + self.logger.warning(msg) |
| 50 | + |
| 51 | + def error(self, msg: str, **kwargs: Any) -> None: |
| 52 | + """Log error message.""" |
| 53 | + if kwargs: |
| 54 | + msg = f"{msg} | {' | '.join(f'{k}={v}' for k, v in kwargs.items())}" |
| 55 | + self.logger.error(msg) |
| 56 | + |
| 57 | + def start_benchmark( |
| 58 | + self, |
| 59 | + n_algorithms: int, |
| 60 | + n_providers: int, |
| 61 | + n_total_runs: int, |
| 62 | + ) -> None: |
| 63 | + """Log benchmark start.""" |
| 64 | + self.info( |
| 65 | + "Starting benchmark execution", |
| 66 | + algorithms=n_algorithms, |
| 67 | + providers=n_providers, |
| 68 | + total_runs=n_total_runs, |
| 69 | + ) |
| 70 | + |
| 71 | + def algorithm_start(self, algo_name: str, n_thresholds: int) -> None: |
| 72 | + """Log algorithm processing start.""" |
| 73 | + self.info( |
| 74 | + f"Processing algorithm: {algo_name}", |
| 75 | + thresholds=n_thresholds, |
| 76 | + ) |
| 77 | + |
| 78 | + def threshold_processed( |
| 79 | + self, |
| 80 | + algo_name: str, |
| 81 | + threshold: float, |
| 82 | + n_providers: int, |
| 83 | + ) -> None: |
| 84 | + """Log threshold processing.""" |
| 85 | + self.debug( |
| 86 | + "Threshold processed", |
| 87 | + algo=algo_name, |
| 88 | + threshold=f"{threshold:.4f}", |
| 89 | + providers=n_providers, |
| 90 | + ) |
| 91 | + |
| 92 | + def cache_hit(self, algo_name: str, threshold: float, provider: str) -> None: |
| 93 | + """Log cache hit.""" |
| 94 | + self.debug( |
| 95 | + "Cache hit", |
| 96 | + algo=algo_name, |
| 97 | + threshold=f"{threshold:.4f}", |
| 98 | + provider=provider, |
| 99 | + ) |
| 100 | + |
| 101 | + def solver_start(self, algo_name: str, provider: str, threshold: float) -> None: |
| 102 | + """Log solver execution start.""" |
| 103 | + self.debug( |
| 104 | + "Executing solver", |
| 105 | + algo=algo_name, |
| 106 | + provider=provider, |
| 107 | + threshold=f"{threshold:.4f}", |
| 108 | + ) |
| 109 | + |
| 110 | + def metrics_computed( |
| 111 | + self, |
| 112 | + algo_name: str, |
| 113 | + threshold: float, |
| 114 | + metric_names: list[str], |
| 115 | + ) -> None: |
| 116 | + """Log metrics computation.""" |
| 117 | + self.debug( |
| 118 | + "Metrics computed", |
| 119 | + algo=algo_name, |
| 120 | + threshold=f"{threshold:.4f}", |
| 121 | + metrics=", ".join(metric_names), |
| 122 | + ) |
| 123 | + |
| 124 | + def benchmark_complete(self, total_runs: int, elapsed_sec: float) -> None: |
| 125 | + """Log benchmark completion.""" |
| 126 | + avg_time = elapsed_sec / total_runs if total_runs > 0 else 0 |
| 127 | + self.info( |
| 128 | + "Benchmark completed", |
| 129 | + total_runs=total_runs, |
| 130 | + elapsed_time=f"{elapsed_sec:.2f}s", |
| 131 | + avg_time_per_run=f"{avg_time:.3f}s", |
| 132 | + ) |
| 133 | + |
| 134 | + def warning_no_metrics(self) -> None: |
| 135 | + """Log warning about missing metrics.""" |
| 136 | + self.warning("No metrics registered for evaluation") |
| 137 | + |
| 138 | + def error_exception(self, algo_name: str, threshold: float, error: str) -> None: |
| 139 | + """Log exception during benchmark.""" |
| 140 | + self.error( |
| 141 | + "Error during execution", |
| 142 | + algo=algo_name, |
| 143 | + threshold=f"{threshold:.4f}", |
| 144 | + error=error, |
| 145 | + ) |
0 commit comments