Open Bug 1853928 Opened 2 years ago Updated 1 year ago

Asynchronous network request to get javascript file blocking other API requests

Categories

(Core :: Networking, defect, P3)

Firefox 117
defect

Tracking

()

UNCONFIRMED

People

(Reporter: leoblmat, Unassigned)

References

(Blocks 1 open bug)

Details

(Whiteboard: [necko-triaged])

Attachments

(6 files)

1.33 KB, text/html
Details
3.50 MB, video/quicktime
Details
2.69 MB, video/quicktime
Details
1.18 MB, application/zip
Details
532.08 KB, application/zip
Details
530.58 KB, application/zip
Details
Attached file index.html

User Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10.15; rv:109.0) Gecko/20100101 Firefox/117.0

Steps to reproduce:

  1. Call a backend server to retrieve a .js file asynchronously for dynamic loading
  2. Call a post endpoint to do some logic and return a JSON object asynchronously
    3 Wait on the endpoint to return the JSON object
    4 Wait on the .js file to be returned

Environment: Set network throttling to simulate bad networks

Actual results:

The endpoint that returns the JSON object blocks until the .js file is returned thus blocking code execution.

Expected results:

The .js file downloads in the background until the promise from fetch API is awaited on allowing the execution of code to carry on and the post endpoint to not be blocked

The Bugbug bot thinks this bug should belong to the 'Core::Networking' component, and is moving the bug to that component. Please correct in case you think the bot is wrong.

Component: Untriaged → Networking
Product: Firefox → Core

Thanks for the report. I have a few questions

The endpoint that returns the JSON object blocks until the .js file is returned thus blocking code execution.

  1. Are you saying that the line const fastResponse = await fastReturnedPromise; blocks until the .js finishes downloading?
  2. It seems like the network/server config could be causing an issue here. Can you guarantee that the JSON file is actually making it back first? Maybe the JSON endpoint logic you describe is slowing things down enough so that the .js file actually does make it back first. Maybe the bad network environment affects the .js transfer because there are more bytes to corrupt? Are you able to provide the server-side code or reproduce with a different server(s)?
Flags: needinfo?(leoblmat)
Attached video chrome.mov

Chrome

Flags: needinfo?(leoblmat)
Attached video FireFox.mov

FireFox

Attached file code.zip

Attached replicated code, requires a js file to be put in wwwroot

Question one: Yes that is correct so the first console log and the code below it will not get hit until the js file is fetched. I have attached two videos showing this side effect, first video is chrome and second is firefox.

Question two: I replicated this issue with a simple example I have attached the code above. The endpoint that returns the JSON object is empty and should return before the large js file is fetched especially if network throttling is used. The js file I used was about 8mb. I have attached a dummy dotnet server that replicates the issue I am having with application backend.

Flags: needinfo?(edgul)

Thanks, can you also upload some networking logs of the firefox interaction?
You can use about:logging with networking preset with logging to a file selected.

Flags: needinfo?(edgul) → needinfo?(leoblmat)
Attached file log.zip

Here is the wanted log file with network interactions from firefox

Flags: needinfo?(leoblmat)

The logs show that the json request goes out first, then the js request. Though the js response comes back much faster than the json response.
I can see a cache hit on at least the header for the js, though it looks like we still go to network for the file itself.
Logging for the json transaction seems to pause while we are reading from the js transaction's socket so it kind of looks like the Socket thread is blocking the json. I'm wondering if the cache hit affects the priority, so can you try clearing/disabling the cache and see if the behaviour changes?

:kershaw, can you confirm if this is correct and/or expected?

Flags: needinfo?(leoblmat)
Flags: needinfo?(kershaw)
Attached file log-no-cache.zip

Here is the logs with cache disabled

Flags: needinfo?(leoblmat)

Same issue happens with cache disabled

Flags: needinfo?(kershaw)

re-ping

Flags: needinfo?(kershaw)

Sorry for the delay.
I've looked at the log and this is what happens:

  1. We create two connections (one for json and the other one for js) to the server. The log shows that the connection 19465fe00 starts TLS handshake earlier than connection 10af0a600.
2023-09-21 19:18:15.731009 UTC - [Parent 71051: Socket Thread]: V/nsHttp TlsHandshaker::EnsureNPNComplete [mOwner=19465fe00] drive TLS handshake
2023-09-21 19:18:15.753691 UTC - [Parent 71051: Socket Thread]: V/nsHttp TlsHandshaker::EnsureNPNComplete [mOwner=10af0a600] drive TLS handshake
  1. The problem here is that the json request selects the connection 10af0a600, which is the one that completes the TLS handshake later. That's because we won't use null transaction to drive the TLS handshake when the pending queue is not empty.

However, I think the Fetch spec doesn't specify the order of resource loading, so this might not be a high priority issue to fix.

Blocks: necko-perf
Severity: -- → S3
Flags: needinfo?(kershaw)
Priority: -- → P3
Whiteboard: [necko-triaged]
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: