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.

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

[BUG] $onRoutesInit takes a long time since 6.59.6 #1496

Closed
jpc-dnr opened this issue Aug 25, 2021 · 29 comments
Closed

[BUG] $onRoutesInit takes a long time since 6.59.6 #1496

jpc-dnr opened this issue Aug 25, 2021 · 29 comments
Assignees
Labels

Comments

@jpc-dnr
Copy link

jpc-dnr commented Aug 25, 2021

Information

  • Version: 6.59.6

Since the upgrade to v6.59.6, the $onRoutesInit hook is taking a long time (like 4 seconds).
We are using in our project the $onBeforeRoutesInit and $onAfterRoutesInit hooks but not the $onRoutesInit.

It was working fine with v6.59.5 ($onRoutesInit takes some milliseconds only to execute).

Is there something we are missing? How can we diagnose this issue?

Thanks!

@Romakita
Copy link
Collaborator

And if you upgrade to another version ?

@jpc-dnr
Copy link
Author

jpc-dnr commented Aug 25, 2021

Yes, I pointed v6.59.6 because I wanted to be as accurate as possible on the version number.

I tried with v6.60.0, v6.61.1, v6.62.0 and v6.63.2, there is a waiting time in $onRoutesInit.

I should mention that with v6.62.0 and v6.63.2, the wait is not as long as with v6.60.0 or v6.61.1, it is 2 seconds (against 4 seconds for v6.60.0 and v6.61.1).

@Romakita
Copy link
Collaborator

Ok I'll investigate ^^.

@Romakita
Copy link
Collaborator

Hello @jpc-dnr

Can you install the latest version and run the server with the following options please:

 const platform = await PlatformExpress.bootstrap(Server, {
        logger: {
          perf: true
        }
      });
}

you should have only the perf log displayed in the terminal. Can send me the result please :) ?

See you
Romain

@jpc-dnr
Copy link
Author

jpc-dnr commented Aug 26, 2021

Hi Romain,

Thank you for that, you can find the log result below.

