Skip to content

http: significant performance regression on master #37937

Closed
Closed
http: significant performance regression on master#37937
Assignees
mcollina
Labels
confirmed-bugIssues and PRs for confirmed bugs.httpIssues and PRs related to the http subsystem.

Description

@mcollina
mcollina
opened on Mar 26, 2021
  • 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:

Activity

  1. mcollina commented on Mar 26, 2021

    @mcollina
    mcollina
    on Mar 26, 2021
    SponsorMemberAuthor

    cc @ronag

  2. mcollina
    added
    confirmed-bugIssues and PRs for confirmed bugs.
    httpIssues and PRs related to the http subsystem.
    on Mar 26, 2021

  3. Linkgoron commented on Mar 27, 2021

    @Linkgoron
    Linkgoron
    on Mar 27, 2021
    Contributor

    I think that the warning messages originated here: #36816

  4. mcollina commented on Mar 27, 2021

    @mcollina
    mcollina
    on Mar 27, 2021
    SponsorMemberAuthor

    I think that the warning messages originated here: #36816

    I think so as well.

  5. ronag commented on Mar 27, 2021

    @ronag
    ronag
    on Mar 27, 2021
    Member

    I will take a look as soon as I can

  6. mcollina commented on Mar 27, 2021

    @mcollina
    mcollina
    on Mar 27, 2021
    SponsorMemberAuthor

    I'm looking into it as well!

  7. ronag commented on Mar 27, 2021

    @ronag
    ronag
    on Mar 27, 2021
    Member

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

  8. mcollina commented on Mar 27, 2021

    @mcollina
    mcollina
    on Mar 27, 2021
    SponsorMemberAuthor

    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.

  9. mcollina commented on Mar 27, 2021

    @mcollina
    mcollina
    on Mar 27, 2021
    SponsorMemberAuthor

    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)

  10. ronag commented on Mar 27, 2021

    @ronag
    ronag
    on Mar 27, 2021
    Member

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

    I will sort this.

  11. ronag commented on Mar 27, 2021

    @ronag
    ronag
    on Mar 27, 2021
    Member

    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?

  12. ronag commented on Mar 27, 2021

    @ronag
    ronag
    on Mar 27, 2021
    Member

    @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());

  13. mcollina commented on Mar 27, 2021

    @mcollina
    mcollina
    on Mar 27, 2021
    SponsorMemberAuthor

    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.

  14. mcollina commented on Mar 27, 2021

    @mcollina
    mcollina
    on Mar 27, 2021
    SponsorMemberAuthor

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

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

  15. 35 remaining items

  16. ronag commented on Apr 2, 2021

    @ronag
    ronag
    on Apr 2, 2021
    Member

    @mcollina excellent work!

  17. jasnell commented on Apr 2, 2021

    @jasnell
    jasnell
    on Apr 2, 2021
    Member

    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

  18. ronag commented on Apr 2, 2021

    @ronag
    ronag
    on Apr 2, 2021
    Member

    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?

  19. mcollina commented on Apr 2, 2021

    @mcollina
    mcollina
    on Apr 2, 2021
    SponsorMemberAuthor

    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.

  20. jasnell commented on Apr 2, 2021

    @jasnell
    jasnell
    on Apr 2, 2021
    Member

    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

  21. MylesBorins
    added a commit that references this issue on Apr 4, 2021

    http: optimize debug function correctly

    d86aca9
  22. mcollina
    removed
    tsc-agendaIssues and PRs to discuss during Technical Steering Committee meetings.
    on Apr 14, 2021

  23. mcollina commented on Apr 15, 2021

    @mcollina
    mcollina
    on Apr 15, 2021
    SponsorMemberAuthor

    Here is another one: #38245.

    I have one more coming :).

  24. mcollina commented on Apr 15, 2021

    @mcollina
    mcollina
    on Apr 15, 2021
    SponsorMemberAuthor

    #38246 include my last findings.

  25. mcollina commented on Apr 20, 2021

    @mcollina
    mcollina
    on Apr 20, 2021
    SponsorMemberAuthor

    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.

  26. mcollina
    closed this as completedon Apr 20, 2021
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

Labels

confirmed-bugIssues and PRs for confirmed bugs.httpIssues and PRs related to the http subsystem.

Type

No type

Projects

No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions