diff --git a/src/commands/assemble.js b/src/commands/assemble.js index 216f34d..c64c91d 100644 --- a/src/commands/assemble.js +++ b/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; + }); }); }; diff --git a/src/commands/java/compile.js b/src/commands/java/compile.js index aba2816..def550a 100644 --- a/src/commands/java/compile.js +++ b/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; diff --git a/src/elapsed.js b/src/elapsed.js new file mode 100644 index 0000000..dd9e58e --- /dev/null +++ b/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; + } + }); +}; diff --git a/test/test_elapsed.js b/test/test_elapsed.js new file mode 100644 index 0000000..32834ae --- /dev/null +++ b/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; + } + ); + }); +});