[bootstrap]    0.746ms - START - PlatformBuilder.createInjector()                (from latest: +0.424ms)
[bootstrap]   25.989ms - END   - PlatformBuilder.createInjector()                (method: +25.546ms)
[bootstrap]   26.081ms - START - PlatformBuilder.createRootModule()              (from latest: +0.005ms)
[bootstrap]   26.477ms - END   - PlatformBuilder.createRootModule()              (method: +0.375ms)
[bootstrap]   26.542ms - START - PlatformBuilder.runLifecycle()                  (from latest: +0.005ms)
[bootstrap]   26.694ms - START - PlatformBuilder.importProviders()               (from latest: +0.147ms)
[bootstrap]  288.074ms - END   - PlatformBuilder.importProviders()               (method: +261.359ms)
[bootstrap]  288.229ms - START - PlatformBuilder.loadInjector()                  (from latest: +0.015ms)
[bootstrap]  288.345ms - START - PlatformBuilder.callHook()                      (from latest: +0.134ms)
[bootstrap]  289.370ms - START - PlatformBuilder.loadMiddlewaresFor()            (from latest: +1.152ms)
[bootstrap]  289.548ms - END   - PlatformBuilder.loadMiddlewaresFor()            (method: +0.185ms)
[bootstrap]  289.607ms - END   - PlatformBuilder.callHook()                      (method: +1.264ms)
[bootstrap]  289.719ms - LOG   - Build providers                                 (from latest: +0.069ms)
[bootstrap]  408.610ms - LOG   - Settings and injector loaded                    (from latest: +118.834ms)
[bootstrap]  408.711ms - START - PlatformBuilder.callHook()                      (from latest: +0.016ms)
[bootstrap]  408.769ms - START - PlatformBuilder.loadMiddlewaresFor()            (from latest: +0.075ms)
[bootstrap]  408.820ms - END   - PlatformBuilder.loadMiddlewaresFor()            (method: +0.057ms)
[bootstrap]  408.857ms - END   - PlatformBuilder.callHook()                      (method: +0.152ms)
[bootstrap]  408.900ms - END   - PlatformBuilder.loadInjector()                  (method: +120.69ms)
[bootstrap]  408.936ms - START - PlatformExpress.useContext()                    (from latest: +0.004ms)
[bootstrap]  409.704ms - END   - PlatformExpress.useContext()                    (method: +0.757ms)
[bootstrap]  409.768ms - START - PlatformExpress.useRouter()                     (from latest: +0.004ms)
[bootstrap]  409.890ms - END   - PlatformExpress.useRouter()                     (method: +0.121ms)
[bootstrap]  409.935ms - START - PlatformExpress.loadRoutes()                    (from latest: +0.003ms)
[bootstrap]  410.046ms - START - PlatformExpress.configureViewsEngine()          (from latest: +0.113ms)
[bootstrap]  410.636ms - END   - PlatformExpress.configureViewsEngine()          (method: +0.586ms)
[bootstrap]  410.784ms - LOG   - Load routes                                     (from latest: +0.096ms)
[bootstrap]  410.835ms - START - PlatformBuilder.callHook()                      (from latest: +0.009ms)
[bootstrap]  419.804ms - START - PlatformBuilder.loadMiddlewaresFor()            (from latest: +8.967ms)
[bootstrap]  419.920ms - END   - PlatformBuilder.loadMiddlewaresFor()            (method: +0.127ms)
[bootstrap]  421.570ms - END   - PlatformBuilder.callHook()                      (method: +10.728ms)
[bootstrap]  421.643ms - START - PlatformBuilder.callHook()                      (from latest: +0.005ms)
[bootstrap]  421.697ms - START - PlatformBuilder.loadMiddlewaresFor()            (from latest: +0.059ms)
[bootstrap]  421.740ms - END   - PlatformBuilder.loadMiddlewaresFor()            (method: +0.045ms)
[bootstrap]  425.670ms - END   - PlatformBuilder.callHook()                      (method: +4.022ms)
[bootstrap]  425.763ms - START - PlatformBuilder.callHook()                      (from latest: +0.004ms)
[bootstrap]  425.817ms - START - PlatformBuilder.loadMiddlewaresFor()            (from latest: +0.059ms)
[bootstrap]  425.896ms - END   - PlatformBuilder.loadMiddlewaresFor()            (method: +0.079ms)
[bootstrap] 2280.321ms - END   - PlatformBuilder.callHook()                      (method: +1854.541ms)
[bootstrap] 2280.419ms - START - PlatformBuilder.loadStatics()                   (from latest: +0.006ms)
[bootstrap] 2280.922ms - END   - PlatformBuilder.loadStatics()                   (method: +0.502ms)
[bootstrap] 2280.978ms - START - PlatformBuilder.callHook()                      (from latest: +0.004ms)
[bootstrap] 2329.132ms - START - PlatformBuilder.loadMiddlewaresFor()            (from latest: +48.144ms)
[bootstrap] 2330.001ms - END   - PlatformBuilder.loadMiddlewaresFor()            (method: +0.876ms)
[bootstrap] 2330.551ms - END   - PlatformBuilder.callHook()                      (method: +49.468ms)
[bootstrap] 2330.776ms - END   - PlatformExpress.loadRoutes()                    (method: +1920.835ms)
[bootstrap] 2331.086ms - START - PlatformBuilder.logRoutes()                     (from latest: +0.007ms)
[bootstrap] 2334.267ms - END   - PlatformBuilder.logRoutes()                     (method: +3.178ms)
[bootstrap] 2335.665ms - END   - PlatformBuilder.runLifecycle()                  (method: +2309.111ms)
[bootstrap] 2335.748ms - START - PlatformBuilder.listen()                        (from latest: +0.011ms)
[bootstrap] 2335.875ms - START - PlatformBuilder.callHook()                      (from latest: +0.137ms)
[bootstrap] 2336.624ms - START - PlatformBuilder.loadMiddlewaresFor()            (from latest: +0.879ms)
[bootstrap] 2337.123ms - END   - PlatformBuilder.loadMiddlewaresFor()            (method: +0.282ms)
[bootstrap] 2337.489ms - END   - PlatformBuilder.callHook()                      (method: +1.574ms)
[bootstrap] 2337.647ms - START - PlatformBuilder.listenServers()                 (from latest: +0.006ms)
[bootstrap] 2347.666ms - END   - PlatformBuilder.listenServers()                 (method: +10.013ms)
[bootstrap] 2348.865ms - START - PlatformBuilder.callHook()                      (from latest: +0.01ms)
[bootstrap] 2349.645ms - START - PlatformBuilder.loadMiddlewaresFor()            (from latest: +0.857ms)
[bootstrap] 2349.796ms - END   - PlatformBuilder.loadMiddlewaresFor()            (method: +0.164ms)
[bootstrap] 2349.931ms - END   - PlatformBuilder.callHook()                      (method: +1.145ms)
[bootstrap] 2350.403ms - START - PlatformBuilder.ready()                         (from latest: +0.01ms)
[bootstrap] 2350.608ms - START - PlatformBuilder.callHook()                      (from latest: +0.217ms)
[bootstrap] 2383.830ms - START - PlatformBuilder.loadMiddlewaresFor()            (from latest: +33.433ms)
[bootstrap] 2384.026ms - END   - PlatformBuilder.loadMiddlewaresFor()            (method: +0.183ms)
[bootstrap] 2384.702ms - END   - PlatformBuilder.callHook()                      (method: +34.099ms)
[bootstrap] 2384.819ms - LOG   - Started in 2386 ms                              (from latest: +0.055ms)
[bootstrap] 2384.919ms - END   - PlatformBuilder.ready()                         (method: +34.524ms)
[bootstrap] 2385.118ms - ending                                                  (from start: +2385.103ms)

@derevnjuk
Copy link
Contributor

I also postponed upgrading to 6.6x because of this issue 😄

@Romakita it seems it somehow relates to Swagger UI. It takes too much time to build paths, also it blocks the event loop on each request to Swagger UI. Attached you will find the result of profiling: tsed-cpu-profile.cpuprofile.zip

@Romakita
Copy link
Collaborator

Hoo ok. Thanks for the report. It help me a lot.

I would really like to learn how to use profiling tools well. Today it's one of the things that I can't use at all... :(

@Romakita
Copy link
Collaborator

The latest release should solve this issue. I let this issue open until you haven't confirmed the fix ^^

@derevnjuk
Copy link
Contributor

@Romakita the issue is still there. Since you use the same method (i.e. getOpenAPISpec) at both $onReady and any requests to Swagger UI,

 private middlewareSwaggerJson(conf: SwaggerSettings) {
    return (ctx: PlatformContext) => {
      ctx.response.status(200).body(this.swaggerService.getOpenAPISpec(conf));
    };
  }

it blocks the event loop making the service unreachable for ~30s in total in my case.

So, notice the new deepMerge function:

image

CPU-20210828T123946.cpuprofile.zip

@Romakita
Copy link
Collaborator

Romakita commented Aug 28, 2021

Yes I’m arrived on the same conclusion about the deepMerge function. I’ll take a time to find a way to lazyLoad the swagger and optimize the deepMerge function but there nothing magical when the swagger contains a lot of routes xD

@derevnjuk
Copy link
Contributor

derevnjuk commented Aug 28, 2021

Yeah, that's true. Anyway, we should try to avoid building a spec while request executing. Let's start from that, I suggest caching a spec in memory on the $onReady hook.

@Romakita
Copy link
Collaborator

Yes I’ll do that ^^

@Romakita Romakita added this to To do in Global Board via automation Aug 29, 2021
@Romakita Romakita moved this from To do to In progress in Global Board Aug 29, 2021
@Romakita Romakita moved this from In progress to Review in progress in Global Board Aug 30, 2021
@jpc-dnr
Copy link
Author

jpc-dnr commented Aug 31, 2021

Hi!

Sorry I was unable to do some testing until today.

I can confirm that my original issue is resolved with the new 6.64.1 version. No more delay in the $onRoutesInit hook, thanks!

So for me this issue is resolved unless you want to leave it open for other reasons.

Thank you again

@jpc-dnr
Copy link
Author

jpc-dnr commented Aug 31, 2021

Unfortunately I have spoken prematurely because now, with 6.64.1, the swagger JSON file is not created as expected. So this seems like another issue or maybe it is related?

@Romakita
Copy link
Collaborator

The file should be created when the server is ready.

@jpc-dnr
Copy link
Author

jpc-dnr commented Aug 31, 2021

Ok, thanks for the tip. I was doing Swagger UI initialization in the $afterRoutesInit hook, but now I have to do it in the $onReady hook. It is fine for me. Thanks!

@Romakita
Copy link
Collaborator

@jpc-dnr Yes sorry, this is the only way to resolve the bootstrap perf issue ^^

@derevnjuk Can you confirm that the fix solve also your issue please ;)?

