From 8984b7c340ff44b92ae608cabc9ee36daf66e110 Mon Sep 17 00:00:00 2001 From: Tom Lieber Date: Sat, 2 Aug 2014 14:53:35 -0700 Subject: [PATCH] make caught exceptions less noisy, more accurate * 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 --- lib/tracer.js | 84 ++++++++++++++++++++---------- test/scripts/exceptions.js | 16 ++++-- test/test-exceptions.js | 102 ++++++++++++++++++++++++++++++++++--- 3 files changed, 162 insertions(+), 40 deletions(-) diff --git a/lib/tracer.js b/lib/tracer.js index f5616d9..8e2d3fc 100644 --- a/lib/tracer.js +++ b/lib/tracer.js @@ -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 = []; @@ -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 = []; @@ -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); } } } @@ -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; + } } @@ -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); @@ -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); } } } @@ -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 @@ -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); }); } } @@ -1056,9 +1100,6 @@ if (typeof {name} === 'undefined') { this.traceExceptionThrown = function (info, exception) { if (_bailedTick) return; - if (exception === lastException) { - return; - } lastException = exception; var parsedStack; @@ -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; } }; @@ -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) { @@ -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])); diff --git a/test/scripts/exceptions.js b/test/scripts/exceptions.js index 904fd97..acd9a2a 100644 --- a/test/scripts/exceptions.js +++ b/test/scripts/exceptions.js @@ -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(); diff --git a/test/test-exceptions.js b/test/test-exceptions.js index 712ec05..16827a0 100644 --- a/test/test-exceptions.js +++ b/test/test-exceptions.js @@ -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(); @@ -41,11 +42,9 @@ 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; @@ -53,12 +52,99 @@ test('hits', function (t) { 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); +});