Fixing origin when wrapping Bristol (fixes #29)

[MarkHerhold]

Fix from issue #29.

The solution proposed in the issue did not work out because of cases where there are multiple callsites in the logger itself, meaning that index + 1 would sometimes still reference the Bristol logger file.

For example, the stack from one of the mocha tests:

0:"/Users/Mark/projects/Bristol/src/Bristol.js"
1:"/Users/Mark/projects/Bristol/src/Bristol.js"
2:"/Users/Mark/projects/Bristol/src/Bristol.js"
3:"/Users/Mark/projects/Bristol/test/src/Bristol.js"
4:"/Users/Mark/projects/Bristol/node_modules/mocha/lib/runnable.js"
5:"/Users/Mark/projects/Bristol/node_modules/mocha/lib/runnable.js"
6:"/Users/Mark/projects/Bristol/node_modules/mocha/lib/runner.js"
7:"/Users/Mark/projects/Bristol/node_modules/mocha/lib/runner.js"
8:"/Users/Mark/projects/Bristol/node_modules/mocha/lib/runner.js"
9:"/Users/Mark/projects/Bristol/node_modules/mocha/lib/runner.js"
10:"/Users/Mark/projects/Bristol/node_modules/mocha/lib/runner.js"
11:"/Users/Mark/projects/Bristol/node_modules/mocha/lib/runner.js"
12:"timers.js"
13:"timers.js"
14:"timers.js"

The fix was just to look for the last occurrence of the Bristol logger file.

[TomFrost]

Nice! I love the brevity of this. My only concern is that this solution is O(2n) rather than O(n) -- but that may be entirely moot benchmark-wise because of how well-optimized map and lastIndexOf are. Will merge when I confirm!

[TomFrost]

Annoyingly enough, the verbose loop measurably outperforms map & lastIndexOf (at least on Node 7). Bringing it back to O(n), here's what I have -- what do you think?

_getOrigin() {
  Error.prepareStackTrace = arrayPrepareStackTrace
  const stack = (new Error()).stack
  let origin = null
  for (let i = 1; i < stack.length; i++) {
    if (stack[i].getFileName() === __filename && stack[i + 1]) {
      origin = {
        file: stack[i + 1].getFileName(),
        line: stack[i + 1].getLineNumber().toString()
      }
    }
  }
  Error.prepareStackTrace = originalPrepareStackTrace
  return origin
}

[MarkHerhold]

@TomFrost This won't work for the case I have above where multiple callsites are from Bristol.js itself. I can make adjustments to mine to be more performant though. I was on the fence on messing with the code to gain O(1n) better perf.

[TomFrost]

That doesn't give you the record after the final Bristol entry? Would you mind throwing a test script together that'll let me play with your use case?

[MarkHerhold]

@TomFrost I apologize, your code will work as intended. I didn't notice that you removed the break statement when reading it.

I made some changes and I believe that my new code will be slightly more performant than the above code because I traverse the stack backwards and create an a new origin object (which also incurs multiple function calls) only once as opposed to every time with the above code.

[TomFrost]

I actually tried the same method, and strangely enough it was slower than the code above. I also added an else if (origin) break at the end of the conditional to exit early, and THAT was slower too -- though that may have only been slower because I was testing with a shallow stack trace. I'll post my benchmark script with everything I tried when I get back to my computer.

[MarkHerhold]

Ok, well if you have something that works and are happy with it, let's just get that committed to master and I will close this PR. That would work for both of us. 👍

[TomFrost]

Here's what I was playing with last night-- Old is current, New is the solution in this PR, New2 is what I have above, and the successive ones are my failed attempts at further optimization. Right now, New2 is the winner, but I'd like to test this with a larger stack trace before we pull the trigger.

'use strict'

const originalPrepareStackTrace = Error.prepareStackTrace
const arrayPrepareStackTrace = (err, stack) => { return stack }

const getOriginNew = () => {
  Error.prepareStackTrace = arrayPrepareStackTrace
  const stack = (new Error()).stack
  const lastIndex = stack.map(s => s.getFileName()).lastIndexOf(__filename)
  const line = stack[lastIndex + 1]
  const origin = {
    file: line.getFileName(),
    line: line.getLineNumber().toString()
  }
  Error.prepareStackTrace = originalPrepareStackTrace
  return origin
}

const getOriginNew2 = () => {
  Error.prepareStackTrace = arrayPrepareStackTrace
  const stack = (new Error()).stack
  let origin = null
  for (let i = 1; i < stack.length; i++) {
    if (stack[i].getFileName() === __filename && stack[i + 1]) {
      origin = {
        file: stack[i + 1].getFileName(),
        line: stack[i + 1].getLineNumber().toString()
      }
    }
  }
  Error.prepareStackTrace = originalPrepareStackTrace
  return origin
}

const getOriginNew3 = () => {
  Error.prepareStackTrace = arrayPrepareStackTrace
  const stack = (new Error()).stack
  let origin = null
  for (let i = stack.length - 1; i > 0; i--) {
    if (stack[i].getFileName() === __filename && stack[i + 1]) {
      origin = {
        file: stack[i + 1].getFileName(),
        line: stack[i + 1].getLineNumber().toString()
      }
      break
    }
  }
  Error.prepareStackTrace = originalPrepareStackTrace
  return origin
}

const getOriginNew4 = () => {
  Error.prepareStackTrace = arrayPrepareStackTrace
  const stack = (new Error()).stack
  let origin = null
  stack.forEach((entry, idx) => {
    if (entry.getFileName() === __filename && stack[idx + 1]) {
      origin = {
        file: stack[idx + 1].getFileName(),
        line: stack[idx + 1].getLineNumber().toString()
      }
    }
  })
  Error.prepareStackTrace = originalPrepareStackTrace
  return origin
}

const getOriginNew5 = () => {
  Error.prepareStackTrace = arrayPrepareStackTrace
  const stack = (new Error()).stack
  let origin = null
  for (let i = 1; i < stack.length; i++) {
    if (stack[i].getFileName() === __filename && stack[i + 1]) {
      origin = {
        file: stack[i + 1].getFileName(),
        line: stack[i + 1].getLineNumber().toString()
      }
    } else if (origin) break
  }
  Error.prepareStackTrace = originalPrepareStackTrace
  return origin
}

const getOriginOld = () => {
  Error.prepareStackTrace = arrayPrepareStackTrace
  const stack = (new Error()).stack
  let origin = null
  for (let i = 1; i < stack.length; i++) {
    const file = stack[i].getFileName()
    if (file !== __filename) {
      origin = {
        file,
        line: stack[i].getLineNumber().toString()
      }
      break
    }
  }
  Error.prepareStackTrace = originalPrepareStackTrace
  return origin
}

const ITERS = 100000

console.log('Testing old...')
let start = Date.now()
for (let i = 0; i < ITERS; i++) getOriginOld()
console.log('Old: ' + (Date.now() - start))

console.log('Testing new...')
start = Date.now()
for (let i = 0; i < ITERS; i++) getOriginNew()
console.log('New: ' + (Date.now() - start))

console.log('Testing new2...')
start = Date.now()
for (let i = 0; i < ITERS; i++) getOriginNew2()
console.log('New2: ' + (Date.now() - start))

console.log('Testing new3...')
start = Date.now()
for (let i = 0; i < ITERS; i++) getOriginNew3()
console.log('New3: ' + (Date.now() - start))

console.log('Testing new4...')
start = Date.now()
for (let i = 0; i < ITERS; i++) getOriginNew4()
console.log('New4: ' + (Date.now() - start))

console.log('Testing new5...')
start = Date.now()
for (let i = 0; i < ITERS; i++) getOriginNew5()
console.log('New5: ' + (Date.now() - start))

Output:

╭─<tom@tom-ta>-<~/Projects/test>-<1:38PM>-◇
╰─➤ node bench.js
Testing old...
Old: 1840
Testing new...
New: 2155
Testing new2...
New2: 2045
Testing new3...
New3: 2089
Testing new4...
New4: 2212
Testing new5...
New5: 2086

[MarkHerhold]

Neat! I think we should utilize benchmark to do this comparison if we are really interested in perf.

 ~/c/stack-perf  node index.js
getOriginNew x 56,743 ops/sec ±0.99% (88 runs sampled)
getOriginNew2 x 62,641 ops/sec ±1.30% (92 runs sampled)
getOriginNew3 x 62,477 ops/sec ±1.38% (88 runs sampled)
getOriginNew4 x 59,580 ops/sec ±1.22% (92 runs sampled)
getOriginNew5 x 65,890 ops/sec ±1.24% (89 runs sampled)
getOriginOld x 66,595 ops/sec ±1.30% (87 runs sampled)
Fastest is getOriginOld

Run npm i benchmark to install.

'use strict'

const Benchmark = require('benchmark');
const suite = new Benchmark.Suite;

// add tests
suite.add('getOriginNew', function() {
  getOriginNew()
})
.add('getOriginNew2', function() {
  getOriginNew2()
})
.add('getOriginNew3', function() {
  getOriginNew3()
})
.add('getOriginNew4', function() {
  getOriginNew4()
})
.add('getOriginNew5', function() {
  getOriginNew5()
})
.add('getOriginOld', function() {
  getOriginOld()
})
// add listeners
.on('cycle', function(event) {
  console.log(String(event.target));
})
.on('complete', function() {
  console.log('Fastest is ' + this.filter('fastest').map('name'));
})
// run async
.run({ 'async': true });

// functions here
// removed for shorter message

[TomFrost]

Oh, that's handy! It also proves that #5, the version with the break, is most certainly faster with a more realistic stack trace.

[MarkHerhold]

@TomFrost ok, so are we decided on #5 then?

[TomFrost]

Looks like the winner, unless you have any other ideas or optimizations :)

(Though it still boggles the mind why the reverse traversal that you suggested isn't faster... that's got to be some V8 optimization magic right there)

[MarkHerhold]

I tested approach #5 in my application and unfortunately it still logs the wrapper line. I'll have to take a look at why it doesn't work and will also add a test to the PR to replicate my scenario.

I'll have time to do this tomorrow.

[MarkHerhold]

@TomFrost I isolated out the stack processing logic for testability and optimized it a bit further. I think it's about as good as it's going to get, having even pulled a variable out of the for-loop. Please take a look when you get a chance.

[TomFrost]

Excellent!