From f1bd72e972a4d7df9a37423bcb06c5a199af40f7 Mon Sep 17 00:00:00 2001 From: Kevin Mas Ruiz Date: Wed, 29 Nov 2023 14:57:09 +0100 Subject: [PATCH 01/10] chore: refactor and add categorisation to marks --- package-lock.json | 4 +- packages/cli-repl/src/cli-repl.ts | 64 +++++++++------ packages/cli-repl/src/mongosh-repl.ts | 24 +++--- packages/cli-repl/src/run.ts | 7 +- packages/cli-repl/src/startup-timing.spec.ts | 22 +++++ packages/cli-repl/src/startup-timing.ts | 80 ++++++++++++------- packages/shell-evaluator/package.json | 3 +- .../shell-evaluator/src/shell-evaluator.ts | 28 +++++-- packages/types/src/index.ts | 34 ++++++++ 9 files changed, 190 insertions(+), 76 deletions(-) create mode 100644 packages/cli-repl/src/startup-timing.spec.ts diff --git a/package-lock.json b/package-lock.json index 0f716eecb..26e4fae2d 100644 --- a/package-lock.json +++ b/package-lock.json @@ -31575,7 +31575,8 @@ "dependencies": { "@mongosh/async-rewriter2": "0.0.0-dev.0", "@mongosh/history": "0.0.0-dev.0", - "@mongosh/shell-api": "0.0.0-dev.0" + "@mongosh/shell-api": "0.0.0-dev.0", + "@mongosh/types": "0.0.0-dev.0" }, "devDependencies": { "@mongodb-js/eslint-config-mongosh": "^1.0.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..55865b897 100644 --- a/packages/cli-repl/src/cli-repl.ts +++ b/packages/cli-repl/src/cli-repl.ts @@ -37,7 +37,11 @@ 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'; @@ -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,7 +409,7 @@ export class CliRepl implements MongoshIOProvider { this.mongoshRepl ), }); - markTime('set up editor'); + markTime(TimingCategories.REPLInstantiation, 'set up editor'); if (willExecuteCommandLineScripts) { this.mongoshRepl.setIsInteractive(willEnterInteractiveMode); @@ -413,6 +420,7 @@ export class CliRepl implements MongoshIOProvider { commandLineLoadFiles, evalScripts ); + // HERE! if (exitCode !== 0) { await this.exit(exitCode); return; @@ -440,12 +448,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 +463,9 @@ 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); + // HERE } injectReplFunctions(): void { @@ -537,7 +548,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 +556,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 +595,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 +605,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 +990,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 +1010,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 +1019,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 +1037,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..b32026bfc --- /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', function () { + const timingData: [TimingCategory, string, number][] = [ + [TimingCategories.REPLInstantiation, '1 REPL', 50], + [TimingCategories.Main, '1 Main', 50], + [TimingCategories.REPLInstantiation, '2 REPL', 150], + [TimingCategories.Main, '2 Main', 90], + ]; + + const summary = summariseTimingData(timingData); + expect(summary).to.deep.equal([ + [TimingCategories.REPLInstantiation, 150], + [TimingCategories.Main, 90], + ]); + }); + }); +}); diff --git a/packages/cli-repl/src/startup-timing.ts b/packages/cli-repl/src/startup-timing.ts index 0da279cda..b73545001 100644 --- a/packages/cli-repl/src/startup-timing.ts +++ b/packages/cli-repl/src/startup-timing.ts @@ -1,30 +1,53 @@ -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: [TimingCategory, string, number][] +): [TimingCategory, number][] { + const durationByCategory = new Map(); + + // eslint-disable-next-line @typescript-eslint/no-unused-vars + for (const [category, _, time] of timingData) { + const duration = Math.max((durationByCategory.get(category) || 0, time)); + durationByCategory.set(category, duration); + } + + return Array.from(durationByCategory.entries()); +} +const timing: TimingInterface = linkTimingInterface(); export const markTime = timing.markTime; export const getTimingData = timing.getTimingData; @@ -35,11 +58,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 +71,4 @@ if (process.env.MONGOSH_SHOW_TIMING_DATA) { }); } -markTime('cli-repl timing initialized'); +markTime(TimingCategories.REPLInstantiation, 'cli-repl timing initialized'); diff --git a/packages/shell-evaluator/package.json b/packages/shell-evaluator/package.json index 4aeeb5288..a82884509 100644 --- a/packages/shell-evaluator/package.json +++ b/packages/shell-evaluator/package.json @@ -46,6 +46,7 @@ "dependencies": { "@mongosh/async-rewriter2": "0.0.0-dev.0", "@mongosh/history": "0.0.0-dev.0", - "@mongosh/shell-api": "0.0.0-dev.0" + "@mongosh/shell-api": "0.0.0-dev.0", + "@mongosh/types": "0.0.0-dev.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][]; +}; From 79f2a7092bd8eca59106fa37c667cd43d9d249c8 Mon Sep 17 00:00:00 2001 From: Kevin Mas Ruiz Date: Wed, 29 Nov 2023 15:07:14 +0100 Subject: [PATCH 02/10] chore: connect startup with session started event --- packages/cli-repl/src/cli-repl.ts | 13 +++++++-- packages/cli-repl/src/startup-timing.spec.ts | 20 ++++++------- packages/cli-repl/src/startup-timing.ts | 21 +++++++------- .../logging/src/setup-logger-and-telemetry.ts | 28 +++++++++++++++++++ 4 files changed, 58 insertions(+), 24 deletions(-) diff --git a/packages/cli-repl/src/cli-repl.ts b/packages/cli-repl/src/cli-repl.ts index 55865b897..58965ca21 100644 --- a/packages/cli-repl/src/cli-repl.ts +++ b/packages/cli-repl/src/cli-repl.ts @@ -47,7 +47,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'; +import { getTimingData, markTime, summariseTimingData } from './startup-timing'; /** * Connecting text key. @@ -420,7 +420,11 @@ export class CliRepl implements MongoshIOProvider { commandLineLoadFiles, evalScripts ); - // HERE! + + this.bus.emit('mongosh:start-session', { + isInteractive: false, + timings: summariseTimingData(getTimingData()), + }); if (exitCode !== 0) { await this.exit(exitCode); return; @@ -465,7 +469,10 @@ export class CliRepl implements MongoshIOProvider { this.bus.emit('mongosh:start-mongosh-repl', { version }); markTime(TimingCategories.REPLInstantiation, 'starting repl'); await this.mongoshRepl.startRepl(initialized); - // HERE + this.bus.emit('mongosh:start-session', { + isInteractive: true, + timings: summariseTimingData(getTimingData()), + }); } injectReplFunctions(): void { diff --git a/packages/cli-repl/src/startup-timing.spec.ts b/packages/cli-repl/src/startup-timing.spec.ts index b32026bfc..fdcef5ab5 100644 --- a/packages/cli-repl/src/startup-timing.spec.ts +++ b/packages/cli-repl/src/startup-timing.spec.ts @@ -2,21 +2,21 @@ import { TimingCategories, type TimingCategory } from '@mongosh/types'; import { summariseTimingData } from './startup-timing'; import { expect } from 'chai'; -describe('startup timing', function () { +describe.only('startup timing', function () { describe('summariseTimingData', function () { - it('should calculate durations of each category', function () { + it('should calculate durations of each category in milliseconds', function () { const timingData: [TimingCategory, string, number][] = [ - [TimingCategories.REPLInstantiation, '1 REPL', 50], - [TimingCategories.Main, '1 Main', 50], - [TimingCategories.REPLInstantiation, '2 REPL', 150], - [TimingCategories.Main, '2 Main', 90], + [TimingCategories.REPLInstantiation, '1 REPL', 50000000], + [TimingCategories.Main, '1 Main', 50000000], + [TimingCategories.REPLInstantiation, '2 REPL', 150000000], + [TimingCategories.Main, '2 Main', 90000000], ]; const summary = summariseTimingData(timingData); - expect(summary).to.deep.equal([ - [TimingCategories.REPLInstantiation, 150], - [TimingCategories.Main, 90], - ]); + expect(summary).to.deep.equal({ + [TimingCategories.REPLInstantiation]: 150, + [TimingCategories.Main]: 90, + }); }); }); }); diff --git a/packages/cli-repl/src/startup-timing.ts b/packages/cli-repl/src/startup-timing.ts index b73545001..9873c0282 100644 --- a/packages/cli-repl/src/startup-timing.ts +++ b/packages/cli-repl/src/startup-timing.ts @@ -1,8 +1,4 @@ -import { - TimingCategories, - type TimingCategory, - type TimingInterface, -} from '@mongosh/types'; +import { TimingCategories, type TimingInterface } from '@mongosh/types'; const jsTimingEntries: [string, string, bigint][] = []; @@ -33,18 +29,21 @@ function linkTimingInterface(): TimingInterface { }; } -export function summariseTimingData( - timingData: [TimingCategory, string, number][] -): [TimingCategory, number][] { - const durationByCategory = new Map(); +export function summariseTimingData(timingData: [string, string, number][]): { + [key: string]: number; +} { + const durationByCategory = new Map(); // eslint-disable-next-line @typescript-eslint/no-unused-vars for (const [category, _, time] of timingData) { - const duration = Math.max((durationByCategory.get(category) || 0, time)); + const timeInMs = time / 1_000_000; + const duration = Math.max( + (durationByCategory.get(category) || 0, timeInMs) + ); durationByCategory.set(category, duration); } - return Array.from(durationByCategory.entries()); + return Object.fromEntries(durationByCategory.entries()); } const timing: TimingInterface = linkTimingInterface(); diff --git a/packages/logging/src/setup-logger-and-telemetry.ts b/packages/logging/src/setup-logger-and-telemetry.ts index 40968a248..80d870487 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'; @@ -146,6 +147,33 @@ export function setupLoggerAndTelemetry( }); }); + bus.on('mongosh:start-session', function (args: SessionStartedEvent) { + const params = { + session_id, + userId, + telemetryAnonymousId, + ...args, + }; + + log.info( + 'MONGOSH', + mongoLogId(1_000_000_004), + 'session', + 'Session started', + params + ); + + analytics.track({ + ...getTelemetryUserIdentity(), + event: 'Startup Time', + properties: { + ...trackProperties, + isInteractive: args.isInteractive, + ...args.timings, + }, + }); + }); + bus.on( 'mongosh:new-user', function (newTelemetryUserIdentity: { From d89a18f078aeb3159fa4d7cfbafe722bce7e05f9 Mon Sep 17 00:00:00 2001 From: Kevin Mas Ruiz Date: Wed, 29 Nov 2023 15:07:25 +0100 Subject: [PATCH 03/10] chore: remove .only --- packages/cli-repl/src/startup-timing.spec.ts | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/packages/cli-repl/src/startup-timing.spec.ts b/packages/cli-repl/src/startup-timing.spec.ts index fdcef5ab5..6add75965 100644 --- a/packages/cli-repl/src/startup-timing.spec.ts +++ b/packages/cli-repl/src/startup-timing.spec.ts @@ -2,7 +2,7 @@ import { TimingCategories, type TimingCategory } from '@mongosh/types'; import { summariseTimingData } from './startup-timing'; import { expect } from 'chai'; -describe.only('startup timing', function () { +describe('startup timing', function () { describe('summariseTimingData', function () { it('should calculate durations of each category in milliseconds', function () { const timingData: [TimingCategory, string, number][] = [ From 0f76f9fa02bfcb0ad69d393a86a4fc3ec35de0e4 Mon Sep 17 00:00:00 2001 From: Kevin Mas Ruiz Date: Wed, 29 Nov 2023 16:43:35 +0100 Subject: [PATCH 04/10] chore: fix names and duration calculation --- packages/cli-repl/src/startup-timing.spec.ts | 10 +++--- packages/cli-repl/src/startup-timing.ts | 12 ++++--- .../src/setup-logger-and-telemetry.spec.ts | 22 ++++++++++++ .../logging/src/setup-logger-and-telemetry.ts | 34 +++++++++++-------- 4 files changed, 53 insertions(+), 25 deletions(-) diff --git a/packages/cli-repl/src/startup-timing.spec.ts b/packages/cli-repl/src/startup-timing.spec.ts index 6add75965..7cdd7a82e 100644 --- a/packages/cli-repl/src/startup-timing.spec.ts +++ b/packages/cli-repl/src/startup-timing.spec.ts @@ -7,15 +7,15 @@ describe('startup timing', 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', 50000000], - [TimingCategories.REPLInstantiation, '2 REPL', 150000000], - [TimingCategories.Main, '2 Main', 90000000], + [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]: 150, - [TimingCategories.Main]: 90, + [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 9873c0282..112ed8817 100644 --- a/packages/cli-repl/src/startup-timing.ts +++ b/packages/cli-repl/src/startup-timing.ts @@ -33,14 +33,16 @@ export function summariseTimingData(timingData: [string, 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 timeInMs = time / 1_000_000; - const duration = Math.max( - (durationByCategory.get(category) || 0, timeInMs) - ); - durationByCategory.set(category, duration); + 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()); diff --git a/packages/logging/src/setup-logger-and-telemetry.spec.ts b/packages/logging/src/setup-logger-and-telemetry.spec.ts index 51c1c0e3e..2dbedf777 100644 --- a/packages/logging/src/setup-logger-and-telemetry.spec.ts +++ b/packages/logging/src/setup-logger-and-telemetry.spec.ts @@ -60,6 +60,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 +388,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 80d870487..47397cd1e 100644 --- a/packages/logging/src/setup-logger-and-telemetry.ts +++ b/packages/logging/src/setup-logger-and-telemetry.ts @@ -147,29 +147,33 @@ export function setupLoggerAndTelemetry( }); }); - bus.on('mongosh:start-session', function (args: SessionStartedEvent) { - const params = { - session_id, - userId, - telemetryAnonymousId, - ...args, - }; + const 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; + } - log.info( - 'MONGOSH', - mongoLogId(1_000_000_004), - 'session', - 'Session started', - params + return matches.map((x) => x.toLowerCase()).join('_'); + }; + + 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, - isInteractive: args.isInteractive, - ...args.timings, + is_interactive: args.isInteractive, + ...normalisedTimings, }, }); }); From d9667e69931a4fe1b29970c161139cc46bceef4a Mon Sep 17 00:00:00 2001 From: Kevin Mas Ruiz Date: Thu, 30 Nov 2023 12:24:35 +0100 Subject: [PATCH 05/10] chore: apply suggestions from PR --- .../src/setup-logger-and-telemetry.spec.ts | 23 +++++++++++++++++++ .../logging/src/setup-logger-and-telemetry.ts | 22 +++++++++--------- packages/shell-evaluator/package.json | 4 ++-- 3 files changed, 36 insertions(+), 13 deletions(-) diff --git a/packages/logging/src/setup-logger-and-telemetry.spec.ts b/packages/logging/src/setup-logger-and-telemetry.spec.ts index 2dbedf777..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[]; diff --git a/packages/logging/src/setup-logger-and-telemetry.ts b/packages/logging/src/setup-logger-and-telemetry.ts index 47397cd1e..d3b1f6df7 100644 --- a/packages/logging/src/setup-logger-and-telemetry.ts +++ b/packages/logging/src/setup-logger-and-telemetry.ts @@ -59,6 +59,17 @@ class MultiSet> { } } +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. * @@ -147,17 +158,6 @@ export function setupLoggerAndTelemetry( }); }); - const 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('_'); - }; - bus.on('mongosh:start-session', function (args: SessionStartedEvent) { const normalisedTimingsArray = Object.entries(args.timings).map( ([key, duration]) => { diff --git a/packages/shell-evaluator/package.json b/packages/shell-evaluator/package.json index a82884509..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", @@ -46,7 +47,6 @@ "dependencies": { "@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" + "@mongosh/shell-api": "0.0.0-dev.0" } } From b2ebf962e9dd4d12f3a4a357c7d2f018427bf004 Mon Sep 17 00:00:00 2001 From: Kevin Mas Ruiz Date: Thu, 30 Nov 2023 12:27:33 +0100 Subject: [PATCH 06/10] chore: add a jsdoc to toSnakeCase --- packages/logging/src/setup-logger-and-telemetry.ts | 14 ++++++++++++++ 1 file changed, 14 insertions(+) diff --git a/packages/logging/src/setup-logger-and-telemetry.ts b/packages/logging/src/setup-logger-and-telemetry.ts index d3b1f6df7..42ebfee2f 100644 --- a/packages/logging/src/setup-logger-and-telemetry.ts +++ b/packages/logging/src/setup-logger-and-telemetry.ts @@ -59,6 +59,20 @@ class MultiSet> { } } +/** + * It transforms a random string into snake case. Snake case is completely + * lowercase and uses '_' to separate words. For example: + * + * '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 From 86190a454161c85280c789ec474e1c4084016174 Mon Sep 17 00:00:00 2001 From: Kevin Mas Ruiz Date: Thu, 30 Nov 2023 12:33:07 +0100 Subject: [PATCH 07/10] chore: move non-interactive start session a bit earlier, before evaluating scripts --- packages/cli-repl/src/cli-repl.ts | 11 +++++++---- 1 file changed, 7 insertions(+), 4 deletions(-) diff --git a/packages/cli-repl/src/cli-repl.ts b/packages/cli-repl/src/cli-repl.ts index 58965ca21..8bc119455 100644 --- a/packages/cli-repl/src/cli-repl.ts +++ b/packages/cli-repl/src/cli-repl.ts @@ -413,18 +413,21 @@ export class CliRepl implements MongoshIOProvider { 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 ); - this.bus.emit('mongosh:start-session', { - isInteractive: false, - timings: summariseTimingData(getTimingData()), - }); if (exitCode !== 0) { await this.exit(exitCode); return; From 6796a7da0b216335b2ba694f08f0e305e7fca42b Mon Sep 17 00:00:00 2001 From: Kevin Mas Ruiz Date: Thu, 30 Nov 2023 17:01:25 +0100 Subject: [PATCH 08/10] chore: Update packages/logging/src/setup-logger-and-telemetry.ts Co-authored-by: Bailey Pearson --- packages/logging/src/setup-logger-and-telemetry.ts | 2 ++ 1 file changed, 2 insertions(+) diff --git a/packages/logging/src/setup-logger-and-telemetry.ts b/packages/logging/src/setup-logger-and-telemetry.ts index 42ebfee2f..7f3d24a10 100644 --- a/packages/logging/src/setup-logger-and-telemetry.ts +++ b/packages/logging/src/setup-logger-and-telemetry.ts @@ -63,6 +63,8 @@ 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 From 1233d5af56f9e32589dd4881346ccfff76098f79 Mon Sep 17 00:00:00 2001 From: Kevin Mas Ruiz Date: Thu, 30 Nov 2023 17:03:50 +0100 Subject: [PATCH 09/10] chore: fix package-lock.json --- package-lock.json | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/package-lock.json b/package-lock.json index 26e4fae2d..93c9bcf97 100644 --- a/package-lock.json +++ b/package-lock.json @@ -31575,13 +31575,13 @@ "dependencies": { "@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" + "@mongosh/shell-api": "0.0.0-dev.0" }, "devDependencies": { "@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", From f544ee31395a27d897ea43f3eff2fea113cd6d39 Mon Sep 17 00:00:00 2001 From: Kevin Mas Ruiz Date: Thu, 30 Nov 2023 17:05:03 +0100 Subject: [PATCH 10/10] chore: make clearer that timingData can contain TimingCategory or any other string --- packages/cli-repl/src/startup-timing.ts | 10 ++++++++-- 1 file changed, 8 insertions(+), 2 deletions(-) diff --git a/packages/cli-repl/src/startup-timing.ts b/packages/cli-repl/src/startup-timing.ts index 112ed8817..4ba4d4b41 100644 --- a/packages/cli-repl/src/startup-timing.ts +++ b/packages/cli-repl/src/startup-timing.ts @@ -1,4 +1,8 @@ -import { TimingCategories, type TimingInterface } from '@mongosh/types'; +import { + TimingCategories, + type TimingCategory, + type TimingInterface, +} from '@mongosh/types'; const jsTimingEntries: [string, string, bigint][] = []; @@ -29,7 +33,9 @@ function linkTimingInterface(): TimingInterface { }; } -export function summariseTimingData(timingData: [string, string, number][]): { +export function summariseTimingData( + timingData: [string | TimingCategory, string, number][] +): { [key: string]: number; } { const durationByCategory = new Map();