Skip to content

Commit 1cf4d7c

Browse files
committed
Enhance logging configuration and functionality
- Improved ColoredFormatter to support microseconds in timestamps. - Enhanced MultiProcessingLog to use a shared lock and prefix for log filenames. - Updated ColoredLogger to handle new configuration options for log formatting and file handling. - Added comprehensive tests for log filename configuration from various sources (environment variables, YAML, CLI). - Refactored tests to remove unused imports and improve clarity. - Ensured proper handling of log file creation and rotation settings. - Added priority tests for log filename and date format configurations.
1 parent 3729b5c commit 1cf4d7c

25 files changed

Lines changed: 896 additions & 991 deletions

.github/workflows/prismalog_ci.yml

Lines changed: 11 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -32,6 +32,15 @@ jobs:
3232
with:
3333
python-version: ${{ matrix.python-version }}
3434

35+
# Step 2.5: Cache dependencies
36+
- name: Cache pip dependencies
37+
uses: actions/cache@v4
38+
with:
39+
path: ~/.cache/pip
40+
key: ${{ runner.os }}-pip-${{ hashFiles('**/setup.py', '**/pyproject.toml') }}
41+
restore-keys: |
42+
${{ runner.os }}-pip-
43+
3544
# Step 3: Install dependencies (Install dev and docs extras)
3645
- name: Install dependencies
3746
run: |
@@ -64,9 +73,9 @@ jobs:
6473
- name: Test logging performance
6574
if: matrix.python-version == '3.10'
6675
run: |
67-
python benchmark/performance_test_multiprocessing.py > reports/performance_py${{ matrix.python-version }}.txt
76+
python benchmark/performance_test.py -p 3 -t 1 > reports/performance_py${{ matrix.python-version }}.txt
6877
MSGS_PER_SEC=$(grep -oP '(?<=Messages per second: )[0-9.]+' reports/performance_py${{ matrix.python-version }}.txt || echo "0")
69-
echo "## Performance: $MSGS_PER_SEC messages/sec" >> $GITHUB_STEP_SUMMARY
78+
echo "## Performance (3p x 1t): $MSGS_PER_SEC messages/sec" >> $GITHUB_STEP_SUMMARY # Updated summary text
7079
7180
# Step 7: Run comprehensive performance comparison (only for Python 3.10 to avoid long run times)
7281
- name: Run comprehensive performance comparison

benchmark/README.md

Lines changed: 64 additions & 8 deletions
Original file line numberDiff line numberDiff line change
@@ -8,10 +8,33 @@ Comprehensive benchmarks were conducted to evaluate the performance characterist
88

99
| Test Type | Processes | Threads |
1010
|------------------|-------------------------|----------------|
11-
| Multiprocessing | 4 processes | 1 thread |
12-
| Multithreading | 1 processe | 4 threads |
13-
| Mixed Mode | 3 processes | 2 threads |
14-
| Standard Logging | 1 processe | 4 threads |
11+
| Multiprocessing | 3 processes | 1 thread |
12+
| Multithreading | 1 processe | 3 threads |
13+
| Mixed Mode | 2 processes | 2 threads |
14+
| Standard Logging | 1 processe | 3 threads |
15+
16+
### Key Observations
17+
18+
1. **Concurrency Models**:
19+
* The highest throughput was observed in the multiprocessing model, with nearly 27,000 messages processed per second.
20+
* A good balance of throughput and resource utilization was achieved in the mixed mode (processes with threads).
21+
* The multithreading model demonstrated consistent performance at around 10,000 messages per second.
22+
* The standard logging library processed approximately 6,500 messages per second.
23+
24+
2. **Latency**:
25+
* The lowest per-message latency (0.07-0.08ms) was provided by multiprocessing.
26+
* Medium latency (0.17-0.21ms) was observed in mixed mode.
27+
* Higher latency (0.26-0.42ms) was observed in thread-based approaches.
28+
* Standard logging exhibited the highest latency (0.40-0.46ms) across all log levels.
29+
30+
3. **Resource Usage**:
31+
* Minimal memory consumption (0.20-0.49MB) was observed across prismalog approaches.
32+
* Standard logging showed the lowest memory increase (0.04MB) but with slower performance.
33+
* Log file sizes remained compact (0.61-1.13MB) across all approaches.
34+
35+
4. **Timestamp Formatting Impact**:
36+
* **Crucially, the choice of timestamp format significantly impacts performance.** Using `%(created)f` (which logs a raw numeric timestamp) can achieve substantially higher throughput (observed up to **~35,000 msgs/sec** in testing) compared to using `%(asctime)s` (which formats the timestamp into a human-readable string, observed maxing out around **~25,000 msgs/sec**).
37+
* While `%(created)f` requires post-processing to convert timestamps for readability, it drastically reduces logging overhead.
1538

1639
### Results Summary
1740

