http: significant performance regression on master

Version: master vs v14 and v15
Platform: linux
Subsystem: http

What steps will reproduce the bug?

run:

'use strict'

const server = require('http').createServer(function (req, res) {
  res.setHeader('content-type', 'application/json; charset=utf-8')
  res.end(JSON.stringify({ hello: 'world' }))
})

server.listen(3000)

and then:

$ npm i autocannon -g
$ autocannon -c 100 -d 5 -p 10 localhost:3000

on v14.16 this produces:

$ autocannon -c 100 -d 5 -p 10 localhost:3000
Running 5s test @ http://localhost:3000
100 connections with 10 pipelining factor

┌─────────┬──────┬───────┬───────┬───────┬──────────┬─────────┬────────┐
│ Stat    │ 2.5% │ 50%   │ 97.5% │ 99%   │ Avg      │ Stdev   │ Max    │
├─────────┼──────┼───────┼───────┼───────┼──────────┼─────────┼────────┤
│ Latency │ 5 ms │ 13 ms │ 21 ms │ 27 ms │ 13.05 ms │ 5.93 ms │ 129 ms │
└─────────┴──────┴───────┴───────┴───────┴──────────┴─────────┴────────┘
┌───────────┬─────────┬─────────┬─────────┬─────────┬─────────┬─────────┬─────────┐
│ Stat      │ 1%      │ 2.5%    │ 50%     │ 97.5%   │ Avg     │ Stdev   │ Min     │
├───────────┼─────────┼─────────┼─────────┼─────────┼─────────┼─────────┼─────────┤
│ Req/Sec   │ 60543   │ 60543   │ 77439   │ 78079   │ 73916.8 │ 6747.59 │ 60531   │
├───────────┼─────────┼─────────┼─────────┼─────────┼─────────┼─────────┼─────────┤
│ Bytes/Sec │ 11.3 MB │ 11.3 MB │ 14.5 MB │ 14.6 MB │ 13.8 MB │ 1.26 MB │ 11.3 MB │
└───────────┴─────────┴─────────┴─────────┴─────────┴─────────┴─────────┴─────────┘

Req/Bytes counts sampled once per second.

370k requests in 5.04s, 69.1 MB read

on master:

$ autocannon -c 100 -d 5 -p 10 localhost:3000
Running 5s test @ http://localhost:3000
100 connections with 10 pipelining factor

┌─────────┬───────┬───────┬───────┬───────┬──────────┬─────────┬────────┐
│ Stat    │ 2.5%  │ 50%   │ 97.5% │ 99%   │ Avg      │ Stdev   │ Max    │
├─────────┼───────┼───────┼───────┼───────┼──────────┼─────────┼────────┤
│ Latency │ 10 ms │ 14 ms │ 29 ms │ 54 ms │ 16.83 ms │ 8.54 ms │ 163 ms │
└─────────┴───────┴───────┴───────┴───────┴──────────┴─────────┴────────┘
┌───────────┬─────────┬─────────┬─────────┬─────────┬─────────┬─────────┬─────────┐
│ Stat      │ 1%      │ 2.5%    │ 50%     │ 97.5%   │ Avg     │ Stdev   │ Min     │
├───────────┼─────────┼─────────┼─────────┼─────────┼─────────┼─────────┼─────────┤
│ Req/Sec   │ 43007   │ 43007   │ 61151   │ 62143   │ 57724.8 │ 7388.63 │ 42988   │
├───────────┼─────────┼─────────┼─────────┼─────────┼─────────┼─────────┼─────────┤
│ Bytes/Sec │ 8.04 MB │ 8.04 MB │ 11.4 MB │ 11.6 MB │ 10.8 MB │ 1.38 MB │ 8.04 MB │
└───────────┴─────────┴─────────┴─────────┴─────────┴─────────┴─────────┴─────────┘

Req/Bytes counts sampled once per second.

289k requests in 5.03s, 54 MB read

On master it also produces a significant amount of warnings:

(node:235900) MaxListenersExceededWarning: Possible EventEmitter memory leak detected. 11 close listeners added to [Socket]. Use emitter.setMaxListeners() to increase limit
(node:235900) MaxListenersExceededWarning: Possible EventEmitter memory leak detected. 11 error listeners added to [Socket]. Use emitter.setMaxListeners() to increase limit

Update as of 2021/3/29 bisect from head a9cdeed:

requestTimeout df08d52 80k -> 76k
SafeArrayIterator 0b6d307 72k -> 67k
align with stream.Writable e2f5bb7 67k -> 60k - revert at Revert "http: align with stream.Writable" #37963

@ronag

cc @ronag

I think that the warning messages originated here: #36816

I think that the warning messages originated here: #36816

I think so as well.

I will take a look as soon as I can

I'm looking into it as well!

I will have time tonight. Please keep me posted if you find anything.

A couple of notes:

#36816 is the cause of the warnings and likely memory leak.

Going to the parent commit has a minor performance benefit:

$ autocannon -c 100 -d 5 -p 10 localhost:3000
Running 5s test @ http://localhost:3000
100 connections with 10 pipelining factor

