gristlabs_grist-core/test/common/promises.js

/**
 * Do some timing of promises, as well as of nextTick and setTimeout, so that we have an idea of
 * how long different things take.
 *
 * To see actual timings, comment out the console.log inside the `log` function below.
 */


/* global describe, it, before */

var assert = require('chai').assert;

var bluebird = require('bluebird');

// Disable longStackTraces, which seem to be enabled in the browser by default.
bluebird.config({ longStackTraces: false });

function log(message) {
  //console.log(message);
}

/**
 * Measurement helpers. Usage:
 *  var start = startTimer();
 *  ...
 *  var usec = usecElapsed(start);    // Returns microseconds.
 */
var startTimer, usecElapsed;
if (typeof process !== 'undefined' && typeof process.hrtime !== 'undefined') {
  startTimer = function() {
    return process.hrtime();
  };
  usecElapsed = function(start) {
    var elapsed = process.hrtime(start);
    return elapsed[0] * 1000000 + elapsed[1] / 1000;
  };
} else {
  startTimer = function() {
    return Date.now();
  };
  usecElapsed = function(start) {
    var elapsedMs = (Date.now() - start);
    return elapsedMs * 1000;
  };
}

/**
 * Helper to run timing tests. Adds a test case to run the given function, possibly multiple
 * times, and check the timing value that it returns.
 *
 * Example:
 *    describe("myClass", function() {
 *      timeIt("myFunc", { reps: 3, expectedUs: 100, fudgeFactor: 4}, myFunc);
 *    });
 * Produces:
 *    myFunc should take ~100us (up to x4) [got 123us]: 316ms
 * Notes:
 *  - The number at the end isn't very meaningful (includes repetitions and measurements).
 *  - Fudge factors should be pretty large, since tests often take shorter or longer depending
 *    on platform, system load, etc.
 *
 * @param {Number} options.reps - Run the test this many times and check the min value.
 * @param {Number} options.expectedUs - Expected number of microseconds to receive from func.
 * @param {Number} options.fudgeFactor - It's fine if the test takes this factor longer or shorter.
 * @param {Number} options.noLowerBound - don't test for being too fast.
 * @param {Function} func - Will call func(reportUs), where reportUs is a function that should be
 *      called with the test measurement when func is done.
 * @return {Function} Function that takes a `done` callback and calls it when all is done.
 */
function timeIt(name, options, func) {
  var reps = options.reps || 1;
  var fudgeFactor = options.fudgeFactor || 1;
  var expectedUs = options.expectedUs;
  var noLowerBound = options.noLowerBound;
  var test = it(name + " should take ~" + expectedUs + "us (up to x" + fudgeFactor + ")",
                function(done) {
    var n = 0;
    var minTimeUs = Infinity;
    function iteration(timeUs) {
      try {
        minTimeUs = Math.min(minTimeUs, timeUs);
        if (n++ < reps) {
          func(next);
          return;
        }
        log("Ran test " + n + " times, min time " + minTimeUs);
        assert(minTimeUs <= expectedUs * fudgeFactor,
               "Time of " + minTimeUs + "us is longer than expected (" + expectedUs + ") " +
               "by more than fudge factor of " + fudgeFactor);
        if (!noLowerBound) {
          assert(minTimeUs >= expectedUs / fudgeFactor,
                 "Time of " + minTimeUs + "us is shorter than expected (" + expectedUs + ") " +
                 "by more than fudge factor of " + fudgeFactor);
        }
        tackOnMeasuredTime(test, minTimeUs);
        done();
      } catch (err) {
        tackOnMeasuredTime(test, minTimeUs);
        done(err);
      }
    }
    function next(timeUs) {
      setTimeout(iteration, 0, timeUs);
    }
    next(Infinity);
  });
}

function tackOnMeasuredTime(test, timeUs) {
  // Output the measured time as 123.1, or 0.0005 when small
  var str = timeUs > 10 ? timeUs.toFixed(0) : timeUs.toPrecision(2);
  test.title = test.title.replace(/( \[got [^]]*us\])?$/, " [got " + str + "us]");
}