@@ -41,26 +64,59 @@ Comprehensive benchmarks were conducted to evaluate the performance characterist
4164
- Standard logging showed the lowest memory increase (0.04MB) but with slower performance.
4265
- Log file sizes remained compact (0.61-1.13MB) across all approaches.
4366

67+
### Performance Benchmarking
68+
69+
The `benchmark/performance_test.py` script allows you to measure logging performance under different concurrency models.
70+
71+
**Arguments:**
72+
73+
* `-p N`, `--processes N`: Use N worker processes (default: 2).
74+
* `-t M`, `--threads M`: Use M worker threads per process (default: 2).
75+
76+
**Examples:**
77+
78+
* **Multiprocessing Test (e.g., 3 processes, 1 thread each):**
79+
```bash
80+
python benchmark/performance_test.py -p 3 -t 1
81+
```
82+
83+
* **Multithreading Test (e.g., 1 process, 3 threads):**
84+
```bash
85+
python benchmark/performance_test.py -p 1 -t 3
86+
```
87+
88+
* **Mixed Concurrency Test (e.g., 2 processes, 2 threads each):**
89+
```bash
90+
python benchmark/performance_test.py -p 2 -t 2
91+
# Or simply run with defaults:
92+
# python benchmark/performance_test.py
93+
```
94+
95+
The script also accepts standard `prismalog` arguments like `--log-level`, `--log-format`, etc., to configure the logger during the benchmark. Rotation is automatically disabled during the benchmark run for consistent results.
96+
4497
### Feature Advantages Over Standard Logging
4598

4699
While performance benchmarks provide valuable insights, several important features are offered by `prismalog` that are not available in the standard logging library:
47100

48-
1. **Color-coded Console Output**:
101+
1. **Process-Safe & Thread-Safe File Handling**:
102+
* The included file handlers (`MultiProcessingLog`) are specifically designed to handle concurrent writes from multiple processes and threads safely, preventing log corruption or race conditions. Standard `RotatingFileHandler` is not inherently process-safe without external locking mechanisms.
103+
104+
2. **Color-coded Console Output**:
49105
- Syntax highlighting for log messages is applied automatically based on their severity level.
50106
- Customizable color schemes are supported for different environments.
51107
- Readability is improved by visually distinguishing between different message types.
52108

53-
2. **Special Critical Message Handling**:
109+
3. **Special Critical Message Handling**:
54110
- Application termination on critical errors is optionally supported.
55111
- Configurable callbacks for critical message events are provided.
56112
- Stack trace preservation is ensured for critical failures.
57113

58-
3. **Advanced Configuration**:
114+
4. **Advanced Configuration**:
59115
- Environment variable support is included, with sensible defaults and multiple fallback patterns.
60116
- Command-line argument integration is supported, with automatic help generation.
61117
- Configuration file support (YAML) is provided, with automatic detection.
62118

63-
4. **Developer Experience Enhancements**:
119+
5. **Developer Experience Enhancements**:
64120
- A simplified API is offered for common logging patterns.
65121
- Context managers are provided for temporary logging level changes.
66122
- Convenient decorators are included for function entry/exit logging.

benchmark/performance_compare.py

Lines changed: 44 additions & 27 deletions
Original file line numberDiff line numberDiff line change
@@ -10,9 +10,8 @@
1010
import os
1111
import re
1212
import subprocess
13-
from collections.abc import Mapping # Add this import
1413
from datetime import datetime
15-
from typing import Any, Dict, List, Optional, Tuple, TypedDict, Union, cast
14+
from typing import Any, Dict, List, Optional, TypedDict, Union
1615

1716

1817
# Define explicit types for the nested dictionaries
@@ -31,6 +30,8 @@ class RelativePerfDict(TypedDict):
3130
from prismalog.argparser import extract_logging_args, get_argument_parser
3231
from prismalog.log import LoggingConfig, get_logger
3332

33+
# Set up the logging configuration
34+
os.environ["LOG_FILENAME"] = "performance_compare"
3435
# Create parser with standard logging arguments
3536
parser = get_argument_parser(description="prismalog Performance Comparison")
3637

@@ -76,36 +77,36 @@ def extract_metrics(output: str) -> Dict[str, Union[str, float]]:
7677

7778
# Extract log file size
7879
log_size_match = re.search(r"• Size: ([\d.]+) MB", output)
80+
log_size_match = re.search(r"• Size: ([\d.]+) MB", output)
7981
if log_size_match:
8082
metrics["log_size_mb"] = float(log_size_match.group(1))
8183

8284
return metrics
8385

8486

85-
def run_test(script_name: str) -> Optional[str]:
86-
"""Run a performance test script and capture output while showing logs in real-time."""
87+
def run_test(script_name: str, args: List[str] = []) -> Optional[str]:
88+
"""Run a performance test script with arguments and capture output."""
89+
args_str = " ".join(args)
8790
print(f"\n{'-'*60}")
88-
print(f"Running {script_name}...")
91+
print(f"Running {script_name} {args_str}...")
8992
print(f"{'-'*60}")
9093

