Fix `cy.visit` slowness by removing Electron timers workaround #4385

flotwig · 2019-06-04T18:53:01Z

changes HttpAgent to override addRequest instead of createSocket (more correct)
Removes timers fix - this fixes the slowness between addRequest and onResponseReceived
Does not pass the destination's Connection header through proxy to the browser - Connection is a hop by hop header
~~Make calls to stdout.write and stderr.write asynchronous to prevent slowdown when TTY is unresponsive~~
- Even when stdio is blocking, it's not enough lag to make a difference unless you're dumping multiple kbps of data into a TTY, so it's not worth it to add this fix here.

flotwig · 2019-06-04T19:32:46Z

This navigation_spec completes quickly, in 9 seconds:

    it.only "completes immediately on localhost", ->
      _.times 100, ->
        cy.visit('http://localhost:3500/dump-method')

This same test with Python's SimpleHTTPServer takes waaaay too long (60+ seconds).

driver/test server headers proxied by Cypress:

Details

And in a regular browser:

Details

SimpleHTTPServer headers proxied by Cypress:

Details

And in a regular browser:

Details

flotwig · 2019-06-05T14:19:53Z

I happened to notice that while SimpleHTTPServer doesn't support keep-alive, Cypress was forcing the addition of a Connection: keep-alive header to the responses, which doesn't really help anything. The agent will keep-alive any request that supports keep-alive, and the browser connection to the proxy is kept alive using Proxy-Connection: keep-alive. So I think this chunk of code can be removed:

cypress/packages/server/lib/request.coffee

Lines 444 to 448 in 768381b

    
           ## send keep-alive with requests since Chrome won't send it in proxy mode 
        
           ## https://github.com/cypress-io/cypress/pull/3531#issuecomment-476269041 
        
           headers: { 
        
             "Connection": "keep-alive" 
        
           }

EDIT: I've narrowed it down, it seems like the issue only occurs when the server sends connection: close

EDIT 2: Tried setting this hack, but didn't help anything:

const net = require('net')

const connect = net.Socket.prototype.connect

net.Socket.prototype.connect = function (...args) {
  const s = connect.call(this, ...args)

  s.setNoDelay(true)

  return s
}

EDIT 3: Removing the new CombinedAgent does not fix this, leading me to think the issue could be in the request retries code.

#4385 (comment)

flotwig · 2019-06-10T18:46:49Z

Noticed that a few factors appear to influence this slowdown:

connection: close vs. keep-alive from destination server
if a large amount of output is being sent to stderr
- Related: Node.js halts when console window is scrolled
if the timers fix is in place or not
if running headlessly or not

`Connection: close`?	`DEBUG` on?	Timers fix?	Was `cy.visit` fast?
❌	❌	❌	✔️
❌	❌	✔️	❌
❌	✔️	❌	❌
❌	✔️	✔️	❌
✔️	❌	❌	✔️*
✔️	❌	✔️	❌
✔️	✔️	❌	❌
✔️	✔️	✔️	❌

*The visits with close were slightly slower (~2ms vs ~1ms) than the visits from Connection: keep-alive, probably due to the overhead of creating a new socket connection.

Conclusions:

close vs. keep-alive does not affect this behavior
If a large amount of output is sent to stderr (presumably stdout as well), it will cause a slowdown on Linux/macOS because stderr writes are synchronous on these platforms.
- Could add a workaround to make writes async. Something like fs.write(2, 'message')
  - debug does process.stderr.write, which is sync: https://github.com/visionmedia/debug/blob/master/src/node.js#L189
  - Downside: Could cause partial output to stderr, interleaved output to stderr
The timers fix causes a slowdown, not sure why yet.

EDIT: The following workaround fixes the issue with blocking on stderr/stdout writes:

const _ = require('lodash')
const debug = require('debug')
const fs = require('fs')
const util = require('util')

process.stdout.write = function write (str) {
  fs.write(1, str, _.noop)
}

process.stderr.write = function write (str) {
  fs.write(2, str, _.noop)
}

