Merge branch 'add-db-timings-to-sidekiq-logs' into 'master'

Add database timings to Sidekiq JSON logs

See merge request gitlab-org/gitlab!22548

changelogs/unreleased/add-db-timings-to-sidekiq-logs.yml

+---
+title: Log database time in Sidekiq JSON logs
+merge_request: 22548
+author:
+type: other

doc/administration/logs.md

@@ -249,7 +249,7 @@ Instead of the format above, you can opt to generate JSON logs for
 Sidekiq. For example:
 
 ```json
-{"severity":"INFO","time":"2018-04-03T22:57:22.071Z","queue":"cronjob:update_all_mirrors","args":[],"class":"UpdateAllMirrorsWorker","retry":false,"queue_namespace":"cronjob","jid":"06aeaa3b0aadacf9981f368e","created_at":"2018-04-03T22:57:21.930Z","enqueued_at":"2018-04-03T22:57:21.931Z","pid":10077,"message":"UpdateAllMirrorsWorker JID-06aeaa3b0aadacf9981f368e: done: 0.139 sec","job_status":"done","duration":0.139,"completed_at":"2018-04-03T22:57:22.071Z"}
+{"severity":"INFO","time":"2018-04-03T22:57:22.071Z","queue":"cronjob:update_all_mirrors","args":[],"class":"UpdateAllMirrorsWorker","retry":false,"queue_namespace":"cronjob","jid":"06aeaa3b0aadacf9981f368e","created_at":"2018-04-03T22:57:21.930Z","enqueued_at":"2018-04-03T22:57:21.931Z","pid":10077,"message":"UpdateAllMirrorsWorker JID-06aeaa3b0aadacf9981f368e: done: 0.139 sec","job_status":"done","duration":0.139,"completed_at":"2018-04-03T22:57:22.071Z","db_duration":0.05,"db_duration_s":0.0005,"gitaly_duration":0,"gitaly_calls":0}
 ```
 
 For Omnibus GitLab installations, add the configuration option:

lib/gitlab/sidekiq_logging/structured_logger.rb

 # frozen_string_literal: true
 
+require 'active_record'
+require 'active_record/log_subscriber'
+
 module Gitlab
   module SidekiqLogging
     class StructuredLogger
@@ -10,6 +13,7 @@ module Gitlab
       def call(job, queue)
         started_time = get_time
         base_payload = parse_job(job)
+        ActiveRecord::LogSubscriber.reset_runtime
 
         Sidekiq.logger.info log_job_start(base_payload)
 
@@ -63,6 +67,9 @@ module Gitlab
 
         convert_to_iso8601(payload, DONE_TIMESTAMP_FIELDS)
 
+        payload['db_duration'] = ActiveRecord::LogSubscriber.runtime
+        payload['db_duration_s'] = payload['db_duration'] / 1000
+
         payload
       end
 

spec/lib/gitlab/sidekiq_logging/structured_logger_spec.rb

 # frozen_string_literal: true
 
-require 'fast_spec_helper'
+require 'spec_helper'
 
 describe Gitlab::SidekiqLogging::StructuredLogger do
   describe '#call' do
@@ -40,8 +40,10 @@ describe Gitlab::SidekiqLogging::StructuredLogger do
         'message' => 'TestWorker JID-da883554ee4fe414012f5f42: done: 0.0 sec',
         'job_status' => 'done',
         'duration' => 0.0,
-        "completed_at" => timestamp.iso8601(3),
-        "cpu_s" => 1.111112
+        'completed_at' => timestamp.iso8601(3),
+        'cpu_s' => 1.111112,
+        'db_duration' => 0,
+        'db_duration_s' => 0
       )
     end
     let(:exception_payload) do
@@ -183,6 +185,43 @@ describe Gitlab::SidekiqLogging::StructuredLogger do
         end
       end
     end
+
+    context 'when the job performs database queries' do
+      before do
+        allow(Time).to receive(:now).and_return(timestamp)
+        allow(Process).to receive(:clock_gettime).and_call_original
+      end
+
+      let(:expected_start_payload) { start_payload.except('args') }
+
+      let(:expected_end_payload) do
+        end_payload.except('args').merge('cpu_s' => a_value > 0)
+      end
+
+      let(:expected_end_payload_with_db) do
+        expected_end_payload.merge(
+          'db_duration' => a_value >= 100,
+          'db_duration_s' => a_value >= 0.1
+        )
+      end
+
+      it 'logs the database time' do
+        expect(logger).to receive(:info).with(expected_start_payload).ordered
+        expect(logger).to receive(:info).with(expected_end_payload_with_db).ordered
+
+        subject.call(job, 'test_queue') { ActiveRecord::Base.connection.execute('SELECT pg_sleep(0.1);') }
+      end
+
+      it 'prevents database time from leaking to the next job' do
+        expect(logger).to receive(:info).with(expected_start_payload).ordered
+        expect(logger).to receive(:info).with(expected_end_payload_with_db).ordered
+        expect(logger).to receive(:info).with(expected_start_payload).ordered
+        expect(logger).to receive(:info).with(expected_end_payload).ordered
+
+        subject.call(job, 'test_queue') { ActiveRecord::Base.connection.execute('SELECT pg_sleep(0.1);') }
+        subject.call(job, 'test_queue') { }
+      end
+    end
   end
 
   describe '#add_time_keys!' do