I recently found myself working on a little side project and needed a way to log the mongoose query and keep track of how long the queries took, because they took a long time. Ideally, you’d have an APM tool like Sentry or otherwise set up, but that would have been overkill, so this article is my lazy approach to building a MongoDB/Mongoose profiler. USER SCHEMA USER SCHEMA USER SCHEMA Given a generic User details schema as below // user.schema.ts

type IUser {
 _id: string;
 name: string;
 email: string;
}

const UserSchema = new Schema<IUser>(
{
  name: { type: String, required: true },
  email: { type: String, required: true }
},
{ timestamps: true }
)

const user = model<IUser>('user', UserSchema); // user.schema.ts

type IUser {
 _id: string;
 name: string;
 email: string;
}

const UserSchema = new Schema<IUser>(
{
  name: { type: String, required: true },
  email: { type: String, required: true }
},
{ timestamps: true }
)

const user = model<IUser>('user', UserSchema); This schema is a generic user schema to keep track of the  user name and email, which is quite adequate for our use case. THE PROFILER THE PROFILER THE PROFILER The code block below is the implementation of the basic profiler // mongoose-profiler.ts

const redactConditionsValue = (conditions: Record<string, any>): void => {
  const keys = Object.keys(conditions);
  keys.forEach((key) => {
    conditions[key] = 'REDACTED';
  });
};

export const mongooseProfiler = (schema: Schema) => {
  schema.pre(/^find/, function (this: any, next: () => void) {
    this._startTime = process.hrtime();
    next();
  });

  schema.post(/^find/, function (this: any, _result: any, next: () => void) {
    const start = this._startTime;
    if (start) {
      const diff = process.hrtime(start);
      const durationMs = (diff[0] * 1e3 + diff[1] / 1e6).toFixed(2);
      const modelName = this.model?.modelName || 'UnknownModel';
      const operation = this.op || 'unknownOp';

      redactConditionsValue(this._conditions);
      logger.info(`[Mongoose] ${modelName}.${operation}, conditions: ${JSON.stringify(this._conditions)} duration ${durationMs}ms`);
    }
    next();
  });

  schema.pre('distinct', function (this: any, next: () => void) {
    this._startTime = process.hrtime();
    next();
  });

  schema.post('distinct', function (this: any, _result: any, next: () => void) {
    const start = this._startTime;
    if (start) {
      const diff = process.hrtime(start);
      const durationMs = (diff[0] * 1e3 + diff[1] / 1e6).toFixed(2);
      const modelName = this.model?.modelName || 'UnknownModel';
      const operation = this.op || 'unknownOp';

      redactConditionsValue(this._conditions);
      logger.info(
        `[Mongoose] ${modelName}.${operation}, conditions: ${JSON.stringify(this._conditions)}, distinct: ${this._distinct} duration ${durationMs}ms`
      );
    }
    next();
  });

  schema.pre('aggregate', function (this: any, next: () => void) {
    this._startTime = process.hrtime();
    next();
  });

  schema.post('aggregate', function (this: any, _result: any, next: () => void) {
    const start = this._startTime;
    if (start) {
      const diff = process.hrtime(start);
      const durationMs = (diff[0] * 1e3 + diff[1] / 1e6).toFixed(2);
      const modelName = this._model?.modelName || 'UnknownModel';
      redactConditionsValue(this.pipeline());
      logger.info(`[Mongoose] ${modelName}.aggregate, pipeline: ${JSON.stringify(this.pipeline())} duration ${durationMs}ms`);
    }
    next();
  });
}; // mongoose-profiler.ts

const redactConditionsValue = (conditions: Record<string, any>): void => {
  const keys = Object.keys(conditions);
  keys.forEach((key) => {
    conditions[key] = 'REDACTED';
  });
};

export const mongooseProfiler = (schema: Schema) => {
  schema.pre(/^find/, function (this: any, next: () => void) {
    this._startTime = process.hrtime();
    next();
  });

  schema.post(/^find/, function (this: any, _result: any, next: () => void) {
    const start = this._startTime;
    if (start) {
      const diff = process.hrtime(start);
      const durationMs = (diff[0] * 1e3 + diff[1] / 1e6).toFixed(2);
      const modelName = this.model?.modelName || 'UnknownModel';
      const operation = this.op || 'unknownOp';

      redactConditionsValue(this._conditions);
      logger.info(`[Mongoose] ${modelName}.${operation}, conditions: ${JSON.stringify(this._conditions)} duration ${durationMs}ms`);
    }
    next();
  });

  schema.pre('distinct', function (this: any, next: () => void) {
    this._startTime = process.hrtime();
    next();
  });

  schema.post('distinct', function (this: any, _result: any, next: () => void) {
    const start = this._startTime;
    if (start) {
      const diff = process.hrtime(start);
      const durationMs = (diff[0] * 1e3 + diff[1] / 1e6).toFixed(2);
      const modelName = this.model?.modelName || 'UnknownModel';
      const operation = this.op || 'unknownOp';

      redactConditionsValue(this._conditions);
      logger.info(
        `[Mongoose] ${modelName}.${operation}, conditions: ${JSON.stringify(this._conditions)}, distinct: ${this._distinct} duration ${durationMs}ms`
      );
    }
    next();
  });

  schema.pre('aggregate', function (this: any, next: () => void) {
    this._startTime = process.hrtime();
    next();
  });

  schema.post('aggregate', function (this: any, _result: any, next: () => void) {
    const start = this._startTime;
    if (start) {
      const diff = process.hrtime(start);
      const durationMs = (diff[0] * 1e3 + diff[1] / 1e6).toFixed(2);
      const modelName = this._model?.modelName || 'UnknownModel';
      redactConditionsValue(this.pipeline());
      logger.info(`[Mongoose] ${modelName}.aggregate, pipeline: ${JSON.stringify(this.pipeline())} duration ${durationMs}ms`);
    }
    next();
  });
}; EXPLANATION EXPLANATION The profiler makes use of the available mongoose pre  and post middleware hooks, the start time is stored before the query execution begins, when the pre hook is called, the duration calculation then happens in the post hook. pre post pre post The redactConditionsValue was added to redact query information, because by default, Mongoose would log your query conditions, which is not ideal if you are building a production-ready system. redactConditionsValue You can add hooks for create and update functions if that suits your use case. create update USAGE USAGE To make use of the profiler, you add the following code to your schema file mongoooseProfiler(UserSchema); mongoooseProfiler(UserSchema); OUTPUT OUTPUT This is what the log looks like: it contains the model, operation, a redacted query, and duration in milliseconds [Mongoose] User.findOne, conditions: {"_id":"REDACTED"} duration 40.59ms [Mongoose] User.findOne, conditions: {"_id":"REDACTED"} duration 40.59ms CONCLUSION CONCLUSION For the scale of the project I was working on, this allows me to know which queries are been run and which queries are taking a long time to execute, so I can take note to optimise them, consequently improving performance. Feel free to reach out if you have any questions.

The Secret to Faster JSON Queries in MySQL: Generated Columns

Tracking Mongoose Query Times with a Few Lines of Code

About Author

Comments

TOPICS

THIS ARTICLE WAS FEATURED IN

Related Stories

Stop Buffering: Stream JSON to S3 in CSV Format Using Node.js and Axios

10 Web Development Boosting Node.js Libraries and Frameworks

2019 Database Trends – SQL vs. NoSQL, Top Databases, Single vs. Multiple Database Use

The Noonification: The Denominator (5/9/2023)

52 Stories To Learn About Nosql

The Noonification: Nvidias Ascent Proves AI is Where Its At 🤖 (6/7/2023)

Stop Buffering: Stream JSON to S3 in CSV Format Using Node.js and Axios

10 Web Development Boosting Node.js Libraries and Frameworks

2019 Database Trends – SQL vs. NoSQL, Top Databases, Single vs. Multiple Database Use

The Noonification: The Denominator (5/9/2023)

52 Stories To Learn About Nosql

The Noonification: Nvidias Ascent Proves AI is Where Its At 🤖 (6/7/2023)

Light-Mode

Classic

Newspaper

Minty

Dark-Mode

Neon Noir

Minty

HN StartUps