91-
# Check if the script exists
9294
script_path = os.path.join(os.path.dirname(__file__), script_name)
9395
if not os.path.exists(script_path):
9496
logger.warning(f"Script not found: {script_path}")
9597
return None
9698

9799
try:
98-
# Run the script and stream output to console while also capturing it
100+
command = ["python", script_path] + args # Combine script and args
99101
output = []
100102
with subprocess.Popen(
101-
["python", script_path],
103+
command, # Use the combined command
102104
stdout=subprocess.PIPE,
103105
stderr=subprocess.STDOUT,
104106
text=True,
105-
bufsize=1, # Line buffered
107+
bufsize=1,
106108
) as process:
107-
# Read and display output in real-time
108-
if process.stdout is not None: # Add this check
109+
if process.stdout is not None:
109110
for line in iter(process.stdout.readline, ""):
110111
if not line:
111112
break
@@ -117,17 +118,17 @@ def run_test(script_name: str) -> Optional[str]:
117118
return_code = process.wait()
118119

119120
if return_code != 0:
120-
logger.error(f"{script_name} exited with code {return_code}")
121+
logger.error(f"{script_name} {args_str} exited with code {return_code}")
121122
return None
122123

123124
print(f"{'-'*60}")
124-
print(f"Completed {script_name}")
125+
print(f"Completed {script_name} {args_str}")
125126
print(f"{'-'*60}\n")
126127

127128
return "".join(output)
128129

129130
except Exception as e:
130-
logger.error(f"Error running {script_name}: {e}")
131+
logger.error(f"Error running {script_name} {args_str}: {e}")
131132
return None
132133

133134

@@ -165,34 +166,50 @@ def save_benchmark_results(results: Dict[str, Any], test_type: str) -> str:
165166

166167

167168
def main() -> None:
168-
"""Run all performance tests and compare results."""
169+
"""Run performance tests for different concurrency models and compare results."""
169170
print(f"\n{'='*80}")
170171
print(f"LOGGING PERFORMANCE COMPARISON - {datetime.now().strftime('%Y-%m-%d %H:%M:%S')}")
171172
print(f"{'='*80}\n")
172173

173-
# Track available test results
174174
test_metrics = {}
175175

176-
# Run performance tests
177176
try:
178-
# Run all tests and collect metrics
179-
test_files = [
180-
("performance_test_multiprocessing.py", "multiproc", "Multiprocessing"),
181-
("performance_test_threading.py", "threading", "Multithreading"),
182-
("performance_test_mixed.py", "mixed", "Mixed Mode"),
183-
("standard_logging_benchmark.py", "std", "Standard Logging"),
177+
# Define test configurations for the performance compare script
178+
test_configs = [
179+
# Config: (arguments_list, result_key, display_name)
180+
(["-p", "3", "-t", "1"], "multiproc", "Multiprocessing (3p x 1t)"),
181+
(["-p", "1", "-t", "3"], "threading", "Multithreading (1p x 3t)"),
182+
(["-p", "2", "-t", "2"], "mixed", "Mixed Mode (2p x 2t)"),
184183
]
185184

186-
for script_name, key, display_name in test_files:
187-
output = run_test(script_name)
185+
# Script to run for prismalog tests
186+
prismalog_script = "performance_test.py"
187+
188+
for args_list, key, display_name in test_configs:
189+
# Add the specific log filename for this test run
190+
subprocess_args = args_list + ["--log-filename", key] # Use the 'key' as the prefix
191+
192+
# Run the test with specific arguments including the log filename
193+
output = run_test(prismalog_script, subprocess_args) # Pass the modified args
188194
if output:
189195
metrics = extract_metrics(output)
190-
metrics["test"] = display_name
196+
metrics["test"] = display_name # Use the descriptive name
191197
test_metrics[key] = metrics
192198
save_benchmark_results(metrics, f"test_{key}")
193199

200+
# Optionally, give the standard logging test its own prefix
201+
std_script = "standard_logging_benchmark.py"
202+
std_output = run_test(std_script) # Pass the args
203+
if std_output:
204+
std_metrics = extract_metrics(std_output)
205+
std_metrics["test"] = "Standard Logging"
206+
test_metrics["std"] = std_metrics
207+
save_benchmark_results(std_metrics, "test_std")
208+
194209
if not test_metrics:
195-
logger.error("No test metrics collected. Please ensure at least one test script is available.")
210+
logger.error(
211+
"No test metrics collected. Please ensure benchmark scripts are available and run successfully."
212+
)
196213
return
197214

198215
# Define table structure

0 commit comments

Comments
 (0)