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

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

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

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.stack.imgur.com/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.stack.imgur.com/kdIyT.jpg?s=32&g=1",314]
[48,"https://i.stack.imgur.com/65UsL.jpg?s=32&g=1",297]
[61,"https://i.stack.imgur.com/KLQJy.jpg?s=32&g=1",286]

HTTP/1.1

There are several reasons why Chrome could be queuing 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