Skip to content
This repository was archived by the owner on Apr 3, 2024. It is now read-only.

Commit 4aab7bf

Browse files
author
Matt Loring
committed
Configurable throttling for log points
1 parent fedd5f4 commit 4aab7bf

File tree

4 files changed

+270
-19
lines changed

4 files changed

+270
-19
lines changed

‎config.js‎

Lines changed: 8 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -68,6 +68,14 @@ module.exports = {
6868
maxStringLength: 100
6969
},
7070

71+
log: {
72+
// The maximum number of logs to record per second per logpoint.
73+
maxLogsPerSecond: 50,
74+
// Number of seconds to wait after the `maxLogsPerSecond` rate is hit before
75+
// logging resumes per logpoint.
76+
logDelaySeconds: 1
77+
},
78+
7179
// These configuration options are for internal experimentation only.
7280
internal: {
7381
registerDelayOnFetcherErrorSec: 300, // 5 minutes.

‎lib/debuglet.js‎

Lines changed: 15 additions & 19 deletions
Original file line numberDiff line numberDiff line change
@@ -333,27 +333,23 @@ Debuglet.prototype.addBreakpoint_ = function(breakpoint, cb) {
333333
that.logger_.info('\tsuccessfully added breakpoint ' + breakpoint.id);
334334
that.activeBreakpointMap_[breakpoint.id] = breakpoint;
335335

336-
that.v8debug_.wait(breakpoint, function waitHandler(err) {
337-
if (err) {
338-
that.logger_.error(err);
339-
cb(err);
340-
return;
341-
}
342-
343-
that.logger_.info('Breakpoint hit!: ' + breakpoint.id);
344-
if (breakpoint.action === 'LOG') {
345-
var message = Debuglet.format(breakpoint.logMessageFormat,
346-
breakpoint.evaluatedExpressions.map(JSON.stringify));
347-
console.log(message);
348-
if (!that.completedBreakpointMap_[breakpoint.id]) {
349-
setTimeout(function() {
350-
that.v8debug_.wait(breakpoint, waitHandler);
351-
}, 500);
336+
if (breakpoint.action === 'LOG') {
337+
that.v8debug_.log(breakpoint, Debuglet.format,
338+
function() {
339+
return that.completedBreakpointMap_[breakpoint.id];
340+
});
341+
} else {
342+
that.v8debug_.wait(breakpoint, function(err) {
343+
if (err) {
344+
that.logger_.error(err);
345+
cb(err);
346+
return;
352347
}
353-
} else {
348+
349+
that.logger_.info('Breakpoint hit!: ' + breakpoint.id);
354350
that.completeBreakpoint_(breakpoint);
355-
}
356-
});
351+
});
352+
}
357353
});
358354
};
359355

‎lib/v8debugapi.js‎

Lines changed: 40 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -201,6 +201,19 @@ module.exports.create = function(logger_, config_, fileStats_) {
201201
listeners[num] = listener;
202202
},
203203

204+
/**
205+
* @param {Breakpoint} breakpoint
206+
* @param {Function} callback
207+
*/
208+
log: function(breakpoint, format, shouldStop) {
209+
var num = breakpoints[breakpoint.id].v8Breakpoint.number();
210+
var listener = onBreakpointHit.bind(
211+
null, breakpoint,
212+
createLogpointHandler(breakpoint, format, shouldStop, listener));
213+
214+
listeners[num] = listener;
215+
},
216+
204217
// The following are for testing:
205218
messages: messages,
206219
numBreakpoints_: function() { return Object.keys(breakpoints).length; },
@@ -305,6 +318,33 @@ module.exports.create = function(logger_, config_, fileStats_) {
305318
setImmediate(function() { cb(null); }); // success.
306319
}
307320

