Add database timings to Sidekiq JSON logs

Sidekiq JSON logs have total duration, queuing time, Gitaly time, and
CPU time. They don't (before this change) have database time.

We provide two fields: db_duration and db_duration_s. That's because the
units between the different duration fields are currently confusing, so
providing an explicit unit moves us closer to that goal, while keeping
the raw figure in the un-suffixed fields.

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