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

H4ad · 2023-11-14T19:50:32Z

PR Checklist

Please check if your PR fulfills the following requirements:

The commit message follows our guidelines: https://github.com/nestjs/nest/blob/master/CONTRIBUTING.md
Tests for the changes have been added (for bug fixes / features)
Docs have been added / updated (for bug fixes / features)

PR Type

What kind of change does this PR introduce?

What is the current behavior?

The serialization can be slow and the user will never know about it.

Issue Number: #12738
Fixes #12738

What is the new behavior?

Now we emit a warning using process.emitWarning when the serialization took more than 10ms.

This is an arbitrary value, we can raise or lower this value depending on the real-world applications.

Does this PR introduce a breaking change?

Yes
No

micalevisk · 2023-11-14T19:53:18Z

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

+      process.emitWarning(
+        `The module "${opaqueToken.module}" took ${timeSpentInMs.toFixed(
+          2,
+        )}ms to serialize, consider reduce the size of the object. More details: https://github.com/nestjs/nest/issues/12738`,


I guess we can also suggest them to use factory providers over value providers

and I'm not sure if the word object here would help the end user. But yeah, this is not a log to the app, it's an internal one

The issue could be related to the Factory Providers but can be also some issue on exports or provide.

and I'm not sure if the word object here would help the end user. But yeah, this is not a log to the app, it's an internal one

I don't know a better term to describe, maybe consider reduce the size of the module?

Personally, regarding the last line "More details: https://github.com/nestjs/nest/issues/12738" if we want to put a reference maybe I would make a comment above. 🙂

@Tony133 what do you mean?

This wouldn't be the first time we've had a link in the exception

And I'm certain we've linked to issues from within our docs. If we really don't want to link to the issue directly, then we should make a new section of the FAQ > Common Errors for this

I think documenting this in the documentation is a great idea too 😉👍, of course you have to figure out how to handle this part in the documentation 😄 , maybe to create a small section inside common errors ? 🤔

Updated the message to be a little bit more generic and more assertive about the problem.

Using the Logger is much better, I like it 😉👍

coveralls · 2023-11-14T19:55:50Z

Pull Request Test Coverage Report for Build 52f35b21-f7de-440f-a2ae-b5106b7146d2

6 of 7 (85.71%) changed or added relevant lines in 1 file are covered.
No unchanged relevant lines lost coverage.
Overall coverage decreased (-0.006%) to 92.254%

Changes Missing Coverage	Covered Lines	Changed/Added Lines	%
packages/core/injector/module-token-factory.ts	6	7	85.71%

Totals
Change from base Build e7c88d17-2198-4c13-b01a-98aa728736b6:	-0.006%
Covered Lines:	6693
Relevant Lines:	7255

💛 - Coveralls

micalevisk · 2023-11-15T03:19:56Z

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

    const opaqueTokenString = this.getStringifiedOpaqueToken(opaqueToken);
+    const timeSpentInMs = performance.now() - start;
+
+    if (timeSpentInMs > 10) {


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 :/

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

~~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

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

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.

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?

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.

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

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

jmcdo29

Looks good to me

kamilmysliwiec · 2023-11-17T12:11:32Z

LGTM

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

c49030e

micalevisk reviewed Nov 14, 2023

View reviewed changes

micalevisk reviewed Nov 15, 2023

View reviewed changes

kamilmysliwiec mentioned this pull request Nov 15, 2023

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

Closed

15 tasks

fixup! feat(core): emit warning when serialization of module is slow

7e385e9

micalevisk approved these changes Nov 15, 2023

View reviewed changes

Tony133 approved these changes Nov 15, 2023

View reviewed changes

jmcdo29 approved these changes Nov 15, 2023

View reviewed changes

kamilmysliwiec merged commit 4bc75e9 into nestjs:master Nov 17, 2023
5 checks passed

kamilmysliwiec added type: enhancement 🐺 scope: core labels Nov 17, 2023

H4ad deleted the feat/emit-warning-for-heavier-modules branch November 17, 2023 12:12

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

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

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

H4ad commented Nov 14, 2023

micalevisk Nov 14, 2023

micalevisk Nov 14, 2023 •

edited

Loading

H4ad Nov 14, 2023

Tony133 Nov 14, 2023

H4ad Nov 14, 2023

jmcdo29 Nov 14, 2023

jmcdo29 Nov 14, 2023

Tony133 Nov 14, 2023

H4ad Nov 15, 2023

Tony133 Nov 15, 2023

coveralls commented Nov 14, 2023 •

edited

Loading

micalevisk Nov 15, 2023 •

edited

Loading

H4ad Nov 15, 2023

jmcdo29 Nov 15, 2023 •

edited

Loading

H4ad Nov 15, 2023 •

edited

Loading

micalevisk Nov 15, 2023

H4ad Nov 15, 2023

jmcdo29 Nov 15, 2023

H4ad Nov 15, 2023

jmcdo29 left a comment

kamilmysliwiec commented Nov 17, 2023

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

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

Conversation

H4ad commented Nov 14, 2023

PR Checklist

PR Type

What is the current behavior?

What is the new behavior?

Does this PR introduce a breaking change?

Choose a reason for hiding this comment

micalevisk Nov 14, 2023 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

coveralls commented Nov 14, 2023 • edited Loading

Pull Request Test Coverage Report for Build 52f35b21-f7de-440f-a2ae-b5106b7146d2

💛 - Coveralls

micalevisk Nov 15, 2023 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

jmcdo29 Nov 15, 2023 • edited Loading

Choose a reason for hiding this comment

H4ad Nov 15, 2023 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

jmcdo29 left a comment

Choose a reason for hiding this comment

kamilmysliwiec commented Nov 17, 2023

micalevisk Nov 14, 2023 •

edited

Loading

coveralls commented Nov 14, 2023 •

edited

Loading

micalevisk Nov 15, 2023 •

edited

Loading

jmcdo29 Nov 15, 2023 •

edited

Loading

H4ad Nov 15, 2023 •

edited

Loading