Skip to content

Commit

Permalink
Support options, url stats
Browse files Browse the repository at this point in the history
  • Loading branch information
@chadn
chadn committed Mar 29, 2013
1 parent b62adeb commit 4d5e5b5
Show file tree
Hide file tree
Showing 3 changed files with 95 additions and 17 deletions.
43 changes: 38 additions & 5 deletions bin/parse_logs.js
View file
Expand Up @@ -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');
Expand Down Expand Up @@ -58,6 +90,7 @@ function processLine(line) {
t.total.linesProd++;
}
*/
//console.log('processLine DONE:', [p]);
myProfiler.addLineToTotal(p);
}

Expand Down
66 changes: 55 additions & 11 deletions lib/profile_time.js
View file
Expand Up @@ -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;
Expand All @@ -17,6 +17,7 @@ exports = module.exports = (function (){
for (k in opts) {
options[k] = opts[k];
}
return options;
}

/**
Expand Down Expand Up @@ -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 || '<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;
Expand Down Expand Up @@ -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');
Expand 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;
}
Expand All @@ -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])) {
Expand All @@ -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;
}

Expand All @@ -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);
Expand All @@ -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
Expand All @@ -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 || {};
Expand Down
3 changes: 2 additions & 1 deletion package.json
View file
Expand Up @@ -14,7 +14,8 @@
"url": "git://github.com/chadn/profile_time.git"
},
"dependencies": {
"lazy" : "*"
"commander" : "*",
"lazy" : "*"
},
"devDependencies": {
"mocha" : "*",
Expand Down

0 comments on commit 4d5e5b5

Please sign in to comment.