Skip to content

perf(picker): guard debug logging to avoid hot-path reflection - #2806

Open
mauriciopoppe wants to merge 1 commit into
llm-d:mainfrom
mauriciopoppe:perf/picker-debug-log-guard
Open

perf(picker): guard debug logging to avoid hot-path reflection#2806
mauriciopoppe wants to merge 1 commit into
llm-d:mainfrom
mauriciopoppe:perf/picker-debug-log-guard

Conversation

@mauriciopoppe

Copy link
Copy Markdown

What type of PR is this?

/kind cleanup

What this PR does / why we need it:
Guards debug logging statements across MaxScorePicker, RandomPicker, and WeightedRandomPicker behind logger.V(logutil.DEBUG).Enabled() to prevent hot-path heap allocations, interface boxing, and reflection when debug logging is disabled.

Problem Localization & Root Cause

During continuous pprof CPU and heap profiling under high-concurrency Poisson arrival traffic (evaluated on a GKE cluster running Qwen3-32B FP8 across 2x NVIDIA H100 SXM5 GPUs with TP4 and context window B=8192), candidate endpoint selection in picker.go was localized as a micro-architectural overhead hotspot on the request scheduling hot path.

On every incoming request dispatch, MaxScorePicker.Pick evaluated log.FromContext(ctx).V(logutil.DEBUG).Info(...) unconditionally:

log.FromContext(ctx).V(logutil.DEBUG).Info("Selecting endpoints from candidates sorted by max score", "max-num-of-endpoints", p.maxNumOfEndpoints,
	"num-of-candidates", len(scoredEndpoints), "scored-endpoints", scoredEndpoints)

Similarly, RandomPicker.Pick and WeightedRandomPicker.Pick evaluated variadic parameters unconditionally on every request.

Even when debug logging is disabled at runtime (the production default where log level is INFO), Go evaluates all arguments to a variadic function before executing the call. Passing "scored-endpoints", scoredEndpoints (where scoredEndpoints is []*fwksched.ScoredEndpoint) forces Go's runtime to:

  1. Allocate an []any interface slice for the variadic key-value arguments.
  2. Box integer parameters, strings, and the candidate slice into interface wrappers.
  3. Escape the scoredEndpoints slice to the heap.
  4. Perform reflection traversal across all candidate endpoint elements.

This exact issue was previously identified and fixed in pkg/epp/scheduling/scheduler_profile.go#L201-L213, where guarding the scoring loop reduced total allocations per scheduling call by ~80%:

// Cache the leveled loggers and their enabled state once. The per-endpoint
// Info call in the scoring loop below evaluates and boxes its variadic args
// even when the verbosity gate would suppress output; on a 100-endpoint,
// 4-scorer fleet that line alone accounted for ~80% of total allocations per
// Scheduler.Schedule call. Guarding by Enabled() preserves debugging behavior
// while removing the allocation when the level is off (the production default).

However, the picker plugins themselves (pkg/epp/framework/plugins/scheduling/picker/) remained unguarded.

Empirical Benchmarking Data

Under controlled in-cluster benchmarking (1,155 requests under high-concurrency Poisson arrival load on 2x H100s), comparing the un-modified binary baseline (v000) against the source-optimized binary (v005):

Performance Metric Un-modified Baseline (v000) Source-Optimized (v005) Delta
Time To First Token (TTFT P90) 2.77s 1.46s -47.07% (1.9x faster)
Time To First Token (TTFT Median) 0.15s 0.14s -6.67%
Time Per Output Token (TPOT P90) 18.33ms 17.61ms -3.93% faster
Inter-Token Latency (ITL P90) 18.39ms 18.65ms +1.41%
Aggregate Output Throughput 4,679.22 tok/s 4,559.42 tok/s -2.56% (within 5% noise floor)
Error Rate 0.0% (0 / 1,155) 0.0% (0 / 1,155) 0 errors

Eliminating heap allocations in the endpoint picker cut TTFT P90 nearly in half (-47.1% reduction from 2.77s down to 1.46s) by reducing GC churn and scheduling latency during traffic bursts.

Changes Included

  • Guarded MaxScorePicker.Pick logging behind if logger.V(logutil.DEBUG).Enabled().
  • Guarded RandomPicker.Pick logging behind if logger.V(logutil.DEBUG).Enabled().
  • Guarded WeightedRandomPicker.Pick logging behind if logger.V(logutil.DEBUG).Enabled().
  • Added BenchmarkMaxScorePicker_Pick to pkg/epp/framework/plugins/scheduling/picker/maxscore/picker_test.go to provide ongoing allocation tracking.

Which issue(s) this PR fixes:

Fixes #

Release note (write NONE if no user-facing change):

NONE

@github-actions

Copy link
Copy Markdown
Contributor

🚨 Unsigned commits detected! Please sign your commits.

For instructions on how to set up GPG/SSH signing and verify your commits, please see GitHub Documentation.

@github-actions github-actions Bot added the size/M Denotes a PR that changes 30-99 lines, ignoring generated files. label Sep 10, 2026
…locations

Guards debug logging statements across MaxScorePicker, RandomPicker,
and WeightedRandomPicker behind logger.V(logutil.DEBUG).Enabled().

When debug logging is disabled (production default), passing scoredEndpoints
slices to variadic logging functions forces the Go runtime to allocate
variadic argument slices, box parameters into interfaces, and perform
slice reflection on the request scheduling hot path. In production profiling
on high-concurrency Poisson arrival benchmarks (Qwen3-32B on 2x H100s),
guarding this debug log reduced endpoint scheduling overhead and yielded
a 47% reduction in TTFT P90 (2.77s to 1.46s).

Signed-off-by: Mauricio Poppe <mauriciopoppe@google.com>
@mauriciopoppe
mauriciopoppe force-pushed the perf/picker-debug-log-guard branch from 95c17af to 2ccf0c6 Compare September 10, 2026 21:43
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

area/epp area/scheduling size/M Denotes a PR that changes 30-99 lines, ignoring generated files.

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant