diff options
| -rw-r--r-- | lib/gitlab/graphql/query_analyzers/logger_analyzer.rb | 40 | ||||
| -rw-r--r-- | spec/lib/gitlab/graphql/query_analyzers/logger_analyzer_spec.rb | 40 | ||||
| -rw-r--r-- | spec/requests/api/graphql/gitlab_schema_spec.rb | 2 | ||||
| -rw-r--r-- | spec/requests/api/graphql_spec.rb | 26 |
4 files changed, 78 insertions, 30 deletions
diff --git a/lib/gitlab/graphql/query_analyzers/logger_analyzer.rb b/lib/gitlab/graphql/query_analyzers/logger_analyzer.rb index 3796eefd608..2cebd739a4e 100644 --- a/lib/gitlab/graphql/query_analyzers/logger_analyzer.rb +++ b/lib/gitlab/graphql/query_analyzers/logger_analyzer.rb @@ -4,10 +4,6 @@ module Gitlab module Graphql module QueryAnalyzers class LoggerAnalyzer - def initialize - @info_hash = {} - end - # Called before initializing the analyzer. # Returns true to run this analyzer, or false to skip it. def analyze?(query) @@ -18,16 +14,20 @@ module Gitlab # Returns the initial value for `memo` def initial_value(query) { - time_started: Time.zone.now, + time_started: Gitlab::Metrics::System.monotonic_time, query_string: query.query_string, - variables: query.provided_variables + variables: process_variables(query.provided_variables), + complexity: nil, + depth: nil, + duration: nil } end # This is like the `reduce` callback. # The return value is passed to the next call as `memo` def call(memo, visit_type, irep_node) - memo + memo = set_complexity(memo) + set_depth(memo) end # Called when we're done the whole visit. @@ -35,29 +35,37 @@ module Gitlab # Or, you can use this hook to write to a log, etc def final_value(memo) memo[:duration] = "#{duration(memo[:time_started]).round(1)}ms" - set_complexity - set_depth - GraphqlLogger.info(memo.except!(:time_started).merge(@info_hash)) + GraphqlLogger.info(memo.except!(:time_started)) memo end private - def set_complexity + def process_variables(variables) + if variables.respond_to?(:to_unsafe_h) + variables.to_unsafe_h + else + variables + end + end + + def set_complexity(memo) GraphQL::Analysis::QueryComplexity.new do |query, complexity_value| - @info_hash[:complexity] = complexity_value + memo[:complexity] = complexity_value end + memo end - def set_depth + def set_depth(memo) GraphQL::Analysis::QueryDepth.new do |query, depth_value| - @info_hash[:depth] = depth_value + memo[:depth] = depth_value end + memo end def duration(time_started) - nanoseconds = Time.zone.now - time_started - nanoseconds / 1000000 + nanoseconds = Gitlab::Metrics::System.monotonic_time - time_started + nanoseconds * 1000000 end end end diff --git a/spec/lib/gitlab/graphql/query_analyzers/logger_analyzer_spec.rb b/spec/lib/gitlab/graphql/query_analyzers/logger_analyzer_spec.rb index 53a1d7f8e42..f85a3a206b1 100644 --- a/spec/lib/gitlab/graphql/query_analyzers/logger_analyzer_spec.rb +++ b/spec/lib/gitlab/graphql/query_analyzers/logger_analyzer_spec.rb @@ -7,21 +7,43 @@ describe Gitlab::Graphql::QueryAnalyzers::LoggerAnalyzer do subject { described_class.new } let(:query_string) { "abc" } let(:provided_variables) { { a: 1, b: 2, c: 3 } } + let!(:now) { Gitlab::Metrics::System.monotonic_time } let(:complexity) { 4 } let(:depth) { 2 } - let(:expected_hash) do - { query_string: query_string, + let(:initial_values) do + { time_started: now, + query_string: query_string, variables: provided_variables, - complexity: complexity, - depth: depth } + complexity: nil, + depth: nil, + duration: nil } + end + before do + allow(Gitlab::Metrics::System).to receive(:monotonic_time).and_return(now) end - it 'assembles a hash' do - query = OpenStruct.new(query_string: query_string, provided_variables: provided_variables) - - subject.initial_value(query) + describe '#initial_value' do + it 'assembles a hash with initial values' do + query = OpenStruct.new(query_string: query_string, provided_variables: provided_variables) - expect(subject.instance_variable_get("@info_hash")).to eq expected_hash + expect(subject.initial_value(query)).to eq initial_values + end end + describe '#call' do + before do + # some statements to fudge the complexity and depth + end + + it 'sets the complexity and depth' do + expected_hash = { time_started: now, + query_string: query_string, + variables: provided_variables, + complexity: nil, + depth: depth, + duration: complexity } + + expect(subject.call(initial_values, nil, nil)).to eq expected_hash + end + end end diff --git a/spec/requests/api/graphql/gitlab_schema_spec.rb b/spec/requests/api/graphql/gitlab_schema_spec.rb index 0eb026f1ed9..dcce8c1dbad 100644 --- a/spec/requests/api/graphql/gitlab_schema_spec.rb +++ b/spec/requests/api/graphql/gitlab_schema_spec.rb @@ -85,7 +85,7 @@ describe 'GitlabSchema configurations' do context 'logging' do it 'writes to the GraphQL log' do - expect(Gitlab::GraphqlLogger).to receive(:info).with(/Query Complexity/) + expect(Gitlab::GraphqlLogger).to receive(:info) query = File.read(Rails.root.join('spec/fixtures/api/graphql/introspection.graphql')) diff --git a/spec/requests/api/graphql_spec.rb b/spec/requests/api/graphql_spec.rb index 103b02ba7a7..036dfa41952 100644 --- a/spec/requests/api/graphql_spec.rb +++ b/spec/requests/api/graphql_spec.rb @@ -17,14 +17,32 @@ describe 'GraphQL' do end context 'logging' do - it 'logs the query' do - expected = { query_string: query, variables: {}, duration: anything } - + before do expect(Gitlab::GraphqlLogger).to receive(:info).with(expected) + end - post_graphql(query) + context 'with no variables' do + let(:expected) do + { query_string: query, variables: {}, duration: anything, depth: 0, complexity: 0 } + end + + it 'logs the query' do + post_graphql(query) + end end + context 'with variables' do + let!(:variables) do + { foo: "bar" } + end + let(:expected) do + { query_string: query, variables: variables, duration: anything, depth: 0, complexity: 0 } + end + + it 'logs the query' do + post_graphql(query, variables: variables) + end + end end context 'invalid variables' do |