Optimise the execution time of PK CLI calls by not importing the entire kitchen sink

[CMCDragonkai]

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 build and node ./dist/bin/polykey -h it still showed about 0.55s for real time.

[nix-shell:~/Projects/js-polykey]$ time node ./dist/bin/polykey.js -h
Usage: polykey [options] [command]

Options:
  -V, --version        output the version number
  -h, --help           display help for command

Commands:
  bootstrap [options]  Initializes a polykey node
  agent                manipulate agent
  vaults               manipulate vaults
  secrets              manipulate secrets for a given vault
  keys                 manipulate keys
  node                 nodes commands
  identities           identities commands
  notifications        notifications commands
  echoes               echo things
  help [command]       display help for command

real	0m0.550s
user	0m0.613s
sys	0m0.044s

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 dist and also using the 0x flamegraph 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 in vercel/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 require will tell us this. This https://stackoverflow.com/questions/20671222/how-can-i-log-all-requires-in-node-js tells us how to monkey patch the require call and can give us a log of all the code being required and how long they are taking to do so.

Additional context

• https://gitlab.com/MatrixAI/Engineering/Polykey/js-polykey/-/merge_requests/213#note_716673667 - thread discussing this discovery of slow execution time
• flame graph 0x dist/bin/polykey.js -h:
  

Tasks

1. - Upgrade ts-node to use --transpile-only option for the polykey command but not the ts-node command for npm.
2. - Use 0x to check the flamegraph to see if there's slow execution.
3. - Create a simple utility to trace require and also to show us the most expensive requires which translates to expensive imports
4. - Look into cleaning up our require/import graph to be less recursive, this can be complicated by the src/errors.ts which imports all other errors. But errors should be not be importing any utilities and so they should be a self-contained mutual recursion.
5. - Optimise the execution time. The benchmark for a hello world script is 0.035s, which is about 34ms. So I reckon showing the help page should only take about 100ms, instead of the current 550ms.
6. - Add CLI script execution time to the benchmarks in order to monitor for regressions

[CMCDragonkai]

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
hi

Firstly... why is pk -h even loading DB? That's because obviously of too many mutually recursive imports.

Interesting that the DB takes 57 ms.

Inspecting it tells us that the combination of threads and level and subleveldown ends up being about 60ms. So that does make sense. But these are unavoidable.

[CMCDragonkai]

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 id can be a relative path. And getting __dirname is 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.

[CMCDragonkai]

The @grpc/grpc-js also takes about 30ms.

So if all together the @matrixai/db and the GRPC will at least take 100ms by themselves.

It seems the problem can be resolved if we ensure that the src/bin commands 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:

• https://github.com/vercel/nft
• https://github.com/vercel/ncc
• https://github.com/vercel/pkg

[CMCDragonkai]

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 utils imports 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 --help which 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.

[tegefaulkes]

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.

[CMCDragonkai]

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.

[CMCDragonkai]

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

[CMCDragonkai]

Important to ensure that all utilities imported statically aren't importing everything in the application. Watch out for bin/utils.ts and 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!

[CMCDragonkai]

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.

[CMCDragonkai]

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.