Skip to content

Commit 310ea4a

Browse files
jim80netjim80net
authored
Merge pull request #3 from scribd/jimp/issue/2
Tune `SLOWLOG get` length
2 parents c19ff45 + 9302b3e commit 310ea4a

File tree

3 files changed

+145
-47
lines changed

3 files changed

+145
-47
lines changed

‎lambda_function.rb

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -8,7 +8,7 @@
88
require_relative 'lib/slowlog_check'
99

1010
LOGGER = Logger.new($stdout)
11-
LOGGER.level = Logger::DEBUG
11+
LOGGER.level = Logger::INFO
1212
LOGGER.freeze
1313

1414
def event_time

‎lib/slowlog_check.rb

Lines changed: 11 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -3,6 +3,7 @@
33

44
class SlowlogCheck
55
::LOGGER ||= ::Logger.new($stdout)
6+
MAXLENGTH = 1048576 #255 levels of recursion for #
67

78
def initialize(params = {})
89
@ddog = params.fetch(:ddog)
@@ -114,8 +115,16 @@ def add_metric_to_bucket(prior, new)
114115
}
115116
end
116117

117-
def redis_slowlog
118-
@redis.slowlog('get')
118+
def did_i_get_it_all?(slowlog)
119+
slowlog[-1][0] == 0
120+
end
121+
122+
def redis_slowlog(length=128)
123+
resp = @redis.slowlog('get', length)
124+
125+
return resp if length > MAXLENGTH
126+
return resp if did_i_get_it_all?(resp)
127+
return redis_slowlog(length * 2)
119128
end
120129

121130
def slowlogs_by_flush_interval

‎spec/slowlog_check_spec.rb

Lines changed: 133 additions & 44 deletions
Original file line numberDiff line numberDiff line change
@@ -17,36 +17,31 @@
1717
let(:frozen_time) { Time.utc(2020,4,20,4,20,45) }
1818
let(:ddog_time) { Time.utc(2020,4,20,4,16).to_i * 1000.0 }
1919

