dbw `network-server-latency` is 0 for localhost on windows #15160

connorjclark · 2023-06-13T18:21:47Z

This is addressing the current dbw smoke fixture for Windows on the main branch. #15113 added this assertion for network-server-latency to be >0 on dbw. It's now failing in main branch.

On Windows:

"items": [
	{
	"origin": "http://localhost:10503",
	"serverResponseTime": 0
	}
],

The RTT estimate for localhost is ~300ms. This Is huge for localhost. Bad estimate, breaks how estimateResponseTimeByOrigin works and returns zeros.

sample `timing.receiveHeadersEnd - timing.sendEnd = ttfb estimate`:
304.316 - 303.566 = 0.75
104.016 - 0.915 = 103.101
214.32 - 1.126 = 213.194
2315.673 - 104.282 = 2211.3909999999996
417.554 - 214.576 = 202.97799999999998
3274.78 - 260.782 = 3013.998
2315.683 - 307.7 = 2007.983
3320.68 - 307.588 = 3013.0919999999996
308.221 - 307.389 = 0.8319999999999936
812.71 - 308.529 = 504.18100000000004
5428.048 - 416.457 = 5011.590999999999
1.393 - 0.533 = 0.86
1.208 - 0.739 = 0.469
1.207 - 0.649 = 0.558
1.077 - 0.439 = 0.6379999999999999
1.445 - 0.642 = 0.803
2.895 - 0.563 = 2.332
1.627 - 0.371 = 1.256
1.821 - 0.983 = 0.838
1.846 - 0.683 = 1.163
7.905 - 0.499 = 7.406000000000001
1.886 - 0.679 = 1.2069999999999999
212.456 - 1.05 = 211.40599999999998
42.897 - 0.43 = 42.467
1.084 - 0.273 = 0.811
1.891 - 0.545 = 1.346
0.93 - 0.325 = 0.605

So then for many samples, we get ttfb - rtt < 0, which means we get 0.

On Mac:

The RTT estimate is 0.05 ms, which is why we get a >0 latency here (as expected).

The text was updated successfully, but these errors were encountered:

connorjclark · 2023-06-13T18:50:49Z

I collected the timing and Network.responseReceived events for the main document on Windows and Mac, and also using yarn static-server and python -m http.server.

Notably, the only variant that has connectStart/End timing is Windows yarn static-server, which gives a huge ~300ms estimate. All the other variants oddly have -1 timings. This means they fall back to the poorer estimates, which are close enough to a reasonable RTT to give a nonzero latency result in the audit.

Here's what I got:

Windows yarn static-server timing for html request: {connectStart: 0, sslStart: -1, sslEnd: -1, connectEnd: 312.913}

{
  "method": "Network.responseReceived",
  "params": {
    "requestId": "9622D4FECAB3BF8EC4A7313450C6E8BD",
    "loaderId": "9622D4FECAB3BF8EC4A7313450C6E8BD",
    "timestamp": 3029.115015,
    "type": "Document",
    "response": {
      "url": "http://localhost:10503/dobetterweb/dbw_tester.html",
      "status": 200,
      "statusText": "OK",
      "headers": {
        "Access-Control-Allow-Origin": "*",
        "Connection": "keep-alive",
        "Content-Type": "text/html; charset=utf-8",
        "Date": "Tue, 13 Jun 2023 18:38:14 GMT",
        "Keep-Alive": "timeout=5",
        "Origin-Agent-Cluster": "?1",
        "Transfer-Encoding": "chunked"
      },
      "mimeType": "text/html",
      "connectionReused": false,
      "connectionId": 40,
      "remoteIPAddress": "127.0.0.1",
      "remotePort": 10503,
      "fromDiskCache": false,
      "fromServiceWorker": false,
      "fromPrefetchCache": false,
      "encodedDataLength": 229,
      "timing": {
        "requestTime": 3028.796112,
        "proxyStart": -1,
        "proxyEnd": -1,
        "dnsStart": 0,
        "dnsEnd": 0,
        "connectStart": 0,
        "connectEnd": 311.441,
        "sslStart": -1,
        "sslEnd": -1,
        "workerStart": -1,
        "workerReady": -1,
        "workerFetchStart": -1,
        "workerRespondWithSettled": -1,
        "sendStart": 311.537,
        "sendEnd": 311.607,
        "pushStart": 0,
        "pushEnd": 0,
        "receiveHeadersStart": 318.083,
        "receiveHeadersEnd": 318.225
      },
      "responseTime": 1686681494392.91,
      "protocol": "http/1.1",
      "alternateProtocolUsage": "unspecifiedReason",
      "securityState": "secure"
    },
    "hasExtraInfo": true,
    "frameId": "99CF051DDF5DADC9ED34C06B9C53B515"
  },
  "targetType": "page",
  "sessionId": "721AFD5537B606A7C23E3694DB418C19"
}

