Merge branch 'log_cpu_user_s' into 'master'

Log cpu user time to structured logging

Closes #30567

See merge request gitlab-org/gitlab!18498

config/initializers/lograge.rb

@@ -32,6 +32,10 @@ unless Sidekiq.server?
       payload[:response] = event.payload[:response] if event.payload[:response]
       payload[Labkit::Correlation::CorrelationId::LOG_KEY] = Labkit::Correlation::CorrelationId.current_id
 
+      if cpu_s = Gitlab::Metrics::System.thread_cpu_duration(::Gitlab::RequestContext.start_thread_cpu_time)
+        payload[:cpu_s] = cpu_s
+      end
+
       payload
     end
   end

lib/gitlab/metrics/system.rb

@@ -65,6 +65,8 @@ module Gitlab
       end
 
       def self.thread_cpu_time
+        # Not all OS kernels are supporting `Process::CLOCK_THREAD_CPUTIME_ID`
+        # Refer: https://gitlab.com/gitlab-org/gitlab/issues/30567#note_221765627
         return unless defined?(Process::CLOCK_THREAD_CPUTIME_ID)
 
         Process.clock_gettime(Process::CLOCK_THREAD_CPUTIME_ID, :float_second)

lib/gitlab/request_context.rb

@@ -6,6 +6,10 @@ module Gitlab
       def client_ip
         Gitlab::SafeRequestStore[:client_ip]
       end
+
+      def start_thread_cpu_time
+        Gitlab::SafeRequestStore[:start_thread_cpu_time]
+      end
     end
 
     def initialize(app)
@@ -23,6 +27,8 @@ module Gitlab
 
       Gitlab::SafeRequestStore[:client_ip] = req.ip
 
+      Gitlab::SafeRequestStore[:start_thread_cpu_time] = Gitlab::Metrics::System.thread_cpu_time
+
       @app.call(env)
     end
   end

spec/initializers/lograge_spec.rb

@@ -34,5 +34,38 @@ describe 'lograge', type: :request do
 
       subject
     end
+
+    it 'logs cpu_s on supported platform' do
+      allow(Gitlab::Metrics::System).to receive(:thread_cpu_time)
+        .and_return(
+          0.111222333,
+          0.222333833
+        )
+
+      expect(Lograge.formatter).to receive(:call)
+        .with(a_hash_including(cpu_s: 0.1111115))
+        .and_call_original
+
+      expect(Lograge.logger).to receive(:send)
+        .with(anything, include('"cpu_s":0.1111115'))
+        .and_call_original
+
+      subject
+    end
+
+    it 'does not log cpu_s on unsupported platform' do
+      allow(Gitlab::Metrics::System).to receive(:thread_cpu_time)
+        .and_return(nil)
+
+      expect(Lograge.formatter).to receive(:call)
+        .with(hash_not_including(:cpu_s))
+        .and_call_original
+
+      expect(Lograge.logger).not_to receive(:send)
+        .with(anything, include('"cpu_s":'))
+        .and_call_original
+
+      subject
+    end
   end
 end

spec/lib/gitlab/metrics/system_spec.rb

@@ -58,4 +58,44 @@ describe Gitlab::Metrics::System do
       expect(described_class.monotonic_time).to be_an(Float)
     end
   end
+
+  describe '.thread_cpu_time' do
+    it 'returns cpu_time on supported platform' do
+      stub_const("Process::CLOCK_THREAD_CPUTIME_ID", 16)
+
+      expect(Process).to receive(:clock_gettime)
+        .with(16, kind_of(Symbol)) { 0.111222333 }
+
+      expect(described_class.thread_cpu_time).to eq(0.111222333)
+    end
+
+    it 'returns nil on unsupported platform' do
+      hide_const("Process::CLOCK_THREAD_CPUTIME_ID")
+
+      expect(described_class.thread_cpu_time).to be_nil
+    end
+  end
+
+  describe '.thread_cpu_duration' do
+    let(:start_time) { described_class.thread_cpu_time }
+
+    it 'returns difference between start and current time' do
+      stub_const("Process::CLOCK_THREAD_CPUTIME_ID", 16)
+
+      expect(Process).to receive(:clock_gettime)
+        .with(16, kind_of(Symbol))
+        .and_return(
+          0.111222333,
+          0.222333833
+        )
+
+      expect(described_class.thread_cpu_duration(start_time)).to eq(0.1111115)
+    end
+
+    it 'returns nil on unsupported platform' do
+      hide_const("Process::CLOCK_THREAD_CPUTIME_ID")
+
+      expect(described_class.thread_cpu_duration(start_time)).to be_nil
+    end
+  end
 end