console: implement timeLog method

Refs: whatwg/console#138 PR-URL: #21312 Reviewed-By: Colin Ihrig <cjihrig@gmail.com> Reviewed-By: Gus Caplan <me@gus.host> Reviewed-By: Anatoli Papirovski <apapirovski@mac.com> Reviewed-By: Weijia Wang <starkwang@126.com> Reviewed-By: Ruben Bridgewater <ruben@bridgewater.de> Reviewed-By: James M Snell <jasnell@gmail.com>
nodejs · Jul 4, 2018 · b016745 · b016745
1 parent 7951e6d
commit b016745
Show file tree

Hide file tree

Showing 3 changed files with 66 additions and 15 deletions.
diff --git a/doc/api/console.md b/doc/api/console.md
@@ -413,6 +413,25 @@ console.timeEnd('100-elements');
 // prints 100-elements: 225.438ms
 ```
 
+### console.timeLog([label][, ...data])
+<!-- YAML
+added: REPLACEME
+-->
+* `label` {string} **Default:** `'default'`
+* `...data` {any}
+
+For a timer that was previously started by calling [`console.time()`][], prints
+the elapsed time and other `data` arguments to `stdout`:
+
+```js
+console.time('process');
+const value = expensiveProcess1(); // Returns 42
+console.timeLog('process', value);
+// Prints "process: 365.227ms 42".
+doExpensiveProcess2(value);
+console.timeEnd('process');
+```
+
 ### console.trace([message][, ...args])
 <!-- YAML
 added: v0.1.104

diff --git a/lib/console.js b/lib/console.js
@@ -235,18 +235,34 @@ Console.prototype.time = function time(label = 'default') {
 };
 
 Console.prototype.timeEnd = function timeEnd(label = 'default') {
+  const hasWarned = timeLogImpl(this, 'timeEnd', label);
+  if (!hasWarned) {
+    this._times.delete(label);
+  }
+};
+
+Console.prototype.timeLog = function timeLog(label, ...data) {
+  timeLogImpl(this, 'timeLog', label, data);
+};
+
+// Returns true if label was not found
+function timeLogImpl(self, name, label = 'default', data) {
   // Coerces everything other than Symbol to a string
   label = `${label}`;
-  const time = this._times.get(label);
+  const time = self._times.get(label);
   if (!time) {
-    process.emitWarning(`No such label '${label}' for console.timeEnd()`);
+    process.emitWarning(`No such label '${label}' for console.${name}()`);
-    return;
+    return true;
   }
   const duration = process.hrtime(time);
   const ms = duration[0] * 1000 + duration[1] / 1e6;
-  this.log('%s: %sms', label, ms.toFixed(3));
+  if (data === undefined) {
-  this._times.delete(label);
+    self.log('%s: %sms', label, ms.toFixed(3));
-};
+  } else {
+    self.log('%s: %sms', label, ms.toFixed(3), ...data);
+  }
+  return false;
+}
 
 Console.prototype.trace = function trace(...args) {
   const err = {

diff --git a/test/parallel/test-console.js b/test/parallel/test-console.js
@@ -31,11 +31,18 @@ if (common.isMainThread) {
   assert.strictEqual(typeof process.stdout.fd, 'number');
   assert.strictEqual(typeof process.stderr.fd, 'number');
 }
-process.once('warning', common.mustCall((warning) => {
-  assert(/no such label/.test(warning.message));
-}));
 
-console.timeEnd('no such label');
+common.expectWarning(
+  'Warning',
+  [
+    ['No such label \'nolabel\' for console.timeEnd()', common.noWarnCode],
+    ['No such label \'nolabel\' for console.timeLog()', common.noWarnCode],
+    ['Label \'test\' already exists for console.time()', common.noWarnCode]
+  ]
+);
+
+console.timeEnd('nolabel');
+console.timeLog('nolabel');
 
 console.time('label');
 console.timeEnd('label');
@@ -144,15 +151,16 @@ console.timeEnd(NaN);
 console.time('test');
 const time = console._times.get('test');
 setTimeout(() => {
-  common.expectWarning(
-    'Warning',
-    'Label \'test\' already exists for console.time()',
-    common.noWarnCode);
   console.time('test');
   assert.deepStrictEqual(console._times.get('test'), time);
   console.timeEnd('test');
 }, 1);
 
+console.time('log1');
+console.timeLog('log1');
+console.timeLog('log1', 'test');
+console.timeLog('log1', {}, [1, 2, 3]);
+console.timeEnd('log1');
 
 console.assert(false, '%s should', 'console.assert', 'not throw');
 assert.strictEqual(errStrings[errStrings.length - 1],
@@ -219,6 +227,14 @@ assert.ok(/^default: \d+\.\d{3}ms$/.test(strings.shift().trim()));
 assert.ok(/^default: \d+\.\d{3}ms$/.test(strings.shift().trim()));
 assert.ok(/^NaN: \d+\.\d{3}ms$/.test(strings.shift().trim()));
 
+assert.ok(/^log1: \d+\.\d{3}ms$/.test(strings.shift().trim()));
+assert.ok(/^log1: \d+\.\d{3}ms test$/.test(strings.shift().trim()));
+assert.ok(/^log1: \d+\.\d{3}ms {} \[ 1, 2, 3 ]$/.test(strings.shift().trim()));
+assert.ok(/^log1: \d+\.\d{3}ms$/.test(strings.shift().trim()));
+
+// Make sure that we checked all strings
+assert.strictEqual(strings.length, 0);
+
 assert.strictEqual(errStrings.shift().split('\n').shift(),
                    'Trace: This is a {"formatted":"trace"} 10 foo');
 
@@ -229,6 +245,6 @@ common.hijackStderr(common.mustCall(function(data) {
 
   // stderr.write will catch sync error, so use `process.nextTick` here
   process.nextTick(function() {
-    assert.strictEqual(data.includes('no such label'), true);
+    assert.strictEqual(data.includes('nolabel'), true);
   });
 }));