Merge branch 'jp-pbar-stats' into 'master'

Log also gitaly and redis stats

See merge request gitlab-org/gitlab!71570

doc/administration/logs.md

@@ -1090,7 +1090,7 @@ Performance bar statistics (currently only duration of SQL queries) are recorded
 in that file. For example:
 
 ```json
-{"severity":"INFO","time":"2020-12-04T09:29:44.592Z","correlation_id":"33680b1490ccd35981b03639c406a697","filename":"app/models/ci/pipeline.rb","method_path":"app/models/ci/pipeline.rb:each_with_object","request_id":"rYHomD0VJS4","duration_ms":26.889,"count":2,"type": "sql"}
+{"severity":"INFO","time":"2020-12-04T09:29:44.592Z","correlation_id":"33680b1490ccd35981b03639c406a697","filename":"app/models/ci/pipeline.rb","method_path":"app/models/ci/pipeline.rb:each_with_object","request_id":"rYHomD0VJS4","duration_ms":26.889,"count":2,"query_type": "active-record"}
 ```
 
 These statistics are logged on .com only, disabled on self-deployments.

lib/gitlab/performance_bar/stats.rb

@@ -9,6 +9,8 @@ module Gitlab
         ee/lib/ee/peek
         lib/peek
         lib/gitlab/database
+        lib/gitlab/gitaly_client/call.rb
+        lib/gitlab/instrumentation/redis_interceptor.rb
       ].freeze
 
       def initialize(redis)
@@ -19,7 +21,9 @@ module Gitlab
         data = request(id)
         return unless data
 
-        log_sql_queries(id, data)
+        log_queries(id, data, 'active-record')
+        log_queries(id, data, 'gitaly')
+        log_queries(id, data, 'redis')
       rescue StandardError => err
         logger.error(message: "failed to process request id #{id}: #{err.message}")
       end
@@ -32,15 +36,17 @@ module Gitlab
         Gitlab::Json.parse(json_data)
       end
 
