chore: add a new “Startup Time” event for sessions MONGOSH-1653 (#1761)

* chore: refactor and add categorisation to marks

* chore: connect startup with session started event

* chore: remove .only

* chore: fix names and duration calculation

* chore: apply suggestions from PR

* chore: add a jsdoc to toSnakeCase

* chore: move non-interactive start session a bit earlier, before evaluating scripts

* chore: Update packages/logging/src/setup-logger-and-telemetry.ts

Co-authored-by: Bailey Pearson <[email protected]>

* chore: fix package-lock.json

* chore: make clearer that timingData can contain TimingCategory or any other string

---------

Co-authored-by: Bailey Pearson <[email protected]>

Author: kmruiz

package-lock.json

@@ -37,13 +37,17 @@ import {
   SampledAnalytics,
 } from '@mongosh/logging';
 import type { MongoshBus } from '@mongosh/types';
-import { CliUserConfig, CliUserConfigValidator } from '@mongosh/types';
+import {
+  CliUserConfig,
+  CliUserConfigValidator,
+  TimingCategories,
+} from '@mongosh/types';
 import { promises as fs } from 'fs';
 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';
+import { getTimingData, markTime, summariseTimingData } from './startup-timing';
 
 /**
  * Connecting text key.
@@ -228,11 +232,14 @@ export class CliRepl implements MongoshIOProvider {
   ): Promise<void> {
     const { version } = require('../package.json');
     await this.verifyNodeVersion();
-    markTime('verified node version');
+    markTime(TimingCategories.REPLInstantiation, 'verified node version');
 
     this.isContainerizedEnvironment =
       await this.getIsContainerizedEnvironment();
-    markTime('checked containerized environment');
+    markTime(
+      TimingCategories.REPLInstantiation,
+      'checked containerized environment'
+    );
 
     if (!this.cliOptions.nodb) {
       const cs = new ConnectionString(driverUri);
@@ -253,23 +260,23 @@ export class CliRepl implements MongoshIOProvider {
     } catch (err: any) {
       this.warnAboutInaccessibleFile(err);
     }
-    markTime('ensured shell homedir');
+    markTime(TimingCategories.REPLInstantiation, 'ensured shell homedir');
 
     await this.logManager.cleanupOldLogfiles();
-    markTime('cleaned up log files');
+    markTime(TimingCategories.Logging, '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');
+    markTime(TimingCategories.Logging, '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');
+    markTime(TimingCategories.Logging, 'logged initial message');
 
     let analyticsSetupError: Error | null = null;
     try {
@@ -280,7 +287,7 @@ export class CliRepl implements MongoshIOProvider {
       analyticsSetupError = err;
     }
 
-    markTime('created analytics instance');
+    markTime(TimingCategories.Telemetry, 'created analytics instance');
     setupLoggerAndTelemetry(
       this.bus,
       logger,
@@ -293,7 +300,7 @@ export class CliRepl implements MongoshIOProvider {
       },
       version
     );
-    markTime('completed telemetry setup');
+    markTime(TimingCategories.Telemetry, 'completed telemetry setup');
 
     if (analyticsSetupError) {
       this.bus.emit('mongosh:error', analyticsSetupError, 'analytics');
@@ -308,7 +315,7 @@ export class CliRepl implements MongoshIOProvider {
     }
 
     this.globalConfig = await this.loadGlobalConfigFile();
-    markTime('read global config files');
+    markTime(TimingCategories.UserConfigLoading, 'read global config files');
 
     // Needs to happen after loading the mongosh config file(s)
     void this.fetchMongoshUpdateUrl();
@@ -342,7 +349,7 @@ export class CliRepl implements MongoshIOProvider {
     }
 
     driverOptions = await this.prepareOIDCOptions(driverOptions);
-    markTime('prepared OIDC options');
+    markTime(TimingCategories.DriverSetup, 'prepared OIDC options');
 
     let initialServiceProvider;
     try {
@@ -358,12 +365,12 @@ export class CliRepl implements MongoshIOProvider {
       }
       throw err;
     }
-    markTime('completed SP setup');
+    markTime(TimingCategories.DriverSetup, 'completed SP setup');
     const initialized = await this.mongoshRepl.initialize(
       initialServiceProvider,
       await this.getMoreRecentMongoshVersion()
     );
-    markTime('initialized mongosh repl');
+    markTime(TimingCategories.REPLInstantiation, 'initialized mongosh repl');
     this.injectReplFunctions();
 
     const commandLineLoadFiles = this.cliOptions.fileNames ?? [];
@@ -402,17 +409,25 @@ export class CliRepl implements MongoshIOProvider {
         this.mongoshRepl
       ),
     });
-    markTime('set up editor');
+    markTime(TimingCategories.REPLInstantiation, 'set up editor');
 
     if (willExecuteCommandLineScripts) {
       this.mongoshRepl.setIsInteractive(willEnterInteractiveMode);
+
+      this.bus.emit('mongosh:start-session', {
+        isInteractive: false,
+        timings: summariseTimingData(getTimingData()),
+      });
+
       this.bus.emit('mongosh:start-loading-cli-scripts', {
         usesShellOption: !!this.cliOptions.shell,
       });
+
       const exitCode = await this.loadCommandLineFilesAndEval(
         commandLineLoadFiles,
         evalScripts
       );
+
       if (exitCode !== 0) {
         await this.exit(exitCode);
         return;
@@ -440,21 +455,27 @@ 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');
+      markTime(TimingCategories.SnippetLoading, 'start load snippets');
       await snippetManager?.loadAllSnippets();
-      markTime('done load snippets');
+      markTime(TimingCategories.SnippetLoading, 'done load snippets');
     }
+
+    markTime(TimingCategories.ResourceFileLoading, 'loading rc files');
     await this.loadRcFiles();
-    markTime('loaded rc files');
+    markTime(TimingCategories.ResourceFileLoading, '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');
+    markTime(TimingCategories.REPLInstantiation, 'starting repl');
     await this.mongoshRepl.startRepl(initialized);
+    this.bus.emit('mongosh:start-session', {
+      isInteractive: true,
+      timings: summariseTimingData(getTimingData()),
+    });
   }
 
   injectReplFunctions(): void {
@@ -537,15 +558,15 @@ export class CliRepl implements MongoshIOProvider {
     let lastEvalResult: any;
     let exitCode = 0;
     try {
-      markTime('start eval scripts');
+      markTime(TimingCategories.Eval, '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');
+      markTime(TimingCategories.Eval, '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
@@ -584,7 +605,8 @@ export class CliRepl implements MongoshIOProvider {
       this.output.write(formattedResult + '\n');
     }
 
-    markTime('wrote eval output, start loading external files');
+    markTime(TimingCategories.Eval, 'wrote eval output');
+    markTime(TimingCategories.EvalFile, 'start loading external files');
     for (const file of files) {
       if (!this.cliOptions.quiet) {
         this.output.write(
@@ -593,7 +615,7 @@ export class CliRepl implements MongoshIOProvider {
       }
       await this.mongoshRepl.loadExternalFile(file);
     }
-    markTime('finished external files');
+    markTime(TimingCategories.EvalFile, 'finished external files');
     return exitCode;
   }
 
@@ -978,7 +1000,7 @@ export class CliRepl implements MongoshIOProvider {
    * Close all open resources held by this REPL instance.
    */
   async close(): Promise<void> {
-    markTime('start closing');
+    markTime(TimingCategories.REPLInstantiation, 'start closing');
     if (this.closing) {
       return;
     }
@@ -998,7 +1020,7 @@ export class CliRepl implements MongoshIOProvider {
         await new Promise((resolve) => this.output.write('', resolve));
       }
     }
-    markTime('output flushed');
+    markTime(TimingCategories.REPLInstantiation, 'output flushed');
     this.closing = true;
     const analytics = this.toggleableAnalytics;
     let flushError: string | null = null;
@@ -1007,7 +1029,7 @@ export class CliRepl implements MongoshIOProvider {
       const flushStart = Date.now();
       try {
         await promisify(analytics.flush.bind(analytics))();
-        markTime('flushed analytics');
+        markTime(TimingCategories.Telemetry, 'flushed analytics');
       } catch (err: any) {
         flushError = err.message;
       } finally {
@@ -1025,7 +1047,7 @@ export class CliRepl implements MongoshIOProvider {
       }
     );
     await this.logWriter?.flush();
-    markTime('flushed log writer');
+    markTime(TimingCategories.Logging, 'flushed log writer');
     this.bus.emit('mongosh:closed');
   }
 

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

@@ -18,7 +18,11 @@ import {
 import type { ShellResult } from '@mongosh/shell-evaluator';
 import { ShellEvaluator } from '@mongosh/shell-evaluator';
 import type { ConfigProvider, MongoshBus } from '@mongosh/types';
-import { CliUserConfig, CliUserConfigValidator } from '@mongosh/types';
+import {
+  CliUserConfig,
+  CliUserConfigValidator,
+  TimingCategories,
+} from '@mongosh/types';
 import askcharacter from 'askcharacter';
 import askpassword from 'askpassword';
 import { Console } from 'console';
@@ -174,7 +178,7 @@ class MongoshNodeRepl implements EvaluationListener {
     );
     instanceState.setEvaluationListener(this);
     await instanceState.fetchConnectionInfo();
-    markTime('fetched connection info');
+    markTime(TimingCategories.REPLInstantiation, 'fetched connection info');
 
     const { buildInfo, extraInfo } = instanceState.connectionInfo;
     let mongodVersion = extraInfo?.is_stream
@@ -188,7 +192,7 @@ class MongoshNodeRepl implements EvaluationListener {
     }
     await this.greet(mongodVersion, moreRecentMongoshVersion);
     await this.printBasicConnectivityWarning(instanceState);
-    markTime('greeted');
+    markTime(TimingCategories.REPLInstantiation, 'greeted');
 
     this.inspectCompact =
       (await this.getConfig('inspectCompact')) ?? this.inspectCompact;
@@ -198,7 +202,7 @@ class MongoshNodeRepl implements EvaluationListener {
       (await this.getConfig('showStackTraces')) ?? this.showStackTraces;
     this.redactHistory =
       (await this.getConfig('redactHistory')) ?? this.redactHistory;
-    markTime('fetched config vars');
+    markTime(TimingCategories.UserConfigLoading, 'fetched config vars');
 
     const repl = asyncRepl.start({
       // 'repl' is not supported in startup snapshots yet.
@@ -347,7 +351,7 @@ class MongoshNodeRepl implements EvaluationListener {
     // https://github.com/nodejs/node/issues/36773
     (repl as Mutable<typeof repl>).line = '';
 
-    markTime('created repl object');
+    markTime(TimingCategories.REPLInstantiation, 'created repl object');
     const historyFile = this.ioProvider.getHistoryFilePath();
     try {
       await promisify(repl.setupHistory).call(repl, historyFile);
@@ -410,7 +414,7 @@ class MongoshNodeRepl implements EvaluationListener {
       this.output.write(this.writer(warn) + '\n');
     }
 
-    markTime('set up history file');
+    markTime(TimingCategories.UserConfigLoading, 'set up history file');
     (repl as any).on(asyncRepl.evalStart, () => {
       this.bus.emit('mongosh:evaluate-started');
     });
@@ -442,7 +446,7 @@ class MongoshNodeRepl implements EvaluationListener {
       }
     }
 
-    markTime('finished initialization');
+    markTime(TimingCategories.REPLInstantiation, 'finished initialization');
     return { __initialized: 'yes' };
   }
 
@@ -545,7 +549,7 @@ class MongoshNodeRepl implements EvaluationListener {
     context: any,
     filename: string
   ): Promise<any> {
-    markTime('start repl eval');
+    markTime(TimingCategories.Eval, 'start repl eval');
     if (!this.insideAutoCompleteOrGetPrompt) {
       this.lineByLineInput.enableBlockOnNewLine();
     }
@@ -599,7 +603,7 @@ class MongoshNodeRepl implements EvaluationListener {
       }
       throw err;
     } finally {
-      markTime('done repl eval');
+      markTime(TimingCategories.Eval, 'done repl eval');
       if (!this.insideAutoCompleteOrGetPrompt && !interrupted) {
         // In case of an interrupt, onAsyncSigint will print the prompt when completed
         repl.setPrompt(await this.getShellPrompt());
@@ -608,7 +612,7 @@ class MongoshNodeRepl implements EvaluationListener {
       if (this.loadNestingLevel <= 1) {
         this.bus.emit('mongosh:eval-complete'); // For testing purposes.
       }
-      markTime('re-set prompt');
+      markTime(TimingCategories.Eval, 're-set prompt');
     }
   }
 

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

@@ -29,6 +29,7 @@ import { PassThrough } from 'stream';
 import crypto from 'crypto';
 import net from 'net';
 import v8 from 'v8';
+import { TimingCategories } from '@mongosh/types';
 
 // TS does not yet have type definitions for v8.startupSnapshot
 if ((v8 as any)?.startupSnapshot?.isBuildingSnapshot?.()) {
@@ -48,7 +49,7 @@ if ((v8 as any)?.startupSnapshot?.isBuildingSnapshot?.()) {
 
   (v8 as any).startupSnapshot.setDeserializeMainFunction(() => {
     enableFipsIfRequested();
-    markTime('loaded pre-snapshot deps');
+    markTime(TimingCategories.Snapshot, 'loaded pre-snapshot deps');
 
     void main();
   });
@@ -58,7 +59,7 @@ if ((v8 as any)?.startupSnapshot?.isBuildingSnapshot?.()) {
 
 // eslint-disable-next-line complexity
 async function main() {
-  markTime('entered main');
+  markTime(TimingCategories.Main, '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 ...
@@ -217,7 +218,7 @@ async function main() {
       shellHomePaths: shellHomePaths,
       globalConfigPaths: globalConfigPaths,
     });
-    markTime('entering repl.start()');
+    markTime(TimingCategories.REPLInstantiation, 'entering repl.start()');
     await repl.start(connectionInfo.connectionString, {
       productName: 'MongoDB Shell',
       productDocsLink: 'https://www.mongodb.com/docs/mongodb-shell/',