debug.log = function log (...args) {
  return process.stderr.write(`${util.format(...args)}\n`)
}

I am not sure if this will have detrimental effects like out-of-order output, have to do some testing. Not sure if this complexity is worth the marginal benefit - users usually don't have tons of output spitting out during a run.

All tests pass with the async stdio stuff: https://circleci.com/workflow-run/9150993a-cecc-450b-8229-583035a45cb5

Which makes sense, I don't see how interleaving could be possible since .writes will be queued in order in the Node event loop.

This reverts commit b9d65a4.

This reverts commit c51b395.

This reverts commit 8b82f0e.

flotwig · 2019-06-11T16:48:22Z

Notes on trying to figure out what caused this issue:

Tried to use system Node.js for timers in c51b395 to see if it made any difference. The delay was still present.
- Additionally, there's not a delay in the IPC channel created by cp.fork() after reviewing the logs carefully.
Tried to run the timers_spec within Electron v2.0.18 in 8b82f0e to see if anything failed, but all tests pass.

Wrote a small script that creates 10000 setTimeouts and then measures the extremes of how different the actual execution time is from the specified execution time and tested it against Node.js and Electron and our timers fix.

const _ = require('lodash')
const percentile = require('percentile')

// require('./timers/parent').fix()

const N = 10000

let differences = []

_.times(N, () => {
  const ms = Math.random() * 60 * 1000 // between 0 and 1 minute
  const started = new Date

  setTimeout(() => {
    const elapsed = new Date - started
    const difference = elapsed - ms

    differences.push(difference)

    //console.log(`Expected: ${ms}ms\tActual: ${elapsed}ms\tDifference: ${difference}ms`)

    if (differences.length === N) {
      printSummary()
    }
  }, ms)
})

function printSummary () {
  console.log(`Node version: ${process.versions.node}\tElectron version: ${process.versions.electron}`)

  ;[10, 20, 30, 40, 50, 60, 70, 80, 90, 95, 98, 99, 99.5, 99.7, 100].forEach((p) => {
    const q = percentile(p, differences)

    console.log(`${p}%\t of setTimeout calls finished with less than ${q}ms\t of difference`)
  })
}

Results

Without timer fix

Details

Node

Node version: 8.9.3     Electron version: undefined
10%      of setTimeout calls finished with less than -0.808537569224427ms        of difference
20%      of setTimeout calls finished with less than -0.6259799470499274ms       of difference
30%      of setTimeout calls finished with less than -0.44502581776032457ms      of difference
40%      of setTimeout calls finished with less than -0.25167741533732624ms      of difference
50%      of setTimeout calls finished with less than -0.061525145909399725ms     of difference
60%      of setTimeout calls finished with less than 0.16497256675938843ms       of difference
70%      of setTimeout calls finished with less than 0.3981649662964628ms        of difference
80%      of setTimeout calls finished with less than 0.6206283314459142ms        of difference
90%      of setTimeout calls finished with less than 0.8536222528127837ms        of difference
95%      of setTimeout calls finished with less than 0.9763406618367299ms        of difference
98%      of setTimeout calls finished with less than 1.5096292363086832ms        of difference
99%      of setTimeout calls finished with less than 1.7955813532098546ms        of difference
99.5%    of setTimeout calls finished with less than 1.936103021940653ms         of difference
99.7%    of setTimeout calls finished with less than 1.9872977593477117ms        of difference
100%     of setTimeout calls finished with less than 30.233294656009093ms        of difference

Electron

