chore(cli-repl): add startup timing measurement functionality #1741

addaleax · 2023-11-15T18:25:18Z

$ time env MONGOSH_SHOW_TIMING_DATA=1 ./dist/mongosh --version
0.0.0-dev.0
┌─────────┬─────────────────────────────────────┬────────────┬─────────────┐
│ (index) │                  0                  │     1      │      2      │
├─────────┼─────────────────────────────────────┼────────────┼─────────────┤
│    0    │      'Process initialization'       │  '0.00ms'  │     ''      │
│    1    │        'Enter BoxednodeMain'        │  '0.09ms'  │  '+0.09ms'  │
│    2    │  'Start InitializeOncePerProcess'   │  '0.09ms'  │  '+0.00ms'  │
│    3    │ 'Finished InitializeOncePerProcess' │  '1.75ms'  │  '+1.67ms'  │
│    4    │          'Initialized V8'           │  '2.42ms'  │  '+0.67ms'  │
│    5    │         'Initialized Loop'          │  '2.51ms'  │  '+0.09ms'  │
│    6    │          'Created Isolate'          │  '5.05ms'  │  '+2.54ms'  │
│    7    │        'Created IsolateData'        │  '5.27ms'  │  '+0.22ms'  │
│    8    │          'Created Context'          │ '12.28ms'  │  '+7.01ms'  │
│    9    │        'Created Environment'        │ '40.49ms'  │ '+28.21ms'  │
│   10    │          'Added bindings'           │ '40.50ms'  │  '+0.01ms'  │
│   11    │        'Calling entrypoint'         │ '58.83ms'  │ '+18.33ms'  │
│   12    │    'cli-repl timing initialized'    │ '61.07ms'  │  '+2.24ms'  │
│   13    │           'entered main'            │ '204.97ms' │ '+143.90ms' │
│   14    │         'Called entrypoint'         │ '208.02ms' │  '+3.04ms'  │
│   15    │ 'Loaded Environment, entering loop' │ '208.34ms' │  '+0.32ms'  │
└─────────┴─────────────────────────────────────┴────────────┴─────────────┘

real	0m0,226s
user	0m0,195s
sys	0m0,052s

For full `--eval --nodb` roundtrip

$ time env MONGOSH_SHOW_TIMING_DATA=1 ./dist/mongosh --norc --nodb --eval '' --eval '' --quiet
┌─────────┬───────────────────────────────────────────────────┬────────────┬─────────────┐
│ (index) │                         0                         │     1      │      2      │
├─────────┼───────────────────────────────────────────────────┼────────────┼─────────────┤
│    0    │             'Process initialization'              │  '0.00ms'  │     ''      │
│    1    │               'Enter BoxednodeMain'               │  '0.08ms'  │  '+0.08ms'  │
│    2    │         'Start InitializeOncePerProcess'          │  '0.09ms'  │  '+0.00ms'  │
│    3    │        'Finished InitializeOncePerProcess'        │  '1.76ms'  │  '+1.67ms'  │
│    4    │                 'Initialized V8'                  │  '2.49ms'  │  '+0.73ms'  │
│    5    │                'Initialized Loop'                 │  '2.58ms'  │  '+0.09ms'  │
│    6    │                 'Created Isolate'                 │  '5.27ms'  │  '+2.69ms'  │
│    7    │               'Created IsolateData'               │  '5.49ms'  │  '+0.23ms'  │
│    8    │                 'Created Context'                 │ '12.53ms'  │  '+7.04ms'  │
│    9    │               'Created Environment'               │ '41.56ms'  │ '+29.02ms'  │
│   10    │                 'Added bindings'                  │ '41.57ms'  │  '+0.01ms'  │
│   11    │               'Calling entrypoint'                │ '63.89ms'  │ '+22.32ms'  │
│   12    │           'cli-repl timing initialized'           │ '67.12ms'  │  '+3.24ms'  │
│   13    │                  'entered main'                   │ '223.87ms' │ '+156.74ms' │
│   14    │              'entering repl.start()'              │ '228.82ms' │  '+4.95ms'  │
│   15    │                'Called entrypoint'                │ '230.64ms' │  '+1.82ms'  │
│   16    │              'verified node version'              │ '230.88ms' │  '+0.24ms'  │
│   17    │        'Loaded Environment, entering loop'        │ '231.16ms' │  '+0.27ms'  │
│   18    │        'checked containerized environment'        │ '231.87ms' │  '+0.71ms'  │
│   19    │              'ensured shell homedir'              │ '232.21ms' │  '+0.34ms'  │
│   20    │              'cleaned up log files'               │ '237.10ms' │  '+4.90ms'  │
│   21    │             'instantiated log writer'             │ '238.13ms' │  '+1.03ms'  │
│   22    │             'logged initial message'              │ '279.97ms' │ '+41.84ms'  │
│   23    │           'created analytics instance'            │ '283.77ms' │  '+3.80ms'  │
│   24    │            'completed telemetry setup'            │ '320.04ms' │ '+36.27ms'  │
│   25    │            'read global config files'             │ '326.27ms' │  '+6.22ms'  │
│   26    │              'prepared OIDC options'              │ '326.50ms' │  '+0.24ms'  │
│   27    │               'completed SP setup'                │ '335.09ms' │  '+8.59ms'  │
│   28    │             'fetched connection info'             │ '337.24ms' │  '+2.14ms'  │
│   29    │                     'greeted'                     │ '337.33ms' │  '+0.09ms'  │
│   30    │               'fetched config vars'               │ '337.36ms' │  '+0.03ms'  │
│   31    │               'created repl object'               │ '399.91ms' │ '+62.56ms'  │
│   32    │               'set up history file'               │ '402.28ms' │  '+2.37ms'  │
│   33    │             'finished initialization'             │ '402.71ms' │  '+0.43ms'  │
│   34    │            'initialized mongosh repl'             │ '402.72ms' │  '+0.01ms'  │
│   35    │                  'set up editor'                  │ '403.05ms' │  '+0.33ms'  │
│   36    │               'start eval scripts'                │ '403.17ms' │  '+0.12ms'  │
│   37    │                 'start repl eval'                 │ '403.75ms' │  '+0.58ms'  │
│   38    │               'start async rewrite'               │ '403.92ms' │  '+0.17ms'  │
│   39    │               'done async rewrite'                │ '511.44ms' │ '+107.52ms' │
│   40    │       'start runtimeSupportCode processing'       │ '511.59ms' │  '+0.15ms'  │
│   41    │    'done global runtimeSupportCode processing'    │ '512.98ms' │  '+1.39ms'  │
│   42    │       'finished evaluating processed code'        │ '570.66ms' │ '+57.68ms'  │
│   43    │                 'done repl eval'                  │ '570.74ms' │  '+0.08ms'  │
│   44    │                  're-set prompt'                  │ '571.39ms' │  '+0.64ms'  │
│   45    │                 'start repl eval'                 │ '571.67ms' │  '+0.29ms'  │
│   46    │               'start async rewrite'               │ '571.71ms' │  '+0.04ms'  │
│   47    │               'done async rewrite'                │ '591.64ms' │ '+19.92ms'  │
│   48    │       'finished evaluating processed code'        │ '593.22ms' │  '+1.59ms'  │
│   49    │                 'done repl eval'                  │ '593.23ms' │  '+0.01ms'  │
│   50    │                  're-set prompt'                  │ '593.30ms' │  '+0.06ms'  │
│   51    │              'finished eval scripts'              │ '593.35ms' │  '+0.06ms'  │
│   52    │ 'wrote eval output, start loading external files' │ '593.36ms' │  '+0.00ms'  │
│   53    │             'finished external files'             │ '593.36ms' │  '+0.00ms'  │
│   54    │                  'start closing'                  │ '593.51ms' │  '+0.16ms'  │
│   55    │                 'output flushed'                  │ '593.62ms' │  '+0.11ms'  │
│   56    │               'flushed log writer'                │ '594.39ms' │  '+0.77ms'  │
└─────────┴───────────────────────────────────────────────────┴────────────┴─────────────┘

real 0m0,625s
user 0m0,774s
sys 0m0,185s

gribnoysup · 2023-11-15T18:42:45Z

packages/cli-repl/src/startup-timing.ts

+  process.on('exit', function () {
+    const rawTimingData = getTimingData();
+    if (process.env.MONGOSH_SHOW_TIMING_DATA === 'json') {
+      console.log(JSON.stringify(rawTimingData));


Not sure if this makes sense: as this measures startup time, not exit time, maybe we can always write this to log file on exit? Might be helpful for debugging issues without asking issue reporters to redo whatever they were doing, but with these env vars passed if they already provided a log file

Ah, scratch that, I didn't notice right away that we mark after every eval, this might get pretty noisy in the logs

We can obviously adjust this a bit if we want, I think there was also a suggestion to include this in telemetry, I don’t think we actually created a ticket or anything for that though so I’ll ping Gaurab about it

chore(cli-repl): add startup timing measurement functionality

85da2c1

gribnoysup approved these changes Nov 15, 2023

View reviewed changes

fixup: lint

dd1ef6d

addaleax merged commit fb19029 into main Nov 16, 2023
53 of 57 checks passed

addaleax deleted the startup-timing branch November 16, 2023 12:46

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

chore(cli-repl): add startup timing measurement functionality #1741

chore(cli-repl): add startup timing measurement functionality #1741

addaleax commented Nov 15, 2023 •

edited

Loading

gribnoysup Nov 15, 2023 •

edited

Loading

addaleax Nov 15, 2023

chore(cli-repl): add startup timing measurement functionality #1741

chore(cli-repl): add startup timing measurement functionality #1741

Conversation

addaleax commented Nov 15, 2023 • edited Loading

gribnoysup Nov 15, 2023 • edited Loading

Choose a reason for hiding this comment

addaleax Nov 15, 2023

Choose a reason for hiding this comment

addaleax commented Nov 15, 2023 •

edited

Loading

gribnoysup Nov 15, 2023 •

edited

Loading