Skip to content

perf(NODE-5854): Conditional logger instantiation and precompute willLog perf fix #3984

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
merged 13 commits into from
Feb 9, 2024
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
2 changes: 1 addition & 1 deletion src/cmap/connection.ts
Original file line number Diff line number Diff line change
Expand Up @@ -280,7 +280,7 @@ export class Connection extends TypedEventEmitter<ConnectionEvents> {
(this.monitorCommands ||
(this.established &&
!this.authContext?.reauthenticating &&
this.mongoLogger?.willLog(SeverityLevel.DEBUG, MongoLoggableComponent.COMMAND))) ??
this.mongoLogger?.willLog(MongoLoggableComponent.COMMAND, SeverityLevel.DEBUG))) ??
false
);
}
Expand Down
2 changes: 1 addition & 1 deletion src/cmap/connection_pool.ts
Original file line number Diff line number Diff line change
Expand Up @@ -251,7 +251,7 @@ export class ConnectionPool extends TypedEventEmitter<ConnectionPoolEvents> {
this[kMetrics] = new ConnectionPoolMetrics();
this[kProcessingWaitQueue] = false;

this.mongoLogger = this[kServer].topology.client.mongoLogger;
this.mongoLogger = this[kServer].topology.client?.mongoLogger;
this.component = 'connection';

process.nextTick(() => {
Expand Down
17 changes: 12 additions & 5 deletions src/mongo_client.ts
Original file line number Diff line number Diff line change
Expand Up @@ -25,7 +25,8 @@ import {
type LogComponentSeveritiesClientOptions,
type MongoDBLogWritable,
MongoLogger,
type MongoLoggerOptions
type MongoLoggerOptions,
SeverityLevel
} from './mongo_logger';
import { TypedEventEmitter } from './mongo_types';
import { executeOperation } from './operations/execute_operation';
Expand Down Expand Up @@ -345,7 +346,7 @@ export class MongoClient extends TypedEventEmitter<MongoClientEvents> {
/** @internal */
topology?: Topology;
/** @internal */
override readonly mongoLogger: MongoLogger;
override readonly mongoLogger: MongoLogger | undefined;
/** @internal */
private connectionLock?: Promise<this>;

Expand All @@ -359,7 +360,13 @@ export class MongoClient extends TypedEventEmitter<MongoClientEvents> {
super();

this[kOptions] = parseOptions(url, this, options);
this.mongoLogger = new MongoLogger(this[kOptions].mongoLoggerOptions);

const shouldSetLogger = Object.values(
this[kOptions].mongoLoggerOptions.componentSeverities
).some(value => value !== SeverityLevel.OFF);
this.mongoLogger = shouldSetLogger
? new MongoLogger(this[kOptions].mongoLoggerOptions)
: undefined;

// eslint-disable-next-line @typescript-eslint/no-this-alias
const client = this;
Expand Down Expand Up @@ -405,9 +412,9 @@ export class MongoClient extends TypedEventEmitter<MongoClientEvents> {
const srvHostIsCosmosDB = isHostMatch(COSMOS_DB_CHECK, this[kOptions].srvHost);

if (documentDBHostnames.length !== 0 || srvHostIsDocumentDB) {
this.mongoLogger.info('client', DOCUMENT_DB_MSG);
this.mongoLogger?.info('client', DOCUMENT_DB_MSG);
} else if (cosmosDBHostnames.length !== 0 || srvHostIsCosmosDB) {
this.mongoLogger.info('client', COSMOS_DB_MSG);
this.mongoLogger?.info('client', COSMOS_DB_MSG);
}
}

Expand Down
28 changes: 23 additions & 5 deletions src/mongo_logger.ts
Original file line number Diff line number Diff line change
Expand Up @@ -728,6 +728,7 @@ export class MongoLogger {
logDestination: MongoDBLogWritable;
logDestinationIsStdErr: boolean;
pendingLog: PromiseLike<unknown> | unknown = null;
private severities: Record<MongoLoggableComponent, Record<SeverityLevel, boolean>>;

/**
* This method should be used when logging errors that do not have a public driver API for
Expand Down Expand Up @@ -760,15 +761,27 @@ export class MongoLogger {
this.maxDocumentLength = options.maxDocumentLength;
this.logDestination = options.logDestination;
this.logDestinationIsStdErr = options.logDestinationIsStdErr;
this.severities = this.createLoggingSeverities();
}

willLog(severity: SeverityLevel, component: MongoLoggableComponent): boolean {
return compareSeverity(severity, this.componentSeverities[component]) <= 0;
createLoggingSeverities(): Record<MongoLoggableComponent, Record<SeverityLevel, boolean>> {
const severities = Object();
for (const component of Object.values(MongoLoggableComponent)) {
severities[component] = {};
for (const severityLevel of Object.values(SeverityLevel)) {
severities[component][severityLevel] =
compareSeverity(severityLevel, this.componentSeverities[component]) <= 0;
}
}
return severities;
}

turnOffSeverities() {
for (const key of Object.values(MongoLoggableComponent)) {
this.componentSeverities[key as MongoLoggableComponent] = SeverityLevel.OFF;
for (const component of Object.values(MongoLoggableComponent)) {
this.componentSeverities[component] = SeverityLevel.OFF;
for (const severityLevel of Object.values(SeverityLevel)) {
this.severities[component][severityLevel] = false;
}
}
}

Expand Down Expand Up @@ -797,12 +810,17 @@ export class MongoLogger {
this.pendingLog = null;
}

willLog(component: MongoLoggableComponent, severity: SeverityLevel): boolean {
if (severity === SeverityLevel.OFF) return false;
return this.severities[component][severity];
}

private log(
severity: SeverityLevel,
component: MongoLoggableComponent,
message: Loggable | string
): void {
if (!this.willLog(severity, component)) return;
if (!this.willLog(component, severity)) return;

let logMessage: Log = { t: new Date(), c: component, s: severity };
if (typeof message === 'string') {
Expand Down
2 changes: 1 addition & 1 deletion src/sdam/monitor.ts
Original file line number Diff line number Diff line change
Expand Up @@ -120,7 +120,7 @@ export class Monitor extends TypedEventEmitter<MonitorEvents> {
serverMonitoringMode: options.serverMonitoringMode
});
this.isRunningInFaasEnv = getFAASEnv() != null;
this.mongoLogger = this[kServer].topology.client.mongoLogger;
this.mongoLogger = this[kServer].topology.client?.mongoLogger;

const cancellationToken = this[kCancellationToken];
// TODO: refactor this to pull it directly from the pool, requires new ConnectionPool integration
Expand Down
18 changes: 9 additions & 9 deletions src/sdam/topology.ts
Original file line number Diff line number Diff line change
Expand Up @@ -102,7 +102,7 @@ export type ServerSelectionCallback = Callback<Server>;
export interface ServerSelectionRequest {
serverSelector: ServerSelector;
topologyDescription: TopologyDescription;
mongoLogger: MongoLogger;
mongoLogger: MongoLogger | undefined;
transaction?: Transaction;
startTime: number;
callback: ServerSelectionCallback;
Expand Down Expand Up @@ -568,7 +568,7 @@ export class Topology extends TypedEventEmitter<TopologyEvents> {
}

options = { serverSelectionTimeoutMS: this.s.serverSelectionTimeoutMS, ...options };
this.client.mongoLogger.debug(
this.client.mongoLogger?.debug(
MongoLoggableComponent.SERVER_SELECTION,
new ServerSelectionStartedEvent(selector, this.description, options.operationName)
);
Expand All @@ -578,7 +578,7 @@ export class Topology extends TypedEventEmitter<TopologyEvents> {
const transaction = session && session.transaction;

if (isSharded && transaction && transaction.server) {
this.client.mongoLogger.debug(
this.client.mongoLogger?.debug(
MongoLoggableComponent.SERVER_SELECTION,
new ServerSelectionSucceededEvent(
selector,
Expand Down Expand Up @@ -611,7 +611,7 @@ export class Topology extends TypedEventEmitter<TopologyEvents> {
`Server selection timed out after ${options.serverSelectionTimeoutMS} ms`,
this.description
);
this.client.mongoLogger.debug(
this.client.mongoLogger?.debug(
MongoLoggableComponent.SERVER_SELECTION,
new ServerSelectionFailedEvent(
selector,
Expand Down Expand Up @@ -896,7 +896,7 @@ function drainWaitQueue(queue: List<ServerSelectionRequest>, err?: MongoDriverEr

if (!waitQueueMember[kCancelled]) {
if (err) {
waitQueueMember.mongoLogger.debug(
waitQueueMember.mongoLogger?.debug(
MongoLoggableComponent.SERVER_SELECTION,
new ServerSelectionFailedEvent(
waitQueueMember.serverSelector,
Expand Down Expand Up @@ -943,7 +943,7 @@ function processWaitQueue(topology: Topology) {
: serverDescriptions;
} catch (e) {
waitQueueMember.timeoutController.clear();
topology.client.mongoLogger.debug(
topology.client.mongoLogger?.debug(
MongoLoggableComponent.SERVER_SELECTION,
new ServerSelectionFailedEvent(
waitQueueMember.serverSelector,
Expand All @@ -959,7 +959,7 @@ function processWaitQueue(topology: Topology) {
let selectedServer: Server | undefined;
if (selectedDescriptions.length === 0) {
if (!waitQueueMember.waitingLogged) {
topology.client.mongoLogger.info(
topology.client.mongoLogger?.info(
MongoLoggableComponent.SERVER_SELECTION,
new WaitingForSuitableServerEvent(
waitQueueMember.serverSelector,
Expand Down Expand Up @@ -992,7 +992,7 @@ function processWaitQueue(topology: Topology) {
'server selection returned a server description but the server was not found in the topology',
topology.description
);
topology.client.mongoLogger.debug(
topology.client.mongoLogger?.debug(
MongoLoggableComponent.SERVER_SELECTION,
new ServerSelectionFailedEvent(
waitQueueMember.serverSelector,
Expand All @@ -1011,7 +1011,7 @@ function processWaitQueue(topology: Topology) {

waitQueueMember.timeoutController.clear();

topology.client.mongoLogger.debug(
topology.client.mongoLogger?.debug(
MongoLoggableComponent.SERVER_SELECTION,
new ServerSelectionSucceededEvent(
waitQueueMember.serverSelector,
Expand Down
43 changes: 11 additions & 32 deletions test/integration/node-specific/feature_flags.test.ts
Original file line number Diff line number Diff line change
@@ -1,6 +1,6 @@
import { expect } from 'chai';

import { MongoClient, type MongoLoggableComponent, SeverityLevel } from '../../mongodb';
import { MongoClient, SeverityLevel } from '../../mongodb';

describe('Feature Flags', () => {
describe('@@mdb.skipPingOnConnect', () => {
Expand Down Expand Up @@ -45,16 +45,10 @@ describe('Feature Flags', () => {
}
});

// TODO(NODE-5672): Release Standardized Logger
describe('@@mdb.enableMongoLogger', () => {
let cachedEnv;
const loggerFeatureFlag = Symbol.for('@@mdb.enableMongoLogger');
const components: Array<MongoLoggableComponent | 'default'> = [
'default',
'topology',
'serverSelection',
'connection',
'command'
];

before(() => {
cachedEnv = process.env;
Expand All @@ -74,7 +68,7 @@ describe('Feature Flags', () => {
const client = new MongoClient('mongodb://localhost:27017', {
[loggerFeatureFlag]: true
});
expect(client.mongoLogger.componentSeverities).to.have.property(
expect(client.mongoLogger?.componentSeverities).to.have.property(
'command',
SeverityLevel.EMERGENCY
);
Expand All @@ -86,16 +80,11 @@ describe('Feature Flags', () => {
process.env = {};
});

it('does not enable logging for any component', () => {
it('does not create logger', () => {
const client = new MongoClient('mongodb://localhost:27017', {
[loggerFeatureFlag]: true
});
for (const component of components) {
expect(client.mongoLogger.componentSeverities).to.have.property(
component,
SeverityLevel.OFF
);
}
expect(client.mongoLogger).to.not.exist;
});
});
});
Expand All @@ -107,16 +96,11 @@ describe('Feature Flags', () => {
process.env['MONGODB_LOG_COMMAND'] = SeverityLevel.EMERGENCY;
});

it('does not enable logging', () => {
it('does not instantiate logger', () => {
const client = new MongoClient('mongodb://localhost:27017', {
[loggerFeatureFlag]: featureFlagValue
});
for (const component of components) {
expect(client.mongoLogger.componentSeverities).to.have.property(
component,
SeverityLevel.OFF
);
}
expect(client.mongoLogger).to.not.exist;
});
});

Expand All @@ -125,16 +109,11 @@ describe('Feature Flags', () => {
process.env = {};
});

it('does not enable logging', () => {
it('does not instantiate logger', () => {
const client = new MongoClient('mongodb://localhost:27017', {
[loggerFeatureFlag]: featureFlagValue
});
for (const component of components) {
expect(client.mongoLogger.componentSeverities).to.have.property(
component,
SeverityLevel.OFF
);
}
expect(client.mongoLogger).to.not.exist;
});
});
});
Expand Down Expand Up @@ -162,7 +141,7 @@ describe('Feature Flags', () => {
[Symbol.for('@@mdb.internalLoggerConfig')]: undefined
});

expect(client.mongoLogger.componentSeverities).to.have.property(
expect(client.mongoLogger?.componentSeverities).to.have.property(
'command',
SeverityLevel.EMERGENCY
);
Expand All @@ -178,7 +157,7 @@ describe('Feature Flags', () => {
}
});

expect(client.mongoLogger.componentSeverities).to.have.property(
expect(client.mongoLogger?.componentSeverities).to.have.property(
'command',
SeverityLevel.ALERT
);
Expand Down
13 changes: 8 additions & 5 deletions test/unit/mongo_client.test.js
Original file line number Diff line number Diff line change
Expand Up @@ -800,7 +800,10 @@ describe('MongoOptions', function () {
context('loggingOptions', function () {
const expectedLoggingObject = {
maxDocumentLength: 20,
logDestination: new Writable()
logDestination: new Writable(),
componentSeverities: Object.fromEntries(
Object.values(MongoLoggableComponent).map(([value]) => [value, SeverityLevel.OFF])
)
};

before(() => {
Expand Down Expand Up @@ -1075,9 +1078,9 @@ describe('MongoOptions', function () {
).to.not.throw(MongoAPIError);
const client = new MongoClient('mongodb://a/', {
[loggerFeatureFlag]: true,
mongodbLogComponentSeverities: {}
mongodbLogComponentSeverities: { client: 'error' } // dummy so logger doesn't turn on
});
expect(client.mongoLogger.componentSeverities.default).to.equal('off');
expect(client.mongoLogger?.componentSeverities.command).to.equal('off');
});
});
context('when valid client option is provided', function () {
Expand All @@ -1091,9 +1094,9 @@ describe('MongoOptions', function () {
).to.not.throw(MongoAPIError);
const client = new MongoClient('mongodb://a/', {
[loggerFeatureFlag]: true,
mongodbLogComponentSeverities: { default: 'emergency' }
mongodbLogComponentSeverities: { command: 'emergency' }
});
expect(client.mongoLogger.componentSeverities.default).to.equal('emergency');
expect(client.mongoLogger?.componentSeverities.command).to.equal('emergency');
});
});
});
Expand Down
Loading