From 4d5e5b57462eb34bd884c7f43852a5af32496e92 Mon Sep 17 00:00:00 2001 From: Chad Norwood Date: Fri, 29 Mar 2013 11:37:45 -0500 Subject: [PATCH] Support options, url stats --- bin/parse_logs.js | 43 +++++++++++++++++++++++++---- lib/profile_time.js | 66 +++++++++++++++++++++++++++++++++++++-------- package.json | 3 ++- 3 files changed, 95 insertions(+), 17 deletions(-) diff --git a/bin/parse_logs.js b/bin/parse_logs.js index b8775d2..2fa5395 100755 --- a/bin/parse_logs.js +++ b/bin/parse_logs.js @@ -13,14 +13,46 @@ * heroku logs -n 1500 | ./parse_logs.js */ -var fs = require('fs'); -var lazy = require('lazy'); +var lazy = require('lazy'); +var program = require('commander'); +var fs = require('fs'); var profile_time = require('../lib/profile_time'); -var myProfiler = profile_time.Profiler(); +var myProfiler; +function help() { + console.log(' Description:'); + console.log(''); + console.log(' Displays stats based on profile_time log lines, including total, percent, and average times.'); + console.log(' By default, it looks only at the json data string, including any begin/end key data.'); + console.log(' If url option is passed (-u), the total time for each url is processed instead.'); + console.log(''); + console.log(' Examples:'); + console.log(''); + console.log(' $ cat file.log | parse_logs.js'); + console.log(' $ cat file.log | parse_logs.js -u 2'); + console.log(' $ parse_logs.js -l file.log'); + console.log(' $ parse_logs.js -u 1 -l file.log'); + console.log(''); +} function init() { - if (process.argv.length > 2) { - readLazy(fs.createReadStream(process.argv[2])); + program + .version('0.0.2') + .option('-l, --logfile [file.log]', 'parse file.log, not stdin. Looks to stdin if no logfile') + .option('-u, --url [n]', 'Display stats from url instead of from json key data.\n' + + 'Group urls by at most depth n, where depth is number of slashes: /1/2/3') + //.option('-t, --top [n]', 'only show stats for the top [n] values') + //.option('-v, --verbose', 'be verbose in output') + .on('--help', help) + .parse(process.argv); + + myProfiler = profile_time.Profiler({ + //topValues : program.top, + urls : program.url + }); + //process.stdout.write(program.helpInformation()); + + if (program.logfile) { + readLazy( fs.createReadStream(program.logfile) ); } else { process.stdin.resume(); process.stdin.setEncoding('utf8'); @@ -58,6 +90,7 @@ function processLine(line) { t.total.linesProd++; } */ + //console.log('processLine DONE:', [p]); myProfiler.addLineToTotal(p); } diff --git a/lib/profile_time.js b/lib/profile_time.js index fa3354e..f550f0f 100644 --- a/lib/profile_time.js +++ b/lib/profile_time.js @@ -7,7 +7,7 @@ exports = module.exports = (function (){ }; /** - * Sets a few options for profiler + * Sets a few options for profiler 'class' (not object) */ function config(opts){ var k; @@ -17,6 +17,7 @@ exports = module.exports = (function (){ for (k in opts) { options[k] = opts[k]; } + return options; } /** @@ -47,16 +48,29 @@ exports = module.exports = (function (){ * @class Profiler * @constructor * @param {String} [url=""] optional url to be logged with request timing info. + * @param {Object} [options] optional config options * @return {Object} own object */ - var Profiler = function (url) { + var Profiler = function (url, userOptions) { if ( !(this instanceof Profiler) ) { - return new Profiler( url ); + return new Profiler( url, userOptions ); + } + // first handle case where options is passed, but url is not. EX: Profiler(options) + if (typeof url == 'object') { + userOptions = url; + url = undefined; } this.url = url || ''; + this.options = options; + if (typeof userOptions == 'object') { + for (k in userOptions) { + this.options[k] = userOptions[k]; + } + } this.startMs = new Date().getTime(); this.times = {}; this.elapsedMs = {}; + this.linesSeen = 0; this.begin('ALL'); return this; @@ -116,7 +130,7 @@ exports = module.exports = (function (){ */ Profiler.prototype.done = function() { var now = new Date().getTime(); - if (options.min4Log > (now - this.startMs)) { + if (this.options.min4Log > (now - this.startMs)) { return; } this.end('ALL'); @@ -131,11 +145,11 @@ exports = module.exports = (function (){ * @return {Object} own object so methods can be chained */ Profiler.prototype.logDone = function() { - if (typeof options.logDone == 'function') { - options.logDone(this); + if (typeof this.options.logDone == 'function') { + this.options.logDone(this); } else { var date = (new Date(this.startMs)).toJSON(); // ex: 2013-03-23T14:20:07.330Z - options.logger(date +' profile_time '+ this.url +' '+ JSON.stringify(this.elapsedMs)); + this.options.logger(date +' profile_time '+ this.url +' '+ JSON.stringify(this.elapsedMs)); } return this; } @@ -149,6 +163,8 @@ exports = module.exports = (function (){ * @return {Object} object containing parsed log information */ Profiler.prototype.parseLogLine = function(logLine) { + this.linesSeen++; + //console.log('parseLogLine:', logLine); // must match log in logDone() var matches = logLine.match(/(\S+) (_profiler|profile_time) (\S+) (.*)\s*?$/); if (!(matches && matches[2])) { @@ -172,6 +188,7 @@ exports = module.exports = (function (){ } catch (e) { console.warn('Could not parse JSON string: "'+ line.jsonString +'"'); } + //console.log('parseLogLine DONE:', [line]); return line; } @@ -186,6 +203,9 @@ exports = module.exports = (function (){ * @return {Object} updated total object */ Profiler.prototype.addLineToTotal = function(line, total) { + var key = ''; + var depthRemaining = this.options.urls; + var matches, tmp; if (typeof line === 'string') { // assume its log line not yet parsed line = this.parseLogLine(line); @@ -204,16 +224,40 @@ exports = module.exports = (function (){ total.totalLines = total.totalLines || {}; total.totalTime = total.totalTime || {}; - for (key in line.elapsedMs) { + if (this.options.urls) { + matches = line.url.split('/'); + // fix case where /a/b?c should be split into 'a', 'b', '?c' + if (matches[matches.length-1].match(/.+?\?/)) { + tmp = matches[matches.length-1].match(/^(.+)?(\?.*)$/); + matches[matches.length-1] = tmp[1]; + matches[matches.length] = tmp[2]; + } + for (var m=0; depthRemaining && typeof matches[m] != 'undefined'; m++) { + //console.log('xxxxx m='+m, depthRemaining && typeof matches[m] != 'undefined', depthRemaining, typeof matches[m] != 'undefined'); + if (!matches[m]) { + continue; // only count if we have chars between slashes + } + depthRemaining--; + key += '/' + matches[m]; + } + //console.log('url key: ', key); + add2Key(total.totalTime, 'ALL', line.json.Done || line.json['e:ALL']); + add2Key(total.totalTime, key, line.json.Done || line.json['e:ALL']); + add2Key(total.totalLines, 'ALL', 1); add2Key(total.totalLines, key, 1); - add2Key(total.totalTime, key, line.elapsedMs[key]); + } else { + for (key in line.elapsedMs) { + add2Key(total.totalLines, key, 1); + add2Key(total.totalTime, key, line.elapsedMs[key]); + } } + //console.log('addLineToTotal DONE:', [total]); return this.total = total; } /** - * Adds log line info to a "total" object + * Summarizes total, creating averageTime, percentTime, and percentLines * @class Profiler * @method summarizeTotal * @param {Object} total object @@ -222,7 +266,7 @@ exports = module.exports = (function (){ Profiler.prototype.summarizeTotal = function(total) { total = total || this.total || {}; if (!total.totalParsedLines) { - return console.log('No matching lines'); + return console.log('No matching lines out of ' + this.linesSeen +' lines seen.'); } total.averageTime = total.averageTime || {}; total.percentTime = total.percentTime || {}; diff --git a/package.json b/package.json index 842e0ce..d297caa 100644 --- a/package.json +++ b/package.json @@ -14,7 +14,8 @@ "url": "git://github.com/chadn/profile_time.git" }, "dependencies": { - "lazy" : "*" + "commander" : "*", + "lazy" : "*" }, "devDependencies": { "mocha" : "*",