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 0000000000000000000000000000000000000000..eea5038427895ffa1bcb122fbae4f52c4fe66375 --- /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 164954d129326e331924624caaaba30d6078a37e..5e790a9eccb266d9d970c03e42c92ceabe573446 100644 --- a/config/initializers/lograge.rb +++ b/config/initializers/lograge.rb @@ -28,7 +28,12 @@ unless Sidekiq.server? } 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 36dee75bd44e258c5679961180a65fec30b0d208..3d40cda491a1128f374b83e9dc5fede005ca1648 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 e3b9a7a1a89bea16e6b91c5ec20d8c9874c2849e..49cff7517e9b5edc77f63a19981acaebe6b2f703 100644 --- a/lib/gitlab/gitaly_client.rb +++ b/lib/gitlab/gitaly_client.rb @@ -33,12 +33,6 @@ module Gitlab 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 @@ module Gitlab 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 e3b9c59bd6eb00b1dde3587776ca5717d18f8fc0..18ea3a8d2f398853bf4f59bf2d3375da21380847 100644 --- a/lib/gitlab/grape_logging/loggers/perf_logger.rb +++ b/lib/gitlab/grape_logging/loggers/perf_logger.rb @@ -6,7 +6,10 @@ module Gitlab 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