Next.js: Performance issue with /server/resolve.js

[oliviertassinari]

• [x] I have searched the issues of this repository and believe that this is not a duplicate.

Expected Behavior

The server shouldn't spend 20ms to require the Component and the Document components.
I believe we could use a cache to only pay the resolution cost once in production.

Current Behavior

The requests are delayed by 20ms.
It might get worse in the future version as the /server/resolve.js logic has grown to support 5 different extensions in canary:
https://github.com/zeit/next.js/blob/cdbbe928b26af2e79c4508f127351b6652c5aee6/server/resolve.js#L36-L42

where it only supports 2 in 4.2.3
https://github.com/zeit/next.js/blob/44de0f15c96c425c193ffdccacb14f28051051d5/server/resolve.js#L33-L36

Steps to Reproduce (for bugs)

1. Server side render a page with the --inspect flag

Context

I have noticed the following issue investigating a server-side rendering slow issue.
I have noticed that we systematically wait 20ms to require the Component and the Document components.

https://github.com/zeit/next.js/blob/44de0f15c96c425c193ffdccacb14f28051051d5/server/render.js#L56-L59

I believe a simple cache in production could make the resolution instant:

Your Environment

| Tech | Version |
|---------|---------|
| next | 4.2.3 |
| node | 9.4.0 |
| OS | macOS High Sierra 10.13.x |
| browser | N.A |
| etc | |

[timneutkens]

Hey Olivier,
I just ran a test with 100 requests against a reasonably small service.
I took the bit you pointed out and wrapped it in console.time console.timeEnd
https://github.com/zeit/next.js/blob/44de0f15c96c425c193ffdccacb14f28051051d5/server/render.js#L56-L59

As you can see the first request is slow (as you mentioned). The requests thereafter after reasonably faster because Node.js caches filesystem operations as far as I know.

However, I do agree that we can heavily optimize this. Since in production the getTrueFilePath check that is performed might not be needed.

Here are the fetch results:

component fetching: 27.335ms
component fetching: 11.558ms
component fetching: 2.292ms
component fetching: 17.421ms
component fetching: 2.629ms
component fetching: 5.179ms
component fetching: 3.961ms
component fetching: 3.998ms
component fetching: 4.922ms
component fetching: 4.229ms
component fetching: 1.790ms
component fetching: 3.081ms
component fetching: 2.728ms
component fetching: 3.907ms
component fetching: 13.300ms
component fetching: 2.233ms
component fetching: 8.058ms
component fetching: 1.657ms
component fetching: 2.269ms
component fetching: 2.376ms
component fetching: 1.650ms
component fetching: 1.671ms
component fetching: 4.337ms
component fetching: 5.558ms
component fetching: 1.759ms
component fetching: 1.480ms
component fetching: 1.976ms
component fetching: 2.299ms
component fetching: 5.189ms
component fetching: 4.323ms
component fetching: 1.980ms
component fetching: 1.661ms
component fetching: 22.161ms
component fetching: 7.424ms
component fetching: 7.250ms
component fetching: 1.503ms
component fetching: 1.699ms
component fetching: 6.749ms
component fetching: 1.990ms
component fetching: 3.022ms
component fetching: 6.880ms
component fetching: 3.279ms
component fetching: 1.786ms
component fetching: 2.764ms
component fetching: 1.579ms
component fetching: 1.482ms
component fetching: 2.081ms
component fetching: 3.501ms
component fetching: 1.551ms
component fetching: 1.743ms
component fetching: 2.351ms
component fetching: 6.141ms
component fetching: 1.977ms
component fetching: 1.456ms
component fetching: 1.553ms
component fetching: 3.221ms
component fetching: 1.388ms
component fetching: 2.732ms
component fetching: 2.252ms
component fetching: 1.563ms
component fetching: 1.801ms
component fetching: 4.789ms
component fetching: 1.456ms
component fetching: 1.754ms
component fetching: 1.224ms
component fetching: 1.647ms
component fetching: 1.162ms
component fetching: 4.631ms
component fetching: 1.256ms
component fetching: 1.483ms
component fetching: 1.462ms
component fetching: 1.647ms
component fetching: 1.690ms
component fetching: 1.950ms
component fetching: 5.786ms
component fetching: 1.671ms
component fetching: 6.056ms
component fetching: 1.947ms
component fetching: 1.882ms
component fetching: 3.140ms
component fetching: 1.996ms
component fetching: 2.885ms
component fetching: 2.292ms
component fetching: 4.953ms
component fetching: 3.683ms
component fetching: 1.256ms
component fetching: 1.469ms
component fetching: 1.808ms
component fetching: 1.986ms
component fetching: 2.724ms
component fetching: 1.756ms
component fetching: 2.551ms
component fetching: 3.197ms
component fetching: 2.969ms
component fetching: 2.357ms
component fetching: 3.384ms
component fetching: 3.233ms
component fetching: 1.899ms
component fetching: 2.082ms
component fetching: 2.347ms

[oliviertassinari]

@timneutkens Thanks for looking into it that quickly! The filesystem access seems to be much faster after some iterations 👍 . Maybe once the fs cache quicks in? The flame chart I have shared was done after rendering 5 time the same page.

[timneutkens]

With a few changes we can get it to this:

component fetching: 8.860ms
component fetching: 0.115ms
component fetching: 0.079ms
component fetching: 2.918ms
component fetching: 0.082ms
component fetching: 0.076ms
component fetching: 0.072ms
component fetching: 0.092ms
component fetching: 0.086ms
component fetching: 0.077ms
component fetching: 0.058ms
component fetching: 0.088ms
component fetching: 0.059ms
component fetching: 0.079ms
component fetching: 0.078ms
component fetching: 0.076ms
component fetching: 0.078ms
component fetching: 0.071ms
component fetching: 0.076ms
component fetching: 0.074ms
component fetching: 0.067ms
component fetching: 0.070ms
component fetching: 0.077ms
component fetching: 0.073ms
component fetching: 0.163ms
component fetching: 0.057ms
component fetching: 0.067ms
component fetching: 0.214ms
component fetching: 0.076ms
component fetching: 0.073ms
component fetching: 0.076ms
component fetching: 0.067ms
component fetching: 0.070ms
component fetching: 0.066ms
component fetching: 0.078ms
component fetching: 0.053ms
component fetching: 0.072ms
component fetching: 0.067ms
component fetching: 0.074ms
component fetching: 0.072ms
component fetching: 0.072ms
component fetching: 0.072ms
component fetching: 0.127ms
component fetching: 0.068ms
component fetching: 0.107ms
component fetching: 0.119ms
component fetching: 0.116ms
component fetching: 0.063ms
component fetching: 0.080ms
component fetching: 0.053ms
component fetching: 0.126ms
component fetching: 0.417ms
component fetching: 0.075ms
component fetching: 0.067ms
component fetching: 0.075ms
component fetching: 0.067ms
component fetching: 0.089ms
component fetching: 0.067ms
component fetching: 0.126ms
component fetching: 0.074ms
component fetching: 0.074ms
component fetching: 0.053ms
component fetching: 0.123ms
component fetching: 0.074ms
component fetching: 0.074ms
component fetching: 0.080ms
component fetching: 0.077ms
component fetching: 0.072ms
component fetching: 0.071ms
component fetching: 0.134ms
component fetching: 0.073ms
component fetching: 0.075ms
component fetching: 0.071ms
component fetching: 0.049ms
component fetching: 0.053ms
component fetching: 0.067ms
component fetching: 0.120ms
component fetching: 0.076ms
component fetching: 0.077ms
component fetching: 0.087ms
component fetching: 0.072ms
component fetching: 0.078ms
component fetching: 0.076ms
component fetching: 0.074ms
component fetching: 0.079ms
component fetching: 0.071ms
component fetching: 0.076ms
component fetching: 0.133ms
component fetching: 0.083ms
component fetching: 0.068ms
component fetching: 0.071ms
component fetching: 0.084ms
component fetching: 0.079ms
component fetching: 0.079ms
component fetching: 0.089ms
component fetching: 0.076ms
component fetching: 0.081ms
component fetching: 0.088ms
component fetching: 0.082ms
component fetching: 0.082ms

[oliviertassinari]

@timneutkens Wow 😍 this is almost a two order magnitude win! I hope it doesn't add too much complexity :).

[arunoda]

@oliviertassinari thanks for mentioning this.
Actually, we don't need to use this to pick files at runtime. So, we can completely remove use of these.

[oliviertassinari]

Actually, we don't need to use this to pick files at runtime. So, we can completely remove use of these.

@arunoda Oh, it's even better! We started doing some performance benchmark on Next.js. We started having some EMFILE: too many open files, scandir '/app/.next/dist/pages' errors under heavy load. We have increased our ulimit. But we might be able to decrease it in the future :)

[timneutkens]

@oliviertassinari @arunoda I actually did you one better 😁

t: 8.020ms
t: 0.030ms
t: 0.041ms
t: 0.028ms
t: 0.038ms
t: 0.034ms
t: 0.030ms
t: 0.042ms
t: 0.037ms
t: 0.054ms
t: 0.038ms
t: 0.028ms
t: 0.029ms
t: 0.051ms
t: 0.035ms
t: 0.040ms
t: 0.027ms
t: 0.037ms
t: 0.029ms
t: 0.028ms
t: 0.039ms
t: 0.034ms
t: 0.030ms
t: 0.030ms
t: 0.033ms
t: 0.033ms
t: 0.031ms
t: 0.027ms
t: 0.027ms
t: 0.035ms
t: 0.029ms
t: 0.032ms
t: 0.029ms
t: 0.055ms
t: 0.221ms
t: 0.054ms
t: 0.031ms
t: 0.040ms
t: 0.032ms
t: 0.041ms
t: 0.032ms
t: 0.037ms
t: 0.046ms
t: 0.039ms
t: 0.028ms
t: 0.032ms
t: 0.108ms
t: 0.032ms
t: 0.030ms
t: 0.038ms
t: 0.029ms
t: 0.042ms
t: 0.040ms
t: 0.056ms
t: 0.060ms
t: 0.029ms
t: 0.027ms
t: 0.029ms
t: 0.030ms
t: 0.031ms
t: 0.037ms
t: 0.028ms
t: 0.030ms
t: 0.033ms
t: 0.032ms
t: 0.030ms
t: 0.039ms
t: 0.033ms
t: 0.034ms
t: 0.032ms
t: 0.039ms
t: 0.027ms
t: 0.037ms
t: 0.028ms
t: 0.026ms
t: 0.031ms
t: 0.027ms
t: 0.038ms
t: 0.037ms
t: 0.035ms
t: 0.078ms
t: 0.031ms
t: 0.033ms
t: 0.097ms
t: 0.050ms
t: 0.030ms
t: 0.032ms
t: 0.066ms
t: 0.035ms
t: 0.035ms
t: 0.029ms
t: 0.031ms
t: 0.036ms
t: 0.033ms
t: 0.030ms
t: 0.075ms
t: 0.035ms
t: 0.028ms
t: 0.029ms
t: 0.026ms

[timneutkens]

Going to address this tomorrow.