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

Author: addaleax

package-lock.json

@@ -65,7 +65,7 @@
     "@mongodb-js/dl-center": "^1.1.1",
     "@octokit/rest": "^17.9.0",
     "aws-sdk": "^2.674.0",
-    "boxednode": "^2.1.2",
+    "boxednode": "^2.2.0",
     "command-exists": "^1.2.9",
     "download": "^8.0.0",
     "es-aggregate-error": "^1.0.9",

packages/build/package.json

@@ -42,6 +42,7 @@ import path from 'path';
 import { promisify } from 'util';
 import { getOsInfo } from './get-os-info';
 import { UpdateNotificationManager } from './update-notification-manager';
+import { markTime } from './startup-timing';
 
 /**
  * Connecting text key.
@@ -226,9 +227,11 @@ export class CliRepl implements MongoshIOProvider {
   ): Promise<void> {
     const { version } = require('../package.json');
     await this.verifyNodeVersion();
+    markTime('verified node version');
 
     this.isContainerizedEnvironment =
       await this.getIsContainerizedEnvironment();
+    markTime('checked containerized environment');
 
     if (!this.cliOptions.nodb) {
       const cs = new ConnectionString(driverUri);
@@ -249,19 +252,23 @@ export class CliRepl implements MongoshIOProvider {
     } catch (err: any) {
       this.warnAboutInaccessibleFile(err);
     }
+    markTime('ensured shell homedir');
 
     await this.logManager.cleanupOldLogfiles();
+    markTime('cleaned up log files');
     const logger = await this.logManager.createLogWriter();
     if (!this.cliOptions.quiet) {
       this.output.write(`Current Mongosh Log ID:\t${logger.logId}\n`);
     }
     this.logWriter = logger;
+    markTime('instantiated log writer');
 
     logger.info('MONGOSH', mongoLogId(1_000_000_000), 'log', 'Starting log', {
       execPath: process.execPath,
       envInfo: redactSensitiveData(this.getLoggedEnvironmentVariables()),
       ...(await buildInfo()),
     });
+    markTime('logged initial message');
 
     let analyticsSetupError: Error | null = null;
     try {
@@ -272,6 +279,7 @@ export class CliRepl implements MongoshIOProvider {
       analyticsSetupError = err;
     }
 
+    markTime('created analytics instance');
     setupLoggerAndTelemetry(
       this.bus,
       logger,
@@ -284,6 +292,7 @@ export class CliRepl implements MongoshIOProvider {
       },
       version
     );
+    markTime('completed telemetry setup');
 
     if (analyticsSetupError) {
       this.bus.emit('mongosh:error', analyticsSetupError, 'analytics');
@@ -298,6 +307,7 @@ export class CliRepl implements MongoshIOProvider {
     }
 
     this.globalConfig = await this.loadGlobalConfigFile();
+    markTime('read global config files');
 
     // Needs to happen after loading the mongosh config file(s)
     void this.fetchMongoshUpdateUrl();
@@ -331,6 +341,7 @@ export class CliRepl implements MongoshIOProvider {
     }
 
     driverOptions = await this.prepareOIDCOptions(driverOptions);
+    markTime('prepared OIDC options');
 
     let initialServiceProvider;
     try {
@@ -346,10 +357,12 @@ export class CliRepl implements MongoshIOProvider {
       }
       throw err;
     }
+    markTime('completed SP setup');
     const initialized = await this.mongoshRepl.initialize(
       initialServiceProvider,
       await this.getMoreRecentMongoshVersion()
     );
+    markTime('initialized mongosh repl');
     this.injectReplFunctions();
 
     const commandLineLoadFiles = this.cliOptions.fileNames ?? [];
@@ -388,6 +401,7 @@ export class CliRepl implements MongoshIOProvider {
         this.mongoshRepl
       ),
     });
+    markTime('set up editor');
 
     if (willExecuteCommandLineScripts) {
       this.mongoshRepl.setIsInteractive(willEnterInteractiveMode);
@@ -425,16 +439,20 @@ export class CliRepl implements MongoshIOProvider {
        * - Programmatic users who really want a dependency on a snippet can use
        *   snippet('load-all') to explicitly load snippets
        */
