Track startup speed #22

Activity

1. mhdawson commented on Dec 16, 2015

   

   mhdawson

   on Dec 16, 2015

   Member

   More actions

   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.
2. mhdawson commented on Dec 17, 2015

   

   mhdawson

   on Dec 17, 2015

   Member

   More actions

   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.
3. seabaylea commented on Dec 18, 2015

   

   seabaylea

   on Dec 18, 2015

   Contributor

   More actions

   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.
4. gareth-ellis commented on Jan 7, 2016

   

   gareth-ellis

   on Jan 7, 2016

   Member

   More actions

   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).
5. mhdawson commented on Jan 7, 2016

   

   mhdawson

   on Jan 7, 2016

   Member

   More actions

   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.
6. ofrobots commented on Jan 7, 2016

   

   ofrobots

   on Jan 7, 2016

   Collaborator

   More actions

   @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.
7. mhdawson commented on Jan 7, 2016

   

   mhdawson

   on Jan 7, 2016

   Member

   More actions

   @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.
8. ofrobots commented on Jan 7, 2016

   

   ofrobots

   on Jan 7, 2016

   Collaborator

   More actions

   How about node -e ''?
9. sam-github commented on Jan 7, 2016

   

   sam-github

   on Jan 7, 2016

   More actions

   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.
10. mhart commented on Jan 17, 2018

    

    mhart

    on Jan 17, 2018

    More actions

    Related: nodejs/node#17058
11. mhdawson commented on Jan 17, 2018

    

    mhdawson

    on Jan 17, 2018

    Member

    More actions

    @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.