describe("promises", function() {
  // These are normally skipped. They are not really tests of our code, but timings to help
  // understand how long different things take. Because of global state affecting tests (e.g.
  // longStackTraces setting, async_hooks affecting timings), it doesn't work well to run these as
  // part of the full test suite. Instead, they can be run manually using
  //
  //      ENABLE_TIMING_TESTS=1 bin/mocha test/common/promises.ts
  //
  // (Note that things in mocha.opts, such as report-why-tests-hang, affect them and may need to
  // be commented out to see accurate timings.)
  //
  before(function() {
    if (!process.env.ENABLE_TIMING_TESTS) {
      this.skip();
    }
  });

  function test(arg) {
    return arg + 2;
  }

  timeIt("simple calls", { reps: 3, expectedUs: 0.005, fudgeFactor: 10, noLowerBound: true },
         function(reportUs) {
    var iterations = 10000000;
    var start = startTimer();
    var value = 0;
    for (var i = 0; i < iterations; i++) {
      value = test(value);
    }
    var us = usecElapsed(start) / iterations;
    assert.equal(value, iterations * 2);
    log("Direct calls took " + us + " us / iteration");
    reportUs(us);
  });

  function testPromiseLib(promiseLib, libName, setupFunc, timingOptions) {
    var iterations = timingOptions.iters;
    timeIt(libName + " chain", timingOptions, function(reportUs) {
      setupFunc();
      var start = startTimer();
      var chain = promiseLib.resolve(0);
      for (var i = 0; i < iterations; i++) {
        chain = chain.then(test);
      }
      var chainDone = false;
      chain.then(function(value) {
        var us = usecElapsed(start) / iterations;
        chainDone = true;
        assert.equal(value, iterations * 2);
        log(libName + " promise chain took " + us + " us / iteration");
        reportUs(us);
      });
      assert.equal(chainDone, false);
    });
  }

  // Measure bluebird with and without longStackSupport. If switching promise libraries, we could
  // add similar timings here to compare performance. E.g. Q is nearly two orders of magnitude
  // slower than bluebird.
  var isNode = Boolean(process.version);

  testPromiseLib(bluebird, 'bluebird (no long traces)',
                 // Sadly, no way to turn off bluebird.longStackTraces, so just do this test first.
                 function() {
                   assert.isFalse(bluebird.hasLongStackTraces(), "longStackTraces should be off");
                 },
                 { iters: 20000, reps: 3, expectedUs: isNode ? 0.3 : 1, fudgeFactor: 8});

  // TODO: with bluebird 3, we can no longer switch between having and not having longStackTraces.
  // We'd have to measure it in two different test runs. For now, can run this test with
  // BLUEBIRD_DEBUG=1 environment variable.
  //testPromiseLib(bluebird, 'bluebird (with long traces)',
  //               function() { bluebird.longStackTraces(); },
  //               { iters: 20000, reps: 3, expectedUs: isNode ? 0.3 : 1, fudgeFactor: 8});


  function testRepeater(repeaterFunc, name, timingOptions) {
    var iterations = timingOptions.iters;
    timeIt("timing of " + name, timingOptions, function(reportUs) {
      var count = 0;
      function step() {
        if (count < iterations) {
          repeaterFunc(step);
          count++;
        } else {
          var us = usecElapsed(start) / iterations;
          assert.equal(count, iterations);
          log(name + " took " + us + " us / iteration (" + iterations + " iterations)");
          reportUs(us);
        }
      }
      var start = startTimer();
      step();
    });
  }

  if (process.maxTickDepth) {
    // Probably running under Node
    testRepeater(process.nextTick, "process.nextTick",
                 { iters: process.maxTickDepth*9/10, reps: 20, expectedUs: 0.1, fudgeFactor: 4 });
  }
  if (typeof setImmediate !== 'undefined') {
    testRepeater(setImmediate, "setImmediate",
      { iters: 100, reps: 10, expectedUs: 2.0, fudgeFactor: 4 });
  }
});