console: update time formatting

This improves the readability of the `console.timeEnd()` output while keeping a higher output's precision in multiple cases. Instead of e.g. '1.005min' it will print '1:00.300 (m:ss.mmm)'. PR-URL: #29629 Reviewed-By: Anna Henningsen <anna@addaleax.net> Reviewed-By: Michaël Zasso <targos@protonmail.com>
nodejs · Oct 1, 2019 · 204248a · 204248a
1 parent 3473e58
commit 204248a
Show file tree

Hide file tree

Showing 3 changed files with 54 additions and 39 deletions.
diff --git a/lib/internal/console/constructor.js b/lib/internal/console/constructor.js
@@ -3,7 +3,7 @@
 // The Console constructor is not actually used to construct the global
 // console. It's exported for backwards compatibility.
 
-const { Object, ObjectPrototype, Reflect } = primordials;
+const { Object, ObjectPrototype, Reflect, Math } = primordials;
 
 const { trace } = internalBinding('trace_events');
 const {
@@ -533,22 +533,38 @@ function timeLogImpl(self, name, label, data) {
   return true;
 }
 
+function pad(value) {
+  return `${value}`.padStart(2, '0');
+}
+
 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';
+  let hours = 0;
+  let minutes = 0;
+  let seconds = 0;
+
+  if (ms >= kSecond) {
+    if (ms >= kMinute) {
+      if (ms >= kHour) {
+        hours = Math.floor(ms / kHour);
+        ms = ms % kHour;
+      }
+      minutes = Math.floor(ms / kMinute);
+      ms = ms % kMinute;
+    }
+    seconds = ms / kSecond;
+  }
+
+  if (hours !== 0 || minutes !== 0) {
+    [seconds, ms] = seconds.toFixed(3).split('.');
+    const res = hours !== 0 ? `${hours}:${pad(minutes)}` : minutes;
+    return `${res}:${pad(seconds)}.${ms} (${hours !== 0 ? 'h:m' : ''}m:ss.mmm)`;
+  }
+
+  if (seconds !== 0) {
+    return `${seconds.toFixed(3)}s`;
   }
 
-  return value.toFixed(3) + unit;
+  return `${Number(ms.toFixed(3))}ms`;
 }
 
 const keyKey = 'Key';

diff --git a/test/parallel/test-console-formatTime.js b/test/parallel/test-console-formatTime.js
@@ -4,12 +4,11 @@ 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');
+assert.strictEqual(formatTime(100.0096), '100.01ms');
+assert.strictEqual(formatTime(100.0115), '100.011ms');
+assert.strictEqual(formatTime(1500.04), '1.500s');
+assert.strictEqual(formatTime(1000.056), '1.000s');
+assert.strictEqual(formatTime(60300.3), '1:00.300 (m:ss.mmm)');
+assert.strictEqual(formatTime(4000457.4), '1:06:40.457 (h:mm:ss.mmm)');
+assert.strictEqual(formatTime(3601310.4), '1:00:01.310 (h:mm:ss.mmm)');
+assert.strictEqual(formatTime(3213601017.6), '892:40:01.018 (h:mm:ss.mmm)');
diff --git 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|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()));
+assert.ok(/^label: \d+(\.\d{1,3})?(ms|s)$/.test(strings.shift().trim()));
+assert.ok(/^__proto__: \d+(\.\d{1,3})?(ms|s)$/.test(strings.shift().trim()));
+assert.ok(/^constructor: \d+(\.\d{1,3})?(ms|s)$/.test(strings.shift().trim()));
+assert.ok(/^hasOwnProperty: \d+(\.\d{1,3})?(ms|s)$/.test(strings.shift().trim()));
 
 // Verify that console.time() coerces label values to strings as expected
-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()));
+assert.ok(/^: \d+(\.\d{1,3})?(ms|s)$/.test(strings.shift().trim()));
+assert.ok(/^\[object Object\]: \d+(\.\d{1,3})?(ms|s)$/.test(strings.shift().trim()));
+assert.ok(/^\[object Object\]: \d+(\.\d{1,3})?(ms|s)$/.test(strings.shift().trim()));
+assert.ok(/^null: \d+(\.\d{1,3})?(ms|s)$/.test(strings.shift().trim()));
+assert.ok(/^default: \d+(\.\d{1,3})?(ms|s)$/.test(strings.shift().trim()));
+assert.ok(/^default: \d+(\.\d{1,3})?(ms|s)$/.test(strings.shift().trim()));
+assert.ok(/^NaN: \d+(\.\d{1,3})?(ms|s)$/.test(strings.shift().trim()));
+
+assert.ok(/^log1: \d+(\.\d{1,3})?(ms|s)$/.test(strings.shift().trim()));
+assert.ok(/^log1: \d+(\.\d{1,3})?(ms|s) test$/.test(strings.shift().trim()));
+assert.ok(/^log1: \d+(\.\d{1,3})?(ms|s) {} \[ 1, 2, 3 ]$/.test(strings.shift().trim()));
+assert.ok(/^log1: \d+(\.\d{1,3})?(ms|s)$/.test(strings.shift().trim()));
 
 // Make sure that we checked all strings
 assert.strictEqual(strings.length, 0);