@jpc-dnr
Copy link
Author

jpc-dnr commented Aug 31, 2021

Now I just noticed that the swagger JSON file is not created anymore when bootstrapping for tests (await PlatformTest.bootstrap(APIServer, settings)();).

Is it some unwanted side effect or is there something to add?

@Romakita
Copy link
Collaborator

Is it necessary to have the generated file during the unit test?

@Romakita
Copy link
Collaborator

Because unit test should not generate files ^^

@jpc-dnr
Copy link
Author

jpc-dnr commented Aug 31, 2021

For me I would say "yes" because my tests are verifying that Swagger UI is properly initialized and working, so the JSON files are needed.

EDIT: maybe I will see if I can use some hard-coded JSON files for tests

@Romakita
Copy link
Collaborator

You can emit the $onReady event in this case to generate the swagger json :)

PlatformTest.injector.emit("$onReady")

@jpc-dnr
Copy link
Author

jpc-dnr commented Aug 31, 2021

I tried that but it does not generate the swagger json file unfortunately.

I also tried something like

const mod = await PlatformTest.invoke<SwaggerModule>(SwaggerModule);
mod.$onReady();

but it does not work either.

@Romakita
Copy link
Collaborator

Romakita commented Sep 1, 2021

The next release will expose a generateSpecFiles() method on SwaggerModule. You'll be able to do this:

const mod = await PlatformTest.invoke<SwaggerModule>(SwaggerModule);
mod.generateSpecFiles();

There is no reason to not works. The method implementation is the following:

generateSpecFiles() {
    const promises = this.settings.map(async (conf) => {
      const {outFile} = conf;

      if (outFile) {
        const spec = this.swaggerService.getOpenAPISpec(conf);
        return Fs.writeFile(outFile, JSON.stringify(spec, null, 2), {encoding: "utf8"}, () => {});
      }
    });

    return Promise.all(promises);
  }

So if it doesn't works, I'll need a reproducible example or you will have to debug this method in the SwaggerModule.js in your node_modules :)

See you
Romain

@jpc-dnr
Copy link
Author

jpc-dnr commented Sep 1, 2021

Thanks for that!

It does not work with my project unfortunately (tried with 6.64.2). Tomorrow I will try to reproduce that on a small project to see if this is related to Ts.ED or not.

@jpc-dnr
Copy link
Author

jpc-dnr commented Sep 2, 2021

The problem is not related to Ts.ED, it was related to somehow a race condition between Ts.ED and swagger-stats, because we were reading the swagger.json file in the $onReady hook to give the Swagger spec to swagger-stats.

Now we use the directly the SwaggerService service to get the OpenSpec object without relying on the swagger.json file and it works.

If you need a reproducible example, you can find it here: https://github.com/jpc-dnr/tsed-1496

Thanks!

@Romakita Romakita closed this as completed Sep 2, 2021
Global Board automation moved this from Review in progress to Done Sep 2, 2021
@derevnjuk
Copy link
Contributor

@Romakita my issue is still there. See details in #1496 (comment)
Loading Swagger UI blocks other concurrent requests to the server.

@Romakita
Copy link
Collaborator

Romakita commented Sep 2, 2021

But it’s impossible, the spec is lazy loaded during the onReady hook and built only one time for the entire calls (cached).

@Romakita Romakita reopened this Sep 2, 2021
Global Board automation moved this from Done to In progress Sep 2, 2021
@Romakita
Copy link
Collaborator

Romakita commented Sep 2, 2021

Hooo.. sorry, I forgot to release the fix ^^' My bad...

@Romakita Romakita moved this from In progress to Review approved in Global Board Sep 3, 2021
@Romakita Romakita moved this from Review approved to Done in Global Board Sep 3, 2021
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Projects
Archived in project
Development

No branches or pull requests

3 participants