summaryrefslogtreecommitdiff
diff options
context:
space:
mode:
-rw-r--r--app/controllers/application_controller.rb2
-rw-r--r--changelogs/unreleased/sh-log-rails-queue-duration.yml5
-rw-r--r--config/initializers/lograge.rb3
-rw-r--r--doc/administration/logs.md7
-rw-r--r--lib/gitlab/middleware/rails_queue_duration.rb3
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)