Merge branch 'reduce-memory-allocation-in-logging' into 'master'

Reduce object allocation during logging

See merge request gitlab-org/gitlab!25808

config/initializers/lograge.rb

@@ -20,38 +20,6 @@ unless Gitlab::Runtime.sidekiq?
     config.lograge.ignore_actions = ['Gitlab::RequestForgeryProtection::Controller#index']
 
     # Add request parameters to log output
-    config.lograge.custom_options = lambda do |event|
-      params = event.payload[:params]
-        .except(*%w(controller action format))
-        .each_pair
-        .map { |k, v| { key: k, value: v } }
-
-      payload = {
-        time: Time.now.utc.iso8601(3),
-        params: Gitlab::Utils::LogLimitedArray.log_limited_array(params, sentinel: { key: 'truncated', value: '...' }),
-        remote_ip: event.payload[:remote_ip],
-        user_id: event.payload[:user_id],
-        username: event.payload[:username],
-        ua: event.payload[:ua],
-        queue_duration: event.payload[:queue_duration]
-      }
-
-      ::Gitlab::InstrumentationHelper.add_instrumentation_data(payload)
-
-      payload[:response] = event.payload[:response] if event.payload[:response]
-      payload[:etag_route] = event.payload[:etag_route] if event.payload[:etag_route]
-      payload[Labkit::Correlation::CorrelationId::LOG_KEY] = Labkit::Correlation::CorrelationId.current_id
-
-      if cpu_s = Gitlab::Metrics::System.thread_cpu_duration(::Gitlab::RequestContext.instance.start_thread_cpu_time)
-        payload[:cpu_s] = cpu_s
-      end
-
-      # https://github.com/roidrage/lograge#logging-errors--exceptions
-      exception = event.payload[:exception_object]
-
-      ::Gitlab::ExceptionLogFormatter.format!(exception, payload)
-
-      payload
-    end
+    config.lograge.custom_options = Gitlab::Lograge::CustomOptions
   end
 end

lib/gitlab/grape_logging/formatters/lograge_with_timestamp.rb

@@ -6,6 +6,8 @@ module Gitlab
       class LogrageWithTimestamp
         include Gitlab::EncodingHelper
 
+        EMPTY_ARRAY = [].freeze
+
         def call(severity, datetime, _, data)
           time = data.delete :time
           data[:params] = process_params(data)
@@ -16,30 +18,27 @@ module Gitlab
             duration: time[:total],
             db: time[:db],
             view: time[:view]
-          }.merge(data)
-          ::Lograge.formatter.call(attributes) + "\n"
+          }.merge!(data)
+
+          ::Lograge.formatter.call(attributes) << "\n"
         end
 
         private
 
         def process_params(data)
-          return [] unless data.has_key?(:params)
+          return EMPTY_ARRAY unless data.has_key?(:params)
 
-          params_array =
-            data[:params]
-              .each_pair
-              .map { |k, v| { key: k, value: utf8_encode_values(v) } }
+          params_array = data[:params].map { |k, v| { key: k, value: utf8_encode_values(v) } }
 
-          Gitlab::Utils::LogLimitedArray.log_limited_array(params_array,
-                                                           sentinel: { key: 'truncated', value: '...' })
+          Gitlab::Utils::LogLimitedArray.log_limited_array(params_array, sentinel: Gitlab::Lograge::CustomOptions::LIMITED_ARRAY_SENTINEL)
         end
 
         def utf8_encode_values(data)
           case data
           when Hash
-            data.merge(data) { |k, v| utf8_encode_values(v) }
+            data.merge!(data) { |k, v| utf8_encode_values(v) }
           when Array
-            data.map { |v| utf8_encode_values(v) }
+            data.map! { |v| utf8_encode_values(v) }
           when String
             encode_utf8(data)
           end

lib/gitlab/lograge/custom_options.rb

+# frozen_string_literal: true
+
+module Gitlab
+  module Lograge
+    module CustomOptions
+      LIMITED_ARRAY_SENTINEL = { key: 'truncated', value: '...' }.freeze
+      IGNORE_PARAMS = Set.new(%w(controller action format)).freeze
+
+      def self.call(event)
+        params = event
+          .payload[:params]
+          .each_with_object([]) { |(k, v), array| array << { key: k, value: v } unless IGNORE_PARAMS.include?(k) }
+
+        payload = {
+          time: Time.now.utc.iso8601(3),
+          params: Gitlab::Utils::LogLimitedArray.log_limited_array(params, sentinel: LIMITED_ARRAY_SENTINEL),
+          remote_ip: event.payload[:remote_ip],
+          user_id: event.payload[:user_id],
+          username: event.payload[:username],
+          ua: event.payload[:ua],
+          queue_duration: event.payload[:queue_duration]
+        }
+
+        ::Gitlab::InstrumentationHelper.add_instrumentation_data(payload)
+
+        payload[:response] = event.payload[:response] if event.payload[:response]
+        payload[:etag_route] = event.payload[:etag_route] if event.payload[:etag_route]
+        payload[Labkit::Correlation::CorrelationId::LOG_KEY] = Labkit::Correlation::CorrelationId.current_id
+
+        if cpu_s = Gitlab::Metrics::System.thread_cpu_duration(::Gitlab::RequestContext.instance.start_thread_cpu_time)
+          payload[:cpu_s] = cpu_s
+        end
+
+        # https://github.com/roidrage/lograge#logging-errors--exceptions
+        exception = event.payload[:exception_object]
+
+        ::Gitlab::ExceptionLogFormatter.format!(exception, payload)
+
+        payload
+      end
+    end
+  end
+end

spec/lib/gitlab/grape_logging/formatters/lograge_with_timestamp_spec.rb

+# frozen_string_literal: true
+
+require 'spec_helper'
+
+describe Gitlab::GrapeLogging::Formatters::LogrageWithTimestamp do
+  let(:log_entry) do
+    {
+      status: 200,
+      time:  {
+        total: 758.58,
+        db: 77.06,
+        view: 681.52
+      },
+      method: 'PUT',
+      path: '/api/v4/projects/1',
+      params: {
+        'description': '[FILTERED]',
+        'name': 'gitlab test'
+      },
+      host: 'localhost',
+      remote_ip: '127.0.0.1',
+      ua: 'curl/7.66.0',
+      route: '/api/:version/projects/:id',
+      user_id: 1,
+      username: 'root',
+      queue_duration: 1764.06,
+      gitaly_calls: 6,
+      gitaly_duration: 20.0,
+      correlation_id: 'WMefXn60429'
+    }
+  end
+  let(:time) { Time.now }
+  let(:result) { JSON.parse(subject) }
+
+  subject { described_class.new.call(:info, time, nil, log_entry) }
+
+  it 'turns the log entry to valid JSON' do
+    expect(result['status']).to eq(200)
+  end
+
+  it 're-formats the params hash' do
+    params = result['params']
+
+    expect(params).to eq([
+      { 'key' => 'description', 'value' => '[FILTERED]' },
+      { 'key' => 'name', 'value' => 'gitlab test' }
+    ])
+  end
+end