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>

Author: targos

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');
+constvalue=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

lib/console.js

@@ -231,18 +231,34 @@ Console.prototype.time = function time(label = 'default') {
 };
 
 Console.prototype.timeEnd=functiontimeEnd(label='default'){
+consthasWarned=timeLogImpl(this,'timeEnd',label);
+if(!hasWarned){
+this._times.delete(label);
+}
+};
+
+Console.prototype.timeLog=functiontimeLog(label, ...data){
+timeLogImpl(this,'timeLog',label,data);
+};
+
+// Returns true if label was not found
+functiontimeLogImpl(self,name,label='default',data){
 // Coerces everything other than Symbol to a string
 label=`${label}`;
-consttime=this._times.get(label);
+consttime=self._times.get(label);
 if(!time){
-process.emitWarning(`No such label '${label}' for console.timeEnd()`);
-return;
+process.emitWarning(`No such label '${label}' for console.${name}()`);
+returntrue;
 }
 constduration=process.hrtime(time);
 constms=duration[0]*1000+duration[1]/1e6;
-this.log('%s: %sms',label,ms.toFixed(3));
-this._times.delete(label);
-};
+if(data===undefined){
+self.log('%s: %sms',label,ms.toFixed(3));
+}else{
+self.log('%s: %sms',label,ms.toFixed(3), ...data);
+}
+returnfalse;
+}
 
 Console.prototype.trace=functiontrace(...args){
 consterr={

test/parallel/test-console.js

@@ -22,6 +22,7 @@
 'use strict';
 constcommon=require('../common');
 constassert=require('assert');
+constutil=require('util');
 
 assert.ok(process.stdout.writable);
 assert.ok(process.stderr.writable);
@@ -30,11 +31,17 @@ if (common.isMainThread) {
 assert.strictEqual(typeofprocess.stdout.fd,'number');
 assert.strictEqual(typeofprocess.stderr.fd,'number');
 }
-process.once('warning',common.mustCall((warning)=>{
-assert(/nosuchlabel/.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]
+]
+);
+
+console.timeEnd('nolabel');
+console.timeLog('nolabel');
 
 console.time('label');
 console.timeEnd('label');
@@ -47,8 +54,8 @@ assert.throws(() => console.timeEnd(Symbol('test')),
 TypeError);
 
 
-// an Object with a custom .inspect() function
-constcustom_inspect={foo: 'bar',inspect: ()=>'inspect'};
+// An Object with a custom inspect function.
+constcustom_inspect={foo: 'bar',[util.inspect.custom]: ()=>'inspect'};
 
 conststrings=[];
 consterrStrings=[];
@@ -139,6 +146,12 @@ console.timeEnd();
 console.time(NaN);
 console.timeEnd(NaN);
 
+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],
 'Assertion failed: console.assert should not throw\n');
@@ -179,9 +192,11 @@ for (const expected of expectedStrings) {
 }
 
 assert.strictEqual(strings.shift(),
-"{ foo: 'bar', inspect: [Function: inspect] }\n");
+"{ foo: 'bar',\n [Symbol(util.inspect.custom)]: "+
+'[Function: [util.inspect.custom]] }\n');
 assert.strictEqual(strings.shift(),
-"{ foo: 'bar', inspect: [Function: inspect] }\n");
+"{ foo: 'bar',\n [Symbol(util.inspect.custom)]: "+
+'[Function: [util.inspect.custom]] }\n');
 assert.ok(strings.shift().includes('foo: [Object]'));
 assert.strictEqual(strings.shift().includes('baz'),false);
 assert.strictEqual(strings.shift(),'inspect inspect\n');
@@ -202,6 +217,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}mstest$/.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');
 
@@ -212,6 +235,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);
 });
 }));