Skip to content

Commit

Permalink
bug 734495: Add statsd measurements
Browse files Browse the repository at this point in the history 
* Sprinkle statsd measurements everywhere

* Expose statsd to templates

* Test updates
  • Loading branch information
@lmorchard
lmorchard committed Jul 19, 2012
1 parent 2790478 commit ffe128b
Show file tree
Hide file tree
Showing 6 changed files with 122 additions and 12 deletions.
15 changes: 15 additions & 0 deletions lib/kumascript/caching.js
View file
Expand Up @@ -61,6 +61,9 @@ module.exports.ResponseCache = ks_utils.Class({
// If the configuration is missing, use the fake stub cache
this.memcached = new ks_utils.FakeMemcached();
}

// Grab a statsd reporter
this.statsd = ks_utils.getStatsD(this.options);
},

// ### cacheResponse
Expand Down Expand Up @@ -118,12 +121,23 @@ module.exports.ResponseCache = ks_utils.Class({
$this.options.max_age : ua_cc['max-age']
};

var s_pre = 'kumascript.response_caching.';
if (opts.no_cache) {
$this.statsd.increment(s_pre + 'no_cache');
}
if (opts.max_age == 0) {
$this.statsd.increment(s_pre + 'max_age_zero');
}

$this.get(cache_key, opts, function (err, headers, body, meta) {
if (err == $this.ERR_MISS || err == $this.ERR_STALE) {
$this.statsd.increment(s_pre + 'miss');
return $this.revalidate(cache_key, opts, req, res, err, response_cb);
} else if (err == $this.ERR_NOT_MODIFIED) {
$this.statsd.increment(s_pre + 'not_modified');
return $this.sendNotModified(req, res, meta);
} else {
$this.statsd.increment(s_pre + 'hit');
return $this.sendCacheEntry(cache_key, req, res, headers, body, meta);
}
});
Expand Down Expand Up @@ -344,6 +358,7 @@ module.exports.ResponseCache = ks_utils.Class({
module.exports.request = function (req_opts, cb) {
var memcached = req_opts.memcached;
var timeout = req_opts.timeout;
var statsd = ks_utils.getStatsD(req_opts);

var base_key = 'kumascript:request:' + ks_utils.md5(req_opts.url);
var key = function (name) { return base_key + ':' + name; }
Expand Down
8 changes: 6 additions & 2 deletions lib/kumascript/macros.js
View file
Expand Up @@ -40,7 +40,11 @@ var MacroProcessor = ks_utils.Class(EventEmitter, {
loader_options: {},
// Template execution queue concurrency
queue_concurrency: 1,
macro_timeout: 120000
macro_timeout: 100000
},

initialize: function (options) {
this.statsd = ks_utils.getStatsD(this.options);
},

// #### Process macros in content
Expand Down Expand Up @@ -239,7 +243,7 @@ var MacroProcessor = ks_utils.Class(EventEmitter, {
errors.push(ex);
$this.emit('error', ex);
return next('{{ ' + tok.name + ' }}');
}, $this.options.macro_timeout || 120000);
}, $this.options.macro_timeout || 100000);

// Now, start with the execution!
tmpl.execute(tok.args, clone_ctx, function (err, result) {
Expand Down
46 changes: 42 additions & 4 deletions lib/kumascript/server.js
View file
Expand Up @@ -62,6 +62,8 @@ var Server = ks_utils.Class({
this.memcached = new ks_utils.FakeMemcached();
}

this.statsd = ks_utils.getStatsD(this.options);

// Configure the HTTP server...
app.configure(function () {
// Configure a logger that pipes to the winston logger.
Expand Down Expand Up @@ -104,6 +106,8 @@ var Server = ks_utils.Class({
var $this = this,
opts = {};

$this.statsd.increment('kumascript.GET');

// Vary caching on values of env vars, as well as X-FireLogger
var pfx = this.options.env_header_prefix;
var vary = _.chain(req.headers).keys().filter(function (key) {
Expand All @@ -114,7 +118,8 @@ var Server = ks_utils.Class({

// Create a response cache instance
var cache = new ks_caching.ResponseCache({
memcache: this.options.memcache
memcache: this.options.memcache,
statsd: this.statsd
});
cache.cacheResponse(req, res, opts, function (req, res) {
var path = req.params[0],
Expand All @@ -125,7 +130,8 @@ var Server = ks_utils.Class({
memcached: $this.memcached,
timeout: $this.options.cache_timeout || 3600,
cache_control: req.header('cache-control'),
url: doc_url
url: doc_url,
statsd: this.statsd
};
ks_caching.request(req_opts, function (err, resp, src) {
$this._evalMacros(src, req, res);
Expand All @@ -139,6 +145,8 @@ var Server = ks_utils.Class({
docs_POST: function (req, res) {
var $this = this,
buf = '';

$this.statsd.increment('kumascript.POST');

// TODO: Be more flexible with encodings.
req.setEncoding('utf8');
Expand Down Expand Up @@ -183,7 +191,8 @@ var Server = ks_utils.Class({
server_options: $this.options,
env: env_vars,
source: src,
log: res.log
log: res.log,
statsd: $this.statsd
});

var macro_processor;
Expand All @@ -210,7 +219,8 @@ var Server = ks_utils.Class({
url_template: this.options.template_url_template,
template_class: template_class
},
macro_timeout: this.options.macro_timeout
macro_timeout: this.options.macro_timeout,
statsd: this.statsd
});
}

Expand All @@ -232,6 +242,34 @@ var Server = ks_utils.Class({
});
}

// Common prefix for statsd keys
var ks = 'kumascript.macro_processor.';

// Measure durations of various processing events...
var durations = {
"end": "overall",
"autorequireEnd": "autorequire",
"templateLoadEnd": "template_load",
"macroEnd": "macro"
};
_(durations).each(function (s_name, ev_name) {
macro_processor.on(ev_name, function (m) {
$this.statsd.timing(ks + s_name, m.duration);
});
});

// Measure template cache hits / misses
macro_processor.on('templateLoadEnd', function (m) {
$this.statsd.increment(ks + 'template_load.cache_' +
(m.cache_hit ? 'hit' : 'miss'));
});

// Measure some misc things from the end event
macro_processor.on('end', function (m) {
$this.statsd.increment(ks + 'macros_ct', m.macros_ct);
$this.statsd.increment(ks + 'templates_ct', m.templates_ct);
});

// Process the macros...
macro_processor.process(src, api_ctx, function (errors, result) {
if (errors) {
Expand Down
27 changes: 26 additions & 1 deletion lib/kumascript/utils.js
View file
Expand Up @@ -7,6 +7,8 @@
// ### Prerequisites
var util = require('util'),
crypto = require('crypto'),
log = require('winston'),
StatsD = require('node-statsd').StatsD,
_ = require('underscore');

// ### Class
Expand Down Expand Up @@ -73,6 +75,28 @@ var FakeMemcached = Class({
}
});

// ### get_statsd
// Quick shortcut to get a working statsd out of options, or provide a fake
// mockup with stubs.
function getStatsD (options) {
if ('statsd' in options && options.statsd) {
return options.statsd;
} else if ('statsd_conf' in options && options.statsd_conf.enabled) {
return new StatsD(options.statsd_conf.host, options.statsd_conf.port);
} else {
// HACK: StatsD disabled, so make a fake client
var statsd = {};
var method_names = ['timing', 'increment', 'decrement', 'gauge',
'update_stats'];
_(method_names).each(function (n) {
statsd[n] = function () {
log.debug("statsd."+n+"("+util.inspect(arguments)+")");
};
});
return statsd;
}
}

// ### md5
// Quick shortcut to produce an MD5 hash of a utf-8 string.
function md5 (str) {
Expand Down Expand Up @@ -107,5 +131,6 @@ module.exports = {
Class: Class,
tmpl: tmpl,
FakeMemcached: FakeMemcached,
md5: md5
md5: md5,
getStatsD: getStatsD
};
11 changes: 11 additions & 0 deletions run.js
View file
Expand Up @@ -37,6 +37,11 @@ var DEFAULT_CONFIG = {
maxFiles: 5
}
},
statsd: {
enabled: false,
host: '127.0.0.1',
port: 8125
},
server: {
port: 9080,
numWorkers: 4,
Expand Down Expand Up @@ -92,7 +97,13 @@ if (log_conf.file) {
// Make a nicer alias to the default logger
var log = winston;

var statsd = ks_utils.getStatsD({
statsd_conf: nconf.get('statsd')
});

var server_conf = nconf.get('server');
server_conf.statsd = statsd;

var workers = {};
var worker_list = [];
var is_exiting = false;
Expand Down
27 changes: 22 additions & 5 deletions tests/test-macros.js
View file
Expand Up @@ -33,6 +33,7 @@ function processFixture(test, mp, fixture_path, next) {
function makeErrorHandlingTestcase(fixtureName) {
return function(test) {
var mp = new ks_macros.MacroProcessor({
macro_timeout: 500,
loader_class: ks_test_utils.JSONifyLoader
});
processFixture(test, mp, fixtureName,
Expand All @@ -54,6 +55,7 @@ module.exports = nodeunit.testCase({

"Basic macro substitution should work": function (test) {
var mp = new ks_macros.MacroProcessor({
macro_timeout: 500,
loader_class: ks_test_utils.JSONifyLoader
});
processFixture(test, mp, 'macros1.txt',
Expand All @@ -65,6 +67,7 @@ module.exports = nodeunit.testCase({

"Errors in document parsing should be handled gracefully and reported": function (test) {
var mp = new ks_macros.MacroProcessor({
macro_timeout: 500,
loader_class: ks_test_utils.JSONifyLoader
});
processFixture(test, mp, 'macros-document-syntax-error.txt',
Expand All @@ -88,6 +91,7 @@ module.exports = nodeunit.testCase({

"Escaped single and double quotes should work in any quoting context": function (test) {
var mp = new ks_macros.MacroProcessor({
macro_timeout: 500,
loader_class: ks_test_utils.JSONifyLoader
});
processFixture(test, mp, 'macros-document-escaped-quotes.txt',
Expand All @@ -99,6 +103,7 @@ module.exports = nodeunit.testCase({

"Empty parameters should be accepted": function (test) {
var mp = new ks_macros.MacroProcessor({
macro_timeout: 500,
loader_class: ks_test_utils.JSONifyLoader
});
processFixture(test, mp, 'macros-document-empty-parameter.txt',
Expand All @@ -110,6 +115,7 @@ module.exports = nodeunit.testCase({

"Double right brace in a document should not result in a syntax error": function (test) {
var mp = new ks_macros.MacroProcessor({
macro_timeout: 500,
loader_class: ks_test_utils.JSONifyLoader
});
processFixture(test, mp, 'macros-document-double-brace.txt',
Expand Down Expand Up @@ -156,6 +162,7 @@ module.exports = nodeunit.testCase({
});

var mp = new ks_macros.MacroProcessor({
macro_timeout: 500,
loader_class: LocalClassLoader,
loader_options: {
templates: {
Expand All @@ -168,11 +175,12 @@ module.exports = nodeunit.testCase({
}
});

var events = [],
event_names = ['start', 'end', 'error',
'templateLoadStart', 'templateLoadEnd',
'macroStart', 'macroEnd'];
_(event_names).each(function (name, idx) {
var events = [];
var ev_names = ['start', 'error', 'end',
'autorequireStart', 'autorequireEnd',
'templateLoadStart', 'templateLoadEnd',
'macroStart', 'macroEnd'];
_(ev_names).each(function (name, idx) {
mp.on(name, function (m) {
events.push([name, (m && 'name' in m) ? m.name : null]);
});
Expand Down Expand Up @@ -200,22 +208,29 @@ module.exports = nodeunit.testCase({

var expected_events = [
[ 'start', null ],
[ 'autorequireStart', null ],
[ 'autorequireEnd', null ],
[ 'templateLoadStart', 'MacroUsingParams' ],
[ 'templateLoadEnd', 'MacroUsingParams' ],
[ 'templateLoadStart', 'broken1' ],
[ 'error', 'TemplateLoadingError' ],
[ 'templateLoadEnd', 'broken1' ],
[ 'templateLoadStart', 'broken3' ],
[ 'templateLoadEnd', 'broken3' ],
[ 'templateLoadStart', 'broken2' ],
[ 'error', 'TemplateLoadingError' ],
[ 'templateLoadEnd', 'broken2' ],
[ 'templateLoadStart', 'AnotherFoundMacro' ],
[ 'templateLoadEnd', 'AnotherFoundMacro' ],
[ 'macroStart', 'MacroUsingParams' ],
[ 'macroEnd', 'MacroUsingParams' ],
[ 'macroStart', 'broken1' ],
[ 'macroEnd', 'broken1' ],
[ 'macroStart', 'broken3' ],
[ 'error', 'TemplateExecutionError' ],
[ 'macroEnd', 'broken3' ],
[ 'macroStart', 'broken2' ],
[ 'macroEnd', 'broken2' ],
[ 'macroStart', 'AnotherFoundMacro' ],
[ 'macroEnd', 'AnotherFoundMacro' ],
[ 'end', null ]
Expand Down Expand Up @@ -251,6 +266,7 @@ module.exports = nodeunit.testCase({
}
});
var mp = new ks_macros.MacroProcessor({
macro_timeout: 500,
loader_class: CounterTemplateLoader
});
processFixture(test, mp, 'macros-repeated-macros.txt',
Expand All @@ -265,6 +281,7 @@ module.exports = nodeunit.testCase({
"Documents with no macros should not cause the server to hang": function (test) {
var done = false;
var mp = new ks_macros.MacroProcessor({
macro_timeout: 500,
loader_class: ks_test_utils.JSONifyLoader
});
setTimeout(function () {
Expand Down

0 comments on commit ffe128b

Please sign in to comment.