Merge pull request #20 from taskcluster/add-timer

added monitor.timer

README.md

@@ -56,6 +56,51 @@ stopMonitor();
 
 More details on the usage of measure and count can be found at [the Statsum client](https://github.com/taskcluster/node-statsum#statsum-client-for-nodejs).
 
+### Timing Functions/Promises
+
+Often we wish to measure how long time an operation takes, synchronous or
+asynchronous, this can done using the `monitor.timer(key, funcOrPromise)`
+method. It takes a `key` (as name of the metric) and a function or promise to
+measure the time of. If the function returns a promise, it'll include the time
+it takes for the promise to resolve.
+
+The following examples are valid usages:
+```js
+let monitor = await monitoring({
+  project: 'tc-stats-collector',
+  credentials: {clientId: 'test-client', accessToken: 'test'},
+});
+
+
+// Timing a synchronous operation
+let root = monitor.timer('compute-sqrt', () => {
+  return Math.sqrt(25);
+})
+assert(root === 5);
+
+// Timing a single asynchronous function (promise)
+let task = monitor.timer('load-task', queue.task(taskId));
+assert(task.workerType == '...'); // task is the task definition response
+
+// Timing an asynchronous function
+let task = monitor.timer('poll-for-task', async () => {
+  while (true) {
+    try {
+      return await queue.task(taskId);
+    } catch (err) {
+      // Ignore error and try again
+      // In the real would you want a maximum time before you stop polling
+      // And probably some sleeping between each polling attempt...
+    }
+  }
+});
+assert(task.workerType == '...'); // task is the task definition response
+
+```
+
+Rejected promises and errors will be allowed bubble up, and the time will
+measured and recoded just like successful functions or promises.
+
 ### Timing Handlers
 
 A common pattern in Taskcluster projects is to have handler functions in a worker that take a message as an argument and perform some action. These

src/monitor.js

@@ -62,6 +62,10 @@ class Monitor {
     );
   }
 
+  timer(key, funcOrPromise) {
+    return utils.timer(this, key, funcOrPromise);
+  }
+
   timedHandler(name, handler) {
     return utils.timedHandler(this, name, handler);
   }
@@ -107,6 +111,10 @@ class MockMonitor {
     this.measures[k] = (this.measures[k] || []).concat(val);
   }
 
+  timer(key, funcOrPromise) {
+    return utils.timer(this, key, funcOrPromise);
+  }
+
   timedHandler(name, handler) {
     return async (message) => { await handler(message); };
   }

src/utils.js

@@ -7,6 +7,7 @@
  */
 let debug = require('debug')('taskcluster-lib-monitor');
 let usage = require('usage');
+let Promise = require('promise');
 
 /**
  * Given an express api method, this will time it
@@ -99,3 +100,22 @@ export function resources(monitor, proc, seconds) {
   monitor._resourceInterval = interval;
   return () => clearInterval(interval);
 }
+
+export function timer(monitor, prefix, funcOrPromise) {
+  let start = process.hrtime();
+  let done = () => {
+    let d = process.hrtime(start);
+    monitor.measure(prefix, d[0] * 1000 + d[1] / 1000000);
+  };
+  if (funcOrPromise instanceof Function) {
+    try {
+      funcOrPromise = funcOrPromise();
+    } finally {
+      // If this is a sync function that throws, we let it...
+      // We just remember to call done() afterwards
+      done();
+    }
+  }
+  Promise.resolve(funcOrPromise).then(done, done);
+  return funcOrPromise;
+}

test/mockmonitor_test.js

@@ -73,4 +73,39 @@ suite('MockMonitor', () => {
       done(e);
     }
   });
+
+  test('montor.timer(k, value)', async () => {
+    let v = monitor.timer('k', 45);
+    assert(v == 45);
+    // Sleep so that the promise handler can be handled before we check that
+    // something was recorded...
+    await new Promise(accept => setTimeout(accept, 10));
+    assert(monitor.measures['mm.k'].length === 1);
+  });
+
+  test('montor.timer(k, () => value)', async () => {
+    let v = monitor.timer('k', () => 45);
+    assert(v == 45);
+    assert(monitor.measures['mm.k'].length === 1);
+  });
+
+  test('montor.timer(k, async () => value)', async () => {
+    let v = await monitor.timer('k', async () => {
+      await new Promise(accept => setTimeout(accept, 100));
+      return 45;
+    });
+    assert(v == 45);
+    assert(monitor.measures['mm.k'].length === 1);
+  });
+
+  test('montor.timer(k, () => {throw new Error()})', async () => {
+    try {
+      monitor.timer('k', () => {throw new Error();});
+    } catch (err) {
+      await new Promise(accept => setTimeout(accept, 10));
+      assert(monitor.measures['mm.k'].length === 1);
+      return;
+    }
+    assert(false);
+  });
 });