Windows python -m http.server timing for html request: {connectStart: -1, sslStart: -1, sslEnd: -1, connectEnd: -1}

{
"method": "Network.responseReceived",
"params": {
	"requestId": "5F64E59DEB7A31B7AF889687291528DE",
	"loaderId": "5F64E59DEB7A31B7AF889687291528DE",
	"timestamp": 2930.335041,
	"type": "Document",
	"response": {
	"url": "http://localhost:10503/dobetterweb/dbw_tester.html",
	"status": 200,
	"statusText": "OK",
	"headers": {
		"Content-Length": "18013",
		"Content-type": "text/html",
		"Date": "Tue, 13 Jun 2023 18:36:35 GMT",
		"Last-Modified": "Tue, 13 Jun 2023 18:06:58 GMT",
		"Server": "SimpleHTTP/0.6 Python/3.9.5"
	},
	"mimeType": "text/html",
	"connectionReused": true,
	"connectionId": 28,
	"remoteIPAddress": "[::1]",
	"remotePort": 10503,
	"fromDiskCache": false,
	"fromServiceWorker": false,
	"fromPrefetchCache": false,
	"encodedDataLength": 187,
	"timing": {
		"requestTime": 2930.332351,
		"proxyStart": -1,
		"proxyEnd": -1,
		"dnsStart": -1,
		"dnsEnd": -1,
		"connectStart": -1,
		"connectEnd": -1,
		"sslStart": -1,
		"sslEnd": -1,
		"workerStart": -1,
		"workerReady": -1,
		"workerFetchStart": -1,
		"workerRespondWithSettled": -1,
		"sendStart": 0.86,
		"sendEnd": 0.92,
		"pushStart": 0,
		"pushEnd": 0,
		"receiveHeadersStart": 1.838,
		"receiveHeadersEnd": 1.949
	},
	"responseTime": 1686681395612.787,
	"protocol": "http/1.0",
	"alternateProtocolUsage": "unspecifiedReason",
	"securityState": "secure"
	},
	"hasExtraInfo": true,
	"frameId": "FD066E4067B33BE216F3B126EEFFCAA7"
},
"targetType": "page",
"sessionId": "9F6561684EA5655AEB91D7E9DE0B13CD"
}

Mac yarn static-server timing for html request: {connectStart: -1, sslStart: -1, sslEnd: -1, connectEnd: -1}

