Skip to content

Commit

Permalink
make caught exceptions less noisy, more accurate
Browse files Browse the repository at this point in the history 
* report hits only for uncaught exceptions
* exceptions show up on all invocations from which they're thrown
* an exception log only shows uncaught exceptions

adobe-research/theseus#46
  • Loading branch information
@alltom
alltom committed Aug 2, 2014
1 parent 0f844e5 commit 8984b7c
Show file tree
Hide file tree
Showing 3 changed files with 162 additions and 40 deletions.
84 changes: 56 additions & 28 deletions lib/tracer.js
View file
Original file line number Diff line number Diff line change
Expand Up @@ -83,7 +83,7 @@ if (typeof {name} === 'undefined') {
var nodeHitCounts = {}; // { query-handle: { nodeId: hit-count } }
var exceptionCounts = {}; // { query-handle: { nodeId: exception-count } }
var logEntries = {}; // { query-handle: [invocation id] }
var anonFuncParentInvocation, lastException; // yucky globals track state between trace* calls
var anonFuncParentInvocation, lastException, lastExceptionThrownFromInvocation; // yucky globals track state between trace* calls
var nextInvocationId = 0;
var _hitQueries = [];
var _exceptionQueries = [];
Expand Down Expand Up @@ -119,7 +119,7 @@ if (typeof {name} === 'undefined') {
nodeHitCounts = {}; // { query-handle: { nodeId: hit-count } }
exceptionCounts = {}; // { query-handle: { nodeId: exception-count } }
logEntries = {}; // { query-handle: [invocation id] }
anonFuncParentInvocation, lastException; // yucky globals track state between trace* calls
anonFuncParentInvocation = undefined, lastException = undefined, lastExceptionThrownFromInvocation = undefined; // yucky globals track state between trace* calls
_hitQueries = [];
_exceptionQueries = [];
_logQueries = [];
Expand Down Expand Up @@ -588,13 +588,13 @@ if (typeof {name} === 'undefined') {
var query = _logQueries[handle];
if (query.logs && invocation.f.id === "log") {
if (callSite) {
logEntries[handle].push(callSite.id);
addLogEntry(handle, callSite.id);
} else {
console.log("no call site! I needed one!", invocation.getParents());
}
}
if (query.ids && query.ids.indexOf(id) !== -1) {
logEntries[handle].push(invocation.id);
addLogEntry(handle, invocation.id);
}
}
}
Expand Down Expand Up @@ -676,7 +676,14 @@ if (typeof {name} === 'undefined') {
}

ids = ids.sort(function (a, b) { return invocationById[a].tick - invocationById[b].tick });
return ids;
return { entries: ids, seenIds: seenIds };
}

function addLogEntry(handle, invocationId) {
if (!(invocationId in logEntries[handle].seenIds)) {
logEntries[handle].entries.push(invocationId);
logEntries[handle].seenIds[invocationId] = true;
}
}


