From 66043e18128dc80457f4e184b7ed7faedcd93ca7 Mon Sep 17 00:00:00 2001
From: Xavier Stouder <xavier@stouder.io>
Date: Wed, 21 Aug 2019 18:31:06 +0200
Subject: [PATCH] console: display timeEnd with suitable time unit
MIME-Version: 1.0
Content-Type: text/plain; charset=UTF-8
Content-Transfer-Encoding: 8bit

When timeEnd function is called, display result with a suitable
time unit instead of a big amount of milliseconds.

Refs: https://github.com/nodejs/node/issues/29099

PR-URL: https://github.com/nodejs/node/pull/29251
Reviewed-By: Anna Henningsen <anna@addaleax.net>
Reviewed-By: Michaël Zasso <targos@protonmail.com>
Reviewed-By: Colin Ihrig <cjihrig@gmail.com>
---
 lib/internal/console/constructor.js      | 32 +++++++++++++++++++++---
 test/parallel/test-console-formatTime.js | 15 +++++++++++
 test/parallel/test-console.js            | 32 ++++++++++++------------
 3 files changed, 60 insertions(+), 19 deletions(-)
 create mode 100644 test/parallel/test-console-formatTime.js

diff --git a/lib/internal/console/constructor.js b/lib/internal/console/constructor.js
index a618457124c877..554323d9e30c1d 100644
--- a/lib/internal/console/constructor.js
+++ b/lib/internal/console/constructor.js
@@ -32,6 +32,10 @@ const kTraceBegin = 'b'.charCodeAt(0);
 const kTraceEnd = 'e'.charCodeAt(0);
 const kTraceInstant = 'n'.charCodeAt(0);
 
+const kSecond = 1000;
+const kMinute = 60 * kSecond;
+const kHour = 60 * kMinute;
+
 const {
   isArray: ArrayIsArray,
   from: ArrayFrom,
@@ -518,14 +522,35 @@ function timeLogImpl(self, name, label, data) {
   }
   const duration = process.hrtime(time);
   const ms = duration[0] * 1000 + duration[1] / 1e6;
+
+  const formatted = formatTime(ms);
+
   if (data === undefined) {
-    self.log('%s: %sms', label, ms.toFixed(3));
+    self.log('%s: %s', label, formatted);
   } else {
-    self.log('%s: %sms', label, ms.toFixed(3), ...data);
+    self.log('%s: %s', label, formatted, ...data);
   }
   return true;
 }
 
+function formatTime(ms) {
+  let value = ms;
+  let unit = 'ms';
+
+  if (ms >= kHour) {
+    value = ms / kHour;
+    unit = 'h';
+  } else if (ms >= kMinute) {
+    value = ms / kMinute;
+    unit = 'min';
+  } else if (ms >= kSecond) {
+    value = ms / kSecond;
+    unit = 's';
+  }
+
+  return value.toFixed(3) + unit;
+}
+
 const keyKey = 'Key';
 const valuesKey = 'Values';
 const indexKey = '(index)';
@@ -547,5 +572,6 @@ Console.prototype.groupCollapsed = Console.prototype.group;
 module.exports = {
   Console,
   kBindStreamsLazy,
-  kBindProperties
+  kBindProperties,
+  formatTime // exported for tests
 };
diff --git a/test/parallel/test-console-formatTime.js b/test/parallel/test-console-formatTime.js
new file mode 100644
index 00000000000000..aa5f7ec7aa4bf2
--- /dev/null
+++ b/test/parallel/test-console-formatTime.js
@@ -0,0 +1,15 @@
+'use strict';
+// Flags: --expose-internals
+require('../common');
+const { formatTime } = require('internal/console/constructor');
+const assert = require('assert');
+
+const test1 = formatTime(100);
+const test2 = formatTime(1500);
+const test3 = formatTime(60300);
+const test4 = formatTime(4000000);
+
+assert.strictEqual(test1, '100.000ms');
+assert.strictEqual(test2, '1.500s');
+assert.strictEqual(test3, '1.005min');
+assert.strictEqual(test4, '1.111h');
diff --git a/test/parallel/test-console.js b/test/parallel/test-console.js
index e2c5291d915c1d..1d76c42edc082e 100644
--- a/test/parallel/test-console.js
+++ b/test/parallel/test-console.js
@@ -246,24 +246,24 @@ assert.ok(strings[0].includes('foo: { bar: { baz:'));
 assert.ok(strings[0].includes('quux'));
 assert.ok(strings.shift().includes('quux: true'));
 
-assert.ok(/^label: \d+\.\d{3}ms$/.test(strings.shift().trim()));
-assert.ok(/^__proto__: \d+\.\d{3}ms$/.test(strings.shift().trim()));
-assert.ok(/^constructor: \d+\.\d{3}ms$/.test(strings.shift().trim()));
-assert.ok(/^hasOwnProperty: \d+\.\d{3}ms$/.test(strings.shift().trim()));
+assert.ok(/^label: \d+\.\d{3}(ms|s|min|h)$/.test(strings.shift().trim()));
+assert.ok(/^__proto__: \d+\.\d{3}(ms|s|min|h)$/.test(strings.shift().trim()));
+assert.ok(/^constructor: \d+\.\d{3}(ms|s|min|h)$/.test(strings.shift().trim()));
+assert.ok(/^hasOwnProperty: \d+\.\d{3}(ms|s|min|h)$/.test(strings.shift().trim()));
 
 // Verify that console.time() coerces label values to strings as expected
-assert.ok(/^: \d+\.\d{3}ms$/.test(strings.shift().trim()));
-assert.ok(/^\[object Object\]: \d+\.\d{3}ms$/.test(strings.shift().trim()));
-assert.ok(/^\[object Object\]: \d+\.\d{3}ms$/.test(strings.shift().trim()));
-assert.ok(/^null: \d+\.\d{3}ms$/.test(strings.shift().trim()));
-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()));
+assert.ok(/^: \d+\.\d{3}(ms|s|min|h)$/.test(strings.shift().trim()));
+assert.ok(/^\[object Object\]: \d+\.\d{3}(ms|s|min|h)$/.test(strings.shift().trim()));
+assert.ok(/^\[object Object\]: \d+\.\d{3}(ms|s|min|h)$/.test(strings.shift().trim()));
+assert.ok(/^null: \d+\.\d{3}(ms|s|min|h)$/.test(strings.shift().trim()));
+assert.ok(/^default: \d+\.\d{3}(ms|s|min|h)$/.test(strings.shift().trim()));
+assert.ok(/^default: \d+\.\d{3}(ms|s|min|h)$/.test(strings.shift().trim()));
+assert.ok(/^NaN: \d+\.\d{3}(ms|s|min|h)$/.test(strings.shift().trim()));
+
+assert.ok(/^log1: \d+\.\d{3}(ms|s|min|h)$/.test(strings.shift().trim()));
+assert.ok(/^log1: \d+\.\d{3}(ms|s|min|h) test$/.test(strings.shift().trim()));
+assert.ok(/^log1: \d+\.\d{3}(ms|s|min|h) {} \[ 1, 2, 3 ]$/.test(strings.shift().trim()));
+assert.ok(/^log1: \d+\.\d{3}(ms|s|min|h)$/.test(strings.shift().trim()));
 
 // Make sure that we checked all strings
 assert.strictEqual(strings.length, 0);