Skip to content

Commit

Permalink
perf(NODE-5854): Conditional logger instantiation and precompute will…
Browse files Browse the repository at this point in the history
…Log perf fix (#3984)

Co-authored-by: Alena Khineika <alena.khineika@gmail.com>
Co-authored-by: Durran Jordan <durran@gmail.com>
  • Loading branch information
3 people committed Feb 9, 2024
1 parent ca3780a commit a63fbc2
Show file tree
Hide file tree
Showing 9 changed files with 133 additions and 59 deletions.
2 changes: 1 addition & 1 deletion src/cmap/connection.ts
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
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
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
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
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
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
@@ -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
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

0 comments on commit a63fbc2

Please sign in to comment.