Skip to content

perf: fix unconditional logging overhead in plugin framework (2-5x speedup)#2085

Merged
crivetimihai merged 1 commit intomainfrom
feat/plugin_manager_logging_performance
Jan 14, 2026
Merged

perf: fix unconditional logging overhead in plugin framework (2-5x speedup)#2085
crivetimihai merged 1 commit intomainfrom
feat/plugin_manager_logging_performance

Conversation

@araujof
Copy link
Copy Markdown
Member

@araujof araujof commented Jan 13, 2026 •
edited
Loading

Summary

Fixes a performance regression in the plugin framework where logger.error() was being called on every plugin invocation due to a type mismatch. This caused 30-60% of execution time to be spent on logging, even for successful plugin executions.

Impact: 2-5x performance improvement across all plugins, with minimal plugins seeing up to 4.9x speedup.

Fix #2084

Problem

The plugin performance profiling revealed that logger.error() was being called 1000 times for 1000 plugin invocations, adding 20-22μs of logging overhead per call. This overhead accounted for:

  • 30-60% of total execution time for typical plugins
  • 70% of execution time for minimal plugins (e.g., DenyListPlugin: 3μs work + 20μs logging)

Root Cause

The issue was caused by a type mismatch in invoke_hook_for_plugin():

  1. The method signature expected context: PluginContext
  2. Performance tests (and potentially other callers) passed GlobalContext instead
  3. When execute_plugin() tried to access local_context.global_context (line 228), it raised AttributeError
  4. This exception was caught by the except Exception handler (line 287-290), triggering logger.error() on every invocation
  5. Even though the exception was caught and processing continued, the logging overhead accumulated

Before (with exception on every call):

PIIFilterPlugin tool_pre_invoke: 0.059ms
  - Logging overhead:  0.020ms (34%)
  - Plugin work:       0.026ms (44%)
  - Framework:         0.013ms (22%)

Solution

Changes Made

1. Auto-wrap GlobalContext in PluginContext (manager.py:690-735)

Updated invoke_hook_for_plugin() to accept both PluginContext and GlobalContext, with automatic wrapping:

async def invoke_hook_for_plugin(
    self,
    name: str,
    hook_type: str,
    payload: Union[PluginPayload, dict[str, Any], str],
    context: Union[PluginContext, GlobalContext],  # Now accepts both types
    violations_as_exceptions: bool = False,
    payload_as_json: bool = False,
) -> PluginResult:
    # Auto-wrap GlobalContext in PluginContext for convenience
    if isinstance(context, GlobalContext):
        context = PluginContext(global_context=context)

    # ... rest of method

Benefits:

  • Backward compatible - existing code using PluginContext continues to work
  • Convenient - callers can pass GlobalContext directly (common in tests/benchmarks)
  • Prevents AttributeError exceptions in the hot path

2. Fixed f-string in logger.debug (manager.py:361)

Changed from eager f-string formatting to lazy logger formatting:

# Before:
logger.debug(f"Plugin observability setup failed: {e}")

# After:
logger.debug("Plugin observability setup failed: %s", e)

Benefits:

  • String interpolation only happens if DEBUG logging is enabled
  • Follows Python logging best practices for performance

Performance Impact

Benchmark Results

Performance profiling with 1000 iterations per plugin-hook combination:

Plugin Hook Before After Improvement
DenyListPlugin prompt_pre_fetch 0.036ms 0.009ms 4.0x faster
CircuitBreaker tool_pre_invoke 0.039ms 0.008ms 4.9x faster
CircuitBreaker tool_post_invoke 0.041ms 0.011ms 3.7x faster
Watchdog tool_pre_invoke 0.039ms 0.007ms 5.6x faster
SchemaGuardPlugin tool_pre_invoke 0.033ms 0.007ms 4.7x faster
CachedToolResultPlugin tool_pre_invoke 0.033ms 0.007ms 4.7x faster
ArgumentNormalizer prompt_pre_fetch 0.059ms 0.032ms 1.8x faster
ArgumentNormalizer tool_pre_invoke 0.051ms 0.023ms 2.2x faster
PIIFilterPlugin tool_pre_invoke 0.059ms 0.030ms 2.0x faster
PIIFilterPlugin prompt_post_fetch 0.047ms 0.022ms 2.1x faster
ReplaceBadWordsPlugin prompt_pre_fetch 0.038ms 0.012ms 3.2x faster

