diff --git a/package-lock.json b/package-lock.json index 0f716eecb..93c9bcf97 100644 --- a/package-lock.json +++ b/package-lock.json @@ -31581,6 +31581,7 @@ "@mongodb-js/eslint-config-mongosh": "^1.0.0", "@mongodb-js/prettier-config-devtools": "^1.0.1", "@mongodb-js/tsconfig-mongosh": "^1.0.0", + "@mongosh/types": "0.0.0-dev.0", "@types/sinon-chai": "^3.2.4", "depcheck": "^1.4.3", "eslint": "^7.25.0", @@ -38351,6 +38352,7 @@ "@mongosh/async-rewriter2": "0.0.0-dev.0", "@mongosh/history": "0.0.0-dev.0", "@mongosh/shell-api": "0.0.0-dev.0", + "@mongosh/types": "0.0.0-dev.0", "@types/sinon-chai": "^3.2.4", "depcheck": "^1.4.3", "eslint": "^7.25.0", diff --git a/packages/cli-repl/src/cli-repl.ts b/packages/cli-repl/src/cli-repl.ts index 03483b86e..8bc119455 100644 --- a/packages/cli-repl/src/cli-repl.ts +++ b/packages/cli-repl/src/cli-repl.ts @@ -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 { 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,12 +455,14 @@ 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(); @@ -453,8 +470,12 @@ export class CliRepl implements MongoshIOProvider { // 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,7 +558,7 @@ 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( @@ -545,7 +566,7 @@ export class CliRepl implements MongoshIOProvider { '@(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 { - 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'); } diff --git a/packages/cli-repl/src/mongosh-repl.ts b/packages/cli-repl/src/mongosh-repl.ts index 0bb99e49c..29cea34b2 100644 --- a/packages/cli-repl/src/mongosh-repl.ts +++ b/packages/cli-repl/src/mongosh-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).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 { - 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'); } } diff --git a/packages/cli-repl/src/run.ts b/packages/cli-repl/src/run.ts index c6aeb955b..65298d233 100644 --- a/packages/cli-repl/src/run.ts +++ b/packages/cli-repl/src/run.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/', diff --git a/packages/cli-repl/src/startup-timing.spec.ts b/packages/cli-repl/src/startup-timing.spec.ts new file mode 100644 index 000000000..7cdd7a82e --- /dev/null +++ b/packages/cli-repl/src/startup-timing.spec.ts @@ -0,0 +1,22 @@ +import { TimingCategories, type TimingCategory } from '@mongosh/types'; +import { summariseTimingData } from './startup-timing'; +import { expect } from 'chai'; + +describe('startup timing', function () { + describe('summariseTimingData', function () { + it('should calculate durations of each category in milliseconds', function () { + const timingData: [TimingCategory, string, number][] = [ + [TimingCategories.REPLInstantiation, '1 REPL', 50000000], + [TimingCategories.Main, '1 Main', 60000000], + [TimingCategories.REPLInstantiation, '2 REPL', 140000000], + [TimingCategories.Main, '2 Main', 150000000], + ]; + + const summary = summariseTimingData(timingData); + expect(summary).to.deep.equal({ + [TimingCategories.REPLInstantiation]: 130, + [TimingCategories.Main]: 20, + }); + }); + }); +}); diff --git a/packages/cli-repl/src/startup-timing.ts b/packages/cli-repl/src/startup-timing.ts index 0da279cda..4ba4d4b41 100644 --- a/packages/cli-repl/src/startup-timing.ts +++ b/packages/cli-repl/src/startup-timing.ts @@ -1,30 +1,60 @@ -const jsTimingEntries: [string, bigint][] = []; -const timing: { - markTime: (label: string) => void; - getTimingData: () => [string, number][]; -} = !process.env.MONGOSH_SHOW_TIMING_DATA - ? { - markTime: () => { - /* ignore */ - }, - getTimingData: () => [], - } - : (process as any).boxednode - ? { - markTime: (process as any).boxednode.markTime, - getTimingData: (process as any).boxednode.getTimingData, - } - : { - markTime: (label: string) => { - jsTimingEntries.push([label, process.hrtime.bigint()]); - }, - getTimingData: () => { - const data = jsTimingEntries.sort((a, b) => Number(a[1] - b[1])); - // Adjust times so that process initialization happens at time 0 - return data.map(([label, time]) => [label, Number(time - data[0][1])]); - }, +import { + TimingCategories, + type TimingCategory, + type TimingInterface, +} from '@mongosh/types'; + +const jsTimingEntries: [string, string, bigint][] = []; + +function linkTimingInterface(): TimingInterface { + const boxedNode = (process as any).boxednode; + + // If we are bundled with boxednode, just use the provided interface + if (boxedNode) { + return { + markTime: boxedNode.markTime, + getTimingData: boxedNode.getTimingData, }; + } + + // Otherwise, use a JS implementation (mostly for development) + return { + markTime: (category, label) => + jsTimingEntries.push([category, label, process.hrtime.bigint()]), + getTimingData: () => { + const data = jsTimingEntries.sort((a, b) => Number(a[2] - b[2])); + // Adjust times so that process initialization happens at time 0 + return data.map(([category, label, time]) => [ + category, + label, + Number(time - data[0][2]), + ]); + }, + }; +} + +export function summariseTimingData( + timingData: [string | TimingCategory, string, number][] +): { + [key: string]: number; +} { + const durationByCategory = new Map(); + let lastTimestamp = 0; + + // eslint-disable-next-line @typescript-eslint/no-unused-vars + for (const [category, _, time] of timingData) { + const durationInNs = time - lastTimestamp; + const durationInMs = durationInNs / 1_000_000; + const durationSum = (durationByCategory.get(category) || 0) + durationInMs; + durationByCategory.set(category, durationSum); + + lastTimestamp = time; + } + + return Object.fromEntries(durationByCategory.entries()); +} +const timing: TimingInterface = linkTimingInterface(); export const markTime = timing.markTime; export const getTimingData = timing.getTimingData; @@ -35,11 +65,12 @@ if (process.env.MONGOSH_SHOW_TIMING_DATA) { console.log(JSON.stringify(rawTimingData)); } else { console.table( - rawTimingData.map(([label, time], i) => [ + rawTimingData.map(([category, label, time], i) => [ + category, label, `${(time / 1_000_000).toFixed(2)}ms`, i > 0 - ? `+${((time - rawTimingData[i - 1][1]) / 1_000_000).toFixed(2)}ms` + ? `+${((time - rawTimingData[i - 1][2]) / 1_000_000).toFixed(2)}ms` : '', ]) ); @@ -47,4 +78,4 @@ if (process.env.MONGOSH_SHOW_TIMING_DATA) { }); } -markTime('cli-repl timing initialized'); +markTime(TimingCategories.REPLInstantiation, 'cli-repl timing initialized'); diff --git a/packages/logging/src/setup-logger-and-telemetry.spec.ts b/packages/logging/src/setup-logger-and-telemetry.spec.ts index 51c1c0e3e..7d6dac90a 100644 --- a/packages/logging/src/setup-logger-and-telemetry.spec.ts +++ b/packages/logging/src/setup-logger-and-telemetry.spec.ts @@ -4,6 +4,29 @@ import { setupLoggerAndTelemetry } from './'; import { EventEmitter } from 'events'; import { MongoshInvalidInputError } from '@mongosh/errors'; import type { MongoshBus } from '@mongosh/types'; +import { toSnakeCase } from './setup-logger-and-telemetry'; + +describe('toSnakeCase', function () { + const useCases = [ + { input: 'MongoDB REPL', output: 'mongo_db_repl' }, + { + input: 'Node.js REPL Instantiation', + output: 'node_js_repl_instantiation', + }, + { input: 'A', output: 'a' }, + { + input: 'OneLongThingInPascalCase', + output: 'one_long_thing_in_pascal_case', + }, + { input: 'Removes .Dots in Node.js', output: 'removes_dots_in_node_js' }, + ]; + + for (const { input, output } of useCases) { + it(`should convert ${input} to ${output}`, function () { + expect(toSnakeCase(input)).to.equal(output); + }); + } +}); describe('setupLoggerAndTelemetry', function () { let logOutput: any[]; @@ -60,6 +83,14 @@ describe('setupLoggerAndTelemetry', function () { is_atlas: false, node_version: 'v12.19.0', } as any); + bus.emit('mongosh:start-session', { + isInteractive: true, + timings: { + 'BoxedNode Bindings': 50, + NodeREPL: 100, + }, + }); + bus.emit( 'mongosh:error', new MongoshInvalidInputError('meow', 'CLIREPL-1005', { cause: 'x' }), @@ -380,6 +411,20 @@ describe('setupLoggerAndTelemetry', function () { }, }, ], + [ + 'track', + { + anonymousId: '53defe995fa47e6c13102d9d', + event: 'Startup Time', + properties: { + is_interactive: true, + boxed_node_bindings: 50, + node_repl: 100, + mongosh_version: '1.0.0', + session_id: '5fb3c20ee1507e894e5340f3', + }, + }, + ], [ 'track', { diff --git a/packages/logging/src/setup-logger-and-telemetry.ts b/packages/logging/src/setup-logger-and-telemetry.ts index 40968a248..7f3d24a10 100644 --- a/packages/logging/src/setup-logger-and-telemetry.ts +++ b/packages/logging/src/setup-logger-and-telemetry.ts @@ -30,6 +30,7 @@ import type { EditorReadVscodeExtensionsFailedEvent, FetchingUpdateMetadataEvent, FetchingUpdateMetadataCompleteEvent, + SessionStartedEvent, } from '@mongosh/types'; import { inspect } from 'util'; import type { MongoLogWriter } from 'mongodb-log-writer'; @@ -58,6 +59,33 @@ class MultiSet> { } } +/** + * It transforms a random string into snake case. Snake case is completely + * lowercase and uses '_' to separate words. For example: + * + * This function defines a "word" as a sequence of characters until the next `.` or capital letter. + * + * 'Random String' => 'random_string' + * + * It will also remove any non alphanumeric characters to ensure the string + * is compatible with Segment. For example: + * + * 'Node.js REPL Instantiation' => 'node_js_repl_instantiation' + * + * @param str Any non snake-case formatted string + * @returns The snake-case formatted string + */ +export function toSnakeCase(str: string): string { + const matches = str.match( + /[A-Z]{2,}(?=[A-Z][a-z]+[0-9]*|\b)|[A-Z]?[a-z]+[0-9]*|[A-Z]|[0-9]+/g + ); + if (!matches) { + return str; + } + + return matches.map((x) => x.toLowerCase()).join('_'); +} + /** * Connect a MongoshBus instance that emits events to logging and analytics providers. * @@ -146,6 +174,26 @@ export function setupLoggerAndTelemetry( }); }); + bus.on('mongosh:start-session', function (args: SessionStartedEvent) { + const normalisedTimingsArray = Object.entries(args.timings).map( + ([key, duration]) => { + const snakeCaseKey = toSnakeCase(key); + return [snakeCaseKey, duration]; + } + ); + + const normalisedTimings = Object.fromEntries(normalisedTimingsArray); + analytics.track({ + ...getTelemetryUserIdentity(), + event: 'Startup Time', + properties: { + ...trackProperties, + is_interactive: args.isInteractive, + ...normalisedTimings, + }, + }); + }); + bus.on( 'mongosh:new-user', function (newTelemetryUserIdentity: { diff --git a/packages/shell-evaluator/package.json b/packages/shell-evaluator/package.json index 4aeeb5288..c572642bb 100644 --- a/packages/shell-evaluator/package.json +++ b/packages/shell-evaluator/package.json @@ -38,6 +38,7 @@ "@mongodb-js/eslint-config-mongosh": "^1.0.0", "@mongodb-js/prettier-config-devtools": "^1.0.1", "@mongodb-js/tsconfig-mongosh": "^1.0.0", + "@mongosh/types": "0.0.0-dev.0", "@types/sinon-chai": "^3.2.4", "depcheck": "^1.4.3", "eslint": "^7.25.0", diff --git a/packages/shell-evaluator/src/shell-evaluator.ts b/packages/shell-evaluator/src/shell-evaluator.ts index 73f05177f..6b53d3ff2 100644 --- a/packages/shell-evaluator/src/shell-evaluator.ts +++ b/packages/shell-evaluator/src/shell-evaluator.ts @@ -13,6 +13,7 @@ type EvaluationFunction = ( ) => Promise; import { HIDDEN_COMMANDS, redactSensitiveData } from '@mongosh/history'; +import { TimingCategories, type TimingCategory } from '@mongosh/types'; let hasAlreadyRunGlobalRuntimeSupportEval = false; // `v8.startupSnapshot` is currently untyped, might as well use `any`. @@ -37,12 +38,12 @@ class ShellEvaluator { private resultHandler: ResultHandler; private hasAppliedAsyncWriterRuntimeSupport = true; private asyncWriter: AsyncWriter; - private markTime?: (label: string) => void; + private markTime?: (category: TimingCategory, label: string) => void; constructor( instanceState: ShellInstanceState, resultHandler: ResultHandler = toShellResult as any, - markTime?: (label: string) => void + markTime?: (category: TimingCategory, label: string) => void ) { this.instanceState = instanceState; this.resultHandler = resultHandler; @@ -86,9 +87,9 @@ class ShellEvaluator { return shellApi[cmd](...argv); } - this.markTime?.('start async rewrite'); + this.markTime?.(TimingCategories.AsyncRewrite, 'start async rewrite'); let rewrittenInput = this.asyncWriter.process(input); - this.markTime?.('done async rewrite'); + this.markTime?.(TimingCategories.AsyncRewrite, 'done async rewrite'); const hiddenCommands = RegExp(HIDDEN_COMMANDS, 'g'); if (!hiddenCommands.test(input) && !hiddenCommands.test(rewrittenInput)) { @@ -99,7 +100,10 @@ class ShellEvaluator { if (!this.hasAppliedAsyncWriterRuntimeSupport) { this.hasAppliedAsyncWriterRuntimeSupport = true; - this.markTime?.('start runtimeSupportCode processing'); + this.markTime?.( + TimingCategories.AsyncRewrite, + 'start runtimeSupportCode processing' + ); const supportCode = this.asyncWriter.runtimeSupportCode(); // Eval twice: We need the modified prototypes to be present in both // the evaluation context and the current one, because e.g. the value of @@ -109,16 +113,26 @@ class ShellEvaluator { if (!hasAlreadyRunGlobalRuntimeSupportEval) { eval(supportCode); } - this.markTime?.('done global runtimeSupportCode processing'); + this.markTime?.( + TimingCategories.AsyncRewrite, + 'done global runtimeSupportCode processing' + ); rewrittenInput = supportCode + ';\n' + rewrittenInput; } try { + this.markTime?.( + TimingCategories.Eval, + 'started evaluating processed code' + ); return await originalEval(rewrittenInput, context, filename); } catch (err: any) { throw this.instanceState.transformError(err); } finally { - this.markTime?.('finished evaluating processed code'); + this.markTime?.( + TimingCategories.Eval, + 'finished evaluating processed code' + ); } } diff --git a/packages/types/src/index.ts b/packages/types/src/index.ts index b94a0850f..1ec9990db 100644 --- a/packages/types/src/index.ts +++ b/packages/types/src/index.ts @@ -174,12 +174,24 @@ export interface FetchingUpdateMetadataCompleteEvent { latest: string | null; } +export interface SessionStartedEvent { + isInteractive: boolean; + timings: { + [category: string]: number; + }; +} + export interface MongoshBusEventsMap extends ConnectEventMap { /** * Signals a connection to a MongoDB instance has been established * or the used database changed. */ 'mongosh:connect': (ev: ConnectEvent) => void; + /** + * Signals when a session is started, that will enable the REPL on interactive + * sessions or close on non-interactive sessions. + */ + 'mongosh:start-session': (ev: SessionStartedEvent) => void; /** * Signals that the shell is started by a new user. */ @@ -585,3 +597,25 @@ function isValidUrl(url: string): boolean { /* eslint-enable @typescript-eslint/ban-ts-comment */ return true; // Currently no overlap between URL-less environments and environments with config options. } + +export const TimingCategories = { + REPLInstantiation: 'REPLInstantiation', + UserConfigLoading: 'UserConfigLoading', + DriverSetup: 'DriverSetup', + Logging: 'Logging', + SnippetLoading: 'SnippetLoading', + Snapshot: 'Snapshot', + ResourceFileLoading: 'ResourceFileLoading', + AsyncRewrite: 'AsyncRewrite', + Eval: 'Eval', + EvalFile: 'EvalFile', + Telemetry: 'Telemetry', + Main: 'Main', +} as const; + +export type TimingCategory = + (typeof TimingCategories)[keyof typeof TimingCategories]; +export type TimingInterface = { + markTime: (category: TimingCategory, label: string) => void; + getTimingData: () => [string, string, number][]; +};