From 74ff33a3fdb83cd03c41436b4ae10ca48075f0e9 Mon Sep 17 00:00:00 2001
From: Stan Hu <stanhu@gmail.com>
Date: Wed, 27 Mar 2019 05:56:36 -0500
Subject: [PATCH] Log Gitaly RPC duration to api_json.log and
production_json.log
This makes it easier to debug Gitaly performance issues in the field.
This commit also makes the tracking of query time thread-safe via
RequestStore.
---
.../unreleased/sh-add-gitaly-duration-logs.yml | 5 +++++
config/initializers/lograge.rb | 7 ++++++-
doc/administration/logs.md | 13 ++++++++-----
lib/gitlab/gitaly_client.rb | 18 ++++++++++++------
.../grape_logging/loggers/perf_logger.rb | 5 ++++-
5 files changed, 35 insertions(+), 13 deletions(-)
create mode 100644 changelogs/unreleased/sh-add-gitaly-duration-logs.yml
diff --git a/changelogs/unreleased/sh-add-gitaly-duration-logs.yml b/changelogs/unreleased/sh-add-gitaly-duration-logs.yml
new file mode 100644
index 0000000000000..eea5038427895
--- /dev/null
+++ b/changelogs/unreleased/sh-add-gitaly-duration-logs.yml
@@ -0,0 +1,5 @@
+---
+title: Log Gitaly RPC duration to api_json.log and production_json.log
+merge_request: 26652
+author:
+type: other
diff --git a/config/initializers/lograge.rb b/config/initializers/lograge.rb
index 164954d129326..5e790a9eccb26 100644
--- a/config/initializers/lograge.rb
+++ b/config/initializers/lograge.rb
@@ -28,7 +28,12 @@
}
gitaly_calls = Gitlab::GitalyClient.get_request_count
- payload[:gitaly_calls] = gitaly_calls if gitaly_calls > 0
+
+ if gitaly_calls > 0
+ payload[:gitaly_calls] = gitaly_calls
+ payload[:gitaly_duration] = Gitlab::GitalyClient.query_time_ms
+ end
+
payload[:response] = event.payload[:response] if event.payload[:response]
payload[Gitlab::CorrelationId::LOG_KEY] = Gitlab::CorrelationId.current_id
diff --git a/doc/administration/logs.md b/doc/administration/logs.md
index 36dee75bd44e2..3d40cda491a11 100644
--- a/doc/administration/logs.md
+++ b/doc/administration/logs.md
@@ -23,16 +23,19 @@ 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,"queue_duration": 112.47}
+{"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,"gitaly_duration":7.41,"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:
+In this example, you can see this was a GET request for a specific
+issue. Notice each line also contains performance data. All times are in
+milliseconds:
-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. `duration`: total time taken to retrieve the request
+1. `queue_duration`: total time 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
+1. `gitaly_duration`: total time taken by Gitaly calls
User clone/fetch activity using http transport appears in this log as `action: git_upload_pack`.
@@ -85,7 +88,7 @@ Introduced in GitLab 10.0, this file lives in
It helps you see requests made directly to the API. For example:
```json
-{"time":"2018-10-29T12:49:42.123Z","severity":"INFO","duration":709.08,"db":14.59,"view":694.49,"status":200,"method":"GET","path":"/api/v4/projects","params":[{"key":"action","value":"git-upload-pack"},{"key":"changes","value":"_any"},{"key":"key_id","value":"secret"},{"key":"secret_token","value":"[FILTERED]"}],"host":"localhost","ip":"::1","ua":"Ruby","route":"/api/:version/projects","user_id":1,"username":"root","queue_duration":100.31,"gitaly_calls":30}
+{"time":"2018-10-29T12:49:42.123Z","severity":"INFO","duration":709.08,"db":14.59,"view":694.49,"status":200,"method":"GET","path":"/api/v4/projects","params":[{"key":"action","value":"git-upload-pack"},{"key":"changes","value":"_any"},{"key":"key_id","value":"secret"},{"key":"secret_token","value":"[FILTERED]"}],"host":"localhost","ip":"::1","ua":"Ruby","route":"/api/:version/projects","user_id":1,"username":"root","queue_duration":100.31,"gitaly_calls":30,"gitaly_duration":5.36}
```
This entry above shows an access to an internal endpoint to check whether an
diff --git a/lib/gitlab/gitaly_client.rb b/lib/gitlab/gitaly_client.rb
index e3b9a7a1a89be..49cff7517e9b5 100644
--- a/lib/gitlab/gitaly_client.rb
+++ b/lib/gitlab/gitaly_client.rb
@@ -33,12 +33,6 @@ def initialize(call_site, invocation_count, max_call_stack, most_invoked_stack)
MUTEX = Mutex.new
- class << self
- attr_accessor :query_time
- end
-
- self.query_time = 0
-
define_histogram :gitaly_controller_action_duration_seconds do
docstring "Gitaly endpoint histogram by controller and action combination"
base_labels Gitlab::Metrics::Transaction::BASE_LABELS.merge(gitaly_service: nil, rpc: nil)
@@ -174,6 +168,18 @@ def self.call(storage, service, rpc, request, remote_storage: nil, timeout: nil)
add_call_details(feature: "#{service}##{rpc}", duration: duration, request: request_hash, rpc: rpc)
end
+ def self.query_time
+ SafeRequestStore[:gitaly_query_time] ||= 0
+ end
+
+ def self.query_time=(duration)
+ SafeRequestStore[:gitaly_query_time] = duration
+ end
+
+ def self.query_time_ms
+ (self.query_time * 1000).round(2)
+ end
+
def self.current_transaction_labels
Gitlab::Metrics::Transaction.current&.labels || {}
end
diff --git a/lib/gitlab/grape_logging/loggers/perf_logger.rb b/lib/gitlab/grape_logging/loggers/perf_logger.rb
index e3b9c59bd6eb0..18ea3a8d2f398 100644
--- a/lib/gitlab/grape_logging/loggers/perf_logger.rb
+++ b/lib/gitlab/grape_logging/loggers/perf_logger.rb
@@ -6,7 +6,10 @@ module GrapeLogging
module Loggers
class PerfLogger < ::GrapeLogging::Loggers::Base
def parameters(_, _)
- { gitaly_calls: Gitlab::GitalyClient.get_request_count }
+ {
+ gitaly_calls: Gitlab::GitalyClient.get_request_count,
+ gitaly_duration: Gitlab::GitalyClient.query_time_ms
+ }
end
end
end
--
GitLab