CLI commands are slow to start

[tegefaulkes]

Specification

There seems to be a lead time before running Polykey does anything. this is demonstrated by running polykey --help to get the help text. This alone takes about 0.5 seconds on my work laptop.

[nix-shell:~/workspace/Polykey-CLI]$ time node dist/polykey --help
Usage: polykey [options] [command]

Polykey CLI

<Help text helpfully redacted to save space in issue>

real    0m0.493s
user    0m0.465s
sys     0m0.078s

Compare this to polykey bootstrap command which does some password hashing and state creation.

[nix-shell:~/workspace/Polykey-CLI]$ time node dist/polykey bootstrap -pf tmp/pass -np tmp/asd2
<recovery code redacted>

real    0m1.854s
user    0m1.613s
sys     0m0.344s

So a good 500ms is spent doing something before anything really runs. We can start by checking that we're importing all of polykey before running any command. After that the likely culprit is commander.

Additional context

Related: #40

Tasks

1. Check that we don't blindly import all of Polykey during the import stage of the code. Large parts of Polykey should only be imported when the command is run, no when it is defined.
2. Look into Commander to see if that could be the source of the slow startup time.
3. Fix anything causing the slow startup time when running Polykey-CLI.

[tegefaulkes]

It's also possible that pkg is doing a bunch of setup each time the command is run. So We'll need to isolate where most of the time is spent.

[tegefaulkes]

There are two parts to this one.

1. Identify the source of the slow command usage. This includes working out a breakdown of where the time is spent. We can do this with profiling but I'll start with some simple AB testing to identify which part is taking up the most time. There are 2 main suspects, PKG unpacking before running and commander doing runtime setup that takes a while.
2. After identifying what stage is the problem we need to find a way to optimise the time taken during that stage.

To do the simple AB testing we need to Obtain the following data points.

1. Full time running the help command on the packaged executable.
2. Full time running the help command with just the bundled code.
3. Console.time() certain points in the program to gauge time taken for each step.

From that we can infer the time taken for pkg, commander, and parts of the code.

From there we can get a more detailed point of view by attaching a debugger to the code and running profiling on it. The profiling with be node specific so we can't get a picture of what the pkg stage is doing with this.

[tegefaulkes]

Running the built linux executable using time stream-run ./result gives us 0.913s.

❯ time steam-run ./result 
Usage: polykey [options] [command]

Polykey CLI

Options:
  -np, --node-path <path>      Path to Node State (default: "/home/brian/.local/share/polykey", env: PK_NODE_PATH)
  -pf, --password-file <path>  Path to Password
  -f, --format <format>        Output Format (choices: "human", "json", default: "human")
  -v, --verbose                Log Verbose Messages (default: 0)
  -V, --version                output the version number
  -h, --help                   display help for command

Commands:
  bootstrap [options]          Bootstrap Keynode State
  agent [options]              Agent Operations
  nodes [options]              Nodes Operations
  secrets [options]            Secrets Operations
  keys [options]               Keys Operations
  vaults [options]             Vaults Operations
  identities [options]         Identities Operations
  notifications [options]      Notifications Operations
  help [command]               display help for command

real    0m0.913s
user    0m0.821s
sys     0m0.244s

Running the bundled code gives us 0.271s.

❯ time node ./dist/polykey.js
Usage: polykey [options] [command]

Polykey CLI

Options:
  -np, --node-path <path>      Path to Node State (default: "/home/brian/.local/share/polykey", env: PK_NODE_PATH)
  -pf, --password-file <path>  Path to Password
  -f, --format <format>        Output Format (choices: "human", "json", default: "human")
  -v, --verbose                Log Verbose Messages (default: 0)
  -V, --version                output the version number
  -h, --help                   display help for command

Commands:
  bootstrap [options]          Bootstrap Keynode State
  agent [options]              Agent Operations
  nodes [options]              Nodes Operations
  secrets [options]            Secrets Operations
  keys [options]               Keys Operations
  vaults [options]             Vaults Operations
  identities [options]         Identities Operations
  notifications [options]      Notifications Operations
  help [command]               display help for command

real    0m0.271s
user    0m0.287s
sys     0m0.042s

Just the built code with node gives us 0.301s.