+      markTime('start load snippets');
       await snippetManager?.loadAllSnippets();
+      markTime('done load snippets');
     }
     await this.loadRcFiles();
+    markTime('loaded rc files');
 
     this.verifyPlatformSupport();
 
     // We only enable/disable here, since the rc file/command line scripts
     // can disable the telemetry setting.
     this.setTelemetryEnabled(await this.getConfig('enableTelemetry'));
     this.bus.emit('mongosh:start-mongosh-repl', { version });
+    markTime('starting repl');
     await this.mongoshRepl.startRepl(initialized);
   }
 
@@ -514,13 +532,15 @@ export class CliRepl implements MongoshIOProvider {
     let lastEvalResult: any;
     let exitCode = 0;
     try {
+      markTime('start eval scripts');
       for (const script of evalScripts) {
         this.bus.emit('mongosh:eval-cli-script');
         lastEvalResult = await this.mongoshRepl.loadExternalCode(
           script,
           '@(shell eval)'
         );
       }
+      markTime('finished eval scripts');
     } catch (err) {
       // We have two distinct flows of control in the exception case;
       // if we are running in --json mode, we treat the error as a
@@ -559,6 +579,7 @@ export class CliRepl implements MongoshIOProvider {
       this.output.write(formattedResult + '\n');
     }
 
+    markTime('wrote eval output, start loading external files');
     for (const file of files) {
       if (!this.cliOptions.quiet) {
         this.output.write(
@@ -567,6 +588,7 @@ export class CliRepl implements MongoshIOProvider {
       }
       await this.mongoshRepl.loadExternalFile(file);
     }
+    markTime('finished external files');
     return exitCode;
   }
 
@@ -951,6 +973,7 @@ export class CliRepl implements MongoshIOProvider {
    * Close all open resources held by this REPL instance.
    */
   async close(): Promise<void> {
+    markTime('start closing');
     if (this.closing) {
       return;
     }
@@ -970,6 +993,7 @@ export class CliRepl implements MongoshIOProvider {
         await new Promise((resolve) => this.output.write('', resolve));
       }
     }
+    markTime('output flushed');
     this.closing = true;
     const analytics = this.toggleableAnalytics;
     let flushError: string | null = null;
@@ -978,6 +1002,7 @@ export class CliRepl implements MongoshIOProvider {
       const flushStart = Date.now();
       try {
         await promisify(analytics.flush.bind(analytics))();
+        markTime('flushed analytics');
       } catch (err: any) {
         flushError = err.message;
       } finally {
@@ -995,6 +1020,7 @@ export class CliRepl implements MongoshIOProvider {
       }
     );
     await this.logWriter?.flush();
+    markTime('flushed log writer');
     this.bus.emit('mongosh:closed');
   }
 

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

@@ -35,6 +35,7 @@ import formatOutput, { formatError } from './format-output';
 import { makeMultilineJSIntoSingleLine } from '@mongosh/js-multiline-to-singleline';
 import { LineByLineInput } from './line-by-line-input';
 import type { FormatOptions } from './format-output';
+import { markTime } from './startup-timing';
 
 /**
  * All CLI flags that are useful for {@link MongoshNodeRepl}.
@@ -168,10 +169,12 @@ class MongoshNodeRepl implements EvaluationListener {
     );
     const shellEvaluator = new ShellEvaluator(
       instanceState,
-      (value: any) => value
+      (value: any) => value,
+      markTime
     );
     instanceState.setEvaluationListener(this);
     await instanceState.fetchConnectionInfo();
+    markTime('fetched connection info');
 
     const { buildInfo, extraInfo } = instanceState.connectionInfo;
     let mongodVersion = extraInfo?.is_stream
@@ -185,6 +188,7 @@ class MongoshNodeRepl implements EvaluationListener {
     }
     await this.greet(mongodVersion, moreRecentMongoshVersion);
     await this.printBasicConnectivityWarning(instanceState);
+    markTime('greeted');
 
     this.inspectCompact =
       (await this.getConfig('inspectCompact')) ?? this.inspectCompact;
@@ -194,6 +198,7 @@ class MongoshNodeRepl implements EvaluationListener {
       (await this.getConfig('showStackTraces')) ?? this.showStackTraces;
     this.redactHistory =
       (await this.getConfig('redactHistory')) ?? this.redactHistory;
+    markTime('fetched config vars');
 
     const repl = asyncRepl.start({
       // 'repl' is not supported in startup snapshots yet.
@@ -342,6 +347,7 @@ class MongoshNodeRepl implements EvaluationListener {
     // https://github.com/nodejs/node/issues/36773
     (repl as Mutable<typeof repl>).line = '';
 
+    markTime('created repl object');
     const historyFile = this.ioProvider.getHistoryFilePath();
     try {
       await promisify(repl.setupHistory).call(repl, historyFile);
@@ -404,6 +410,7 @@ class MongoshNodeRepl implements EvaluationListener {
       this.output.write(this.writer(warn) + '\n');
     }
 
+    markTime('set up history file');
     (repl as any).on(asyncRepl.evalStart, () => {
       this.bus.emit('mongosh:evaluate-started');
     });
@@ -435,6 +442,7 @@ class MongoshNodeRepl implements EvaluationListener {
       }
     }
 
+    markTime('finished initialization');
     return { __initialized: 'yes' };
   }
 
@@ -537,6 +545,7 @@ class MongoshNodeRepl implements EvaluationListener {
     context: any,
     filename: string
   ): Promise<any> {
+    markTime('start repl eval');
     if (!this.insideAutoCompleteOrGetPrompt) {
       this.lineByLineInput.enableBlockOnNewLine();
     }
@@ -590,6 +599,7 @@ class MongoshNodeRepl implements EvaluationListener {
       }
       throw err;
     } finally {
+      markTime('done repl eval');
       if (!this.insideAutoCompleteOrGetPrompt && !interrupted) {
         // In case of an interrupt, onAsyncSigint will print the prompt when completed
         repl.setPrompt(await this.getShellPrompt());
@@ -598,6 +608,7 @@ class MongoshNodeRepl implements EvaluationListener {
       if (this.loadNestingLevel <= 1) {
         this.bus.emit('mongosh:eval-complete'); // For testing purposes.
       }
+      markTime('re-set prompt');
     }
   }
 

packages/cli-repl/src/mongosh-repl.ts

@@ -13,6 +13,7 @@ function enableFipsIfRequested() {
 }
 enableFipsIfRequested();
 
+import { markTime } from './startup-timing';
 import { CliRepl } from './cli-repl';
 import { parseCliArgs } from './arg-parser';
 import { runSmokeTests } from './smoke-tests';
@@ -47,6 +48,8 @@ if ((v8 as any)?.startupSnapshot?.isBuildingSnapshot?.()) {
 
   (v8 as any).startupSnapshot.setDeserializeMainFunction(() => {
     enableFipsIfRequested();
+    markTime('loaded pre-snapshot deps');
+
     void main();
   });
 } else {
@@ -55,6 +58,7 @@ if ((v8 as any)?.startupSnapshot?.isBuildingSnapshot?.()) {
 
 // eslint-disable-next-line complexity
 async function main() {
+  markTime('entered main');
   if (process.env.MONGOSH_RUN_NODE_SCRIPT) {
     // For uncompiled mongosh: node /path/to/this/file script ... -> node script ...
     // FOr compiled mongosh: mongosh mongosh script ... -> mongosh script ...
@@ -213,6 +217,7 @@ async function main() {
       shellHomePaths: shellHomePaths,
       globalConfigPaths: globalConfigPaths,
     });
+    markTime('entering repl.start()');
     await repl.start(connectionInfo.connectionString, {
       productName: 'MongoDB Shell',
       productDocsLink: 'https://www.mongodb.com/docs/mongodb-shell/',