┌─────────┬──────┬───────┬───────┬───────┬──────────┬─────────┬───────┐
│ Stat    │ 2.5% │ 50%   │ 97.5% │ 99%   │ Avg      │ Stdev   │ Max   │
├─────────┼──────┼───────┼───────┼───────┼──────────┼─────────┼───────┤
│ Latency │ 8 ms │ 17 ms │ 19 ms │ 28 ms │ 14.53 ms │ 5.42 ms │ 71 ms │
└─────────┴──────┴───────┴───────┴───────┴──────────┴─────────┴───────┘
┌───────────┬─────────┬─────────┬─────────┬─────────┬─────────┬─────────┬─────────┐
│ Stat      │ 1%      │ 2.5%    │ 50%     │ 97.5%   │ Avg     │ Stdev   │ Min     │
├───────────┼─────────┼─────────┼─────────┼─────────┼─────────┼─────────┼─────────┤
│ Req/Sec   │ 60895   │ 60895   │ 68351   │ 68543   │ 66806.4 │ 2971.63 │ 60887   │
├───────────┼─────────┼─────────┼─────────┼─────────┼─────────┼─────────┼─────────┤
│ Bytes/Sec │ 11.4 MB │ 11.4 MB │ 12.8 MB │ 12.8 MB │ 12.5 MB │ 556 kB  │ 11.4 MB │
└───────────┴─────────┴─────────┴─────────┴─────────┴─────────┴─────────┴─────────┘

Req/Bytes counts sampled once per second.

334k requests in 5.03s, 62.5 MB read

The majority performance regression is present in v15 as well, so it's unrelated.

Apparently the majority of the regression happened in the v15 cycle.

v15.0.0: 77k req/sec (median)
v15.11.0: 67k req/sec (median)

#36816 is the cause of the warnings and likely memory leak.

I will sort this.

Apparently the majority of the regression happened in the v15 cycle.

v15.0.0: 77k req/sec (median)
v15.11.0: 67k req/sec (median)

Are you bisecting?

@mcollina

@mcollina: Any idea how to repro without using autocannon?

I tried:

'use strict';

const common = require('../common');
const http = require('http');
const Countdown = require('../common/countdown');

const NUM_REQ = 128

const agent = new http.Agent({ keepAlive: true });
const countdown = new Countdown(NUM_REQ, () => server.close());

const server = http.createServer(common.mustCall(function(req, res) {
  res.setHeader('content-type', 'application/json; charset=utf-8')
  res.end(JSON.stringify({ hello: 'world' }))
}, NUM_REQ)).listen(0, function() {
  for (let i = 0; i < NUM_REQ; ++i) {
    http.request({
      port: server.address().port,
      agent,
      method: 'GET'
    }, function(res) {
      res.resume();
      res.on('end', () => {
        countdown.dec();
      })
    }).end();
  }
});

process.on('warning', common.mustNotCall());

Are you bisecting?

I've done a nvm "rough" bisect just narrow down a bit my scope of action.

I'm doing a git bisect as we speak, it just takes a lot of time as it spans several V8 versions.

@mcollina

@mcollina: Any idea how to repro without using autocannon?

I think you need to use net to send a manual request with http pipelining.

@mcollina

@mcollina excellent work!

I've got the fix already identified, I'm just not writing any code today so I will do that first thing Monday morning and have the PR open soon after

Do these things not show up when running a cpu profile? Seems a bit unfortunate that we need to git bisect to identify new or old performance bottlenecks?

Do these things not show up when running a cpu profile? Seems a bit unfortunate that we need to git bisect to identify new or old performance bottlenecks?

They show up. However git bisecting is actually simpler because you do not have to code hypothetical fixes.

The hrtime showed up. It's far down from the main bottleneck, but it was a key difference on an hot path.

And I did run perf tests on this one change. I just think some of the other issues were masking the perf hit one the hrtime change making it far less obvious. Fortunately, it's a quick fix

http: optimize debug function correctly

Here is another one: #38245.

I have one more coming :).

#38246 include my last findings.

With the latest PRs having landed, the HTTP throughput of the upcoming v16 is on par with the one of the latest v14. I think this is a milestone and I'll celebrate to close this issue and possibly open a fresh one with other optimizations that we might want to do here.

Navigation Menu

Repository navigation

http: significant performance regression on master #37937

What steps will reproduce the bug?

35 remaining items

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

http: significant performance regression on master #37937

Description

What steps will reproduce the bug?

Activity

mcollina commented on Mar 26, 2021

Linkgoron commented on Mar 27, 2021

mcollina commented on Mar 27, 2021

ronag commented on Mar 27, 2021

mcollina commented on Mar 27, 2021

ronag commented on Mar 27, 2021

mcollina commented on Mar 27, 2021

mcollina commented on Mar 27, 2021

ronag commented on Mar 27, 2021

ronag commented on Mar 27, 2021

ronag commented on Mar 27, 2021

mcollina commented on Mar 27, 2021

mcollina commented on Mar 27, 2021

35 remaining items

ronag commented on Apr 2, 2021

jasnell commented on Apr 2, 2021

ronag commented on Apr 2, 2021

mcollina commented on Apr 2, 2021

jasnell commented on Apr 2, 2021

mcollina commented on Apr 15, 2021

mcollina commented on Apr 15, 2021

mcollina commented on Apr 20, 2021

Metadata

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Issue actions