google-chromenetworkingchromiumrequest-queueing

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


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


Solution

  • 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.

    enter image description here

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

    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
    

    enter image description here