Track startup speed

[rvagg]

Continuing on from nodejs/node#3962, this is an important metric for many users and we have no insight to it over time, at least nobody is tracking it as far as I'm aware.

[mhdawson]

Thanks for the input, I'm working on the simple ones first, including footprint, but startup at least for the basic how long does it take to get to the point were we can first capture the time would be pretty easy so I'll look at that one as a follow on.

[mhdawson]

Added this benchmark to https://github.com/nodejs/benchmarking/tree/master/experimental/benchmarks/startup

to

https://ci.nodejs.org/job/benchmark-footprint-experimental/

It measure both start/stop time by capturing the time it takes to run an empty script. May not be the right thing to measure but will let us start capturing data to see how stable the results are.

[seabaylea]

That looks like a good start. Is it worth adding a second test/extension that also adds in some require statements? And change to module load speed will affect the startup time of any real application.

[gareth-ellis]

I had a go at running the above benchmark, and also created a few other variants.
I was interested how the above would be measuring shutdown as well as startup, so wrote a quick 2 line startup test:

var now=new Date();
console.log( now.getTime())

immediately before starting node I also take the current time stamp and compare that with the time stamp printed by node.

I then went on to put together a startup test using express (using their sample helloWorld application as a basis)

var express = require('express');
var app = express();

app.get('/', function (req, res) {
  res.send('Hello World!');
});

var server = app.listen(3000, function () {
  var host = server.address().address;
  var port = server.address().port;

  console.log('%s Example app listening at http://%s:%s', new Date().getTime(), host, port);
process.exit();
});

Again, I have taken a timestamp immediately before starting node, and compared the two.

I also had a go with using time node app.js and looking at real and cpu (user + sys) across the releases.

I can see startup increase from 0.10 to 0.12, and a slight increase to 4, however in the recent 4.2.4 driver, we improve in startup time again (i assume due to snapshots being reenabled).

[mhdawson]

This is the data I have so far in the benchmark I have been working on. It includes both startup/shutdown time as it uses the unix time command, starting an empty js file.

https://github.com/nodejs/benchmarking/blob/master/experimental/benchmarks/startup/startup.png

I think we'll probably want a few variants. If you check in the pieces needed to run the versions you created into nodejs/benchmarking/experimental/benchmarks/xxx

were xxx is a new directory for each of the benchmarks we can look at adding them to the data that is charted as well.

[ofrobots]

@mhdawson Do you want to use an even more minimal script to track startup/shutdown time: node -pe process.version. For this purpose, it would be better to avoid IO for loading the empty script.

[mhdawson]

@ofrobots I ran a few times (on the non-benchmark machine) to compare and it seems like node -pe process.version is actually slower (10-20%) than running an empty script and a bit more variable as well. It might be because it has some output.

[ofrobots]

How about node -e ''?

[sam-github]

I haven't been bothered by node startup to first line of js executed, but I have been negatively effected by how slow require is... Complex node apps have deeply nested module trees, and every require() does a LOT of searching up the tree for possible node_modules folders. I've seen it take 4-5 hundred milliseconds for a loopback app to require its deps. This may seem fast, but stick it in a unit test framework that is spinning the app up 20 times, and now the test time just has a minimum of 10 seconds to run to completion. Unit testing instead of CLI testing helps a lot, but there are places where automated tests have to call actual CLIs, and its really slow.

stracing the startup, it seemed to me that the main issue is that require is not cacheing the results of its last disk operations, particularly the check from the CWD all the way up to / for any node_modules folders. The intention of this is that if I require A and then B, and A creates a module B synchronously, that it will be found in the require of B.

Cool, but is this really useful? The price of this feature is quite high in startup cost.

[mhart]

Related: nodejs/node#17058

[mhdawson]

@mhart thanks for the cross-post. We have startup/shutdown being tracked nightly in https://benchmarking.nodejs.org/charts/start_stop.png. I've been following #17058 and will be interested to see the difference that #17058 makes.