Average Improvements by Plugin Category

  • Minimal plugins (< 10μs work): 4-5x faster
  • Medium plugins (10-30μs work): 1.8-2.5x faster
  • Complex plugins (> 30μs work): 1.5-2x faster

Real-World Impact

Simple request (5 plugins × 2 hooks = 10 hook calls):

  • Before: 0.50ms overhead → 2,000 req/sec max
  • After: 0.10ms overhead → 10,000 req/sec max (5x throughput)

Complex request (20 plugins × 4 hooks = 80 hook calls):

  • Before: 4.0ms overhead → 250 req/sec max
  • After: 0.80ms overhead → 1,250 req/sec max (5x throughput)

Testing

Verification Steps

  1. Full performance profiling (31 plugins, 1000 iterations each):

    make -C tests/performance test-plugins
- All plugins show 2-5x improvement
- No error logs in output (logger.error only on real failures)

  2. Profile analysis:

    • Before: 1000 calls to logger.error() in every profile
    • After: 0 calls to logger.error() (only actual errors logged)

Test Coverage

  • Backward compatibility: Existing code using PluginContext unaffected
  • New functionality: GlobalContext auto-wrapping works correctly
  • Error handling: Real exceptions still logged appropriately
  • Performance: 2-5x improvement verified across all plugins

Technical Details

Why This Happened

  1. The performance test (and potentially other code) passed GlobalContext to invoke_hook_for_plugin()
  2. The method expected PluginContext but didn't validate the type
  3. Deep in execute_plugin(), accessing local_context.global_context failed silently
  4. The exception was caught, logged, and processing continued (permissive mode)
  5. This pattern repeated for every single invocation

Why It's Fixed Now

  1. Type flexibility: Method now accepts both context types
  2. Explicit handling: Auto-wrapping prevents type mismatch
  3. No hidden exceptions: The AttributeError no longer occurs
  4. Logging only on errors: logger.error() only called for real failures

Current Performance Breakdown

After this fix, typical plugin execution time is spent on:

  • 50-70%: Actual plugin logic (as it should be!)
  • 20-30%: Framework overhead (timeout protection, context management)
  • 0-10%: Logging (only when errors occur)

Migration Guide

For Plugin Authors

No changes required. This fix is transparent to plugin implementations.

For Framework Users

If you're calling invoke_hook_for_plugin() directly:

Before (still works):

context = PluginContext(global_context=GlobalContext(request_id="123"))
result = await manager.invoke_hook_for_plugin(name, hook_type, payload, context)

After (now also works):

# Can pass GlobalContext directly - it will be auto-wrapped
context = GlobalContext(request_id="123")
result = await manager.invoke_hook_for_plugin(name, hook_type, payload, context)

Checklist

  • Changes tested with performance profiling
  • Backward compatibility verified
  • Documentation updated (docstrings)
  • Performance improvement documented
  • No breaking changes
  • Type hints updated
  • Follows logging best practices

Files Changed

  • mcpgateway/plugins/framework/manager.py:
    • Modified invoke_hook_for_plugin() signature to accept both context types (line 695)
    • Added auto-wrapping logic for GlobalContext (lines 733-735)
    • Fixed f-string in logger.debug to lazy formatting (line 361)

Additional Notes

