Extremely slow startup performance when a dynamic module provides a complex object using useValue

[juona]

Is there an existing issue for this?

• I have searched the existing issues

Current behavior

I have encountered a peculiar app startup performance issue. When it has a provider configured a certain way, its startup performance suffers immensely - can easily get 200x, 400x (from 50ms to 20s) or even more slower than it normally is. Because it is so blatant, I decided to register it as a defect instead of a performance suggestion.

Here's the gist. I'd like to set up a provider that looks like so:

@Module({})
class DependencyModule {
  static forRoot() {
    return {
      module: DependencyModule,
      providers: [
        {
          provide: 'LOL',
          useValue: schema, // THIS IS CAUSING PROBLEMS
        },
      ],
    };
  }
}

@Module({
  imports: [DependencyModule.forRoot()],
  controllers: [AppController],
  providers: [AppService],
})
export class AppModule {}

Here schema is relatively complex Mongoose schema (included in the repo). With the module set up like this, the app takes ~12 seconds to start. Altering the complexity of the schema changes things considerably. I can easily get the startup time to 20 or 30 seconds just by adding a few fields and validators. Mongoose schemas are really complex objects, so perhaps providing them is not okay...

Things start to get interesting here

If the imported module is not dynamic, the app takes 50ms to start

@Module({
  providers: [
    {
      provide: 'LOL',
      useValue: schema,
    },
  ],
})
class DependencyModule {}

@Module({
  imports: [DependencyModule],
  controllers: [AppController],
  providers: [AppService],
})
export class AppModule {}

If useFactory is used instead of useValue, the app takes 50ms to start

@Module({
  providers: [
    {
      provide: 'LOL',
      useValue: schema,
    },
  ],
})
class DependencyModule {
  static forRoot() {
    return {
      module: DependencyModule,
      providers: [
        {
          provide: 'LOL',
          useFactory: () => schema,
        },
      ],
    };
  }
}

@Module({
  imports: [DependencyModule.forRoot()],
  controllers: [AppController],
  providers: [AppService],
})
export class AppModule {}

Since I need to have a dynamic module, this is what I went with for now.

These particular inconsistencies are what made me register an issue here first rather than with Mongoose. I am having trouble wrapping my head around why there's such a problem with using a dynamic module + useValue specifically.

Now onto the badly weird

For context, here's the schema:

import { Schema } from 'mongoose';

const listItemSchema = new Schema({
  itemIds: [String],
});

const xSchema = new Schema({
  items: [listItemSchema],
});

const levelSchema = (statsSchema: Schema) =>
  new Schema({
    field: xSchema,
    stats: statsSchema,
  });

const aStats = new Schema({});
const bStats = new Schema({});
const cStats = new Schema({});
const dStats = new Schema({});
const eStats = new Schema({});
const fStats = new Schema({});
const gStats = new Schema({});
const hStats = new Schema({});
const iStats = new Schema({});
const jStats = new Schema({});

const thingSchema = (statsSchema: Schema) =>
  new Schema({
    field: Boolean,
    levels: [levelSchema(statsSchema)],
  });

const specialStats = new Schema({});

// Unused
// But lowers the startup time significantly (6x) if removed...
const specialSchema = new Schema({
  levels: [levelSchema(specialStats)],
});

const thingsSchema = new Schema({
  a: thingSchema(aStats),
  b: thingSchema(bStats),
  c: thingSchema(cStats),
  d: thingSchema(dStats),
  e: thingSchema(eStats),
  f: thingSchema(fStats),
  g: thingSchema(gStats),
  h: thingSchema(hStats),
  i: thingSchema(iStats),
  j: thingSchema(jStats),
});

// ...or moved here

export const schema = new Schema({
  things: thingsSchema,
});

Nothing spectacular, mostly just a bunch of empty schemas, and 5-6 levels of nesting: schema > things > a > levels > field > items > itemIds.

The "badly" weird part is that even though specialSchema is unused, removing it or moving it below thingsSchema decreases the startup time 6 times - from 12s to 2s. The symptoms seem to allude to Mongoose using some global context when registering schemas, which is worrying, and I understand that this is probably out of scope for NestJS. Nevertheless, it might be useful information when debugging.

It seems that dynamic modules with useValue-based providers have trouble working with certain structures that are employed by Mongoose.

Minimum reproduction code

https://github.com/juona/nestjs-startup-perf-issue

Steps to reproduce

I used the NestJS CLI to setup a fresh project, added the Mongoose schema to it, modified the app module slightly and installed Mongoose itself - that is all.

1. npm ci
2. npm run start:dev
3. See how long it takes for "Nest application successfully started" to be printed after "Starting Nest application..."; the time is printed out.
4. Modify the app module / schema according to the issue description to see what effect it has.

Expected behavior

The expectation is that NestJS is able to register such providers without such a large performance hit.

Package

• I don't know. Or some 3rd-party package
• @nestjs/common
• @nestjs/core
• @nestjs/microservices
• @nestjs/platform-express
• @nestjs/platform-fastify
• @nestjs/platform-socket.io
• @nestjs/platform-ws
• @nestjs/testing
• @nestjs/websockets
• Other (see below)

Other package

mongoose

NestJS version

10.2.8

Packages versions

