feat(cli): show individual and total test execution times (#359)

* feat(cli): show individual and total test execution times

* chore: adapt logs

src/@types/list-files.ts

@@ -16,8 +16,8 @@ export type Configs = {
 };
 
 export type FileResults = {
-  success: string[];
-  fail: string[];
+  success: Map<string, string>;
+  fail: Map<string, string>;
 };
 
 /* c8 ignore stop */

src/@types/poku.ts

@@ -102,4 +102,9 @@ export type Configs = {
   deno?: DenoOptions;
 } & ListFilesConfigs;
 
+export type FinalResults = {
+  time: string;
+  started: Date;
+};
+
 /* c8 ignore stop */

src/configs/files.ts

@@ -1,10 +1,13 @@
 /* c8 ignore start */
 
 import type { FileResults } from '../@types/list-files.js';
+import type { FinalResults } from '../@types/poku.js';
 
 export const fileResults: FileResults = {
-  success: [],
-  fail: [],
+  success: new Map(),
+  fail: new Map(),
 };
 
+export const finalResults = {} as FinalResults;
+
 /* c8 ignore stop */

src/helpers/logs.ts

@@ -1,6 +1,6 @@
 /* c8 ignore start */
 
-import { stdout } from 'node:process';
+import process from 'node:process';
 import { EOL } from 'node:os';
 import type { Configs } from '../@types/poku.js';
 
@@ -10,7 +10,7 @@ export const isQuiet = (configs?: Configs): boolean =>
 export const isDebug = (configs?: Configs): boolean => Boolean(configs?.debug);
 
 export const write = (data: string | Uint8Array) =>
-  stdout.write(`${String(data)}\n`);
+  process.stdout.write(`${String(data)}\n`);
 
 export const printOutput = (options: {
   output: string;

src/helpers/runner.ts

@@ -26,6 +26,7 @@ export const runner = (filename: string, configs?: Configs): string[] => {
           '--allow-env', // Poku share the process.env with the `child_process`
           '--allow-run', // Poku CLI
           '--allow-net', // Create Service
+          '--allow-hrtime', // Precise performance execution time
         ];
 
     const denoDeny = configs?.deno?.deny

src/helpers/time.ts

@@ -0,0 +1,20 @@
+/* c8 ignore start */
+
+import { padStart } from '../polyfills/pad.js';
+
+export const setTime = (date: Date): string => {
+  const hours = padStart(date.getHours().toString(), 2, '0');
+  const minutes = padStart(date.getMinutes().toString(), 2, '0');
+  const seconds = padStart(date.getSeconds().toString(), 2, '0');
+
+  return `${hours}:${minutes}:${seconds}`;
+};
+
+export const toSecs = (milliseconds: string): string => {
+  const ms = parseFloat(milliseconds);
+  const seconds = (ms / 1000).toFixed(2);
+
+  return seconds;
+};
+
+/* c8 ignore stop */

src/modules/describe.ts

@@ -1,3 +1,4 @@
+import process from 'node:process';
 import { format, backgroundColor } from '../helpers/format.js';
 import { write } from '../helpers/logs.js';
 /* c8 ignore next */
@@ -39,7 +40,7 @@ export async function describe(
     indentation.hasDescribe = true;
 
     const { background, icon } = options || {};
-    const message = `${cb ? format.dim('◌') : icon || '☰'} ${format.bold(title) || ''}`;
+    const message = `${cb ? format.dim('◌') : icon || '☰'} ${cb ? format.dim(title) : format.bold(title) || ''}`;
     const noBackground = !background;
 
     if (noBackground) write(`${format.bold(message)}`);
@@ -53,15 +54,21 @@ export async function describe(
 
   if (typeof cb !== 'function') return;
 
+  const start = process.hrtime();
   const resultCb = cb();
 
   /* c8 ignore next */
   if (resultCb instanceof Promise) await resultCb;
+  const end = process.hrtime(start);
 
   /* c8 ignore start */
   if (title) {
+    const total = (end[0] * 1e3 + end[1] / 1e6).toFixed(6);
+
     indentation.hasDescribe = false;
-    write(`${format.bold(format.success('●'))} ${format.bold(title)}`);
+    write(
+      `${format.bold(format.success('●'))} ${format.bold(format.success(title))} ${format.dim(`› ${total}ms`)}`
+    );
   }
   /* c8 ignore stop */
 }

src/modules/exit.ts

@@ -6,13 +6,25 @@ import { results } from '../services/run-tests.js';
 import { format } from '../helpers/format.js';
 import type { Code } from '../@types/code.js';
 import { write } from '../helpers/logs.js';
+import { fileResults, finalResults } from '../configs/files.js';
+import { setTime, toSecs } from '../helpers/time.js';
 
 export const exit = (code: Code, quiet?: boolean) => {
   const isPoku = results.success > 0 || results.fail > 0;
 
   !quiet &&
     process.on('exit', (code) => {
       if (isPoku) {
+        hr();
+        write(
+          `    ${format.dim('Start at ›')} ${format.bold(format.dim(`${setTime(finalResults.started)}`))}`
+        );
+        write(
+          `    ${format.dim('Duration ›')} ${format.bold(format.dim(`${finalResults.time}ms`))} ${`${format.dim(`(±${toSecs(finalResults.time)} seconds)`)}`}`
+        );
+        write(
+          `  ${format.dim('Test Files ›')} ${format.bold(format.dim(`${fileResults.success.size + fileResults.fail.size}`))}`
+        );
         hr();
         write(
           format.bg(42, `PASS › ${results.success}`) +
@@ -23,7 +35,7 @@ export const exit = (code: Code, quiet?: boolean) => {
       }
 
       write(
-        `${format.dim('Exited with code')} ${format.bold(format?.[code === 0 ? 'success' : 'fail'](String(code)))}`
+        `${format.dim('Exited with code')} ${format.bold(format?.[code === 0 ? 'success' : 'fail'](String(code)))}\n`
       );
     });
 

src/modules/it.ts

@@ -1,3 +1,4 @@
+import process from 'node:process';
 /* c8 ignore next */
 import { each } from '../configs/each.js';
 /* c8 ignore next */
@@ -37,15 +38,17 @@ export async function it(
   if (message) {
     indentation.hasIt = true;
     write(
-      `${indentation.hasDescribe ? '  ' : ''}${format.dim('◌')} ${format.bold(format.italic(format.dim(message)))}`
+      `${indentation.hasDescribe ? '  ' : ''}${format.dim('◌')} ${format.dim(message)}`
     );
   }
   /* c8 ignore end */
 
+  const start = process.hrtime();
   const resultCb = cb();
 
   /* c8 ignore next */
   if (resultCb instanceof Promise) await resultCb;
+  const end = process.hrtime(start);
 
   if (typeof each.after.cb === 'function' && each.after.test) {
     const afterResult = each.after.cb();
@@ -55,9 +58,11 @@ export async function it(
 
   /* c8 ignore start */
   if (message) {
+    const total = (end[0] * 1e3 + end[1] / 1e6).toFixed(6);
+
     indentation.hasIt = false;
     write(
-      `${indentation.hasDescribe ? '  ' : ''}${format.bold(format.success('●'))} ${format.bold(format.italic(message))}`
+      `${indentation.hasDescribe ? '  ' : ''}${format.bold(format.success('●'))} ${format.bold(format.success(message))} ${format.dim(`› ${total}ms`)}`
     );
   }
   /* c8 ignore stop */

src/modules/poku.ts

@@ -4,20 +4,20 @@
  * Both CLI, API, noExit, sequential and parallel runs are strictly tested, but these tests use deep child process for it
  */
 
-import process, { stdout } from 'node:process';
+import process from 'node:process';
 import { EOL } from 'node:os';
 import { runTests, runTestsParallel } from '../services/run-tests.js';
 import { exit } from './exit.js';
 import { format } from '../helpers/format.js';
 import { isQuiet, write } from '../helpers/logs.js';
 import { hr } from '../helpers/hr.js';
-import { fileResults } from '../configs/files.js';
+import { fileResults, finalResults } from '../configs/files.js';
 import { indentation } from '../configs/indentation.js';
 import type { Code } from '../@types/code.js';
 import type { Configs } from '../@types/poku.js';
 
 process.once('SIGINT', () => {
-  stdout.write('\u001B[?25h');
+  process.stdout.write('\u001B[?25h');
 });
 
 export async function poku(
@@ -34,6 +34,9 @@ export async function poku(
 ): Promise<Code | void> {
   let code: Code = 0;
 
+  finalResults.started = new Date();
+
+  const start = process.hrtime();
   const prepareDirs = Array.prototype.concat(targetPaths);
   const dirs = prepareDirs.length > 0 ? prepareDirs : ['.'];
   const showLogs = !isQuiet(configs);
@@ -51,6 +54,11 @@ export async function poku(
 
     if (configs?.noExit) return code;
 
+    const end = process.hrtime(start);
+    const total = (end[0] * 1e3 + end[1] / 1e6).toFixed(6);
+
+    finalResults.time = total;
+
     exit(code, configs?.quiet);
     return;
   }
@@ -73,26 +81,37 @@ export async function poku(
     const concurrency = await Promise.all(promises);
 
     if (concurrency.some((result) => !result)) code = 1;
-  } catch {}
+  } catch {
+  } finally {
+    const end = process.hrtime(start);
+    const total = (end[0] * 1e3 + end[1] / 1e6).toFixed(6);
+
+    finalResults.time = total;
+  }
 
   showLogs && hr();
 
-  if (showLogs && fileResults.success.length > 0)
+  if (showLogs && fileResults.success.size > 0) {
     write(
-      fileResults.success
+      Array.from(fileResults.success)
         .map(
-          (current) =>
-            `${indentation.test}${format.success('✔')} ${format.dim(current)}`
+          ([file, time]) =>
+            `${indentation.test}${format.success('✔')} ${format.dim(`${file} › ${time}ms`)}`
         )
         .join(EOL)
     );
+  }
 
-  if (showLogs && fileResults.fail.length > 0)
+  if (showLogs && fileResults.fail.size > 0) {
     write(
-      fileResults.fail
-        .map((current) => `${indentation.test}${format.fail('✘')} ${current}`)
+      Array.from(fileResults.success)
+        .map(
+          ([file, time]) =>
+            `${indentation.test}${format.fail('✘')} ${format.dim(`${file} › ${time}ms`)}`
+        )
         .join(EOL)
     );
+  }
 
   if (configs?.noExit) return code;
 

src/modules/test.ts

@@ -1,3 +1,4 @@
+import process from 'node:process';
 /* c8 ignore next */
 import { each } from '../configs/each.js';
 /* c8 ignore next */
@@ -37,14 +38,16 @@ export async function test(
   if (message) {
     indentation.hasTest = true;
 
-    write(`${format.dim('◌')} ${format.bold(message)}`);
+    write(`${format.dim('◌')} ${format.dim(message)}`);
   }
   /* c8 ignore stop */
 
+  const start = process.hrtime();
   const resultCb = cb();
 
   /* c8 ignore next */
   if (resultCb instanceof Promise) await resultCb;
+  const end = process.hrtime(start);
 
   if (typeof each.after.cb === 'function' && each.after.test) {
     const afterResult = each.after.cb();
@@ -54,8 +57,12 @@ export async function test(
 
   /* c8 ignore start */
   if (message) {
+    const total = (end[0] * 1e3 + end[1] / 1e6).toFixed(6);
+
     indentation.hasTest = false;
-    write(`${format.bold(format.success('●'))} ${format.bold(message)}`);
+    write(
+      `${format.bold(format.success('●'))} ${format.bold(format.success(message))} ${format.dim(`› ${total}ms`)}`
+    );
   }
   /* c8 ignore stop */
 }

src/services/run-test-file.ts

@@ -46,6 +46,9 @@ export const runTestFile = (
         );
     }
 
+    const start = process.hrtime();
+    let end: ReturnType<typeof process.hrtime>;
+
     if (!(await beforeEach(fileRelative, configs))) return false;
 
     // Export spawn helper is not an option
@@ -64,6 +67,8 @@ export const runTestFile = (
     child.stderr.on('data', stdOut);
 
     child.on('close', async (code) => {
+      end = process.hrtime(start);
+
       const result = code === 0;
 
       if (showLogs)
@@ -75,16 +80,22 @@ export const runTestFile = (
 
       if (!(await afterEach(fileRelative, configs))) return false;
 
-      if (result) fileResults.success.push(fileRelative);
-      else fileResults.fail.push(fileRelative);
+      const total = (end[0] * 1e3 + end[1] / 1e6).toFixed(6);
+
+      if (result) fileResults.success.set(fileRelative, total);
+      else fileResults.fail.set(fileRelative, total);
 
       resolve(result);
     });
 
     /* c8 ignore start */
     child.on('error', (err) => {
+      end = process.hrtime(start);
+
+      const total = (end[0] * 1e3 + end[1] / 1e6).toFixed(6);
+
       console.error(`Failed to start test: ${filePath}`, err);
-      fileResults.fail.push(fileRelative);
+      fileResults.fail.set(fileRelative, total);
 
       resolve(false);
     });

src/services/run-tests.ts

@@ -50,13 +50,16 @@ export const runTests = async (
     const filePath = files[i];
     const fileRelative = relative(cwd, filePath);
 
+    const start = process.hrtime();
     const testPassed = await runTestFile(filePath, configs);
+    const end = process.hrtime(start);
+    const total = (end[0] * 1e3 + end[1] / 1e6).toFixed(6);
 
     const testNumber = i + 1;
     const counter = format.counter(testNumber, totalTests);
-    const command = `${runner(fileRelative, configs).join(' ')} ${fileRelative}`;
+    const command = `${runner(fileRelative, configs).join(' ')} ${fileRelative} ${format.dim(`› ${total}ms`)}`;
     const nextLine = i + 1 !== files.length ? EOL : '';
-    const log = `${counter}/${totalTests} ${command}`;
+    const log = `${counter}/${totalTests} ${command} `;
 
     if (testPassed) {
       ++results.success;

test/unit/deno/allow.test.ts

@@ -17,6 +17,7 @@ test(() => {
       '--allow-env',
       '--allow-run',
       '--allow-net',
+      '--allow-hrtime',
     ],
     'Default Permissions'
   );