Skip to content
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.

Sign up for GitHub

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

feat(core): emit warning when serialization of module is slow #12739

Merged
merged 2 commits into from
Nov 17, 2023
Merged

feat(core): emit warning when serialization of module is slow #12739

Changes from all commits
Commits
Show all changes
2 commits
Select commit Hold shift + click to select a range
c49030e
feat(core): emit warning when serialization of module is slow
H4ad Nov 14, 2023
7e385e9
fixup! feat(core): emit warning when serialization of module is slow
H4ad Nov 15, 2023
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
16 changes: 15 additions & 1 deletion packages/core/injector/module-token-factory.ts
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -1,16 +1,20 @@
import { DynamicModule } from '@nestjs/common';
import { DynamicModule, Logger } from '@nestjs/common';
import { Type } from '@nestjs/common/interfaces/type.interface';
import { randomStringGenerator } from '@nestjs/common/utils/random-string-generator.util';
import { isFunction, isSymbol } from '@nestjs/common/utils/shared.utils';
import { createHash } from 'crypto';
import stringify from 'fast-safe-stringify';
import { performance } from 'perf_hooks';

const CLASS_STR = 'class ';
const CLASS_STR_LEN = CLASS_STR.length;

export class ModuleTokenFactory {
private readonly moduleTokenCache = new Map<string, string>();
private readonly moduleIdsCache = new WeakMap<Type<unknown>, string>();
private readonly logger = new Logger(ModuleTokenFactory.name, {
timestamp: true,
});

public create(
metatype: Type<unknown>,
Expand All @@ -26,7 +30,17 @@ export class ModuleTokenFactory {
module: this.getModuleName(metatype),
dynamic: dynamicModuleMetadata,
};
const start = performance.now();
const opaqueTokenString = this.getStringifiedOpaqueToken(opaqueToken);
const timeSpentInMs = performance.now() - start;

if (timeSpentInMs > 10) {
Copy link
Member

@micalevisk micalevisk Nov 15, 2023 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I wonder if 10ms is too small

Can you patch this in some real world project just to see if you'll get the warning? I don't have a good nestjs app using v10 :/

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I also don't have a good project with v10, @jmcdo29 or @Tony133, can you give some help about this?

Copy link
Member

@jmcdo29 jmcdo29 Nov 15, 2023 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Interestingly, I'm not seeing all of the modules here that I would expect. But I got no warnings with 10ms as the check time.

Added a console.log({ timeSpentInMs, opaqueToken }) to see what we're looking at here 
{
  timeSpentInMs: 0.5800219774246216,
  opaqueToken: {
    id: 'e16963f9e209181ad0718',
    module: 'InternalCoreModule',
    dynamic: { providers: [Array], exports: [Array] }
  }
}
{
  timeSpentInMs: 0.034444987773895264,
  opaqueToken: {
    id: 'ad071889dc8187858f81b',
    module: 'CacheModule',
    dynamic: { global: undefined, imports: [Array], providers: [Array] }
  }
}
{
  timeSpentInMs: 0.023576021194458008,
  opaqueToken: {
    id: '58f81b9be89c1564788be',
    module: 'OgmaModule',
    dynamic: { providers: [Array], exports: [Array] }
  }
}
{
  timeSpentInMs: 0.02220100164413452,
  opaqueToken: {
    id: '58f81b9be89c1564788be',
    module: 'OgmaModule',
    dynamic: { providers: [Array], exports: [Array] }
  }
}
{
  timeSpentInMs: 0.03898298740386963,
  opaqueToken: {
    id: '226f684678c69bb3e32a1',
    module: 'ServerLoggingModule',
    dynamic: { imports: [Array], providers: [Array] }
  }
}
{
  timeSpentInMs: 0.02251499891281128,
  opaqueToken: {
    id: '84678c69bb3e32a1c97ed',
    module: 'OgmaCoreModule',
    dynamic: { imports: [Array], providers: [Array] }
  }
}
{
  timeSpentInMs: 0.020390987396240234,
  opaqueToken: {
    id: '84678c69bb3e32a1c97ed',
    module: 'OgmaCoreModule',
    dynamic: { imports: [Array], providers: [Array] }
  }
}
{
  timeSpentInMs: 0.025695979595184326,
  opaqueToken: {
    id: '58f81b9be89c1564788be',
    module: 'OgmaModule',
    dynamic: { providers: [Array], exports: [Array] }
  }
}
{
  timeSpentInMs: 0.08169996738433838,
  opaqueToken: {
    id: '226f684678c69bb3e32a1',
    module: 'ServerLoggingModule',
    dynamic: { imports: [Array], providers: [Array] }
  }
}
{
  timeSpentInMs: 0.029079020023345947,
  opaqueToken: {
    id: 'ad071889dc8187858f81b',
    module: 'CacheModule',
    dynamic: { global: undefined, imports: [Array], providers: [Array] }
  }
}
{
  timeSpentInMs: 0.022864997386932373,
  opaqueToken: {
    id: '58f81b9be89c1564788be',
    module: 'OgmaModule',
    dynamic: { providers: [Array], exports: [Array] }
  }
}
{
  timeSpentInMs: 0.06157100200653076,
  opaqueToken: {
    id: '58f81b9be89c1564788be',
    module: 'OgmaModule',
    dynamic: { providers: [Array], exports: [Array] }
  }
}
{
  timeSpentInMs: 0.07260900735855103,
  opaqueToken: {
    id: '84678c69bb3e32a1c97ed',
    module: 'OgmaCoreModule',
    dynamic: { imports: [Array], providers: [Array] }
  }
}
{
  timeSpentInMs: 0.04011797904968262,
  opaqueToken: {
    id: '58f81b9be89c1564788be',
    module: 'OgmaModule',
    dynamic: { providers: [Array], exports: [Array] }
  }
}

Everything looks pretty fast here.

I did force it to error by setting the time to be greater than to 0 and this is what the output looks like

image

Do we want to emit full warnings or just write logs here about it?

Copy link
Contributor Author

@H4ad H4ad Nov 15, 2023 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I don't know if I have access to Logger in that part of the code, I prefer to use logger but if we don't have access, emitWarning is the best option for me.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

To me, as this is all about internal stuff that may not be fixable, I prefer the emitWarning

But we could emit it only if NEST_DEBUG is enabled. What do you think?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I don't like to hide it behind a flag because how the people who are having this issue will know about this flag?

I prefer to leave it as directly as possible, and maybe only add a flag to disable it.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

We can drop a logger in here and use the warn level, as technically devs can work to make the opaque token lighter. This is what the logs look like using ogma
image

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I will push a update to use Logger in this case, which I think is way better than emitWarning.

this.logger.warn(
`The module "${opaqueToken.module}" is taking ${timeSpentInMs.toFixed(
2,
)}ms to serialize, this may be caused by larger objects assigned to the module. More details: https://github.com/nestjs/nest/issues/12738`,
);
}

return this.hashString(opaqueTokenString);
}
Expand Down