Node version: 8.9.3     Electron version: 2.0.18
10%      of setTimeout calls finished with less than -0.8206427405893919ms       of difference
20%      of setTimeout calls finished with less than -0.6416605677586631ms       of difference
30%      of setTimeout calls finished with less than -0.46879562928006635ms      of difference
40%      of setTimeout calls finished with less than -0.30004066277615493ms      of difference
50%      of setTimeout calls finished with less than -0.12525602254027035ms      of difference
60%      of setTimeout calls finished with less than 0.07629123181595787ms       of difference
70%      of setTimeout calls finished with less than 0.32577971076534595ms       of difference
80%      of setTimeout calls finished with less than 0.5810628193685261ms        of difference
90%      of setTimeout calls finished with less than 0.8206066088241641ms        of difference
95%      of setTimeout calls finished with less than 0.9505708953875001ms        of difference
98%      of setTimeout calls finished with less than 1.3272328875042376ms        of difference
99%      of setTimeout calls finished with less than 1.712318293244607ms         of difference
99.5%    of setTimeout calls finished with less than 1.9313783880570554ms        of difference
99.7%    of setTimeout calls finished with less than 2.7338192922288727ms        of difference
100%     of setTimeout calls finished with less than 57.43496641139628ms         of difference

Node version: 8.2.1     Electron version: 1.8.2
10%      of setTimeout calls finished with less than -0.8400778030579659ms       of difference
20%      of setTimeout calls finished with less than -0.6789885455400508ms       of difference
30%      of setTimeout calls finished with less than -0.5213463660184061ms       of difference
40%      of setTimeout calls finished with less than -0.35441039247234585ms      of difference
50%      of setTimeout calls finished with less than -0.1963125350084738ms       of difference
60%      of setTimeout calls finished with less than -0.03586202786391368ms      of difference
70%      of setTimeout calls finished with less than 0.21781149300113611ms       of difference
80%      of setTimeout calls finished with less than 0.4913710689288564ms        of difference
90%      of setTimeout calls finished with less than 0.7543207453345531ms        of difference
95%      of setTimeout calls finished with less than 0.8804111877652758ms        of difference
98%      of setTimeout calls finished with less than 0.9640665196257032ms        of difference
99%      of setTimeout calls finished with less than 0.9899159210617654ms        of difference
99.5%    of setTimeout calls finished with less than 0.9999059387573652ms        of difference
99.7%    of setTimeout calls finished with less than 3.08311010796524ms          of difference
100%     of setTimeout calls finished with less than 86.256371268468ms           of difference

⚠️ Electron (running within cypress:open)

Node version: 8.9.3     Electron version: 2.0.18
10%      of setTimeout calls finished with less than -0.794390320283128ms        of difference
20%      of setTimeout calls finished with less than -0.5783507076121168ms       of difference
30%      of setTimeout calls finished with less than -0.35775092726544244ms      of difference
40%      of setTimeout calls finished with less than -0.146772468018753ms        of difference
50%      of setTimeout calls finished with less than 0.07865236507495865ms       of difference
60%      of setTimeout calls finished with less than 0.34096621516073355ms       of difference
70%      of setTimeout calls finished with less than 0.6108102321377373ms        of difference
80%      of setTimeout calls finished with less than 0.8851327323864098ms        of difference
90%      of setTimeout calls finished with less than 14.757928041928608ms        of difference
95%      of setTimeout calls finished with less than 423.1345273230181ms         of difference
98%      of setTimeout calls finished with less than 1985.8261815088135ms        of difference
99%      of setTimeout calls finished with less than 2662.8106104393437ms        of difference
99.5%    of setTimeout calls finished with less than 2974.7492187043554ms        of difference
99.7%    of setTimeout calls finished with less than 3110.6066542980884ms        of difference
100%     of setTimeout calls finished with less than 3318.813206669146ms         of difference

With timer fix

Details

Node

Node version: 8.9.3     Electron version: undefined
10%      of setTimeout calls finished with less than 47.125507825006025ms        of difference
20%      of setTimeout calls finished with less than 50.809703329607146ms        of difference
30%      of setTimeout calls finished with less than 53.45466294722428ms         of difference
40%      of setTimeout calls finished with less than 56.40672768046716ms         of difference
50%      of setTimeout calls finished with less than 60.00452243758991ms         of difference
60%      of setTimeout calls finished with less than 61.416551582828106ms        of difference
70%      of setTimeout calls finished with less than 62.347652707051566ms        of difference
80%      of setTimeout calls finished with less than 64.17554117484542ms         of difference
90%      of setTimeout calls finished with less than 65.384438686473ms           of difference
95%      of setTimeout calls finished with less than 66.06440910743913ms         of difference
98%      of setTimeout calls finished with less than 66.7141552715184ms          of difference
99%      of setTimeout calls finished with less than 66.92292373694363ms         of difference
99.5%    of setTimeout calls finished with less than 67.06794870285785ms         of difference
99.7%    of setTimeout calls finished with less than 67.60125232554856ms         of difference
100%     of setTimeout calls finished with less than 86.19758732465016ms         of difference