{
  "name": "nest-app",
  "version": "0.0.1",
  "description": "",
  "author": "",
  "private": true,
  "license": "UNLICENSED",
  "scripts": {
    "build": "nest build",
    "format": "prettier --write \"src/**/*.ts\" \"test/**/*.ts\"",
    "start": "nest start",
    "start:dev": "nest start --watch",
    "start:debug": "nest start --debug --watch",
    "start:prod": "node dist/main",
    "lint": "eslint \"{src,apps,libs,test}/**/*.ts\" --fix",
    "test": "jest",
    "test:watch": "jest --watch",
    "test:cov": "jest --coverage",
    "test:debug": "node --inspect-brk -r tsconfig-paths/register -r ts-node/register node_modules/.bin/jest --runInBand",
    "test:e2e": "jest --config ./test/jest-e2e.json"
  },
  "dependencies": {
    "@nestjs/common": "^10.0.0",
    "@nestjs/core": "^10.0.0",
    "@nestjs/platform-express": "^10.0.0",
    "mongoose": "^8.0.0",
    "reflect-metadata": "^0.1.13",
    "rxjs": "^7.8.1"
  },
  "devDependencies": {
    "@nestjs/cli": "^10.0.0",
    "@nestjs/schematics": "^10.0.0",
    "@nestjs/testing": "^10.0.0",
    "@types/express": "^4.17.17",
    "@types/jest": "^29.5.2",
    "@types/node": "^20.3.1",
    "@types/supertest": "^2.0.12",
    "@typescript-eslint/eslint-plugin": "^6.0.0",
    "@typescript-eslint/parser": "^6.0.0",
    "eslint": "^8.42.0",
    "eslint-config-prettier": "^9.0.0",
    "eslint-plugin-prettier": "^5.0.0",
    "jest": "^29.5.0",
    "prettier": "^3.0.0",
    "source-map-support": "^0.5.21",
    "supertest": "^6.3.3",
    "ts-jest": "^29.1.0",
    "ts-loader": "^9.4.3",
    "ts-node": "^10.9.1",
    "tsconfig-paths": "^4.2.0",
    "typescript": "^5.1.3"
  },
  "jest": {
    "moduleFileExtensions": [
      "js",
      "json",
      "ts"
    ],
    "rootDir": "src",
    "testRegex": ".*\\.spec\\.ts$",
    "transform": {
      "^.+\\.(t|j)s$": "ts-jest"
    },
    "collectCoverageFrom": [
      "**/*.(t|j)s"
    ],
    "coverageDirectory": "../coverage",
    "testEnvironment": "node"
  }
}

Node.js version

16.19.1

In which operating systems have you tested?

• macOS
• Windows
• Linux

Other

No response

[jmcdo29]

Looks like this might be related to the fact that a useValue provider needs to reference the value in useValue immediately when we create the InstanceWrapper, but the useFactory provider is able to defer that reference to later in the bootstrapping processes by referencing the useFactory as a metatype instead of the value it provides.

I can only assume that by having to reference the schema immediately, there's an issue with serializing the schema so that it fits within the context of a Map<InjectionToken, InstanceWrapper> instance, whereas when using a function, we're able to reference the function without serializing it (access by reference (factory) vs access by value (value)) so it doesn't take the same time requirements. It definitely appears that using a useFactory for complex serializable objects is a better approach, something I hadn't even thought about before to be honest.

[H4ad]

The @jmcdo29 answer is perfect.

The issue with serialization is probably caused by:

nest/packages/core/injector/module-token-factory.ts

Lines 24 to 31 in ef53448

	const opaqueToken = {
	id: moduleId,
	module: this.getModuleName(metatype),
	dynamic: dynamicModuleMetadata,
	};
	const opaqueTokenString = this.getStringifiedOpaqueToken(opaqueToken);
	return this.hashString(opaqueTokenString);

If you use anything inside the module that is directly available to the object (eg: useValue, provide) and is heavy to serialize, it will slowdown your startup.

[H4ad]

Yeah, is caused by the serialization:

I will create a PR to help identify this kind of issue.

[kamilmysliwiec]

Let's track this here #12739

[juona]

Unlike the startup, this was extremely fast! Thank you all!

[jcamacho14]

Just in case it helps, I just ran into this same issue, and realized that this wasn't happening with version 10.2.5 (it broke when updated to 10.2.10). I quickly "fixed" it by downgrading until we can update some dependency projects using useValue.

Thanks for adding the warning, it led me here and made the troubleshooting easier.

[zWaR]

I can see that this is a closed ticket, but are there any plans for fixing the slow serialization or was adding the warning in #12739 the only planned action item based on this report?

[H4ad]

@zWaR There's a pending work by Kamil at #13336

[zWaR]

@H4ad you guys are the best, thanks so much!

[kazazor]

Thanks @H4ad !
I see it was approved already but wasn't merged, any plans on making it happen?

And also, is I do not care about this warning (I use bull and gets a warning it takes 13ms-20ms) and I would like to disable this specific warning (or at least control what's the threshold)- any way of doing that?

[H4ad]

And also, is I do not care about this warning (I use bull and gets a warning it takes 13ms-20ms) and I would like to disable this specific warning (or at least control what's the threshold)- any way of doing that?

I can open a PR for this, a threshold should be fine.

[kazazor]

That would be amazing @H4ad !!