321+
function createLogpointHandler(breakpoint, format, shouldStop, listener) {
322+
var logsThisSecond = 0;
323+
var timesliceEnd = Date.now() + 1000;
324+
var num = breakpoints[breakpoint.id].v8Breakpoint.number();
325+
return function(err) {
326+
var currTime = Date.now();
327+
if (currTime > timesliceEnd) {
328+
logsThisSecond = 0;
329+
timesliceEnd = currTime + 1000;
330+
}
331+
var message = format(breakpoint.logMessageFormat,
332+
breakpoint.evaluatedExpressions.map(JSON.stringify));
333+
logsThisSecond++;
334+
console.log(message);
335+
if (shouldStop()) {
336+
delete listeners[num];
337+
} else {
338+
if (logsThisSecond > config.log.maxLogsPerSecond) {
339+
delete listeners[num];
340+
setTimeout(function() {
341+
listeners[num] = listener;
342+
}, config.log.logDelaySeconds * 1000);
343+
}
344+
}
345+
};
346+
}
347+
308348
function endsWith(str, suffix) {
309349
if (typeof String.prototype.endsWith === 'function') {
310350
return str.endsWith(suffix);

‎test/e2e/test-log-throttling.js‎

Lines changed: 207 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,207 @@
1+
/* KEEP THIS CODE AT THE TOP SO THAT THE BREAKPOINT LINE NUMBERS DON'T CHANGE */
2+
'use strict';
3+
function fib(n) {
4+
if (n < 2) { return n; } var o = { a: [1, 'hi', true] };
5+
return fib(n - 1, o) + fib(n - 2, o); // adding o to appease linter.
6+
}
7+
/**
8+
* Copyright 2015 Google Inc. All Rights Reserved.
9+
*
10+
* Licensed under the Apache License, Version 2.0 (the "License");
11+
* you may not use this file except in compliance with the License.
12+
* You may obtain a copy of the License at
13+
*
14+
* http://www.apache.org/licenses/LICENSE-2.0
15+
*
16+
* Unless required by applicable law or agreed to in writing, software
17+
* distributed under the License is distributed on an "AS IS" BASIS,
18+
* WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
19+
* See the License for the specific language governing permissions and
20+
* limitations under the License.
21+
*/
22+
23+
process.env.GCLOUD_DEBUG_LOGLEVEL=2;
24+
25+
var assert = require('assert');
26+
var util = require('util');
27+
var GoogleAuth = require('google-auth-library');
28+
var _ = require('lodash'); // for _.find. Can't use ES6 yet.
29+
var Q = require('q');
30+
var cluster = require('cluster');
31+
32+
var DEBUG_API = 'https://clouddebugger.googleapis.com/v2/debugger';
33+
var SCOPES = [
34+
'https://www.googleapis.com/auth/cloud-platform',
35+
'https://www.googleapis.com/auth/cloud_debugger',
36+
];
37+
38+
var agent;
39+
var transcript = '';
40+
41+
function apiRequest(authClient, url, method, body) {
42+
method = method || 'GET';
43+
44+
var deferred = Q.defer();
45+
authClient.request({
46+
url: url,
47+
method: method,
48+
json: true,
49+
body: body
50+
}, function(err, body, response) {
51+
if (err) {
52+
deferred.reject(err);
53+
} else {
54+
deferred.resolve(body);
55+
}
56+
});
57+
return deferred.promise;
58+
}
59+
60+
function runTest() {
61+
Q.delay(10 * 1000).then(function() {
62+
var api = agent.private_.debugletApi_;
63+
64+
var debuggee = api.debuggeeId_;
65+
var project = api.project_;
66+
67+
// Get our own credentials because we need an extra scope
68+
var auth = new GoogleAuth();
69+
auth.getApplicationDefault(function(err, authClient) {
70+
if (err) {
71+
console.log(err);
72+
return;
73+
}
74+
75+
// Inject scopes if they have not been injected by the environment
76+
if (authClient.createScopedRequired &&
77+
authClient.createScopedRequired()) {
78+
authClient = authClient.createScoped(SCOPES);
79+
}
80+
81+
function listDebuggees(project) {
82+
return apiRequest(authClient, DEBUG_API + '/debuggees?project=' +
83+
project);
84+
}
85+
86+
function listBreakpoints(debuggee) {
87+
return apiRequest(authClient, DEBUG_API + '/debuggees/' + debuggee +
88+
'/breakpoints');
89+
}
90+
91+
function deleteBreakpoint(debuggee, breakpoint) {
92+
return apiRequest(authClient, DEBUG_API + '/debuggees/' + debuggee +
93+
'/breakpoints/' + breakpoint.id, 'DELETE');
94+
}
95+
96+
function setBreakpoint(debuggee, body) {
97+
return apiRequest(authClient, DEBUG_API + '/debuggees/' + debuggee +
98+
'/breakpoints/set', 'POST', body);
99+
}
100+
101+
listDebuggees(project)
102+
.then(function(body) {
103+
console.log('-- List of debuggees\n',
104+
util.inspect(body, { depth: null}));
105+
assert.ok(body, 'should get a valid ListDebuggees response');
106+
assert.ok(body.debuggees, 'should have a debuggees property');
107+
var result = _.find(body.debuggees, function(d) {
108+
return d.id === debuggee;
109+
});
110+
assert.ok(result, 'should find the debuggee we just registered');
111+
return debuggee;
112+
})
113+
.then(listBreakpoints)
114+
.then(function(body) {
115+
console.log('-- List of breakpoints\n', body);
116+
body.breakpoints = body.breakpoints || [];
117+
118+
var promises = body.breakpoints.map(function(breakpoint) {
119+
return deleteBreakpoint(debuggee, breakpoint);
120+
});
121+
122+
var deleteAll = Q.all(promises);
123+
124+
return deleteAll;
125+
})
126+
.then(function(deleteResults) {
127+
console.log('-- delete results', deleteResults);
128+
return debuggee;
129+
})
130+
.then(function(debuggee) {
131+
// Set a breakpoint
132+
console.log('-- setting a logpoint');
133+
var promise = setBreakpoint(debuggee, {
134+
id: 'breakpoint-1',
135+
location: {path: 'test-log-throttling.js', line: 5},
136+
condition: 'n === 10',
137+
action: 'LOG',
138+
expressions: ['o'],
139+
log_message_format: 'o is: $0'
140+
});
141+
// I don't know what I am doing. There is a better way to write the
142+
// following using promises.
143+
var result = promise.then(function(body) {
144+
console.log('-- resolution of setBreakpoint', body);
145+
assert.ok(body.breakpoint, 'should have set a breakpoint');
146+
var breakpoint = body.breakpoint;
147+
assert.ok(breakpoint.id, 'breakpoint should have an id');
148+
assert.ok(breakpoint.location, 'breakpoint should have a location');
149+
assert.strictEqual(breakpoint.location.path, 'test-log-throttling.js');
150+
return { debuggee: debuggee, breakpoint: breakpoint };
151+
});
152+
return result;
153+
})
154+
.then(function(result) {
155+
console.log('-- waiting before checking if the log was written');
156+
return Q.delay(10 * 1000).then(function() { return result; });
157+
})
158+
.then(function(result) {
159+
// If no throttling occurs, we expect ~20 logs since we are logging
160+
// 2x per second over a 10 second period.
161+
var logCount = transcript.split('o is: {"a":[1,"hi",true]}').length - 1;
162+
// A log count of greater than 10 indicates that we did not successfully
163+
// pause when the rate of `maxLogsPerSecond` was reached.
164+
assert(logCount < 10);
165+
// A log count of less than 3 indicates that we did not successfully
166+
// resume logging after `logDelaySeconds` have passed.
167+
assert(logCount > 2);
168+
deleteBreakpoint(result.debuggee, result.breakpoint).then();
169+
console.log('Test passed');
170+
process.exit(0);
171+
})
172+
.catch(function(e) {
173+
console.error(e);
174+
process.exit(1);
175+
});
176+
});
177+
}).catch(function(e) {
178+
console.error(e);
179+
process.exit(1);
180+
});
181+
}
182+
183+
if (cluster.isMaster) {
184+
cluster.setupMaster({ silent: true });
185+
var handler = function(m) {
186+
assert.ok(m.private_, 'debuglet has initialized');
187+
var debuglet = m.private_;
188+
assert.ok(debuglet.debugletApi_, 'debuglet api is active');
189+
var api = debuglet.debugletApi_;
190+
assert.ok(api.uid_, 'debuglet provided unique id');
191+
assert.ok(api.debuggeeId_, 'debuglet has registered');
192+
agent = m;
193+
};
194+
var stdoutHandler = function(chunk) {
195+
transcript += chunk;
196+
};
197+
var worker = cluster.fork();
198+
worker.on('message', handler);
199+
worker.process.stdout.on('data', stdoutHandler);
200+
runTest();
201+
} else {
202+
var agent = require('../..');
203+
agent.private_.config_.log.maxLogsPerSecond = 1;
204+
agent.private_.config_.log.logDelaySeconds = 5;
205+
setTimeout(process.send.bind(process, agent), 7000);
206+
setInterval(fib.bind(null, 12), 500);
207+
}

0 commit comments

Comments
 (0)