Electron

Node version: 8.9.3     Electron version: 2.0.18
10%      of setTimeout calls finished with less than 116.5929865264834ms         of difference
20%      of setTimeout calls finished with less than 122.42919143346808ms        of difference
30%      of setTimeout calls finished with less than 132.24118597713095ms        of difference
40%      of setTimeout calls finished with less than 139.83971975833992ms        of difference
50%      of setTimeout calls finished with less than 146.45091776030677ms        of difference
60%      of setTimeout calls finished with less than 150.33835098845157ms        of difference
70%      of setTimeout calls finished with less than 155.55104586421658ms        of difference
80%      of setTimeout calls finished with less than 162.90567006963101ms        of difference
90%      of setTimeout calls finished with less than 170.91927253014728ms        of difference
95%      of setTimeout calls finished with less than 172.49280820543936ms        of difference
98%      of setTimeout calls finished with less than 173.72122882808617ms        of difference
99%      of setTimeout calls finished with less than 174.2916368306869ms         of difference
99.5%    of setTimeout calls finished with less than 174.69849538467315ms        of difference
99.7%    of setTimeout calls finished with less than 175.28803871298078ms        of difference
100%     of setTimeout calls finished with less than 186.8864348078132ms         of difference

Node version: 8.2.1     Electron version: 1.8.2
10%      of setTimeout calls finished with less than 96.40313165812768ms         of difference
20%      of setTimeout calls finished with less than 104.00768624228658ms        of difference
30%      of setTimeout calls finished with less than 114.22537481109975ms        of difference
40%      of setTimeout calls finished with less than 119.17345535971253ms        of difference
50%      of setTimeout calls finished with less than 123.63265788537683ms        of difference
60%      of setTimeout calls finished with less than 132.6886534227524ms         of difference
70%      of setTimeout calls finished with less than 136.14233595062979ms        of difference
80%      of setTimeout calls finished with less than 143.2740848265821ms         of difference
90%      of setTimeout calls finished with less than 149.4148031569639ms         of difference
95%      of setTimeout calls finished with less than 157.0354182605879ms         of difference
98%      of setTimeout calls finished with less than 157.89313474494702ms        of difference
99%      of setTimeout calls finished with less than 158.54258244268567ms        of difference
99.5%    of setTimeout calls finished with less than 158.79518041538176ms        of difference
99.7%    of setTimeout calls finished with less than 158.92159952260408ms        of difference
100%     of setTimeout calls finished with less than 175.95113300157936ms        of difference

⚠️ Electron (running within cypress:open)

Node version: 8.9.3     Electron version: 2.0.18
10%      of setTimeout calls finished with less than 3618.238505667603ms         of difference
20%      of setTimeout calls finished with less than 3622.9328518342154ms        of difference
30%      of setTimeout calls finished with less than 3639.082338413773ms         of difference
40%      of setTimeout calls finished with less than 3652.0457438047342ms        of difference
50%      of setTimeout calls finished with less than 3659.634003181345ms         of difference
60%      of setTimeout calls finished with less than 3665.1496447934915ms        of difference
70%      of setTimeout calls finished with less than 3674.2180531929334ms        of difference
80%      of setTimeout calls finished with less than 3680.4332767665765ms        of difference
90%      of setTimeout calls finished with less than 3688.8052590990046ms        of difference
95%      of setTimeout calls finished with less than 3692.135827753271ms         of difference
98%      of setTimeout calls finished with less than 3793.6803570824486ms        of difference
99%      of setTimeout calls finished with less than 3916.027393950155ms         of difference
99.5%    of setTimeout calls finished with less than 4006.5880852710943ms        of difference
99.7%    of setTimeout calls finished with less than 4099.786606898997ms         of difference
100%     of setTimeout calls finished with less than 4238.4597938540355ms        of difference

