1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
166
167
168
169
170
171
172
173
174
175
176
177
178
179
180
181
182
183
184
185
186
187
188
189
190
191
192
193
194
195
196
197
198
199
200
201
202
203
204
205
206
207
208
209
210
211
212
213
214
215
216
217
218
219
220
221
222
223
224
225
226
227
228
229
230
231
232
233
234
235
236
237
238
239
240
241
242
243
244
245
246
247
248
249
250
251
252
253
254
255
256
257
258
259
260
261
262
263
264
265
266
267
268
269
270
271
272
273
274
275
276
277
278
279
280
281
282
283
284
285
286
287
288
289
290
291
292
293
294
|
# frozen_string_literal: true
require 'spec_helper'
require 'rspec-parameterized'
require 'support/helpers/rails_helpers'
RSpec.describe Gitlab::InstrumentationHelper, :clean_gitlab_redis_repository_cache, :clean_gitlab_redis_cache,
:use_null_store_as_repository_cache, feature_category: :scalability do
using RSpec::Parameterized::TableSyntax
describe '.add_instrumentation_data', :request_store do
let(:payload) { {} }
subject { described_class.add_instrumentation_data(payload) }
before do
described_class.init_instrumentation_data
end
it 'includes DB counts' do
subject
expect(payload).to include(db_count: 0, db_cached_count: 0, db_write_count: 0)
end
context 'when Gitaly calls are made' do
it 'adds Gitaly and Redis data' do
project = create(:project)
RequestStore.clear!
project.repository.exists?
subject
expect(payload[:gitaly_calls]).to eq(1)
expect(payload[:gitaly_duration_s]).to be >= 0
expect(payload[:redis_calls]).to eq(nil)
expect(payload[:redis_duration_ms]).to be_nil
end
end
context 'when Redis calls are made' do
it 'adds Redis data and omits Gitaly data' do
stub_rails_env('staging') # to avoid raising CrossSlotError
Gitlab::Redis::Sessions.with { |redis| redis.mset('test-cache', 123, 'test-cache2', 123) }
Gitlab::Instrumentation::RedisClusterValidator.allow_cross_slot_commands do
Gitlab::Redis::Sessions.with { |redis| redis.mget('cache-test', 'cache-test-2') }
end
Gitlab::Redis::Queues.with { |redis| redis.set('test-queues', 321) }
subject
# Aggregated payload
expect(payload[:redis_calls]).to eq(3)
expect(payload[:redis_cross_slot_calls]).to eq(1)
expect(payload[:redis_allowed_cross_slot_calls]).to eq(1)
expect(payload[:redis_duration_s]).to be >= 0
expect(payload[:redis_read_bytes]).to be >= 0
expect(payload[:redis_write_bytes]).to be >= 0
# Queue payload
expect(payload[:redis_queues_calls]).to eq(1)
expect(payload[:redis_queues_duration_s]).to be >= 0
expect(payload[:redis_queues_read_bytes]).to be >= 0
expect(payload[:redis_queues_write_bytes]).to be >= 0
# Sessions payload
expect(payload[:redis_sessions_calls]).to eq(2)
expect(payload[:redis_sessions_cross_slot_calls]).to eq(1)
expect(payload[:redis_sessions_allowed_cross_slot_calls]).to eq(1)
expect(payload[:redis_sessions_duration_s]).to be >= 0
expect(payload[:redis_sessions_read_bytes]).to be >= 0
expect(payload[:redis_sessions_write_bytes]).to be >= 0
# Gitaly
expect(payload[:gitaly_calls]).to be_nil
expect(payload[:gitaly_duration]).to be_nil
end
end
context 'when LDAP requests are made' do
let(:provider) { 'ldapmain' }
let(:adapter) { Gitlab::Auth::Ldap::Adapter.new(provider) }
let(:conn) { instance_double(Net::LDAP::Connection, search: search) }
let(:search) { double(:search, result_code: 200) } # rubocop: disable RSpec/VerifiedDoubles
it 'adds LDAP data' do
allow_next_instance_of(Net::LDAP) do |net_ldap|
allow(net_ldap).to receive(:use_connection).and_yield(conn)
end
adapter.users('uid', 'foo')
subject
# Query count should be 2, as it will call `open` then `search`
expect(payload[:net_ldap_count]).to eq(2)
expect(payload[:net_ldap_duration_s]).to be >= 0
end
end
context 'when the request matched a Rack::Attack safelist' do
it 'logs the safelist name' do
Gitlab::Instrumentation::Throttle.safelist = 'foobar'
subject
expect(payload[:throttle_safelist]).to eq('foobar')
end
end
context 'rate-limiting gates' do
context 'when the request did not pass through any rate-limiting gates' do
it 'logs an empty array of gates' do
subject
expect(payload[:rate_limiting_gates]).to eq([])
end
end
context 'when the request passed through rate-limiting gates' do
it 'logs an array of gates used' do
Gitlab::Instrumentation::RateLimitingGates.track(:foo)
Gitlab::Instrumentation::RateLimitingGates.track(:bar)
subject
expect(payload[:rate_limiting_gates]).to contain_exactly(:foo, :bar)
end
end
end
it 'logs cpu_s duration' do
subject
expect(payload).to include(:cpu_s)
end
it 'logs the process ID' do
subject
expect(payload).to include(:pid)
end
it 'logs the worker ID' do
expect(Prometheus::PidProvider).to receive(:worker_id).and_return('puma_1')
subject
expect(payload).to include(worker_id: 'puma_1')
end
context 'when logging memory allocations' do
include MemoryInstrumentationHelper
before do
verify_memory_instrumentation_available!
end
it 'logs memory usage metrics' do
subject
expect(payload).to include(
:mem_objects,
:mem_bytes,
:mem_mallocs
)
end
end
it 'includes DB counts' do
subject
expect(payload).to include(db_replica_count: 0,
db_replica_cached_count: 0,
db_primary_count: 0,
db_primary_cached_count: 0,
db_primary_wal_count: 0,
db_replica_wal_count: 0,
db_primary_wal_cached_count: 0,
db_replica_wal_cached_count: 0)
end
context 'when replica caught up search was made' do
before do
Gitlab::SafeRequestStore[:caught_up_replica_pick_ok] = 2
Gitlab::SafeRequestStore[:caught_up_replica_pick_fail] = 1
end
it 'includes related metrics' do
subject
expect(payload).to include(caught_up_replica_pick_ok: 2)
expect(payload).to include(caught_up_replica_pick_fail: 1)
end
end
context 'when only a single counter was updated' do
before do
Gitlab::SafeRequestStore[:caught_up_replica_pick_ok] = 1
Gitlab::SafeRequestStore[:caught_up_replica_pick_fail] = nil
end
it 'includes only that counter into logging' do
subject
expect(payload).to include(caught_up_replica_pick_ok: 1)
expect(payload).not_to include(:caught_up_replica_pick_fail)
end
end
context 'when there is an uploaded file' do
it 'adds upload data' do
uploaded_file = UploadedFile.from_params({
'name' => 'dir/foo.txt',
'sha256' => 'sha256',
'remote_url' => 'http://localhost/file',
'remote_id' => '1234567890',
'etag' => 'etag1234567890',
'upload_duration' => '5.05',
'size' => '123456'
}, nil)
subject
expect(payload[:uploaded_file_upload_duration_s]).to eq(uploaded_file.upload_duration)
expect(payload[:uploaded_file_size_bytes]).to eq(uploaded_file.size)
end
end
context 'when an api call to the search api is made' do
before do
Gitlab::Instrumentation::GlobalSearchApi.set_information(
type: 'basic',
level: 'global',
scope: 'issues',
search_duration_s: 0.1
)
end
it 'adds search data' do
subject
expect(payload).to include({
'meta.search.type' => 'basic',
'meta.search.level' => 'global',
'meta.search.scope' => 'issues',
global_search_duration_s: 0.1
})
end
end
end
describe 'duration calculations' do
where(:end_time, :start_time, :time_now, :expected_duration) do
"2019-06-01T00:00:00.000+0000" | nil | "2019-06-01T02:00:00.000+0000" | 2.hours.to_f
"2019-06-01T02:00:00.000+0000" | nil | "2019-06-01T02:00:00.001+0000" | 0.001
"2019-06-01T02:00:00.000+0000" | "2019-05-01T02:00:00.000+0000" | "2019-06-01T02:00:01.000+0000" | 1
nil | "2019-06-01T02:00:00.000+0000" | "2019-06-01T02:00:00.001+0000" | 0.001
nil | nil | "2019-06-01T02:00:00.001+0000" | nil
"2019-06-01T02:00:00.000+0200" | nil | "2019-06-01T02:00:00.000-0200" | 4.hours.to_f
1571825569.998168 | nil | "2019-10-23T12:13:16.000+0200" | 26.001832
1571825569 | nil | "2019-10-23T12:13:16.000+0200" | 27
"invalid_date" | nil | "2019-10-23T12:13:16.000+0200" | nil
"" | nil | "2019-10-23T12:13:16.000+0200" | nil
0 | nil | "2019-10-23T12:13:16.000+0200" | nil
-1 | nil | "2019-10-23T12:13:16.000+0200" | nil
"2019-06-01T02:00:00.000+0000" | nil | "2019-06-01T00:00:00.000+0000" | 0
Time.at(1571999233).utc | nil | "2019-10-25T12:29:16.000+0200" | 123
end
describe '.queue_duration_for_job' do
with_them do
let(:job) { { 'enqueued_at' => end_time, 'created_at' => start_time } }
it "returns the correct duration" do
travel_to(Time.iso8601(time_now)) do
expect(described_class.queue_duration_for_job(job)).to eq(expected_duration)
end
end
end
end
describe '.enqueue_latency_for_scheduled_job' do
with_them do
let(:job) { { 'enqueued_at' => end_time, 'scheduled_at' => start_time } }
it "returns the correct duration" do
travel_to(Time.iso8601(time_now)) do
expect(described_class.enqueue_latency_for_scheduled_job(job)).to eq(expected_duration)
end
end
end
end
end
end
|