sindresorhus / got

🌐 Human-friendly and powerful HTTP request library for Node.js
MIT License
14.24k stars 933 forks source link

The `merge` function is slow #1016

Closed cesarfd closed 4 years ago

cesarfd commented 4 years ago

What would you like to discuss?

Hi, we are using got heavily in my company to send several thousand requests/s so I'm doing some profiling to see in which places our app spends its time the most.

I've recently upgraded to Got 10 and I've seen that the library spends a significant (though, not alarming) percentage of the time in the normalize arguments phase, which at the same time calls the aforementioned merge function.

Captura de pantalla 2020-01-08 a las 15 50 59

It looks like this single slice call to clone the array seems to spend quite a lot of time. So, my question is, do we really need to clone the array or could it be just referenced? If we need a copy, is slice() the fastest method?

I tried https://jsperf.com/cloning-arrays/3 in Chrome 79 and it seems that there're faster (not so much tbh) alternatives.

Checklist

szmarczak commented 4 years ago

image

Ran on i7-7700k Intel CPU.

szmarczak commented 4 years ago

Hi, we are using got heavily in my company to send several thousand requests/s so I'm doing some profiling to see in which places our app spends its time the most.

Are there any other heavy places like merge.ts? This is very interesting work.

cesarfd commented 4 years ago

image

Ran on i7-7700k Intel CPU.

Captura de pantalla 2020-01-08 a las 20 30 49

On Intel i7-5557U

Weird.

yovanoc commented 4 years ago

I don't know if it will help but on my 2.3 GHz 8-Core Intel Core i9 image

cesarfd commented 4 years ago

Hi, we are using got heavily in my company to send several thousand requests/s so I'm doing some profiling to see in which places our app spends its time the most.

Are there any other heavy places like merge.ts? This is very interesting work.

Here's a more detailed tree where we can see what the code does when we invoke got:

got normalize options

This comes from a 70 second profiling. There are more places where we call got with a different option object each time as we are performing POST json requests.

It seems the normalizeArguments section (and the whole merging process) is the only place where got spends a noticeable amount of time, at least with our use case.

szmarczak commented 4 years ago

@sindresorhus You need to see this:

image

sindresorhus commented 4 years ago

@szmarczak Micro-benchmarks are pretty useless without context. If you run Got seven million times in real-world situations, the network is going to be the bottleneck, not a simple loop.

sindresorhus commented 4 years ago

@cesarfd What Node.js version and OS?

szmarczak commented 4 years ago

Micro-benchmarks are pretty useless without context. If you run Got seven million times in real-world situations, the network is going to be the bottleneck, not a simple loop.

I think it depends if you're running a very very very low-spec machine / VPS and make thousands of requests...

szmarczak commented 4 years ago

@sindresorhus Also shouldn't we deep clone arrays too? For example you can do:

got.extend({hooks: {beforeRequest}});
beforeRequest.push(fn);

and the instance will be affected. I think it's a regression.

szmarczak commented 4 years ago

@cesarfd Could you also provide performance profiling for normalize-arguments.js?

cesarfd commented 4 years ago

@cesarfd What Node.js version and OS?

Node 12.13.1 under a buster-slim docker image + Linux AMI

cesarfd commented 4 years ago

@cesarfd Could you also provide performance profiling for normalize-arguments.js?

Yes, I'll rerun the profiler on Monday.

szmarczak commented 4 years ago

Relevant dockerfile: https://github.com/nodejs/docker-node/blob/cd046b99024274af8a782bc7fb722a89f65ecfdc/12/buster-slim/Dockerfile

cesarfd commented 4 years ago

@szmarczak normalize-arguments.js:

Captura de pantalla 2020-01-13 a las 9 19 59 Captura de pantalla 2020-01-13 a las 9 20 22
szmarczak commented 4 years ago

Thank you very much, if you provide also profiling for mergeOptions and normalizeArguments (it's in the normalize-arguments.js file) that will be great! I've got a few ideas on how to improve the performance.

sindresorhus commented 4 years ago

I think it depends if you're running a very very very low-spec machine / VPS and make thousands of requests...

Sure. My point was that standalone micro-benchmarks doesn't mean anything without the context. It's better to profile the actual running code on the actual system.

sindresorhus commented 4 years ago

Also shouldn't we deep clone arrays too? For example you can do:

Yes

cesarfd commented 4 years ago

Thank you very much, if you provide also profiling for mergeOptions and normalizeArguments (it's in the normalize-arguments.js file) that will be great! I've got a few ideas on how to improve the performance.

Wops, I pasted the pre normalize function before, sorry.

mergeOptions:

Captura de pantalla 2020-01-13 a las 11 17 21

normalizeArguments:

Captura de pantalla 2020-01-13 a las 11 17 42
Jolg42 commented 4 years ago

I also noticed that got can be "relatively slow" to create an instance, If you have any improvements I'm interested to try them :)

In my case the request is done on localhost so the network is fast.

szmarczak commented 4 years ago

@cesarfd What tool do you use to display the performance timings? Could you tell me how to enable it please? That'd be very useful.

cesarfd commented 4 years ago

@szmarczak It's all in the chrome inspect tool. basically the procedure is as follows:

https://nodejs.org/en/docs/guides/debugging-getting-started/

szmarczak commented 4 years ago

@cesarfd I already know that, I thought you were running a fork of Chrome Dev Tools because I can't find anywhere the option to enable the timings in the Source tab...

szmarczak commented 4 years ago

@cesarfd Friendly ping :)

szmarczak commented 4 years ago

I meant this, not the flamegraph (sorry if I got you confused):

image

cesarfd commented 4 years ago

Oh, right, just click on the source code file, where it says the file name and number, it will take you there.

El sáb., 1 feb. 2020 17:15, Szymon Marczak notifications@github.com escribió:

I meant this, not the flamegraph (sorry if I got you confused):

[image: image] https://user-images.githubusercontent.com/36894700/73595229-79021c80-4516-11ea-8207-0ac3522626e2.png

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub https://github.com/sindresorhus/got/issues/1016?email_source=notifications&email_token=ACTTGMVSISWWWPKEJWK7B6LRAWN37A5CNFSM4KEJVIZ2YY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGOEKRAUMQ#issuecomment-581044786, or unsubscribe https://github.com/notifications/unsubscribe-auth/ACTTGMQMVRSFWYYADH6LFE3RAWN37ANCNFSM4KEJVIZQ .

szmarczak commented 4 years ago

Hmm... It takes me there but there are no timings... Will try a different Chromium browser.

szmarczak commented 4 years ago

@cesarfd Oh, I've got it now! The running node script must not exit in order to display the timings (at least in my case I think). Thank you :)

szmarczak commented 4 years ago

image

image

lol I didn't know that comments take CPU time (just kidding). It gives me wrong results. Some functions aren't called at all and it says it took 7ms to run them. The flamegraph gives good results tho. Tried two different browsers: Google Chrome and Brave. I run Node 13.7.0. Will try Node 10 & 12.

resynth1943 commented 4 years ago

Maybe Sindre should consider removing comments as an optimization. :stuck_out_tongue: