Logo Questions Linux Laravel Mysql Ubuntu Git Menu
 

NestJS startup unbelievably slow in development

My application in dev environment is annoyingly slow in it's startup phase. I've set some debug logging on various places to see what is taking up so much time, and found that my main.ts actually uses almost 9 minutes 😱 just to get my app.module imported!

Source

import { performance } from 'perf_hooks';
const startTime = performance.now();

import { Log } from 'api/common/util/logger/log';
Log.log.info(`β”Œβ”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”`);
Log.log.info(`β”‚    Starting: ${new Date().toISOString()}                      β”‚`);
Log.log.info(`β””β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”˜`);

// From here -------------------->
import { NestFactory } from '@nestjs/core';
import { ValidationPipe } from '@nestjs/common';
import 'reflect-metadata';
import { existsSync, mkdirSync, writeFile } from 'fs';
import * as express from 'express';
import * as bodyParser from 'body-parser';
import * as helmet from 'helmet';
import * as morgan from 'morgan';
import * as morganBody from 'morgan-body';
// <------ to here, imports fly in as expected.

// Theese take a bit longer, but not enormously
import { Config } from './api/common/config';
import { HttpExceptionFilter } from './api/common/filters/http-exception.filter';
import { LogService } from 'api/common/util/logger/log.service';

// This one takes up the most time on startup (several minutes)
import { AppModule } from './api/app.module';
Log.log.debug(` * imports done in ${(performance.now() - startTime).toFixed(3)}ms`);
Log.log.debug(` * Memory: ${readMem()}`);

function readMem() {
  const mem = process.memoryUsage();
  const convert = { Kb: n => (n / 1024), Mb: n => convert.Kb(n) / 1024 };
  const toHuman = (n, t) => `${convert[t](n).toFixed(2)}${t}`;
  return `Used ${toHuman(mem.heapUsed, 'Mb')} of ${toHuman(mem.heapTotal, 'Mb')} - RSS: ${toHuman(mem.rss, 'Mb')}`;
}

Output

Production startup:

$ node dist/main.js
info: β”Œβ”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”
info: β”‚    Starting: 2019-01-29T13:06:13.751Z                                    β”‚
info: β”‚      Memory: Used 6.54Mb of 11.70Mb - RSS: 25.33Mb                       β”‚
info: β”‚     Runtime: js                                                          β”‚
info: β””β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”˜
debug:  * imports done in 6862.350ms
debug:  * Memory: Used 87.99Mb of 113.76Mb - RSS: 133.58Mb
info: Nest application successfully started
info: β”Œβ”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”
info: β”‚             Memory: Used 93.71Mb of 122.52Mb - RSS: 144.20Mb             β”‚
info: β”‚             Launch: 2019-01-29T13:06:25.377Z                             β”‚
info: β”‚      Time to start: 11991.049ms                                          β”‚
info: β”‚     Bootstrap time: 5124.189ms                                           β”‚
info: β””β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”˜

Development startup:

$ ts-node -r tsconfig-paths/register src/main.ts
info: β”Œβ”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”
info: β”‚    Starting: 2019-01-29T13:08:06.914Z                                    β”‚
info: β”‚      Memory: Used 157.76Mb of 193.62Mb - RSS: 209.77Mb                   β”‚
info: β”‚     Runtime: ts                                                          β”‚
info: β””β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”˜
debug:  * imports done in 471159.063ms
debug:  * Memory: Used 297.45Mb of 385.35Mb - RSS: 408.90Mb
info: Nest application successfully started
info: β”Œβ”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”
info: β”‚             Memory: Used 216.64Mb of 383.35Mb - RSS: 409.11Mb            β”‚
info: β”‚             Launch: 2019-01-29T13:16:05.521Z                             β”‚
info: β”‚      Time to start: 483228.325ms                                         β”‚
info: β”‚     Bootstrap time: 12042.239ms                                          β”‚
info: β””β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”˜

Yes, I'm starting this using ts-node, but that is what NestJS recommends for development and debugging.

Question

How can I optimize the startup so that each minor change in the backend here does not require a 10 minute procrastination? I have trouble enough with concentration as it is, this does not help.

Do I have too many modules? Will it help if I combine some? I have about 15 DB entity models each included in it's own graphql based module for readability, but many of them have circular dependencies resolved by forwardRef() injection in my module imports. Is this perhaps a problem?

I try to include as few third-party libraries as possible to avoid node_modules hell. What I import in my modules are either my own code or NestJS framework stuff. Of course I do not know how many implicit dependencies gets loaded, but could the amount of libraries I'm dragging with me impact the startup performance? And if so, how can I monitor what gets on the stack and how much memory/cpu each script consumes upon evaluation? And can I somehow precompile some of this to increase startup?

I don't have this problem when running as compiled javascript in production.

like image 204
Øystein Amundsen Avatar asked Jan 29 '19 09:01

Øystein Amundsen


People also ask

Is NestJS better than Express?

Nest offers a ready-to-use application architecture using controllers, providers, and modules. This enables developers and teams create applications that are simple to test and maintain. Express does not require a specific structure, which can provide flexibility for small or one-person development teams.

Is NestJS worth using?

js project, NestJS is a much better choice than ExpressJS since it is built on a clear design with a few simple components (controllers, modules, and providers). This makes dividing apps into microservices a breeze.

Is NestJS fast?

Currently, it is the fastest-growing Node framework powered by TypeScript. NestJS is designed to enable the development of scalable, testable, and loosely coupled applications. It is compatible with PostgreSQL, MongoDB, and MySQL databases.

Is NestJS built on top of Express?

The Nest framework is built using TypeScript which allows developers to build highly scalable and testable applications. Built on top of Express.


2 Answers

Try to set env TS_NODE_TRANSPILE_ONLY=true.

e.g. TS_NODE_TRANSPILE_ONLY=true ts-node -r tsconfig-paths/register src/main.ts

docs: https://github.com/TypeStrong/ts-node#cli-and-programmatic-options

It's speed up my app startup

like image 117
Diluka W Avatar answered Sep 20 '22 18:09

Diluka W


One option is to use tsc-watch instead of ts-node and nodemon. You can set up the start command in your start:dev as follows:

{
  //this is assuming you're building to the dist folder
  ...
  "start:dev": "tsc-watch --onSuccess \"node dist/main.js\" --onFailure \"echo 
  There was a problem with the build!\" -p tscfonig.json" 
  ...
}

In my experience I ran into too many problems with ts-node and registering routes, plus load times were killing me. With tsc-watch I get a fresh build of the project, rebuilding only the files that were changed. This way you're also testing that tsc works while developing.


I also use a tsconfig-bootstrap command to import my custom routes (defined in my tsconfig) and add that into my start command with node -r path/to/my/script.js dist/main.js.

Hope this helps you a bit!

like image 33
Jay McDoniel Avatar answered Sep 18 '22 18:09

Jay McDoniel