Combined with previous fix (#2065):

  • Original baseline: 0.207ms per hook
  • After exc_info removal: 0.032-0.104ms per hook (3-6x faster)
  • After this fix: 0.007-0.077ms per hook (10-30x faster than original!)

Complete comparison analysis to baseline:

====================================================================================================
COMPARISON SUMMARY
====================================================================================================
Test                                                  Baseline (s)     Current (s)          Change
----------------------------------------------------------------------------------------------------
ArgumentNormalizer_prompt_pre_fetch.prof                  0.232463        0.028539          -87.7%
ArgumentNormalizer_tool_pre_invoke.prof                   0.222858        0.022644          -89.8%
CachedToolResultPlugin_tool_post_invoke.prof              0.199008        0.007367          -96.3%
CachedToolResultPlugin_tool_pre_invoke.prof               0.197429        0.007362          -96.3%
CircuitBreaker_tool_post_invoke.prof                      0.699122        0.011303          -98.4%
CircuitBreaker_tool_pre_invoke.prof                       0.683927        0.008212          -98.8%
CitationValidator_resource_post_fetch.prof                0.202397        0.008104          -96.0%
CitationValidator_tool_post_invoke.prof                   0.204045        0.007816          -96.2%
CodeFormatter_resource_post_fetch.prof                    0.215267        0.015318          -92.9%
CodeFormatter_tool_post_invoke.prof                       0.205183        0.007795          -96.2%
CodeSafetyLinterPlugin_tool_post_invoke.prof              0.201381        0.007915          -96.1%
DenyListPlugin_prompt_pre_fetch.prof                      0.203179        0.009407          -95.4%
FileTypeAllowlistPlugin_resource_post_fetch.prof          0.201911        0.007461          -96.3%
FileTypeAllowlistPlugin_resource_pre_fetch.prof           0.205651        0.009541          -95.4%
HTMLToMarkdownPlugin_resource_post_fetch.prof             0.203760        0.009502          -95.3%
HarmfulContentDetector_prompt_pre_fetch.prof              0.246567        0.040892          -83.4%
HarmfulContentDetector_tool_post_invoke.prof              0.271827        0.062341          -77.1%
HeaderInjector_resource_pre_fetch.prof                    0.206886        0.008926          -95.7%
JSONRepairPlugin_tool_post_invoke.prof                    0.199952        0.007429          -96.3%
LicenseHeaderInjector_resource_post_fetch.prof            0.214318        0.013508          -93.7%
LicenseHeaderInjector_tool_post_invoke.prof               0.203814        0.007520          -96.3%
MarkdownCleanerPlugin_prompt_post_fetch.prof              0.211546        0.014593          -93.1%
MarkdownCleanerPlugin_resource_post_fetch.prof            0.211933        0.013449          -93.7%
OutputLengthGuardPlugin_tool_post_invoke.prof             0.201871        0.007746          -96.2%
PIIFilterPlugin_prompt_post_fetch.prof                    0.218788        0.022910          -89.5%
PIIFilterPlugin_prompt_pre_fetch.prof                     0.286409        0.073242          -74.4%
PIIFilterPlugin_tool_post_invoke.prof                     0.257708        0.051315          -80.1%
PIIFilterPlugin_tool_pre_invoke.prof                      0.230615        0.030176          -86.9%
ReplaceBadWordsPlugin_prompt_post_fetch.prof              0.204460        0.010607          -94.8%
ReplaceBadWordsPlugin_prompt_pre_fetch.prof               0.205820        0.012146          -94.1%
ReplaceBadWordsPlugin_tool_post_invoke.prof               0.202146        0.009463          -95.3%
ReplaceBadWordsPlugin_tool_pre_invoke.prof                0.205963        0.012249          -94.1%
ResourceFilterExample_resource_post_fetch.prof            0.669199        0.007357          -98.9%
ResourceFilterExample_resource_pre_fetch.prof             0.731530        0.011740          -98.4%
ResponseCacheByPrompt_tool_post_invoke.prof               0.202545        0.007275          -96.4%
ResponseCacheByPrompt_tool_pre_invoke.prof                0.203682        0.007143          -96.5%
RetryWithBackoffPlugin_resource_post_fetch.prof           0.205346        0.007245          -96.5%
RetryWithBackoffPlugin_tool_post_invoke.prof              0.202987        0.007267          -96.4%
RobotsLicenseGuard_resource_post_fetch.prof               0.207298        0.011263          -94.6%
RobotsLicenseGuard_resource_pre_fetch.prof                0.200414        0.008381          -95.8%
SPARCStaticValidator_tool_pre_invoke.prof                 0.789975        0.008619          -98.9%
SQLSanitizer_prompt_pre_fetch.prof                        0.218705        0.019858          -90.9%
SQLSanitizer_tool_pre_invoke.prof                         0.216702        0.018992          -91.2%
SafeHTMLSanitizer_resource_post_fetch.prof                0.210452        0.013492          -93.6%
SchemaGuardPlugin_tool_post_invoke.prof                   0.201800        0.007772          -96.1%
SchemaGuardPlugin_tool_pre_invoke.prof                    0.201547        0.007399          -96.3%
SecretsDetection_prompt_pre_fetch.prof                    0.224690        0.023792          -89.4%
SecretsDetection_resource_post_fetch.prof                 0.211360        0.014556          -93.1%
SecretsDetection_tool_post_invoke.prof                    0.238682        0.037596          -84.2%
Summarizer_resource_post_fetch.prof                       0.204291        0.008572          -95.8%
Summarizer_tool_post_invoke.prof                          0.201511        0.007077          -96.5%
TimezoneTranslator_tool_post_invoke.prof                  0.215695        0.015193          -93.0%
TimezoneTranslator_tool_pre_invoke.prof                   0.199961        0.007099          -96.4%
URLReputationPlugin_resource_pre_fetch.prof               0.210241        0.010864          -94.8%
VirusTotalURLCheckerPlugin_prompt_post_fetch.prof         0.204989        0.008747          -95.7%
VirusTotalURLCheckerPlugin_resource_post_fetch.prof        0.201330        0.008409          -95.8%
VirusTotalURLCheckerPlugin_resource_pre_fetch.prof        0.209055        0.012118          -94.2%
VirusTotalURLCheckerPlugin_tool_post_invoke.prof          0.209288        0.008498          -95.9%
Watchdog_tool_post_invoke.prof                            0.672092        0.008268          -98.8%
Watchdog_tool_pre_invoke.prof                             0.663058        0.007274          -98.9%
----------------------------------------------------------------------------------------------------
TOTAL                                                    16.186631        0.888663 -94.5%
====================================================================================================

✓ Overall Performance: 94.5% FASTER

@araujof araujof added this to the Release 1.0.0-BETA-2 milestone Jan 13, 2026
@araujof araujof requested a review from terylt January 13, 2026 17:46
@araujof araujof self-assigned this Jan 13, 2026
@araujof araujof added bug Something isn't working performance Performance related items plugins labels Jan 13, 2026
@araujof araujof marked this pull request as draft January 13, 2026 17:47
@araujof araujof force-pushed the feat/plugin_manager_logging_performance branch from 518549e to 5205760 Compare January 13, 2026 17:53
@araujof araujof marked this pull request as ready for review January 13, 2026 17:53
@araujof
Copy link
Copy Markdown
Member Author

araujof commented Jan 13, 2026

@crivetimihai please merge #2065 first.

@araujof @crivetimihai
perf: fix unconditional logging overhead in plugin framework
1217de2 
- Auto-wrap GlobalContext in PluginContext in invoke_hook_for_plugin()
  to prevent AttributeError exceptions on every invocation
- Change f-string to lazy logger formatting in debug statement

This eliminates unnecessary logger.error() calls that were triggered
by a type mismatch when GlobalContext was passed directly, resulting
in 2-5x performance improvement for plugin execution.

Signed-off-by: Mihai Criveti <crivetimihai@gmail.com>
@crivetimihai crivetimihai force-pushed the feat/plugin_manager_logging_performance branch from 5205760 to 1217de2 Compare January 14, 2026 00:25
@crivetimihai crivetimihai merged commit 7f011b8 into main Jan 14, 2026
44 of 46 checks passed
@crivetimihai crivetimihai deleted the feat/plugin_manager_logging_performance branch January 14, 2026 00:25
kcostell06 pushed a commit to kcostell06/mcp-context-forge that referenced this pull request Feb 24, 2026
@araujof
perf: fix unconditional logging overhead in plugin framework (IBM#2085)
07eed11 
- Auto-wrap GlobalContext in PluginContext in invoke_hook_for_plugin()
  to prevent AttributeError exceptions on every invocation
- Change f-string to lazy logger formatting in debug statement

This eliminates unnecessary logger.error() calls that were triggered
by a type mismatch when GlobalContext was passed directly, resulting
in 2-5x performance improvement for plugin execution.

Signed-off-by: Mihai Criveti <crivetimihai@gmail.com>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Reviewers

@crivetimihai crivetimihai crivetimihai approved these changes

@terylt terylt Awaiting requested review from terylt terylt is a code owner

@kevalmahajan kevalmahajan Awaiting requested review from kevalmahajan

@madhav165 madhav165 Awaiting requested review from madhav165

Assignees

@araujof araujof

Labels

bug Something isn't working performance Performance related items plugins

Projects

None yet

Milestone

Release 1.0.0-BETA-2

Development

Successfully merging this pull request may close these issues.

[PERFORMANCE]: Logging overhead in plugin manager

2 participants

@araujof @crivetimihai