From 51ca79228bc2d22b12d47ba177610d228793dc94 Mon Sep 17 00:00:00 2001 From: Stan Hu Date: Sun, 10 Feb 2019 16:43:44 -0800 Subject: [PATCH] Log queue duration in production_json.log `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. --- app/controllers/application_controller.rb | 2 ++ changelogs/unreleased/sh-log-rails-queue-duration.yml | 5 +++++ config/initializers/lograge.rb | 3 ++- doc/administration/logs.md | 7 +++++-- lib/gitlab/middleware/rails_queue_duration.rb | 3 +++ 5 files changed, 17 insertions(+), 3 deletions(-) create mode 100644 changelogs/unreleased/sh-log-rails-queue-duration.yml 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)