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"
}
Edited by Stan Hu