diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml index 2e66162833..8cebbcead7 100644 --- a/.github/workflows/ci.yml +++ b/.github/workflows/ci.yml @@ -11,6 +11,10 @@ env: NODE_LATEST: 19.x PLATFORM: ubuntu-latest CI: true + # the LANG (used by the Intl API, which we use for some of the number + # formatting) is set in the run scripts. This works everywhere, except on + # windows. So, especially for windows ... + LANG: en_US.UTF-8 defaults: run: @@ -77,7 +81,7 @@ jobs: npm install npm run build - run: npm run depcruise - - run: npm test + - run: npx mocha check-berry-integration: runs-on: ubuntu-latest diff --git a/doc/cli.md b/doc/cli.md index 4d24793e8f..727fab1c9f 100644 --- a/doc/cli.md +++ b/doc/cli.md @@ -1078,28 +1078,32 @@ stay in view when dependency-cruiser is done. Typical output ``` - elapsed rss heapTotal heapUsed external after step... - 735ms 125Mb 84Mb 61Mb 2Mb start of node process - 10ms 125Mb 84Mb 62Mb 2Mb parsing options - 90ms 128Mb 85Mb 64Mb 2Mb cache: checking freshness - 202ms 145Mb 91Mb 70Mb 1Mb parsing rule set - 0ms 145Mb 91Mb 70Mb 1Mb determining how to resolve - 0ms 145Mb 91Mb 70Mb 1Mb reading files - 25ms 145Mb 91Mb 73Mb 1Mb reading files: gathering initial sources - 1190ms 194Mb 137Mb 110Mb 1Mb reading files: visiting dependencies - 0ms 194Mb 137Mb 110Mb 1Mb analyzing - 18ms 194Mb 137Mb 116Mb 1Mb analyzing: cycles - 37ms 197Mb 139Mb 119Mb 1Mb analyzing: dependents - 1ms 197Mb 139Mb 119Mb 1Mb analyzing: orphans - 257ms 198Mb 141Mb 122Mb 1Mb analyzing: reachables - 0ms 198Mb 141Mb 122Mb 1Mb analyzing: module metrics - 0ms 198Mb 141Mb 122Mb 1Mb analyzing: add focus (if any) - 87ms 199Mb 141Mb 117Mb 1Mb analyzing: validations - 10ms 200Mb 142Mb 121Mb 2Mb analyzing: comparing against known errors - 5ms 200Mb 142Mb 121Mb 2Mb reporting - 0ms 200Mb 142Mb 121Mb 2Mb really done (2670ms) + real user system ∆rss ∆heapTotal ∆heapUsed ∆external after step... +------------ ------------ ------------ ------------ ------------ ------------ ------------ ------------ + 832ms 835ms 101ms +118,396kB +84,364kB +59,833kB +2,231kB start of node process + 11ms 10ms 1ms +864kB +256kB +420kB 0kB parsing options + 91ms 22ms 11ms +2,656kB +544kB +1,808kB +583kB cache: checking freshness + 226ms 300ms 19ms +20,032kB +5,752kB +5,740kB -1,331kB parsing rule set + 1ms 0ms 0ms +4kB 0kB +28kB 0kB determining how to resolve + 1ms 1ms 0ms +4kB 0kB +12kB 0kB reading files + 31ms 27ms 8ms +60kB 0kB +2,470kB 0kB reading files: gathering initial sources + 1,317ms 1,862ms 106ms +50,076kB +47,616kB +43,172kB +301kB reading files: visiting dependencies + 0ms 0ms 0ms +4kB 0kB +6kB 0kB analyzing + 20ms 43ms 0ms +20kB 0kB +6,734kB 0kB analyzing: cycles + 32ms 40ms 2ms +3,148kB +3,328kB -11,278kB 0kB analyzing: dependents + 1ms 1ms 0ms +4kB 0kB +49kB 0kB analyzing: orphans + 225ms 275ms 3ms +1,396kB +1,024kB +12,862kB -29kB analyzing: reachables + 0ms 0ms 0ms 0kB 0kB +3kB 0kB analyzing: module metrics + 0ms 0ms 0ms 0kB 0kB +4kB 0kB analyzing: add focus (if any) + 97ms 166ms 3ms +484kB +256kB -3,706kB 0kB analyzing: validations + 11ms 9ms 1ms +1,696kB +1,084kB +2,446kB +542kB analyzing: comparing against known errors + 5ms 5ms 0ms +24kB 0kB +797kB 0kB reporting + 0ms 0ms 0ms +8kB 0kB +6kB 0kB really done (2,901ms) ``` +Number formatting takes place with the `Intl` API, so in your locale the numbers +and units might look slightly different. + #### none (the default when you don't pass --progress ) diff --git a/package.json b/package.json index c718c07e80..d0ef87f716 100644 --- a/package.json +++ b/package.json @@ -116,11 +116,11 @@ "scm:push:gitlab-mirror:commits": "git push gitlab-mirror", "scm:push:gitlab-mirror:tags": "git push --tags gitlab-mirror", "scm:stage": "git add .", - "test": "mocha", - "test:i": "mocha --grep \"^\\[[I]\\]\"", - "test:u": "mocha --grep \"^\\[[U]\\]\"", - "test:e": "mocha --grep \"^\\[[E]\\]\"", - "test:cover": "c8 --check-coverage --statements 99.9 --branches 99.7 --functions 100 --lines 99.9 --exclude \"{bin,configs/*.js,configs/rules,configs/plugins/3d-*.js,configs/plugins/stats-*.js,doc,docs,coverage,test,tools,webpack.conf.js,tmp*,src/**/*.template.js,src/cli/tools/svg-in-html-snippets/script.snippet.js,src/cli/init-config/get-user-input.js,src/cli/listeners/*/index.js}\" --reporter text-summary --reporter html --reporter json-summary mocha", + "test": "LANG=en_US.UTF-8 mocha", + "test:i": "LANG=en_US.UTF-8 mocha --grep \"^\\[[I]\\]\"", + "test:u": "LANG=en_US.UTF-8 mocha --grep \"^\\[[U]\\]\"", + "test:e": "LANG=en_US.UTF-8 mocha --grep \"^\\[[E]\\]\"", + "test:cover": "LANG=en_US.UTF-8 c8 --check-coverage --statements 99.9 --branches 99.7 --functions 100 --lines 99.9 --exclude \"{bin,configs/*.js,configs/rules,configs/plugins/3d-*.js,configs/plugins/stats-*.js,doc,docs,coverage,test,tools,webpack.conf.js,tmp*,src/**/*.template.js,src/cli/tools/svg-in-html-snippets/script.snippet.js,src/cli/init-config/get-user-input.js,src/cli/listeners/*/index.js}\" --reporter text-summary --reporter html --reporter json-summary mocha", "test:glob": "set -f && test \"`bin/dependency-cruise.js test/extract/__mocks__/gather-globbing/packages/**/src/**/*.js | grep \"no dependency violations found\"`\" = \"✔ no dependency violations found (6 modules, 0 dependencies cruised)\"", "test:yarn-pnp": "npm-run-all test:yarn-pnp:cleanup test:yarn-pnp:pack test:yarn-pnp:copy test:yarn-pnp:install test:yarn-pnp:version test:yarn-pnp:run test:yarn-pnp:test test:yarn-pnp:cleanup", "test:yarn-pnp:pack": "npm pack", diff --git a/src/cli/listeners/performance-log/format-helpers.js b/src/cli/listeners/performance-log/format-helpers.js index 20f0c35bc1..693c91c540 100644 --- a/src/cli/listeners/performance-log/format-helpers.js +++ b/src/cli/listeners/performance-log/format-helpers.js @@ -1,32 +1,85 @@ +const chalk = require("chalk"); + const MS_PER_SECOND = 1000; -const DECIMAL_BASE = 10; -const MAX_EXPECTED_LENGTH = 9; +const MS_PER_MICRO_SECOND = 0.001; +const MAX_LENGTH_EXPECTED = 12; +const NUMBER_OF_COLUMNS = 8; const K = 1024; +/* + * using `undefined` as the first parameter to Intl.NumberFormat so + * it will fall back to the 'current' locale. Another way to + * accomplish this is to use a non-existent language (e.g. `zz`) also works, + * but this seems to be the lesser of the two evil as `undefined` is closer + * to the intent of just skipping the optional parameter. + */ +// eslint-disable-next-line no-undefined +const LOCALE = undefined; + +const gTimeFormat = new Intl.NumberFormat(LOCALE, { + style: "unit", + unit: "millisecond", + unitDisplay: "narrow", + maximumFractionDigits: 0, +}).format; +const gSizeFormat = new Intl.NumberFormat(LOCALE, { + signDisplay: "exceptZero", + style: "unit", + unit: "kilobyte", + unitDisplay: "narrow", + maximumFractionDigits: 0, +}).format; + +const pad = (pString) => pString.padStart(MAX_LENGTH_EXPECTED); -function formatTime(pNumber) { - return Math.round(MS_PER_SECOND * pNumber) - .toString(DECIMAL_BASE) - .concat("ms") - .padStart(MAX_EXPECTED_LENGTH); +function formatHeader() { + return chalk + .bold( + `${pad("elapsed real")} ${pad("user")} ${pad("system")} ${pad( + "∆ rss" + )} ${pad("∆ heapTotal")} ${pad("∆ heapUsed")} ${pad( + "∆ external" + )} after step...\n` + ) + .concat( + `${`${"-".repeat(MAX_LENGTH_EXPECTED)} `.repeat(NUMBER_OF_COLUMNS)}\n` + ); +} + +function formatTime(pNumber, pConversionMultiplier = MS_PER_SECOND) { + return gTimeFormat(pConversionMultiplier * pNumber).padStart( + MAX_LENGTH_EXPECTED + ); } function formatMemory(pBytes) { - return Math.round(pBytes / K / K) - .toString(DECIMAL_BASE) - .concat("Mb") - .padStart(MAX_EXPECTED_LENGTH); + const lReturnValue = gSizeFormat(pBytes / K).padStart(MAX_LENGTH_EXPECTED); + + return pBytes < 0 ? chalk.blue(lReturnValue) : lReturnValue; } -function formatPerfLine(pTime, pPreviousTime, pMessage) { - return `${formatTime(pTime - pPreviousTime)} ${formatMemory( - process.memoryUsage().rss - )} ${formatMemory(process.memoryUsage().heapTotal)} ${formatMemory( - process.memoryUsage().heapUsed - )} ${formatMemory(process.memoryUsage().external)} ${pMessage}\n`; +function formatPerfLine({ + elapsedTime, + elapsedUser, + elapsedSystem, + deltaRss, + deltaHeapUsed, + deltaHeapTotal, + deltaExternal, + message, +}) { + return `${formatTime(elapsedTime)} ${formatTime( + elapsedUser, + MS_PER_MICRO_SECOND + )} ${formatTime(elapsedSystem, MS_PER_MICRO_SECOND)} ${formatMemory( + deltaRss + )} ${formatMemory(deltaHeapTotal)} ${formatMemory( + deltaHeapUsed + )} ${formatMemory(deltaExternal)} ${message}\n`; } module.exports = { formatTime, formatMemory, formatPerfLine, + formatHeader, }; diff --git a/src/cli/listeners/performance-log/handlers.js b/src/cli/listeners/performance-log/handlers.js index c981fc4bf3..f6dd4d78f1 100644 --- a/src/cli/listeners/performance-log/handlers.js +++ b/src/cli/listeners/performance-log/handlers.js @@ -1,11 +1,13 @@ -const chalk = require("chalk"); -const { formatTime, formatPerfLine } = require("./format-helpers"); +const { + formatTime, + formatPerfLine, + formatHeader, + formatMemory, +} = require("./format-helpers"); function getHeader(pLevel, pMaxLevel) { if (pLevel <= pMaxLevel) { - return chalk.bold( - " elapsed rss heapTotal heapUsed external after step...\n" - ); + return formatHeader(); } return ""; } @@ -15,14 +17,29 @@ function getProgressLine(pMessage, pState, pLevel, pMaxLevel) { if (pLevel <= pMaxLevel) { const lTime = process.uptime(); + const { user, system } = process.cpuUsage(); + const { rss, heapTotal, heapUsed, external } = process.memoryUsage(); + const lStats = { + elapsedTime: lTime - pState.previousTime, + elapsedUser: user - pState.previousUserUsage, + elapsedSystem: system - pState.previousSystemUsage, + deltaRss: rss - pState.previousRss, + deltaHeapUsed: heapUsed - pState.previousHeapUsed, + deltaHeapTotal: heapTotal - pState.previousHeapTotal, + deltaExternal: external - pState.previousExternal, + message: pState.previousMessage, + }; - lReturnValue = formatPerfLine( - lTime, - pState.previousTime, - pState.previousMessage - ); pState.previousMessage = pMessage; pState.previousTime = lTime; + pState.previousUserUsage = user; + pState.previousSystemUsage = system; + pState.previousRss = rss; + pState.previousHeapTotal = heapTotal; + pState.previousHeapUsed = heapUsed; + pState.previousExternal = external; + + lReturnValue = formatPerfLine(lStats); } return lReturnValue; } @@ -30,12 +47,11 @@ function getProgressLine(pMessage, pState, pLevel, pMaxLevel) { function getEndText(pState, pLevel, pMaxLevel) { if (pLevel <= pMaxLevel) { const lTime = process.uptime(); - - return formatPerfLine( - lTime, - pState.previousTime, - `really done (${formatTime(lTime).trim()})` - ); + const { heapUsed } = process.memoryUsage(); + pState.previousMessage = `really done (${formatTime( + lTime + ).trim()}, ${formatMemory(heapUsed).trim()})`; + return getProgressLine("", pState, pLevel, pMaxLevel); } return ""; } diff --git a/src/cli/listeners/performance-log/index.js b/src/cli/listeners/performance-log/index.js index 168380f190..798c621d7a 100644 --- a/src/cli/listeners/performance-log/index.js +++ b/src/cli/listeners/performance-log/index.js @@ -32,6 +32,12 @@ module.exports = function setUpPerformanceLogListener( let lState = { previousMessage: "start of node process", previousTime: 0, + previousUserUsage: 0, + previousSystemUsage: 0, + previousRss: 0, + previousHeapTotal: 0, + previousHeapUsed: 0, + previousExternal: 0, }; pEventEmitter.on("start", getHeaderWriter(pStream, pMaxLevel)); diff --git a/src/main/report-wrap.js b/src/main/report-wrap.js index 88f9208009..78f0c07164 100644 --- a/src/main/report-wrap.js +++ b/src/main/report-wrap.js @@ -9,9 +9,9 @@ const report = require("../report"); /** * - * @param {import('../../types/dependency-cruiser').ICruiseResult} pResult - * @param {import('../../types/dependency-cruiser').IFormatOptions} pFormatOptions - * @returns {import('../../types/dependency-cruiser').ICruiseResult} + * @param {import('../..').ICruiseResult} pResult + * @param {import('../..').IFormatOptions} pFormatOptions + * @returns {import('../..').ICruiseResult} */ function reSummarizeResults(pResult, pFormatOptions) { let lModules = filterBank.applyFilters(pResult.modules, pFormatOptions); @@ -41,9 +41,9 @@ function reSummarizeResults(pResult, pFormatOptions) { } /** * - * @param {import("../../types/dependency-cruiser").ICruiseResult} pResult result of a previous run of dependency-cruiser - * @param {import("../../types/dependency-cruiser").IFormatOptions} pFormatOptions - * @returns {import("../../types/dependency-cruiser").IReporterOutput} + * @param {import("../..).ICruiseResult} pResult result of a previous run of dependency-cruiser + * @param {import("../..").IFormatOptions} pFormatOptions + * @returns {import("../..").IReporterOutput} */ module.exports = function reportWrap(pResult, pFormatOptions) { const lReportFunction = report.getReporter(pFormatOptions.outputType); diff --git a/test/cli/listeners/performance-log-listener/format-helpers.spec.mjs b/test/cli/listeners/performance-log-listener/format-helpers.spec.mjs index 707242e61a..9eee00a7ee 100644 --- a/test/cli/listeners/performance-log-listener/format-helpers.spec.mjs +++ b/test/cli/listeners/performance-log-listener/format-helpers.spec.mjs @@ -1,65 +1,99 @@ /* eslint-disable no-magic-numbers */ import { expect } from "chai"; +import chalk from "chalk"; import formatHelpers from "../../../../src/cli/listeners/performance-log/format-helpers.js"; +/* + * as the formatHelpers use the Intl API, it's necessary to set the locale + * to something uniform so we can actually work with expectations. + * + * The expected values are for now based on the en-US locale - as it's likely + * to be available on most systems. To ensure the formatHelpers are also on + * that set the LANG environment variable to en_US.UTF-8. E.g. to run these + * tests: + * + * LANG=en_US.UTF-8 mocha + * + * (the run-scripts in dependency-cruiser's package.json have all been adjusted + * thusly) + */ + describe("[U] cli/listeners/performance-log/format-helpers - formatTime", () => { - it("converts to ms, leftpads & adds the unit at the end", () => { - expect(formatHelpers.formatTime(14.88041018)).to.equal(" 14880ms"); + it("converts to ms, left pads & adds the unit at the end", () => { + expect(formatHelpers.formatTime(14.88041018)).to.equal(" 14,880ms"); }); - it("converts to ms, leftpads & adds the unit at the end (0)", () => { - expect(formatHelpers.formatTime(0)).to.equal(" 0ms"); + it("converts to ms, left pads & adds the unit at the end (0)", () => { + expect(formatHelpers.formatTime(0)).to.equal(" 0ms"); }); - it("converts to ms, leftpads & adds the unit at the end (negative numbers)", () => { - expect(formatHelpers.formatTime(-3.1415926535)).to.equal(" -3142ms"); + it("converts to ms, left pads & adds the unit at the end (negative numbers)", () => { + expect(formatHelpers.formatTime(-3.1415926535)).to.equal(" -3,142ms"); }); - it("converts to ms, leftpads & adds the unit at the end (null treatment => 0)", () => { - expect(formatHelpers.formatTime(null)).to.equal(" 0ms"); + it("converts to ms, left pads & adds the unit at the end (null treatment => 0)", () => { + expect(formatHelpers.formatTime(null)).to.equal(" 0ms"); }); - it("converts to ms, leftpads & adds the unit at the end (undefined treatment => NaN)", () => { - expect(formatHelpers.formatTime()).to.equal(" NaNms"); + it("converts to ms, left pads & adds the unit at the end (undefined treatment => NaN)", () => { + expect(formatHelpers.formatTime()).to.equal(" NaNms"); }); - it("converts to ms, leftpads & adds the unit at the end (non-number treatment => NaN)", () => { - expect(formatHelpers.formatTime("not a number")).to.equal(" NaNms"); + it("converts to ms, left pads & adds the unit at the end (non-number treatment => NaN)", () => { + expect(formatHelpers.formatTime("not a number")).to.equal(" NaNms"); }); }); describe("[U] cli/listeners/performance-log/format-helpers - formatMemory", () => { - it("converts to Mb, leftpads & adds the unit at the end", () => { - expect(formatHelpers.formatMemory(4033856)).to.equal(" 4Mb"); + let lChalkLevel = chalk.level; + + before("disable chalk coloring", () => { + chalk.level = 0; + }); + + after("enable chalk coloring again", () => { + chalk.level = lChalkLevel; + }); + + it("converts to kB, left pads & adds the unit at the end", () => { + expect(formatHelpers.formatMemory(4033856)).to.equal(" +3,939kB"); }); - it("converts to Mb, leftpads & adds the unit at the end (0)", () => { - expect(formatHelpers.formatMemory(0)).to.equal(" 0Mb"); + it("converts to kB, left pads & adds the unit at the end (0)", () => { + expect(formatHelpers.formatMemory(0)).to.equal(" 0kB"); }); - it("converts to Mb, leftpads & adds the unit at the end (negative numbers)", () => { - expect(formatHelpers.formatMemory(-403385623)).to.equal(" -385Mb"); + it("converts to kB, left pads & adds the unit at the end (negative numbers)", () => { + expect(formatHelpers.formatMemory(-403385623)).to.equal(" -393,931kB"); }); - it("converts to Mb, leftpads & adds the unit at the end (null)", () => { - expect(formatHelpers.formatMemory(0)).to.equal(" 0Mb"); + it("converts to kB, left pads & adds the unit at the end (null)", () => { + expect(formatHelpers.formatMemory(0)).to.equal(" 0kB"); }); - it("converts to Mb, leftpads & adds the unit at the end (undefined)", () => { - expect(formatHelpers.formatMemory()).to.equal(" NaNMb"); + it("converts to kB, left pads & adds the unit at the end (undefined)", () => { + expect(formatHelpers.formatMemory()).to.equal(" NaNkB"); }); - it("converts to Mb, leftpads & adds the unit at the end (not a number)", () => { - expect(formatHelpers.formatMemory("not a number")).to.equal(" NaNMb"); + it("converts to kB, left pads & adds the unit at the end (not a number)", () => { + expect(formatHelpers.formatMemory("not a number")).to.equal(" NaNkB"); }); }); -describe("[U] cli/ears/performance-log-listener/format-helpers - formatPerfLine", () => { - it("produces neat columns with time, memmory and a message", () => { - expect( - formatHelpers.formatPerfLine(14.88041018, 7.245436738, "sim sala bim") - ).to.match( - / {3}7635ms {0,}\d+Mb {0,}\d+Mb {0,}\d+Mb {0,}\d+Mb sim sala bim\n/ +describe("[U] cli/listeners/performance-log/format-helpers - formatPerfLine", () => { + it("produces neat columns with time, memory and a message", () => { + const lStats = { + elapsedTime: 7.634973442, + elapsedUser: 16497, + elapsedSystem: 3518, + deltaRss: 3219456, + deltaHeapUsed: 2857936, + deltaHeapTotal: 2478080, + deltaExternal: 0, + message: "sim sala bim", + }; + expect(formatHelpers.formatPerfLine(lStats, "sim sala bim")).to.match( + / {0,}7,635ms {0,}16ms {0,}4ms {0,}\+3,144kB {0,}\+2,420kB {0,}\+2,791kB {0,}0kB sim sala bim\n/ ); }); }); diff --git a/test/cli/listeners/performance-log-listener/handlers.spec.mjs b/test/cli/listeners/performance-log-listener/handlers.spec.mjs index 0bca95b4f1..c37bc49c14 100644 --- a/test/cli/listeners/performance-log-listener/handlers.spec.mjs +++ b/test/cli/listeners/performance-log-listener/handlers.spec.mjs @@ -58,6 +58,7 @@ describe("[U] cli/listeners/performance-log/handlers - getProgressLine", () => { describe("[U] cli/listeners/performance-log/handlers - getEndText", () => { const lStateMock = { previousTime: process.uptime() - 10, + previousHeapUsed: process.memoryUsage().heapUsed - 1000, }; it("when the level is > the max => empty string", () => { expect(handlers.getEndText(lStateMock, 30, MAX_LEVEL)).to.equal(""); @@ -71,7 +72,7 @@ describe("[U] cli/listeners/performance-log/handlers - getEndText", () => { it("message contains an end time", () => { expect(handlers.getEndText(lStateMock, 10, MAX_LEVEL)).to.match( - /really done \([0-9]+ms\)\n$/g + /really done \([0-9,]+ms, [+-]?[0-9,]+kB\)\n$/g ); }); });