Merge pull request #389 from trapvpack/368

fix(#368): added utility function for elapsed time tracking

src/commands/assemble.js

@@ -25,6 +25,7 @@
 const rel = require('relative');
 const path = require('path');
 const {mvnw, flags} = require('../mvnw');
+const {elapsed} = require('../elapsed');
 
 /**
  * Command to assemble .XMIR files.
@@ -33,8 +34,10 @@ const {mvnw, flags} = require('../mvnw');
  */
 module.exports = function(opts) {
   const target = path.resolve(opts.target);
-  return mvnw(['eo:assemble'].concat(flags(opts)), opts.target, opts.batch).then((r) => {
-    console.info('EO program assembled in %s', rel(target));
-    return r;
+  return elapsed((tracked) => {
+    return mvnw(['eo:assemble'].concat(flags(opts)), opts.target, opts.batch).then((r) => {
+      tracked.print('EO program assembled in %s', rel(target));
+      return r;
+    });
   });
 };

src/commands/java/compile.js

@@ -33,6 +33,10 @@ const path = require('path');
  */
 module.exports = function(opts) {
   const target = path.resolve(opts.target);
+  /**
+   * @todo #368:30min Wrap logs in 'elapsed'
+   *  It is necessary to use 'elapsed' in all logging cases that require output of elapsed time
+   */
   return mvnw(['compiler:compile'].concat(flags(opts)), opts.target, opts.batch).then((r) => {
     console.info('Java .class files compiled into %s', rel(target));
     return r;

src/elapsed.js

@@ -0,0 +1,60 @@
+/*
+ * The MIT License (MIT)
+ *
+ * Copyright (c) 2022-2024 Objectionary.com
+ *
+ * Permission is hereby granted, free of charge, to any person obtaining a copy
+ * of this software and associated documentation files (the "Software"), to deal
+ * in the Software without restriction, including without limitation the rights
+ * to use, copy, modify, merge, publish, distribute, sublicense, and/or sell
+ * copies of the Software, and to permit persons to whom the Software is
+ * furnished to do so, subject to the following conditions:
+ *
+ * The above copyright notice and this permission notice shall be included
+ * in all copies or substantial portions of the Software.
+ *
+ * THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR
+ * IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY,
+ * FITNESS FOR A PARTICULAR PURPOSE AND NON-INFRINGEMENT. IN NO EVENT SHALL THE
+ * AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER
+ * LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM,
+ * OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN THE
+ * SOFTWARE.
+ */
+
+/**
+ * A utility function to measure the elapsed time of a task and provide
+ * detailed timing information.
+ *
+ * This function wraps a given task (callback function) and provides it with
+ * a `tracked` object that includes a `print` method. The `print` method can
+ * be used within the task to log messages along with the elapsed time
+ * since the task started execution. The elapsed time is formatted in milliseconds,
+ * seconds, or minutes, based on the duration.
+ *
+ * @param {Function} task - A callback function to be measured. The function
+ *                          is invoked with a `tracked` object as an argument.
+ * @return {*} Result of the wrapped callback function. The result of the
+ *             `task` callback will be returned unchanged.
+ * @todo #368:30min Decide if the `elapsed` utility function is in the right place,
+ *  consider relocating it and its test file if needed
+ */
+module.exports.elapsed = function elapsed(task) {
+  const startTime = Date.now();
+  return task({
+    print: (message) => {
+      const duration = Date.now() - startTime;
+      let extended;
+      if (duration < 1000) {
+        extended = `${duration}ms`;
+      } else if (duration < 60 * 1000) {
+        extended = `${Math.ceil(duration / 1000)}s`;
+      } else {
+        extended = `${Math.ceil(duration / 3600000)}min`;
+      }
+      const msg = `${message} in ${extended}`;
+      console.info(msg);
+      return msg;
+    }
+  });
+};

test/test_elapsed.js

@@ -0,0 +1,76 @@
+/*
+ * The MIT License (MIT)
+ *
+ * Copyright (c) 2022-2024 Objectionary.com
+ *
+ * Permission is hereby granted, free of charge, to any person obtaining a copy
+ * of this software and associated documentation files (the "Software"), to deal
+ * in the Software without restriction, including without limitation the rights
+ * to use, copy, modify, merge, publish, distribute, sublicense, and/or sell
+ * copies of the Software, and to permit persons to whom the Software is
+ * furnished to do so, subject to the following conditions:
+ *
+ * The above copyright notice and this permission notice shall be included
+ * in all copies or substantial portions of the Software.
+ *
+ * THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR
+ * IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY,
+ * FITNESS FOR A PARTICULAR PURPOSE AND NON-INFRINGEMENT. IN NO EVENT SHALL THE
+ * AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER
+ * LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM,
+ * OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN THE
+ * SOFTWARE.
+ */
+
+const {elapsed} = require('../src/elapsed');
+const assert = require('assert');
+
+describe('elapsed', function() {
+  const snooze = (ms) => new Promise((resolve) => setTimeout(resolve, ms));
+  it('measures time correctly', async () => {
+    return elapsed(async (tracked) => {
+      await snooze(300);
+      return tracked.print('task');
+    }).then(
+      (actual) => assert(
+        /task in 3\d+ms/.test(actual),
+        `Expected "${actual}" to match /task in 3\\d+ms/`
+      )
+    );
+  });
+  it('measures short time correctly', async () => {
+    return elapsed(async (tracked) => {
+      await snooze(10);
+      return tracked.print('short task');
+    }).then(
+      (actual) => assert(
+        /short task in 1\d+ms/.test(actual),
+        `Expected "${actual}" to match /short task in 1\\d+ms/`
+      )
+    );
+  });
+  it('measures long time correctly', async () => {
+    return elapsed(async (tracked) => {
+      await snooze(1200);
+      return tracked.print('long task');
+    }).then(
+      (actual) => assert(
+        /long task in 2s/.test(actual),
+        `Expected "${actual}" to match /long task in 2s/`
+      )
+    );
+  });
+  it('handles errors in task correctly', async () => {
+    await assert.rejects(
+      elapsed(async () => {
+        throw new Error('task error');
+      }),
+      (error) => {
+        assert.throws(() => {
+          throw error;
+        }, /task error/);
+        return true;
+      }
+    );
+  });
+});