[PERFORMANCE]: Logging overhead in plugin manager #2084
Description
Description
Logging overhead accounts for 30-60% of execution time even after the exc_info fix (cf. #2065).
Current Impact (typical plugin hook):
- Fast plugins: 0.032-0.040ms total (25-30K hooks/sec)
- Medium plugins: 0.040-0.060ms total (16-25K hooks/sec)
- Complex plugins: 0.060-0.104ms total (9-16K hooks/sec)
Breakdown (example: PIIFilterPlugin_tool_pre_invoke at 0.059ms):
- 0.026ms (44%) - Actual plugin work
- 0.020ms (34%) - Logging overhead
- 0.013ms (22%) - Framework overhead
Root Cause:
- Logger calls (error/warning) occur on EVERY invocation, even successful ones
- Logger machinery (handlers, formatters, callHandlers) takes 20-22μs per call
Detailed Analysis
Profile Data Evidence
Analysis of PIIFilterPlugin_tool_pre_invoke.prof (after exc_info fix):
Total time: 0.059 seconds for 1000 invocations = 0.059ms per call (3.5x improvement!)
Time breakdown:
Logging overhead: 0.020s (34%)
├─ logger.error() 0.021s
├─ _log() 0.020s
├─ handle/callHandlers 0.020s
├─ emit() 0.009s
└─ write() to file 0.005s
Actual plugin work: 0.026s (44%)
├─ tool_pre_invoke() 0.026s
├─ _process_nested_data 0.024s
└─ detect() 0.018s
Framework overhead: 0.013s (22%)
├─ _execute_with_timeout 0.033s
├─ tasks.wait_for 0.032s
└─ timeouts context mgmt 0.003s
Key Observations:
- Logger.error() called 1000 times - once per invocation, even on success
- Minimal plugins hit maximum logging cost - DenyListPlugin does 3μs work but pays 20μs for logging
- Fast plugins amplify logging impact - For plugins <10μs, logging is 60-70% of time
Trace Analysis
# Every plugin shows this pattern (1000 invocations = 1000 logger calls):
ncalls tottime cumtime function
1000 0.000 0.021 __init__.py:1539(error) # logger.error()
1000 0.000 0.020 __init__.py:1641(_log) # log processing
1000 0.000 0.011 __init__.py:1667(handle) # handler dispatch
1000 0.000 0.010 __init__.py:1721(callHandlers) # call all handlers
1000 0.001 0.010 __init__.py:1011(handle) # handler.handle()
1000 0.000 0.009 __init__.py:1139(emit) # emit to stream
1000 0.005 0.005 {write} # I/O to stderr
Problem:
- Logger calls occur even for successful plugin executions
- This suggests logging in exception handlers is being triggered in normal flow
- OR there's defensive logging that fires on every invocation
- Logger machinery (formatters, handlers, file I/O) cannot be optimized away
Performance Cost:
- 20-22μs per invocation - regardless of whether plugin succeeds or fails
- 30-60% of total execution time for typical plugins
- 70% for minimal plugins (e.g., DenyListPlugin: 3μs work, 20μs logging)
Impact by Plugin Type:
Minimal plugins (e.g., DenyListPlugin):
Total: 0.036ms → Logging: 0.020ms (56%) → Work: 0.003ms (8%)
Medium plugins (e.g., ArgumentNormalizer):
Total: 0.059ms → Logging: 0.022ms (37%) → Work: 0.024ms (41%)
Complex plugins (e.g., PIIFilterPlugin):
Total: 0.104ms → Logging: 0.040ms (38%) → Work: 0.070ms (67%)