-      def log_sql_queries(id, data)
-        queries_by_location(data).each do |location, queries|
+      def log_queries(id, data, type)
+        json_path = ['data', type, 'details']
+
+        queries_by_location(data, json_path).each do |location, queries|
           next unless location
 
           duration = queries.sum { |query| query['duration'].to_f }
           log_info = {
             method_path: "#{location[:filename]}:#{location[:method]}",
             filename: location[:filename],
-            type: :sql,
+            query_type: type,
             request_id: id,
             count: queries.count,
             duration_ms: duration
@@ -50,8 +56,8 @@ module Gitlab
         end
       end
 
-      def queries_by_location(data)
-        return [] unless queries = data.dig('data', 'active-record', 'details')
+      def queries_by_location(data, path)
+        return [] unless queries = data.dig(*path)
 
         queries.group_by do |query|
           parse_backtrace(query['backtrace'])

spec/fixtures/lib/gitlab/performance_bar/peek_data.json

@@ -64,9 +64,54 @@
       "warnings": []
     },
     "gitaly": {
-      "duration": "0ms",
-      "calls": 0,
-      "details": [],
+      "duration": "30ms",
+      "calls": 2,
+      "details": [
+        {
+          "start": 6301.575665897,
+          "feature": "commit_service#get_tree_entries",
+          "duration": 23.709,
+          "request": "{:repository=>\n  {:storage_name=>\"nfs-file-cny01\",\n   :relative_path=>\n    \"@hashed/a6/80/a68072e80f075e89bc74a300101a9e71e8363bdb542182580162553462480a52.git\",\n   :git_object_directory=>\"\",\n   :git_alternate_object_directories=>[],\n   :gl_repository=>\"project-278964\",\n   :gl_project_path=>\"gitlab-org/gitlab\"},\n :revision=>\"master\",\n :path=>\".\",\n :sort=>:TREES_FIRST,\n :pagination_params=>{:page_token=>\"\", :limit=>100}}\n",
+          "rpc": "get_tree_entries",
+          "backtrace": [
+            "lib/gitlab/gitaly_client/call.rb:48:in `block in instrument_stream'",
+            "lib/gitlab/gitaly_client/commit_service.rb:128:in `each'",
+            "lib/gitlab/gitaly_client/commit_service.rb:128:in `each'",
+            "lib/gitlab/gitaly_client/commit_service.rb:128:in `flat_map'",
+            "lib/gitlab/gitaly_client/commit_service.rb:128:in `tree_entries'",
+            "lib/gitlab/git/tree.rb:26:in `block in tree_entries'",
+            "lib/gitlab/git/wraps_gitaly_errors.rb:7:in `wrapped_gitaly_errors'",
+            "lib/gitlab/git/tree.rb:25:in `tree_entries'",
+            "lib/gitlab/git/rugged_impl/tree.rb:29:in `tree_entries'",
+            "lib/gitlab/git/tree.rb:21:in `where'",
+            "app/models/tree.rb:17:in `initialize'",
+            "app/models/repository.rb:681:in `new'",
+            "app/models/repository.rb:681:in `tree'",
+            "app/graphql/resolvers/paginated_tree_resolver.rb:35:in `resolve'",
+            "lib/gitlab/graphql/present/field_extension.rb:18:in `resolve'",
+            "lib/gitlab/graphql/extensions/externally_paginated_array_extension.rb:7:in `resolve'",
+            "lib/gitlab/graphql/generic_tracing.rb:40:in `with_labkit_tracing'",
+            "lib/gitlab/graphql/generic_tracing.rb:30:in `platform_trace'",
+            "lib/gitlab/graphql/generic_tracing.rb:40:in `with_labkit_tracing'",
+            "lib/gitlab/graphql/generic_tracing.rb:30:in `platform_trace'",
+            "lib/gitlab/graphql/generic_tracing.rb:40:in `with_labkit_tracing'",
+            "lib/gitlab/graphql/generic_tracing.rb:30:in `platform_trace'",
+            "app/graphql/gitlab_schema.rb:40:in `multiplex'",
+            "app/controllers/graphql_controller.rb:110:in `execute_multiplex'",
+            "app/controllers/graphql_controller.rb:41:in `execute'",
+            "ee/lib/gitlab/ip_address_state.rb:10:in `with'",
+            "ee/app/controllers/ee/application_controller.rb:44:in `set_current_ip_address'",
+            "app/controllers/application_controller.rb:497:in `set_current_admin'",
+            "lib/gitlab/session.rb:11:in `with_session'",
+            "app/controllers/application_controller.rb:488:in `set_session_storage'",
+            "app/controllers/application_controller.rb:482:in `set_locale'",
+            "app/controllers/application_controller.rb:476:in `set_current_context'",
+            "ee/lib/omni_auth/strategies/group_saml.rb:41:in `other_phase'",
+            "lib/gitlab/jira/middleware.rb:19:in `call'"
+          ],
+          "warnings": []
+        }
+      ],
       "warnings": []
     },
     "redis": {

spec/lib/gitlab/performance_bar/stats_spec.rb

@@ -23,11 +23,19 @@ RSpec.describe Gitlab::PerformanceBar::Stats do
         expect(logger).to receive(:info)
           .with({ duration_ms: 1.096, filename: 'lib/gitlab/pagination/offset_pagination.rb',
                   method_path: 'lib/gitlab/pagination/offset_pagination.rb:add_pagination_headers',
-                  count: 1, request_id: 'foo', type: :sql })
+                  count: 1, request_id: 'foo', query_type: 'active-record' })
         expect(logger).to receive(:info)
           .with({ duration_ms: 1.634, filename: 'lib/api/helpers.rb',
                   method_path: 'lib/api/helpers.rb:find_project',
-                  count: 2, request_id: 'foo', type: :sql })
+                  count: 2, request_id: 'foo', query_type: 'active-record' })
+        expect(logger).to receive(:info)
+          .with({ duration_ms: 23.709, filename: 'lib/gitlab/gitaly_client/commit_service.rb',
+                  method_path: 'lib/gitlab/gitaly_client/commit_service.rb:each',
+                  count: 1, request_id: 'foo', query_type: 'gitaly' })
+        expect(logger).to receive(:info)
+          .with({ duration_ms: 0.155, filename: 'lib/feature.rb',
+                  method_path: 'lib/feature.rb:enabled?',
+                  count: 1, request_id: 'foo', query_type: 'redis' })
 
         subject
       end