## 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, the field validator introduces significant performance overhead: - **2.5x slower** for valid-only fields - **3x slower** with deprecated fields ## Performance Profiling ### Benchmark Script ```ruby # 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](/uploads/b4bbc05bcb744565b92b4655a7ee1c48/profile-not_injected.json) {width=900 height=263} | [profile-injected.json](/uploads/25a6cb44e4eb6e4d1236fa847b3db455/profile-injected.json) {width=900 height=263} | Use [speedscope](https://docs.gitlab.com/development/profiling/#speedscope-flamegraphs) 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 From [MR !213 note](https://gitlab.com/gitlab-org/ruby/gems/labkit-ruby/-/merge_requests/213#note_3044817212): **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 - MR: https://gitlab.com/gitlab-org/ruby/gems/labkit-ruby/-/merge_requests/213 - Performance profiling: https://gitlab.com/gitlab-org/ruby/gems/labkit-ruby/-/merge_requests/213#note_3044643103 - Performance suggestion: https://gitlab.com/gitlab-org/ruby/gems/labkit-ruby/-/merge_requests/213#note_3044817212