This will help identify Sidekiq jobs that invoke excessive number of
filesystem access.
The timing data is stored in `RequestStore`, but this is only active
within the middleware and is not directly accessible to the Sidekiq
logger. However, it is possible for the middleware to modify the job
hash to pass this data along to the logger.
This adds `rugged_duration_ms` and `rugged_calls` fields to
`api_json.log` and `production_json.log`. This will make it easier to
identify performance issues caused by excessive I/O.
Closes https://gitlab.com/gitlab-org/gitlab-ce/issues/64676
This change is a fairly straightforward refactor to extract the tracing
and correlation-id code from the gitlab rails codebase into the new
LabKit-Ruby project.
The corresponding import into LabKit-Ruby was in
https://gitlab.com/gitlab-org/labkit-ruby/merge_requests/1
The code itself remains very similar for now.
Extracting it allows us to reuse it in other projects, such as
Gitaly-Ruby. This will give us the advantages of correlation-ids and
distributed tracing in that project too.
`queue_duration` is a useful metric that is currently in api_json.log
but not in production_json.log. We should add it because it tells us how
long the request sat in Workhorse before Unicorn processed it. Having
this field enables the support team to better troubleshoot when delays
began to happen.
The Correlation ID is taken or generated from received X-Request-ID.
Then it is being passed to all executed services (sidekiq workers
or gitaly calls).
The Correlation ID is logged in all structured logs as `correlation_id`.
We have a number of import errors occurring with 422 errors, and
it's hard to determine why they are happening. This change will
surface the errors in the log lines.
Relates to #47365
This introduces JSON logging for Rails views saved to a file called
`development_json.log`, `production_json.log`, etc.
For example, instead of this unparsable log:
```
Started GET "/" for 127.0.0.1 at 2012-03-10 14:28:14 +0100
Processing by HomeController#index as HTML
Rendered text template within layouts/application (0.0ms)
Rendered layouts/_assets.html.erb (2.0ms)
Rendered layouts/_top.html.erb (2.6ms)
Rendered layouts/_about.html.erb (0.3ms)
Rendered layouts/_google_analytics.html.erb (0.4ms)
Completed 200 OK in 79ms (Views: 78.8ms | ActiveRecord: 0.0ms)
```
We get a single line with this:
```
{"method":"GET","path":"/,"format":"html","controller":"HomeController","action":"index","status":200,"duration":79,"view":78.8,"db":0.0,"location":"http://localhost/","time":"2017-07-18 09:35:17 -0700"}
```
Part of #20060
GitLab Bot
Stan Hu
Heinrich Lee Yu
Andrew Newdigate
Kamil Trzciński