diff options
| -rw-r--r-- | app/controllers/application_controller.rb | 2 | ||||
| -rw-r--r-- | changelogs/unreleased/sh-log-rails-queue-duration.yml | 5 | ||||
| -rw-r--r-- | config/initializers/lograge.rb | 3 | ||||
| -rw-r--r-- | doc/administration/logs.md | 7 | ||||
| -rw-r--r-- | lib/gitlab/middleware/rails_queue_duration.rb | 3 |
5 files changed, 17 insertions, 3 deletions
diff --git a/app/controllers/application_controller.rb b/app/controllers/application_controller.rb index 26cd5dc801f..af0b0c64814 100644 --- a/app/controllers/application_controller.rb +++ b/app/controllers/application_controller.rb @@ -137,6 +137,8 @@ class ApplicationController < ActionController::Base if response.status == 422 && response.body.present? && response.content_type == 'application/json'.freeze payload[:response] = response.body end + + payload[:queue_duration] = request.env[::Gitlab::Middleware::RailsQueueDuration::GITLAB_RAILS_QUEUE_DURATION_KEY] end ## diff --git a/changelogs/unreleased/sh-log-rails-queue-duration.yml b/changelogs/unreleased/sh-log-rails-queue-duration.yml new file mode 100644 index 00000000000..89390aef108 --- /dev/null +++ b/changelogs/unreleased/sh-log-rails-queue-duration.yml @@ -0,0 +1,5 @@ +--- +title: Log queue duration in production_json.log +merge_request: 25075 +author: +type: other diff --git a/config/initializers/lograge.rb b/config/initializers/lograge.rb index c897bc30e76..164954d1293 100644 --- a/config/initializers/lograge.rb +++ b/config/initializers/lograge.rb @@ -23,7 +23,8 @@ unless Sidekiq.server? remote_ip: event.payload[:remote_ip], user_id: event.payload[:user_id], username: event.payload[:username], - ua: event.payload[:ua] + ua: event.payload[:ua], + queue_duration: event.payload[:queue_duration] } gitaly_calls = Gitlab::GitalyClient.get_request_count diff --git a/doc/administration/logs.md b/doc/administration/logs.md index 698f4caab3a..36dee75bd44 100644 --- a/doc/administration/logs.md +++ b/doc/administration/logs.md @@ -23,12 +23,13 @@ requests from the API are logged to a separate file in `api_json.log`. Each line contains a JSON line that can be ingested by Elasticsearch, Splunk, etc. For example: ```json -{"method":"GET","path":"/gitlab/gitlab-ce/issues/1234","format":"html","controller":"Projects::IssuesController","action":"show","status":200,"duration":229.03,"view":174.07,"db":13.24,"time":"2017-08-08T20:15:54.821Z","params":[{"key":"param_key","value":"param_value"}],"remote_ip":"18.245.0.1","user_id":1,"username":"admin","gitaly_calls":76} +{"method":"GET","path":"/gitlab/gitlab-ce/issues/1234","format":"html","controller":"Projects::IssuesController","action":"show","status":200,"duration":229.03,"view":174.07,"db":13.24,"time":"2017-08-08T20:15:54.821Z","params":[{"key":"param_key","value":"param_value"}],"remote_ip":"18.245.0.1","user_id":1,"username":"admin","gitaly_calls":76,"queue_duration": 112.47} ``` In this example, you can see this was a GET request for a specific issue. Notice each line also contains performance data: -1. `duration`: the total time taken to retrieve the request +1. `duration`: total time in milliseconds taken to retrieve the request +1. `queue_duration`: total time in milliseconds that the request was queued inside GitLab Workhorse 1. `view`: total time taken inside the Rails views 1. `db`: total time to retrieve data from the database 1. `gitaly_calls`: total number of calls made to Gitaly @@ -91,6 +92,8 @@ This entry above shows an access to an internal endpoint to check whether an associated SSH key can download the project in question via a `git fetch` or `git clone`. In this example, we see: +1. `duration`: total time in milliseconds taken to retrieve the request +1. `queue_duration`: total time in milliseconds that the request was queued inside GitLab Workhorse 1. `method`: The HTTP method used to make the request 1. `path`: The relative path of the query 1. `params`: Key-value pairs passed in a query string or HTTP body. Sensitive parameters (e.g. passwords, tokens, etc.) are filtered out. diff --git a/lib/gitlab/middleware/rails_queue_duration.rb b/lib/gitlab/middleware/rails_queue_duration.rb index 96c6a0a7d28..a147e165262 100644 --- a/lib/gitlab/middleware/rails_queue_duration.rb +++ b/lib/gitlab/middleware/rails_queue_duration.rb @@ -7,6 +7,8 @@ module Gitlab module Middleware class RailsQueueDuration + GITLAB_RAILS_QUEUE_DURATION_KEY = 'GITLAB_RAILS_QUEUE_DURATION' + def initialize(app) @app = app end @@ -19,6 +21,7 @@ module Gitlab duration = Time.now.to_f * 1_000 - proxy_start.to_f / 1_000_000 trans.set(:rails_queue_duration, duration) metric_rails_queue_duration_seconds.observe(trans.labels, duration / 1_000) + env[GITLAB_RAILS_QUEUE_DURATION_KEY] = duration.round(2) end @app.call(env) |