❯ time node ./build/polykey.js
Usage: polykey [options] [command]

Polykey CLI

Options:
  -np, --node-path <path>      Path to Node State (default: "/home/brian/.local/share/polykey", env: PK_NODE_PATH)
  -pf, --password-file <path>  Path to Password
  -f, --format <format>        Output Format (choices: "human", "json", default: "human")
  -v, --verbose                Log Verbose Messages (default: 0)
  -V, --version                output the version number
  -h, --help                   display help for command

Commands:
  bootstrap [options]          Bootstrap Keynode State
  agent [options]              Agent Operations
  nodes [options]              Nodes Operations
  secrets [options]            Secrets Operations
  keys [options]               Keys Operations
  vaults [options]             Vaults Operations
  identities [options]         Identities Operations
  notifications [options]      Notifications Operations
  help [command]               display help for command

real    0m0.301s
user    0m0.336s
sys     0m0.062s

As a sanity check, ls takes about 0.009s, and running node that just prints helloworld runs in 0.046s.

❯ time ls
<output redacted>

real    0m0.009s
user    0m0.006s
sys     0m0.004s


❯ time node -e "console.log('helloworld')"
helloworld

real    0m0.046s
user    0m0.034s
sys     0m0.014s

❯ time steam-run ls
ADDITIONAL_TERMS  docs        jest.config.js  nodemon.json  package-lock.json  scripts  tests                tsconfig.json
build             flake.lock  LICENSE         npmDepsHash   README.md          secret   tmp                  utils.nix
dist              flake.nix   node_modules    package.json  result             src      tsconfig.build.json

real    0m0.121s
user    0m0.049s
sys     0m0.077s

So given these results

1. 0.913s total 0.913
2. 0.271s bundled only
3. 0.121 steam-run

It seems most of the time is spent by steam-run + pkg. I'm estimating about 0.642 taken up by both and 0.521 take up by pkg alone.

So moving forward we need to see how we can optimise pkg at runtime.

[tegefaulkes]

I did a quick and dirty package of a test.js script that just runs console.log('hello world'); This takes 0.142 seconds.

❯ time steam-run ./packaged
hello world!
steam-run ./packaged  0.07s user 0.08s system 101% cpu 0.142 total

Subtracting the steam-run startup time, we're looking at about 0.021s run time. So pkg can definitely run fast, it seems to be a function of the file size.

[tegefaulkes]

There is a compression option. It defaults to none and switching it to something else seems to increase the time.

None of the pkg options seems useful here. I think the only recourse here is to reduce the size of the of the native binaries in some way.

[CMCDragonkai]

Is esbuild minified? 26 Mar 2024 18:56:33 Brian Botha ***@***.***>:

…

