Skip to content

Commit

Permalink
feature(progress): re-vamps the performance log for ease of use
Browse files Browse the repository at this point in the history
  • Loading branch information
sverweij committed Dec 21, 2022
1 parent f3af5df commit a698328
Show file tree
Hide file tree
Showing 9 changed files with 214 additions and 96 deletions.
6 changes: 5 additions & 1 deletion .github/workflows/ci.yml
Expand Up @@ -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:
Expand Down Expand Up @@ -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
Expand Down
44 changes: 24 additions & 20 deletions doc/cli.md
Expand Up @@ -1078,28 +1078,32 @@ stay in view when dependency-cruiser is done.
<summary>Typical output</summary>

```
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.

</details>

#### none (the default when you don't pass --progress )
Expand Down
10 changes: 5 additions & 5 deletions package.json
Expand Up @@ -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",
Expand Down
87 changes: 70 additions & 17 deletions 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,
};
48 changes: 32 additions & 16 deletions 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 "";
}
Expand All @@ -15,27 +17,41 @@ 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;
}

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 "";
}
Expand Down
6 changes: 6 additions & 0 deletions src/cli/listeners/performance-log/index.js
Expand Up @@ -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));
Expand Down
12 changes: 6 additions & 6 deletions src/main/report-wrap.js
Expand Up @@ -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);
Expand Down Expand Up @@ -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);
Expand Down

0 comments on commit a698328

Please sign in to comment.