{
  "method": "Network.responseReceived",
  "params": {
    "requestId": "04D0B0B7DC9A015E6E0C5C8A4B2D5029",
    "loaderId": "04D0B0B7DC9A015E6E0C5C8A4B2D5029",
    "timestamp": 57791.620675,
    "type": "Document",
    "response": {
      "url": "http://localhost:10503/dobetterweb/dbw_tester.html",
      "status": 200,
      "statusText": "OK",
      "headers": {
        "Access-Control-Allow-Origin": "*",
        "Connection": "keep-alive",
        "Content-Type": "text/html; charset=utf-8",
        "Date": "Tue, 13 Jun 2023 18:40:31 GMT",
        "Keep-Alive": "timeout=5",
        "Origin-Agent-Cluster": "?1",
        "Transfer-Encoding": "chunked"
      },
      "mimeType": "text/html",
      "connectionReused": true,
      "connectionId": 25,
      "remoteIPAddress": "127.0.0.1",
      "remotePort": 10503,
      "fromDiskCache": false,
      "fromServiceWorker": false,
      "fromPrefetchCache": false,
      "encodedDataLength": 229,
      "timing": {
        "requestTime": 57791.619241,
        "proxyStart": -1,
        "proxyEnd": -1,
        "dnsStart": -1,
        "dnsEnd": -1,
        "connectStart": -1,
        "connectEnd": -1,
        "sslStart": -1,
        "sslEnd": -1,
        "workerStart": -1,
        "workerReady": -1,
        "workerFetchStart": -1,
        "workerRespondWithSettled": -1,
        "sendStart": 0.404,
        "sendEnd": 0.431,
        "pushStart": 0,
        "pushEnd": 0,
        "receiveHeadersStart": 0.893,
        "receiveHeadersEnd": 0.941
      },
      "responseTime": 1686681631128.587,
      "protocol": "http/1.1",
      "alternateProtocolUsage": "unspecifiedReason",
      "securityState": "secure"
    },
    "hasExtraInfo": true,
    "frameId": "29E285106EE6CE13E4825C5E404545F0"
  },
  "targetType": "page",
  "sessionId": "93D5096E61D27E3E9FC49451B38B3589"
}

Mac python -m http.server timing for html request: {connectStart: -1, sslStart: -1, sslEnd: -1, connectEnd: -1}

{
  "method": "Network.responseReceived",
  "params": {
    "requestId": "E1DC6E694E495DD061D64966942B6D4F",
    "loaderId": "E1DC6E694E495DD061D64966942B6D4F",
    "timestamp": 58037.407454,
    "type": "Document",
    "response": {
      "url": "http://localhost:10503/dobetterweb/dbw_tester.html",
      "status": 200,
      "statusText": "OK",
      "headers": {
        "Content-Length": "17499",
        "Content-type": "text/html",
        "Date": "Tue, 13 Jun 2023 18:44:36 GMT",
        "Last-Modified": "Mon, 12 Jun 2023 19:58:43 GMT",
        "Server": "SimpleHTTP/0.6 Python/3.10.8"
      },
      "mimeType": "text/html",
      "connectionReused": true,
      "connectionId": 24,
      "remoteIPAddress": "[::1]",
      "remotePort": 10503,
      "fromDiskCache": false,
      "fromServiceWorker": false,
      "fromPrefetchCache": false,
      "encodedDataLength": 188,
      "timing": {
        "requestTime": 58037.404589,
        "proxyStart": -1,
        "proxyEnd": -1,
        "dnsStart": -1,
        "dnsEnd": -1,
        "connectStart": -1,
        "connectEnd": -1,
        "sslStart": -1,
        "sslEnd": -1,
        "workerStart": -1,
        "workerReady": -1,
        "workerFetchStart": -1,
        "workerRespondWithSettled": -1,
        "sendStart": 0.287,
        "sendEnd": 0.323,
        "pushStart": 0,
        "pushEnd": 0,
        "receiveHeadersStart": 2.389,
        "receiveHeadersEnd": 2.442
      },
      "responseTime": 1686681876913.762,
      "protocol": "http/1.0",
      "alternateProtocolUsage": "unspecifiedReason",
      "securityState": "secure"
    },
    "hasExtraInfo": true,
    "frameId": "5C103381C258008A8C4AF6E845BF340E"
  },
  "targetType": "page",
  "sessionId": "1823D73AF8437B26A9B81A9F1A8972EE"
},

connorjclark · 2023-06-13T19:00:04Z

It's very unexpected that we only get connection timing from one of the above variants. Looking closer at that one, 300ms seems huge for connecting to a localhost server. Let's see how long just a direct request takes:

Windows, yarn static-server:

time curl 'http://localhost:10503/dobetterweb/dbw_tester.html' > /dev/null

real    0m0.240s (!!!!)
user    0m0.000s
sys     0m0.015s

Windows, python server:

real    0m0.034s
user    0m0.000s
sys     0m0.015s

Mac:

yarn static-server 0.00s user 0.01s system 62% cpu 0.020 total
python 0.00s user 0.01s system 60% cpu 0.021 total

