Repository navigation
Optimise the execution time of PK CLI calls by not importing the entire kitchen sink #277
Description
Activity
Using this:
var Module = require('module'); var __require = Module.prototype.require Module.prototype.require = function(id) { var ts = process.hrtime(); var res = __require.call(this, id); var t = process.hrtime(ts); var ms = t[0]*1000 + t[1]/1e6; if (ms > 50) { console.log( 'require(\'%s\') took %s ms', id, t[0]*1000 + t[1]/1e6 ); } return res; }
Put it on top of
dist/bin/polykey.js.We get:
[nix-shell:~/Projects/js-polykey]$ node ./dist/bin/polykey.js require('./DB') took 57.355835 ms require('@matrixai/db') took 59.07066 ms require('./errors') took 64.479503 ms require('../utils') took 64.981089 ms require('./utils') took 86.4166 ms require('./KeyManager') took 89.211753 ms require('../keys') took 89.716294 ms require('../sessions/utils') took 115.260817 ms require('./schema') took 84.366824 ms require('./utils') took 87.846608 ms require('./NotificationsManager') took 89.077439 ms require('../notifications') took 89.602299 ms require('./agentService') took 128.237073 ms require('../agent') took 139.359442 ms require('./VaultManager') took 192.128305 ms require('./') took 193.287051 ms require('../vaults/utils') took 205.662504 ms require('../client/utils') took 321.583236 ms require('./CARL') took 368.436571 ms require('./utils') took 386.524559 ms hiFirstly... why is
pk -heven loading DB? That's because obviously of too many mutually recursive imports.Interesting that the
DBtakes57ms.Inspecting it tells us that the combination of
threadsandlevelandsubleveldownends up being about 60ms. So that does make sense. But these are unavoidable.We will need to add this to our benchmarks so we can track this over time.
One problem with the above hack is that we cannot see the full path of the module. Since the
idcan be a relative path. And getting__dirnameis not enough because we want to know the dirname of the caller, whereas using it there will just get the directory name of the top level script. Asked about this in the SO question.The
@grpc/grpc-jsalso takes about 30ms.So if all together the
@matrixai/dband the GRPC will at least take 100ms by themselves.It seems the problem can be resolved if we ensure that the
src/bincommands are not loading the entire kitchen sink when we are executing the commands.Alternatively during the packaging, it will be required to run a tree-shaking minifier to ensure that the CLI scripts aren't loading useless things. There are some options:
- changed the title
[-]Optimise the execution time of PK CLI calls such as `pk --help`[/-][+]Optimise the execution time of PK CLI calls by not importing the entire kitchen sink[/+]on Oct 28, 2021 We can try using dynamic imports. That way, things only imported when the action handler is called. https://javascript.info/modules-dynamic-imports.
@tegefaulkes mentioned that commander has another way of constructing all the commands.
We also need to make our
utilsimports leaner. And then monitor our imports using the hack above to ensure we aren't importing the entire application when we are executing a simple help command.Compare this to other compiled program executions like
step --helpwhich is compiled in Golang and taking only 20ms to show the help page.Our baseline is the node runtime, which takes about 32ms to run a
console.log('hello world');script.Note that MatrixAI/TypeScript-Demo-Lib#32 is about using dynamic imports along with other advanced features in order do feature-tests and importing different implementations based on different platforms. However dynamic imports is already available now, so we start to make use of it in our
src/bin/scripts.Commander has stand alone executable for sub commands. https://www.npmjs.com/package/commander#stand-alone-executable-subcommands
However this means we would need multiple executable files for the final program. I'm not sure how well that will work with pkg either.- The standalone commands might work with the scripts option in pkg. But even import expressions may need pkg configuration if they have variable inputs. Best to try it out on TS demo lib.On 29 October 2021 12:34:09 pm AEDT, Brian Botha ***@***.***> wrote: Commander has stand alone executable for sub commands. https://www.npmjs.com/package/commander#stand-alone-executable-subcommands However this means we would need multiple executable files for the final program. I'm not sure how well that will work with pkg either. -- You are receiving this because you authored the thread. Reply to this email directly or view it on GitHub: #277 (comment)-- Sent from my Android device with K-9 Mail. Please excuse my brevity.
It turns out
require.resolve(localPath)can be used to know what the real path of the required ids are. Should add this into our benchmarking system to track? Maybe as well as jest test coverage. Like how this is done here: https://docs.gitlab.com/ee/ci/unit_test_reports.html#jest and https://docs.gitlab.com/ee/ci/metrics_reports.htmlImportant to ensure that all utilities imported statically aren't importing everything in the application. Watch out for
bin/utils.tsand what it is importing. This is something we need to check and maybe a linting rules can be done on importing calls.Benchmarks on bin code can watch out for performance regressions!
With the merging of https://gitlab.com/MatrixAI/Engineering/Polykey/js-polykey/-/merge_requests/213. All commands are using dynamic imports. We should measure the execution speed of the bin CLI calls again.
With the addition of the typescript compiler cache, execution times for the pk CLI is approaching acceptable speeds now.
Will close this issue for now until we get some problems. Overall benchmarks can be done in a later PR that takes into account the entire application.
- added a parent issue
on Oct 23, 2025
Specification
From reviewing https://gitlab.com/MatrixAI/Engineering/Polykey/js-polykey/-/merge_requests/213 I discovered that it was taking 9 seconds to run the
npm run polykey -- -h. This was optimised to a bit above 6 seconds when using--transpile-only.However then I wanted to know what happens when the code is fully compiled. After running
npm run buildandnode ./dist/bin/polykey -hit still showed about0.55sfor real time.Now taking about half a second to show the help page is bad UX. It also potentially indicates that our application is slow for some reason.
Playing around with disabling the require/imports in the compiled js
distand also using the0xflamegraph seems to indicate that any of the imports going into Polykey results in almost importing the entire application and this contributes to about 400ms of execution time. Our import graph is quite loopy right now to due mutually recursive imports in PK. Usually this would not be a problem in a compiled language where all the code was ultimately in the same executable image. However here, we should look into optimising this so that we can have a cleaner and leaner code. I'm curious what the perf will be once we package it invercel/pkg.However this doesn't tell us whether it's just due to importing so many files that gradually builds up to 400ms or is there something going in one or two or more particular files that is causing the slowdown.
Tracing the
requirewill tell us this. This https://stackoverflow.com/questions/20671222/how-can-i-log-all-requires-in-node-js tells us how to monkey patch therequirecall and can give us a log of all the code being required and how long they are taking to do so.Additional context
0x dist/bin/polykey.js -h:Tasks
ts-nodeto use--transpile-onlyoption for thepolykeycommand but not thets-nodecommand fornpm.src/errors.tswhich imports all other errors. But errors should be not be importing any utilities and so they should be a self-contained mutual recursion.0.035s, which is about 34ms. So I reckon showing the help page should only take about 100ms, instead of the current 550ms.