Is there a way to debug why a chrome request was queued?

Question

Background: Chrome has a requests queue. It will queue delayable requests under some circumstances. But I found it hard to determine which requests are causing the requests queuing.

My question is: do we have a way to dive into the root cause of the queuing issue ?

source code

chrome doc

Answer 1

HTTP/1.1 vs HTTP/2 vs HTTP/3

HTTP/1.1: Browser request queueing. See section below.

HTTP/2: queuing has a different meaning and analysis than HTTP/1.1. Read this great article on Head of Line Blocking (HOLB).

HTTP/3: Head of Line Blocking is greatly reduced by QUIC protocol but can still happen at stream level. In-depth article

Here's my analysis of TTFB timings using Wireshark which could be a complement for the debug job.

HTTP/3

From the source cited above:

This means that we still have a form of HOL blocking, even in QUIC: if there is a byte gap inside a single stream, the latter parts of the stream are still stuck waiting until that gap is filled.

The timings analysis method described below remains usable by just selecting HTTP/3 protocol
jq -c '.log.entries | to_entries[] | select(.value.response.httpVersion == "HTTP/3" and .value.timings.blocked > 0) | [.key, .value.timings.blocked, (.value.request.url | split("/") | .[0] + "//" + .[2])]' some_http3_enabled_site.com_Archive.har.json

[80,1,"https://api-partner.some.com"]
[160,34,"https://www.some.com"]
[161,48,"https://client.some.com"]

HTTP/2

HOLB may have 2 causes: HTTP and TCP. Request blocking can still happen (perhaps over TCP reasons).

Having a HAR file for the page/site, find entries with .blocked > 50 over timings (please, read HTTP/1.1 analysis below)

    "timings": {
      "blocked": 286,
      "dns": 0,
      "connect": 0,
      "ssl": 0,
      "send": 0,
      "wait": 605,
      "receive": 163
    }

jq -r '.log.entries | to_entries[] | select(.value.response.httpVersion == "HTTP/2" and .value.timings.blocked > 0) | [.key, .value.request.url, .value.timings.blocked]' stackoverflow.com.har

Result

[12,"https://www.gravatar.com/avatar/05b09a797fd0c59d1627b30fb4cdba01?s=32&d=identicon&r=PG&f=1",140]
[19,"https://i.sstatic.net/jHqqo.jpg?s=32&g=1",319]
[22,"https://lh3.googleusercontent.com/a/AItbvmmvptZFLppl8vyYo83v1QOQJwt-90sdRzBnyw9Z=k-s32",7]
[23,"https://lh3.googleusercontent.com/a/AATXAJwXX0y4AkD3eL_6KvrwRXLmBviBVEXEb7X6U1WA=k-s32",6]
[27,"https://i.sstatic.net/kdIyT.jpg?s=32&g=1",314]
[48,"https://i.sstatic.net/65UsL.jpg?s=32&g=1",297]
[61,"https://i.sstatic.net/KLQJy.jpg?s=32&g=1",286]

HTTP/1.1

There are several reasons why Chrome could be queueing a request (as any other browser)

Queueing. The browser queues requests when:

• There are higher priority requests.
• There are already six TCP connections open for this origin, which is the limit. Applies to HTTP/1.0 and HTTP/1.1 only.
• The browser is briefly allocating space in the disk cache

From the developer's tools Network tab, save the requests with Save all as HAR with content and analyze the timings object of each request

    "timings": {
      "blocked": 2.0329999979403803,
      "dns": -1,
      "ssl": -1,
      "connect": -1,
      "send": 0.397,
      "wait": 189.6199999998943,
      "receive": 296.10200000024633,
      "_blocked_queueing": 1.1759999979403801
    }

HAR could be filtered with jq, e.g. find entries with _blocked_queueing > 50

jq -r '.log.entries | to_entries[] | if(.value.timings._blocked_queueing > 50) then [.key, .value.request.url, .value.timings._blocked_queueing,.value.timings.blocked ] else empty end' stackoverflow.com.har

Result:

[
  21,
  "https://graph.facebook.com/4191055284264423/picture?type=large",
  160.28299999743467,
  160.66799999743466
]
[
  66,
  "https://fonts.gstatic.com/s/robotoslab/v13/BngbUXZYTXPIvIBgJJSb6s3BzlRRfKOFbvjojISmb2Rm.ttf",
  55.99899999651825,
  109.53999999651825
]
[
  67,
  "https://fonts.gstatic.com/s/robotoslab/v13/BngbUXZYTXPIvIBgJJSb6s3BzlRRfKOFbvjoa4Omb2Rm.ttf",
  56.85599999560509,
  56.85599999560509
]

Then we could inspect 6 preceding entries of one of those requests

jq -r --argjson idx 67 '.log.entries[($idx - 6):($idx + 1)] | .[] | [.request.url, .time, .timings]' stackoverflow.com.har

Or get the highest dns

jq -r '.log.entries | sort_by(.timings.dns|floor)[-1] | .timings.dns, .request.url' stackoverflow.com.har

438.551
https://example.com

Google offers an online HAR Analyzer that could be used similar to Dev tools Network pane.

Hovering over a request on the Waterfall column, the details of a request can be seen. As a first approach, long queuing requests could be preceded by one or several requests with high values on any of the items.

Using the command line below to get a csv and then make a chart with

• date as Unix timestamp [ms]
• request time [ms]
• _blocked_queueing [ms]

jq -r '.log.entries | to_entries[] | [.value.startedDateTime, .value.serverIPAddress, .key, ((.value.startedDateTime[0:19] + "Z"|fromdateiso8601)*1000 + (.value.startedDateTime[20:23]|tonumber)), .value.time, .value.timings._blocked_queueing ] | @csv' stackoverflow.com.har | tee stackoverflow.com.har.csv