20+
def redis_slowlog(index, time, microseconds)
21+
[
22+
index,
23+
time.to_i,
24+
microseconds,
25+
[
26+
"eval",
27+
"",
28+
"0"
29+
],
30+
"192.0.2.40:55700",
31+
""
32+
]
33+
end
34+
2035
before(:example) do
2136
##
2237
# redis mock
2338
allow(redis).to receive(:connection) { {host: 'master.replicationgroup.abcde.use2.cache.amazonaws.com' } }
24-
allow(redis).to receive(:slowlog).with('get') {
39+
allow(redis).to receive(:slowlog).with('get', 128) {
2540
[
26-
[
27-
1,
28-
Time.utc(2020,04,20,04,19,45).to_i,
29-
100000,
30-
[
31-
"eval",
32-
"",
33-
"0"
34-
],
35-
"192.0.2.40:55700",
36-
""
37-
],
38-
[
39-
0,
40-
Time.utc(2020,04,20,04,19,15).to_i,
41-
200000,
42-
[
43-
"eval",
44-
"",
45-
"0"
46-
],
47-
"192.0.2.40:55700",
48-
""
49-
]
41+
redis_slowlog( 3, Time.utc(2020,04,20,04,19,45), 400000 ),
42+
redis_slowlog( 2, Time.utc(2020,04,20,04,19,15), 100000 ),
43+
redis_slowlog( 1, Time.utc(2020,04,20,04,18,45), 100000 ),
44+
redis_slowlog( 0, Time.utc(2020,04,20,04,18,15), 200000 ),
5045
]
5146
}
5247

@@ -96,6 +91,76 @@
9691
allow_any_instance_of(Logger).to receive(:info) {}
9792
end
9893

94+
describe '#redis_slowlog.length' do
95+
context 'redis has 4 entries' do
96+
before(:each) do
97+
allow(redis).to receive(:slowlog).with('get', 128) {
98+
[
99+
redis_slowlog( 3, Time.utc(2020,04,20,04,19,45), 400000 ),
100+
redis_slowlog( 2, Time.utc(2020,04,20,04,19,15), 100000 ),
101+
redis_slowlog( 1, Time.utc(2020,04,20,04,18,45), 100000 ),
102+
redis_slowlog( 0, Time.utc(2020,04,20,04,18,15), 200000 ),
103+
]
104+
}
105+
end
106+
107+
subject { slowlog_check.redis_slowlog.length }
108+
it { is_expected.to eq(4) }
109+
end
110+
111+
context 'redis has 129 entries and a zeroeth entry' do
112+
before(:each) do
113+
allow(redis).to receive(:slowlog).with('get', 128) {
114+
Array.new(129) { |x|
115+
redis_slowlog(x, Time.utc(2020,04,20,04,00,00) + x, x * 1000)
116+
}.reverse[0..127]
117+
}
118+
119+
allow(redis).to receive(:slowlog).with('get', 256) {
120+
Array.new(129) { |x|
121+
redis_slowlog(x, Time.utc(2020,04,20,04,00,00) + x, x * 1000)
122+
}.reverse
123+
}
124+
125+
end
126+
127+
subject { slowlog_check.redis_slowlog.length }
128+
it { is_expected.to eq(129) }
129+
end
130+
131+
context 'redis has 1048576 * 2 + 1 entries and a zeroeth entry' do
132+
let(:sauce) {
133+
Array.new(1048576 * 2 + 1) { |x|
134+
redis_slowlog(x, 1587352800, x) #lettuce not create so many unnecessary Time objects
135+
}.reverse
136+
}
137+
before(:each) do
138+
allow(redis).to receive(:slowlog) { |_,number|
139+
sauce[0..number-1]
140+
}
141+
end
142+
143+
subject { slowlog_check.redis_slowlog.length }
144+
it { is_expected.to eq(1048576 * 2) } # with the last entry dropped
145+
end
146+
147+
context 'redis has 567 entries and no zeroeth entry' do
148+
let(:sauce) {
149+
Array.new(567) { |x|
150+
redis_slowlog(x + 1, Time.utc(2020,04,20,03,20,00) + x, x)
151+
}.reverse
152+
}
153+
before(:each) do
154+
allow(redis).to receive(:slowlog) { |_,number|
155+
sauce[0..number-1]
156+
}
157+
end
158+
159+
subject { slowlog_check.redis_slowlog.length }
160+
it { is_expected.to eq(567) }
161+
162+
end
163+
end
99164

100165
describe '#replication_group' do
101166
subject { slowlog_check.replication_group }
@@ -201,7 +266,7 @@
201266

202267
describe '#slowlogs_by_flush_interval' do
203268
subject { slowlog_check.slowlogs_by_flush_interval }
204-
let(:bucket) {
269+
let(:bucket18) {
205270
{
206271
"eval" =>
207272
{
@@ -216,11 +281,26 @@
216281
}
217282
}
218283
}
284+
let(:bucket19) {
285+
{
286+
"eval" =>
287+
{
288+
_95percentile: 100000,
289+
avg: 250000,
290+
count: 2,
291+
max: 400000,
292+
median: 100000,
293+
min: 100000,
294+
sum: 500000,
295+
values: [400000, 100000]
296+
}
297+
}
298+
}
219299
it { is_expected.to eq(
220300
{
221301
Time.utc(2020,04,20,04,17) => nil,
222-
Time.utc(2020,04,20,04,18) => nil,
223-
Time.utc(2020,04,20,04,19) => bucket,
302+
Time.utc(2020,04,20,04,18) => bucket18,
303+
Time.utc(2020,04,20,04,19) => bucket19,
224304
Time.utc(2020,04,20,04,20) => nil
225305
}
226306
)
@@ -243,28 +323,37 @@
243323

244324
describe '#ship_slowlogs' do
245325
subject { slowlog_check.ship_slowlogs }
246-
let(:tags) { slowlog_check.default_tags.merge(command: 'eval') }
326+
let(:options) {
327+
{
328+
:host=>"replicationgroup",
329+
:interval=>60,
330+
:type=>"gauge",
331+
:tags=>
332+
{
333+
:aws=>"true",
334+
:command=>"eval",
335+
:env=>"test",
336+
:namespace=>"rspec",
337+
:replication_group=>"replicationgroup",
338+
:service=>"replicationgroup"
339+
}
340+
}
341+
}
342+
247343
it 'sends the right data to datadog' do
248344
allow(ddog).to receive(:emit_points) {["200", { "status" => "ok" }]}
249345
subject
250346

251347
expect(ddog).to have_received(:emit_points).with(
252348
"rspec.redis.slowlog.micros.avg",
253-
[[Time.utc(2020,04,20,04,19), 150000]],
254-
{
255-
:host=>"replicationgroup",
256-
:interval=>60,
257-
:type=>"gauge",
258-
:tags=>
259-
{
260-
:aws=>"true",
261-
:command=>"eval",
262-
:env=>"test",
263-
:namespace=>"rspec",
264-
:replication_group=>"replicationgroup",
265-
:service=>"replicationgroup"
266-
}
267-
}
349+
[[Time.utc(2020,04,20,04,18), 150000]],
350+
options
351+
)
352+
353+
expect(ddog).to have_received(:emit_points).with(
354+
"rspec.redis.slowlog.micros.avg",
355+
[[Time.utc(2020,04,20,04,19), 250000]],
356+
options
268357
)
269358
end
270359
end

0 commit comments

Comments
 (0)