Notes

~~Removing the timers fix does not seem to have completely fixed the situation. 2-5% of timeouts still do not resolve within 1000ms.~~
- Never mind, this was only happening because ticks were growing large because the test was running at the same time as Cypress was initializing.
- Tick lengths grow to >1 second while Cypress does a bunch of initial require's, etc.
- This flame graph is from Cypress startup w/o timers fix:

Took a flame graph of Cypress running tests with IPC timers:

That tick happened immediately after a cy.visit and took 2 seconds, causing the visit to be delayed by at least that much.

Now here is a flame graph of Cypress running tests without IPC timers:

The longest tick was 500ms, with most being much less than 100ms.

Somehow, the operation of sending a timer via IPC to a fork causes the event loop to pause for multiple seconds, blocking all FS and network callbacks for at least that long.

This reverts commit 93f15fc.

This reverts commit 9c8337e.

brian-mann · 2019-06-17T13:15:56Z

So do we still want to remove the Connection headers?

flotwig · 2019-06-17T13:21:26Z

@brian-mann It's a hop-by-hop header, so I think the proxy should remove it. The browser's connection to the proxy is still keep-alive - check out the Connection IDs in the network log I produced using this branch:

brian-mann · 2019-06-17T13:26:34Z

It looks like we're only stripping it on the incoming response from the upstream server - before handing it back to the browser.

Are we still sending it when we make the initial proxied request to the upstream server from the cypress proxy?

Does the http agent modify the http header and add it? NOTE: i'm not referring to the TCP keepalive mechanism, just the actual HTTP connection header. Can't remember if we have tests around this or not.

flotwig · 2019-06-17T13:34:41Z

Yeah, this is still there:

cypress/packages/server/lib/request.coffee

Lines 444 to 448 in 8e63476

    
           ## send keep-alive with requests since Chrome won't send it in proxy mode 
        
           ## https://github.com/cypress-io/cypress/pull/3531#issuecomment-476269041 
        
           headers: { 
        
             "Connection": "keep-alive" 
        
           }

If I remove it, then a new socket is opened for each request (net profiler output):

[ X connection opened to localhost:33159 by HttpAgent.connect [as createConnection] (net.js:103:35) ]
  1 [ C client connected from 127.0.0.1:38894 to server on localhost:33159 ]
  1 [ C client disconnected ]
[ X connection closed ]
[ X connection opened to localhost:33159 by HttpAgent.connect [as createConnection] (net.js:103:35) ]
  1 [ C client connected from 127.0.0.1:38896 to server on localhost:33159 ]
  1 [ C client disconnected ]
[ X connection closed ]
[ X connection opened to localhost:33159 by HttpAgent.connect [as createConnection] (net.js:103:35) ]
  1 [ C client connected from 127.0.0.1:38898 to server on localhost:33159 ]
  1 [ C client disconnected ]
[ X connection closed ]
[ X connection opened to localhost:33159 by HttpAgent.connect [as createConnection] (net.js:103:35) ]
  1 [ C client connected from 127.0.0.1:38900 to server on localhost:33159 ]
  1 [ C client disconnected ]
[ X connection closed ]

With it kept in, there is only one connection established for these requests. Looks like it's still good to have.

packages/server/test/support/fixtures/projects/e2e/cypress/integration/fast_visit_spec.coffee

flotwig added 2 commits June 3, 2019 13:03

add tests for getAddress on localhost

3d82220

add test for visit resolving quickly

925efeb

flotwig added 2 commits June 4, 2019 16:20

add debug logs to network

5f678a2

network: override addRequest in HttpAgent, not createSocket

768381b

flotwig added 4 commits June 5, 2019 10:21

don't need to add connection: keep-alive to all responses

79edfa5

#4385 (comment)

test that visit finishes quickly

6083e1e

do not forward connection header

600c9c2

add tests to help reproduce

108d6b6

