Tracking Mongoose Query Times with a Few Lines of Code | HackerNoon

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

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);

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 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();
  });
};

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.

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.

You can add hooks for create and update functions if that suits your use case.

USAGE

To the profiler, you add the following code to your schema file

mongoooseProfiler(UserSchema);

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

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.