Optimize field validator performance for labkit logging rollout

Summary

This issue tracks performance optimization work needed before rolling out the labkit logging field validator to the GitLab monolith.

Performance Concerns

Based on profiling results from MR !213 (merged), the field validator introduces significant performance overhead:

  • 2.5x slower for valid-only fields
  • 3x slower with deprecated fields

Performance Profiling

Benchmark Script 

# frozen_string_literal: true

require "benchmark/ips"
require "stackprof"

require "bundler/setup"

$LOAD_PATH << "./lib"
require "gitlab-labkit"

class MyLogger < Labkit::Logging::JsonLogger
end

def profile(suffix:)
  require "stackprof"
  require "json"
  args = { mode: :wall, interval: 100, raw: true }
  profile = ::StackProf.run(**args) { yield }
  File.write("profile-#{suffix}.json", JSON.generate(profile))
  puts "Run `speedscope profile-#{suffix}.json`"
end

logger = MyLogger.new("/dev/zero") # NOT /dev/null because it's a no-op internally
logger.info user_id: 23

injected = defined? Labkit::Logging::FieldValidator
label = injected ? 'injected' : 'not_injected'

Benchmark.ips do |x|
  x.report "valid #{label}" do
    logger.info ohai: 23
  end

  x.report "invalid #{label}" do
    logger.info user_id: 23
  end

  x.compare!
  x.save! 'compare'
end

puts "Profiling..."

profile suffix: label do
  1.upto(1_000_000) do
    logger.info user_id: 23
  end
end

Results

TL;DR: 2.5x slower (for valid-only fields) and ~3x slower (with deprecated fields)

$ ruby `pwd`/perf.rb
ruby 3.3.10 (2025-10-23 revision 343ea05002) [x86_64-linux]
Warming up --------------------------------------
            injected     8.395k i/100ms
Calculating -------------------------------------
            injected     89.049k (± 3.0%) i/s   (11.23 µs/i) -    444.935k in   5.001253s

Comparison:
        not_injected:   243965.9 i/s
            injected:    89048.7 i/s - 2.74x  slower

Profiling...
Run `speedscope profile-injected.json`

================================================================================
LabKit Logging Field Standardization: New Offenses Detected
================================================================================

perf.rb:24: 'user_id' is deprecated. Use 'Labkit::Fields::GL_USER_ID' instead.

================================================================================
Total: 1 new offense(s) in 1 file(s)

See https://gitlab.com/gitlab-org/ruby/gems/labkit-ruby/-/blob/master/doc/FIELD_STANDARDIZATION.md
================================================================================
/home/peter/devel/gitlab/labkit-ruby/lib/labkit/logging/field_validator.rb:105:in `handle_new_offenses': New LabKit logging offenses detected (RuntimeError)

Flame Graph Profiles

Not Injected Injected
profile-not_injected.json Screenshot_From_2026-01-29_14-56-05 profile-injected.json Screenshot_From_2026-01-29_14-56-16

Use speedscope to inspect the JSON profiles and identify slow paths.

Identified Bottlenecks

1. Stack Frame Processing (Primary)

Location: lib/labkit/logging/field_validator/log_interceptor.rb - determine_callsite method

Issue: Processes unnecessary internal frames

  • Calls caller_locations(1, 30) which processes 30 stack frames
  • First 4 frames are always internal to LabKit/Logger:
    1. log_interceptor.rb:34 in format_data
    2. json_logger.rb:41 in format_message
    3. logger.rb:692 in add
    4. logger.rb:721 in info

Fix: Change line 59 from caller_locations(1, 30) to caller_locations(5, 30) to skip internal frames

Additional: Reduce frame limit from 30 to ~10-15 (most callsites are within this range)

2. String Key Conversion (Secondary)

Location: log_interceptor.rb - extract_string_keys method

Issue: Converts all hash keys to strings on every log call

  • data.keys.to_set(&:to_s) creates intermediate Set objects
  • Happens even when no deprecated fields are present

Fix: Implement lazy conversion - only convert keys if a deprecated field is found

3. Regex Pattern Matching (Tertiary)

Location: determine_callsite method

Issue: Multiple regex patterns checked sequentially per frame

  • IGNORE_PATHS has 4 patterns
  • LogInterceptor.wrapper_patterns adds additional patterns
  • All checked for each frame in the stack

Fix: Pre-compile patterns and consider early-exit strategies

4. Mutex Contention

Location: lib/labkit/logging/field_validator/registry.rb - record_offense method

Issue: Synchronization on every log call

  • @mutex.synchronize blocks in high-throughput scenarios
  • Thread-safe but not optimized for concurrent logging

Fix: Consider lock-free approach or batching updates

Optimization Suggestion from MR !213 (merged)

From MR !213 note:

Proposed fix: Change caller_locations(1, 30) to caller_locations(5, 30) in lib/labkit/logging/field_validator/log_interceptor.rb (line 59) to skip the first 4 internal frames.

Additional recommendation: Add a spec to ensure these frames can be safely skipped in case the code is refactored and the frame count needs adjustment.

Blocking Rollout

This issue blocks the rollout of labkit logging TODO to the gitlab monolith until performance is optimized to acceptable levels.

Related

Edited by Peter Leitzen