Log Redis call count and duration to log files

It has been difficult to see trends in the number of Redis calls without having the number and duration of the calls in structured logs. This commit adds redis_calls and redis_duration_ms fields to all relevant logs (e.g. api_json.log, production_json.log, Sidekiq, etc.):

Examples

Sidekiq

{
  "severity": "INFO",
  "time": "2020-03-21T07:48:10.129Z",
  "class": "ProjectImportScheduleWorker",
  "args": [
    "96"
  ],
  "retry": false,
  "queue": "project_import_schedule",
  "backtrace": true,
  "jid": "825d64af936070c8ecf39ed7",
  "created_at": "2020-03-21T07:48:04.935Z",
  "enqueued_at": "2020-03-21T07:48:04.984Z",
  "meta.project": "root/rouge-import",
  "meta.root_namespace": "root",
  "meta.subscription_plan": "default",
  "meta.caller_id": "UpdateAllMirrorsWorker",
  "correlation_id": "2f5e4686f1fa8ce3a5dec579798b6418",
  "uber-trace-id": "6e02f74e95574050:b8cd69f6bf3cb2c3:e7b726b296aeeaa3:1",
  "duplicate-of": "a4fe5deae353671bb1c80094",
  "pid": 26996,
  "message": "ProjectImportScheduleWorker JID-825d64af936070c8ecf39ed7: done: 5.137914 sec",
  "job_status": "done",
  "scheduling_latency_s": 1.030781,
  "gitaly_calls": 1,
  "gitaly_duration": 8.4,
  "redis_calls": 7,
  "redis_duration_ms": 10.27,
  "duration": 5.137914,
  "cpu_s": 0.419302,
  "completed_at": "2020-03-21T07:48:10.129Z",
  "db_duration": 81.2389999628067,
  "db_duration_s": 0.0812389999628067
}

Rails controller

{
  "method": "GET",
  "path": "/",
  "format": "html",
  "controller": "RootController",
  "action": "index",
  "status": 200,
  "duration": 14607.41,
  "view": 1856.74,
  "db": 59.85,
  "time": "2020-03-21T07:48:21.904Z",
  "params": [],
  "remote_ip": "127.0.0.1",
  "user_id": 1,
  "username": "root",
  "ua": "Mozilla/5.0 (Macintosh; Intel Mac OS X 10.15; rv:74.0) Gecko/20100101 Firefox/74.0",
  "queue_duration": 524.7,
  "gitaly_calls": 18,
  "gitaly_duration": 29.35,
  "rugged_calls": 3,
  "rugged_duration_ms": 4.42,
  "redis_calls": 147,
  "redis_duration_ms": 131.59,
  "correlation_id": "76e09ssD0p9",
  "cpu_s": 14.863416248
}

API

{
  "time": "2020-03-21T08:11:59.212Z",
  "severity": "INFO",
  "duration": 23.63,
  "db": 7.31,
  "view": 16.32,
  "status": 200,
  "method": "GET",
  "path": "/api/v4/projects/1",
  "params": [],
  "host": "localhost",
  "remote_ip": "127.0.0.1",
  "ua": "curl/7.64.1",
  "route": "/api/:version/projects/:id",
  "queue_duration": 180.06,
  "gitaly_calls": 1,
  "gitaly_duration": 2.64,
  "redis_calls": 7,
  "redis_duration_ms": 1.91,
  "correlation_id": "x3oo3n5LoM7"
}