flotwig added 14 commits June 10, 2019 14:52

cleanup

625d4ec

still send keep-alive

5d67a97

update tests

07a8258

remove timers

b9d65a4

add snapshots to e2e test

208775a

remove tests for debugging

ebe4310

try making console writes async

9c8337e

Revert "remove timers"

93f15fc

This reverts commit b9d65a4.

allow DEBUG_COLORS to be passed in an e2e test

aee8a72

try: using system node for the timers, setting up our own IPC

c51b395

Revert "try: using system node for the timers, setting up our own IPC"

d507f52

This reverts commit c51b395.

put the interesting test first

1b14a1b

use electron-mocha to run tests in electron

8b82f0e

Revert "use electron-mocha to run tests in electron"

ae439aa

This reverts commit 8b82f0e.

flotwig changed the title ~~[WIP] Fix 4313~~ Fix cy.visit slowness by removing Electron timers workaround; making stdio operations asynchronous Jun 11, 2019

support legacy addRequest invocation

890e38a

flotwig force-pushed the issue-4313 branch from ca24d1a to 890e38a Compare June 11, 2019 16:55

Revert "Revert "remove timers""

3f077f8

This reverts commit 93f15fc.

update snapshot

2858a5b

flotwig requested a review from brian-mann June 11, 2019 17:30

Revert "try making console writes async"

47860ca

This reverts commit 9c8337e.

flotwig changed the title ~~Fix cy.visit slowness by removing Electron timers workaround; making stdio operations asynchronous~~ Fix cy.visit slowness by removing Electron timers workaround Jun 12, 2019

Merge remote-tracking branch 'origin/develop' into issue-4313

8e63476

brian-mann reviewed Jun 17, 2019

View reviewed changes

packages/server/test/support/fixtures/projects/e2e/cypress/integration/fast_visit_spec.coffee Outdated Show resolved Hide resolved

complete in 150ms, not 1000ms

bbff24d

brian-mann merged commit 1f185f7 into develop Jun 17, 2019

cypress-bot bot mentioned this pull request Jun 17, 2019

cy.visit in 3.3.1 is 2x-4x as slow as 3.2.0 #4313

Closed

flotwig deleted the issue-4313 branch January 24, 2022 18:18

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Fix `cy.visit` slowness by removing Electron timers workaround #4385

Fix `cy.visit` slowness by removing Electron timers workaround #4385

flotwig commented Jun 4, 2019 •

edited

flotwig commented Jun 4, 2019 •

edited

flotwig commented Jun 5, 2019 •

edited

flotwig commented Jun 10, 2019 •

edited

flotwig commented Jun 11, 2019 •

edited

Node

Electron

⚠️ Electron (running within cypress:open)

Node

Electron

⚠️ Electron (running within cypress:open)

brian-mann commented Jun 17, 2019

flotwig commented Jun 17, 2019

brian-mann commented Jun 17, 2019

flotwig commented Jun 17, 2019

Fix cy.visit slowness by removing Electron timers workaround #4385

Fix cy.visit slowness by removing Electron timers workaround #4385

Conversation

flotwig commented Jun 4, 2019 • edited

flotwig commented Jun 4, 2019 • edited

flotwig commented Jun 5, 2019 • edited

flotwig commented Jun 10, 2019 • edited

flotwig commented Jun 11, 2019 • edited

Results

Without timer fix

Node

Electron

⚠️ Electron (running within cypress:open)

With timer fix

Node

Electron

⚠️ Electron (running within cypress:open)

Notes

brian-mann commented Jun 17, 2019

flotwig commented Jun 17, 2019

brian-mann commented Jun 17, 2019

flotwig commented Jun 17, 2019

Fix `cy.visit` slowness by removing Electron timers workaround #4385

Fix `cy.visit` slowness by removing Electron timers workaround #4385

flotwig commented Jun 4, 2019 •

edited

flotwig commented Jun 4, 2019 •

edited

flotwig commented Jun 5, 2019 •

edited

flotwig commented Jun 10, 2019 •

edited

flotwig commented Jun 11, 2019 •

edited