Expand All @@ -689,6 +696,7 @@ if (typeof {name} === 'undefined') {
_epochInvocationDepth = [];
anonFuncParentInvocation = undefined;
lastException = undefined;
lastExceptionThrownFromInvocation = undefined;

if (fromNode) {
console.log("[fondue] bailing from " + (fromNode.name ? (fromNode.name + " at ") : "") + fromNode.path + " line " + fromNode.start.line + ", character " + fromNode.start.column);
Expand Down Expand Up @@ -760,7 +768,7 @@ if (typeof {name} === 'undefined') {
for (var handle in _logQueries) {
var query = _logQueries[handle];
if (query.eventNames && query.eventNames.indexOf(epoch.eventName) !== -1) {
logEntries[handle].push(invocation.id);
addLogEntry(handle, invocation.id);
}
}
}
Expand Down Expand Up @@ -803,15 +811,51 @@ if (typeof {name} === 'undefined') {

var top = invocationStack.pop();

// if the tick was bailed or something, there might not be an invocation
if (top) {
// if the tick was bailed or something, there might not be an invocation
top.endTimestamp = new Date().getTime();
top.duration = top.endTimestamp - top.timestamp;

// if there was an exception before, but this function didn't throw
// it as well, then it must have been caught.
// only functions track exceptions.
if (top.type === 'function' && lastException !== undefined && top.exception !== lastException) {
// traceExceptionThrown sets lastException, but this is where we clear it
if (top.exception === undefined) {
lastException = undefined;
lastExceptionThrownFromInvocation = undefined;
}
}
}

if (invocationStack.length === 0) {
// check for uncaught exceptions
if (lastException !== undefined && lastExceptionThrownFromInvocation !== undefined) {
var id = lastExceptionThrownFromInvocation.f.id;

if (!exceptionsByNodeId[id]) {
exceptionsByNodeId[id] = [];
}
exceptionsByNodeId[id].push({ exception: lastException, invocationId: lastExceptionThrownFromInvocation.id });

for (var handle in exceptionCounts) {
var hits = exceptionCounts[handle];
hits[id] = (hits[id] || 0) + 1;
}

for (var handle in _logQueries) {
if (_logQueries[handle].exceptions) {
// BUG: we're adding this at the end of the tick, which
// means it's technically out-of-order relative to
// the other log entries in this tick.
addLogEntry(handle, lastExceptionThrownFromInvocation.id);
}
}
}

_invocationsThisTick = 0;
lastException = undefined;
lastExceptionThrownFromInvocation = undefined;

// make the file call graph for this tick

Expand Down Expand Up @@ -954,7 +998,7 @@ if (typeof {name} === 'undefined') {
// (callSiteInvocation might be falsy if this tick was bailed)
if (callerInvocation && callSiteInvocation) {
matchingQueryHandles(callerInvocation).forEach(function (handle) {
logEntries[handle].push(callSiteInvocation.id);
addLogEntry(handle, callSiteInvocation.id);
});
}
}
Expand Down Expand Up @@ -1056,9 +1100,6 @@ if (typeof {name} === 'undefined') {
this.traceExceptionThrown = function (info, exception) {
if (_bailedTick) return;

if (exception === lastException) {
return;
}
lastException = exception;

var parsedStack;
Expand Down Expand Up @@ -1110,21 +1151,8 @@ if (typeof {name} === 'undefined') {
top.rawStack = exception.stack;
if (parsedStack) top.exceptionStack = parsedStack;

if (!exceptionsByNodeId[top.f.id]) {
exceptionsByNodeId[top.f.id] = [];
}
exceptionsByNodeId[top.f.id].push({ exception: exception, invocationId: top.id });

var id = top.f.id;
for (var handle in exceptionCounts) {
var hits = exceptionCounts[handle];
hits[id] = (hits[id] || 0) + 1;
}

for (var handle in _logQueries) {
if (_logQueries[handle].exceptions) {
logEntries[handle].push(top.id);
}
if (lastExceptionThrownFromInvocation === undefined) {
lastExceptionThrownFromInvocation = top;
}
};

Expand Down Expand Up @@ -1353,7 +1381,7 @@ if (typeof {name} === 'undefined') {
throw new Error("unrecognized query");
}

return logEntries[handle].length;
return logEntries[handle].entries.length;
};

this.logDelta = function (handle, maxResults) {
Expand All @@ -1363,7 +1391,7 @@ if (typeof {name} === 'undefined') {

maxResults = maxResults || 10;

var ids = logEntries[handle].splice(0, maxResults);
var ids = logEntries[handle].entries.splice(0, maxResults);
var results = ids.map(function (invocationId, i) {
var invocation = invocationById[invocationId];
return makeLogEntry(invocation, findParentsInQuery(invocation, _logQueries[handle]));
Expand Down
16 changes: 12 additions & 4 deletions test/scripts/exceptions.js
View file
Original file line number Diff line number Diff line change
@@ -1,9 +1,17 @@
function foo() {
function except() { throw 'lol' }
function except() { throw 'foo' }

function catches() {
try {
except();
} catch (e) {
}
}
foo();
setTimeout(foo, 100);

function doesNotCatch() {
except();
}

setTimeout(catches, 100);
// setTimeout(doesNotCatch, 100); // the test harness can't handle this yet
catches();
doesNotCatch();
102 changes: 94 additions & 8 deletions test/test-exceptions.js
View file
Original file line number Diff line number Diff line change
Expand Up @@ -25,9 +25,10 @@
var test = require('tap').test;
var simulate = require('./helper/simulate');

// report hits only for uncaught exceptions
test('hits', function (t) {
var o = simulate('scripts/exceptions.js');
t.ok(o.tracer); t.notOk(o.exception);
t.ok(o.tracer); t.ok(o.exception);
var tracer = o.tracer;
var nodes = tracer.nodes();

Expand All @@ -41,24 +42,109 @@ test('hits', function (t) {

var handle1 = tracer.trackExceptions();
var handle2 = tracer.trackExceptions();
var fooNode = nodeWithTypeName('function', 'foo');
var exceptNode = nodeWithTypeName('function', 'except');
var fooCallSiteNode = nodeWithTypeName('callsite', 'foo');
var exceptCallSiteNode = nodeWithTypeName('callsite', 'except');
var fooTimeoutCallSiteNode = nodesWithTypeName('callsite', 'setTimeout')[0];
var catchesNode = nodeWithTypeName('function', 'catches');
var doesNotCatchNode = nodeWithTypeName('function', 'doesNotCatch');

var expected = { counts: {} };
expected.counts[exceptNode.id] = 1;
t.equivalent(tracer.newExceptions(handle1), expected);
t.equivalent(tracer.newExceptions(handle2), expected);

setTimeout(function () {
t.equivalent(tracer.newExceptions(handle1), expected);
t.equivalent(tracer.newExceptions(handle2), expected);

t.equivalent(tracer.newExceptions(handle1), { counts: {} });
t.equivalent(tracer.newExceptions(handle2), { counts: {} });

t.end();
}, 200);
});

// exceptions show up on all invocations from which they're thrown
test('logs', function (t) {
var o = simulate('scripts/exceptions.js');
t.ok(o.tracer); t.ok(o.exception);
var tracer = o.tracer;
var nodes = tracer.nodes();

var nodeWithTypeName = function (type, name) {
return nodes.filter(function (n) { return n.type === type && n.name === name })[0];
};

var nodesWithTypeName = function (type, name) {
return nodes.filter(function (n) { return n.type === type && n.name === name });
};

var exceptNode = nodeWithTypeName('function', 'except');
var catchesNode = nodeWithTypeName('function', 'catches');
var doesNotCatchNode = nodeWithTypeName('function', 'doesNotCatch');

var handle = tracer.trackLogs({ ids: [exceptNode.id, catchesNode.id, doesNotCatchNode.id] });

var log = tracer.logDelta(handle, 4);
var expectedLog = [{
nodeId: catchesNode.id,
// no exception
}, {
nodeId: exceptNode.id,
exception: {},
}, {
nodeId: doesNotCatchNode.id,
exception: {},
}, {
nodeId: exceptNode.id,
exception: {},
}];
t.similar(log, expectedLog);
t.equivalent(tracer.logDelta(handle, 1), []);

setTimeout(function () {
var log = tracer.logDelta(handle, 2);
var expectedLog = [{
nodeId: catchesNode.id,
// no exception
}, {
nodeId: exceptNode.id,
exception: {},
}];
t.similar(log, expectedLog);
t.equivalent(tracer.logDelta(handle, 1), []);

t.end();
}, 200);
});

// an exception log only shows uncaught exceptions
test('logs 2', function (t) {
var o = simulate('scripts/exceptions.js');
t.ok(o.tracer); t.ok(o.exception);
var tracer = o.tracer;
var nodes = tracer.nodes();

var nodeWithTypeName = function (type, name) {
return nodes.filter(function (n) { return n.type === type && n.name === name })[0];
};

var nodesWithTypeName = function (type, name) {
return nodes.filter(function (n) { return n.type === type && n.name === name });
};

var exceptNode = nodeWithTypeName('function', 'except');
var catchesNode = nodeWithTypeName('function', 'catches');
var doesNotCatchNode = nodeWithTypeName('function', 'doesNotCatch');

var handle = tracer.trackLogs({ exceptions: true });

var log = tracer.logDelta(handle, 1);
var expectedLog = [{
nodeId: exceptNode.id,
exception: {},
}];
t.similar(log, expectedLog);
t.equivalent(tracer.logDelta(handle, 1), []);

setTimeout(function () {
t.equivalent(tracer.logDelta(handle, 1), []);

t.end();
}, 200);
});

0 comments on commit 8984b7c

Please sign in to comment.