(good for mac)

connorjclark · 2023-06-13T19:39:58Z

I've found that on Windows, the first request for a server using Node 16 takes an extra 300ms. Subsequent ones are fine. Node 18 seems fine. Using Node 18, the connectStart/End times are now -1 like all the other variants 👀

{
    "method": "Network.responseReceived",
    "params": {
      "requestId": "C384D34C66676C54AEF36EC18374FC1F",
      "loaderId": "C384D34C66676C54AEF36EC18374FC1F",
      "timestamp": 6636.918025,
      "type": "Document",
      "response": {
        "url": "http://localhost:10503/dobetterweb/dbw_tester.html",
        "status": 200,
        "statusText": "OK",
        "headers": {
          "Access-Control-Allow-Origin": "*",
          "Connection": "keep-alive",
          "Content-Type": "text/html; charset=utf-8",
          "Date": "Tue, 13 Jun 2023 19:38:22 GMT",
          "Keep-Alive": "timeout=5",
          "Origin-Agent-Cluster": "?1",
          "Transfer-Encoding": "chunked"
        },
        "mimeType": "text/html",
        "connectionReused": true,
        "connectionId": 28,
        "remoteIPAddress": "[::1]",
        "remotePort": 10503,
        "fromDiskCache": false,
        "fromServiceWorker": false,
        "fromPrefetchCache": false,
        "encodedDataLength": 229,
        "timing": {
          "requestTime": 6636.915782,
          "proxyStart": -1,
          "proxyEnd": -1,
          "dnsStart": -1,
          "dnsEnd": -1,
          "connectStart": -1,
          "connectEnd": -1,
          "sslStart": -1,
          "sslEnd": -1,
          "workerStart": -1,
          "workerReady": -1,
          "workerFetchStart": -1,
          "workerRespondWithSettled": -1,
          "sendStart": 0.792,
          "sendEnd": 0.859,
          "pushStart": 0,
          "pushEnd": 0,
          "receiveHeadersStart": 1.501,
          "receiveHeadersEnd": 1.638
        },
        "responseTime": 1686685102195.87,
        "protocol": "http/1.1",
        "alternateProtocolUsage": "unspecifiedReason",
        "securityState": "secure"
      },
      "hasExtraInfo": true,
      "frameId": "8480173701F8BC3555289CDE38A58BD5"
    },
    "targetType": "page",
    "sessionId": "AD65E46B434B20EDA75D05C5EBF04C59"
  },

None more enlightened as to the root cause (why do we get -1 here?!), but I suppose we could update to Node 18 in CI to resolve this.

github-actions bot assigned paulirish Jun 13, 2023

connorjclark assigned connorjclark and unassigned paulirish Jun 13, 2023

connorjclark mentioned this issue Jun 13, 2023

tests(ci): bump node to fix windows latency failure #15162

Merged

devtools-bot added the needs-priority label Jun 13, 2023

adamraine added P2 test backlog disabled or needed tests and removed needs-priority labels Aug 18, 2023

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

dbw `network-server-latency` is 0 for localhost on windows #15160

dbw `network-server-latency` is 0 for localhost on windows #15160

connorjclark commented Jun 13, 2023 •

edited

Loading

connorjclark commented Jun 13, 2023

connorjclark commented Jun 13, 2023 •

edited

Loading

connorjclark commented Jun 13, 2023 •

edited

Loading

dbw network-server-latency is 0 for localhost on windows #15160

dbw network-server-latency is 0 for localhost on windows #15160

Comments

connorjclark commented Jun 13, 2023 • edited Loading

connorjclark commented Jun 13, 2023

connorjclark commented Jun 13, 2023 • edited Loading

connorjclark commented Jun 13, 2023 • edited Loading

dbw `network-server-latency` is 0 for localhost on windows #15160

dbw `network-server-latency` is 0 for localhost on windows #15160

connorjclark commented Jun 13, 2023 •

edited

Loading

connorjclark commented Jun 13, 2023 •

edited

Loading

connorjclark commented Jun 13, 2023 •

edited

Loading