There is a compression option. It defaults to *none* and switching it to something else seems to increase the time. — Reply to this email directly, view it on GitHub[#102 (comment)], or unsubscribe[https://github.com/notifications/unsubscribe-auth/AAE4OHJVOAIAWUJ2J3W2SWTY2EEY7AVCNFSM6AAAAABCOZNOHGVHI2DSMVQWIX3LMV43OSLTON2WKQ3PNVWWK3TUHMZDAMJZGQ3DGMRQGM]. You are receiving this because you are subscribed to this thread. [Tracking image][https://github.com/notifications/beacon/AAE4OHKH2ESI4E54L3CW5Q3Y2EEY7A5CNFSM6AAAAABCOZNOHGWGG33NNVSW45C7OR4XAZNMJFZXG5LFINXW23LFNZ2KUY3PNVWWK3TUL5UWJTTYL2ICG.gif]

[tegefaulkes]

base case

real 0m0.923s
user 0m0.839s
sys 0m0.226s

removed --no-bytecode

real 0m0.949s
user 0m0.875s
sys 0m0.221s

removed --no-bytecode and --no-native-build

real 0m0.980s
user 0m0.842s
sys 0m0.290s

No real advantages.

And yes, minified is true and I removed the source maps for esbuild.

[tegefaulkes]

Doing manual testing on the office mac, I removed all the extra native modules for platforms we don't need. This brought execution down from 0.72 to 0.57s and the file size down from 100M to 77M

Polykey-CLI % time ./testout
Usage: polykey [options] [command]

Polykey CLI

Options:
  -np, --node-path <path>      Path to Node State (default: "/Users/amyyan/Library/Application Support/polykey",
                               env: PK_NODE_PATH)
  -pf, --password-file <path>  Path to Password
  -f, --format <format>        Output Format (choices: "human", "json", default: "human")
  -v, --verbose                Log Verbose Messages (default: 0)
  -V, --version                output the version number
  -h, --help                   display help for command

Commands:
  bootstrap [options]          Bootstrap Keynode State
  agent [options]              Agent Operations
  nodes [options]              Nodes Operations
  secrets [options]            Secrets Operations
  keys [options]               Keys Operations
  vaults [options]             Vaults Operations
  identities [options]         Identities Operations
  notifications [options]      Notifications Operations
  help [command]               display help for command
./testout  0.57s user 0.06s system 113% cpu 0.562 total

So that's a good chunk right there. While not a full solution, reducing the size of the final binary is definitely something we want to do. So I'll explore this a bit more.

[tegefaulkes]

debuglog.txt
pkglog.txt

Here are some debug logs from testing on the mac. The debuglog outlines what is included in the virtualFS. while the pkglog outlines the packaging process.

We can see that there is 28.2MB of data being included. A good chunk of this, 19.8MB is just the quic and db universal binaries. But ignoring the size of the files for a sec, the number of files can have an impact too. So we should look into reducing all kinds of bloat here. Notably the sodium-native is including its full source code which makes up 1.3MB of assorted small files.

Moving forward I'm going to prune more of the unneeded files that are being included but also look into building the db and quic binaries with more optimisation if possible.

[tegefaulkes]

Marking all of the optionalDependencies as --external in esbuild is resulting in a bunch of dependencies we don't want being pulled into the vfs. This seems problimatic since it's including stuff like async-init or timer in the vfs but also bundled inside of the polykey.js code. I'm pretty sure maintaining 2 versions of a dependency like this should be causing issues with anything that uses instanceOf. I'm really not sure why this hasn't broken timer.

We really need to be more selective about this. Maybe I can modify it to mark only .node files as external.

[CMCDragonkai]

Yea this is a lower priority for now. We can address this later. Focus on finishing the other bugs and I'll return to this. It might require some architectural changes. 27 Mar 2024 14:16:17 Brian Botha ***@***.***>:

…

Marking all of the *optionalDependencies* as *--external* in *esbuild* is resulting in a bunch of dependencies we don't want being pulled into the *vfs*. This seems problimatic since it's including stuff like *async-init* or *timer* in the *vfs* but also bundled inside of the *polykey.js* code. I'm pretty sure maintaining 2 versions of a dependency like this should be causing issues with anything that uses *instanceOf*. I'm really not sure why this hasn't broken *timer*. We really need to be more selective about this. Maybe I can modify it to mark only *.node* files as external. — Reply to this email directly, view it on GitHub[#102 (comment)], or unsubscribe[https://github.com/notifications/unsubscribe-auth/AAE4OHONPAVEJNOZ5WPFONLY2IMV5AVCNFSM6AAAAABCOZNOHGVHI2DSMVQWIX3LMV43OSLTON2WKQ3PNVWWK3TUHMZDAMRRG42DOMBYGU]. You are receiving this because you commented. [Tracking image][https://github.com/notifications/beacon/AAE4OHLUR2BXK4A4E4QOCWDY2IMV5A5CNFSM6AAAAABCOZNOHGWGG33NNVSW45C7OR4XAZNMJFZXG5LFINXW23LFNZ2KUY3PNVWWK3TUL5UWJTTYQFUY2.gif]

[tegefaulkes]

OK, I'll put it on hold for now.

With some testing I got the mac execution down to 0.48s. There is definitely a lot we can do to reduce bloat in the final executable. The @matrixai/db has some issues with how it's structured. It doesn't play nice with esbuild. Given that it's native we need to mark it as external to preserve paths for loading the native modules. But doing so causes us to external all it's dependencies.

I think we need to consider updating @matrixai/db to use the same structure @matrixai/quic uses. That way we can bundle the main code while marking the native dependencies as external with no issue.

The sodium native source code is being included in the packaged vfs as well. So we'll need to exclude that. That alone is adding about 1.8MB to the output.