Require cached pref much lower

[mhdawson]

I just noticed this regressed (quite a while ago).

https://benchmarking.nodejs.org/charts/require_cached.png

Seems like its in the 3400 range on master, 8,x and canary and way higher on 6.x.

This may have been known, but would be doc to capture here what the reason was.

[uttampawar]

@mhdawson Can you post the script to run this 'require' test, please? I lost the screen content after leaving the zoom meeting today.

[mhdawson]

Here it is:

# run the require benchmark
$NODE_ROOT/deps/npm/bin/npm-cli.js install benchmark
export NODE_PATH=$WORKSPACE/bench/node_modules
REQUIRE_RESULT=`node ../benchmarking/experimental/benchmarks/node-api/require/require.perf.js 2`
echo $REQUIRE_RESULT
REQ_NEW_RESULT=`echo $REQUIRE_RESULT | awk 'BEGIN { FS = "," }; {print $2 }' | awk 'BEGIN { FS = " " }; {print $1 }'`
REQ_CACHED_RESULT=`echo $REQUIRE_RESULT |  awk 'BEGIN { FS = "," }; {print $3 }'`

[uttampawar]

@mhdawson Thanks. I'll work on this issue.

[mhdawson]

Just created nodejs/build#1422 to give @uttampawar access.

[uttampawar]

@mhdawson I was able to track this down and determined that this is not a regression. I don't think it's really a drop merely a reporting error. In fact for this test, we should report reduced "ops/sec" as a improvement.

There are two numbers reported while running require_perf.js benchmark as shown below,

Using master node branch.
$ node benchmarking/experimental/benchmarks/node-api/require/require.perf.js 2
require.new,45370
require.cached,4611
The first number shows large number (#ops as per the chart) when required module is a new one requested while the second number is low because this module is already been required and cached, in the memory (and so it has low number of ops), which makes complete sense. We need to update the graph reporting. Am I missing something here?

Anyway, following commit introduced this change nodejs/node@28f0693796.

[mhdawson]

The chart label says ops/s so I think that is what we believed was being reported. For 6.x (and the previous versions before the change in the charts), the number was higher for require.cached which is what we expected.

Looking at the runner however, I see:

  var sum = results.reduce(function(s, event) {
                    return s + event.target.hz;
                }, 0);
                var average = sum / results.length;
                console.log([nameOfTest].concat(average).join(','));

Which does seem to indicate it is reporting the average time per run as opposed to ops/s

[mhdawson]

But then the number fo 6.x is hard to understand in that it would say that it takes longer to load a cached module than a non-cached one.

[mhdawson]

Looking at the code changed by nodejs/node@28f0693 unless adding to the children speeds up lookup, that change looks like it would only slow down require as opposed to speed it out.

@uttampawar can you review the benchmark code to confirm what you believe it is measuring (as I'm not sure based on my quick look at the code and the change) and if we expect a speedup/slowdown from the change you referenced in terms of require for cached modules.

[mhdawson]

Also looking at this in the test runner code

 return s + event.target.hz;

That seems to indicate it might be reporting hz (ops per second?) as we originally thought.

[uttampawar]

@mhdawson I'll take a look.

[davisjam]

I think the units areops/sec. It looks to me like it is reporting AVERAGE(ops/sec) with the average taken over all of the runs.

[uttampawar]

@mhdawson Yes it looks that way, that change of updatingChildren when cached module is found is only going to slow down require. But simple test as shown below shows dramatic difference ...
$ cat top.js
for (var i=0; i < 1e+6; i++) {
require('./a.js');
module.constructor._cache[__dirname + '/a.js'] = undefined;
}

$ time node top.js
real 0m22.934s
user 0m24.464s
sys 0m5.344s

$ cat top.js (without resetting the _cache)
for (var i=0; i < 1e+6; i++) {
require('./a.js');
}

$ time top.js
real 0m1.597s
user 0m1.420s
sys 0m0.240s

Huge difference.

[uttampawar]

@mhdawson Here is the update. I debugged the code and it's definitely working as expected (as shown in previous example).
I seperated the require.new and require.cached into two separate program codes and I get expected speedup. See details below,

$ node experimental/benchmarks/node-api/require/require.new perf.js 2
require.new,54551.57659729372

$ node experimental/benchmarks/node-api/require/require.cached perf.js 2
require.cached,535782.8600008131

I not sure but it could be something to do with require.perf.js loading "a.js" in the main module.

If you reverse the invocation of cached and the new we get following,
require.cached,563795.85026919
require.new,55780.14691066807