POST'ing with file backed input does main thread IO via Available()

RESOLVED FIXED in Firefox 55

Status

()

Core
Networking: HTTP
RESOLVED FIXED
20 days ago
5 days ago

People

(Reporter: florian, Assigned: mcmanus, NeedInfo)

Tracking

unspecified
mozilla55
x86_64
Windows 10
Points:
---

Firefox Tracking Flags

(firefox55 fixed)

Details

(Whiteboard: [qf][necko-active])

MozReview Requests

()

Submitter Diff Changes Open Issues Last Updated
Loading...
Error loading review requests:

Attachments

(2 attachments)

(Reporter)

Description

20 days ago
See this startup profile on the quantum reference device where we spend 220ms on this soon after startup: https://perfht.ml/2pO2iF6

I haven't been able to figure out what's the caller or which local file is being accessed, but given that the stack contains nsAsyncResolveRequest, I suspect the caller expected this to not block.
(Assignee)

Comment 1

19 days ago
the nsAsyncResolveRequest isn't the problem (it only goes async when it would block, which is not always - in this case the callback just gets run on the stack).

that code implies some kind of a file backed upload (e.g. POST) stream.. it would be really interesting to figure out what it is.
(Reporter)

Comment 2

19 days ago
(In reply to Patrick McManus [:mcmanus] from comment #1)
> the nsAsyncResolveRequest isn't the problem (it only goes async when it
> would block

Isn't this (uploading a local file from the disk) a case where it does block and should go async?
(Reporter)

Comment 3

19 days ago
And now that you tell me that it's a POST file upload, it becomes easy to guess what the caller is, as just before this in the profile we have main thread IO from CrashSubmit.jsm.

The caller is: http://searchfox.org/mozilla-central/rev/6580dd9a4eb0224773897388dba2ddf5ed7f4216/toolkit/crashreporter/CrashSubmit.jsm#256

Sending 2 files:
    let promises = [
      File.createFromFileName(this.dump.path).then(file => {
        formData.append("upload_file_minidump", file);
      })
    ]

    if (this.memory) {
      promises.push(File.createFromFileName(this.memory.path).then(file => {
        formData.append("memory_report", file);
      }));
    }

And this is an asynchronous XHR. So in my opinion the caller doesn't expect this to block the main thread.
Summary: nsHttpTransaction::Init causes main thread IO when calling Available on the stream → POST'ing files with an async XHR does main thread IO
(Assignee)

Comment 4

19 days ago
(In reply to Florian Quèze [:florian] [:flo] from comment #2)
> (In reply to Patrick McManus [:mcmanus] from comment #1)
> > the nsAsyncResolveRequest isn't the problem (it only goes async when it
> > would block
> 
> Isn't this (uploading a local file from the disk) a case where it does block
> and should go async?

we're just failing to communicate over a minor piece of necko nomenclature. The blocking you're seeing is indeed unintended - its just not part of nsAsyncResolveRequest which is the proxy resolution code. That code will go async if it has blocking work to do, and if it doesn't it actually invokes the callback right on the stack - which is what has happened here. If it went async you would still see the same blocking issue but with a shorter stack.

Thanks so much for confirming the file backed hypothesis.

the bug is that available() on the main thread causes the IO when file backed and that shouldn't be done main thread. Definitely sounds like qf material, perhaps qf2 as I don't think file backed is common enough to be qf1.. but we'll fix it no matter.
(Assignee)

Updated

19 days ago
Summary: POST'ing files with an async XHR does main thread IO → POST'ing with file backed input does main thread IO via Available()
Comment hidden (mozreview-request)
Comment hidden (mozreview-request)
Comment hidden (mozreview-request)
Comment hidden (mozreview-request)
Comment hidden (mozreview-request)
Comment hidden (mozreview-request)
Comment hidden (mozreview-request)
Comment hidden (mozreview-request)
Comment hidden (mozreview-request)
If this winds up being tricky to fix we could also presumably just fix CrashSubmit.jsm to use io.File to read the minidump file contents asynchronously and then post that instead.
Comment on attachment 8865021 [details]
Bug 1362388 - dont let File backed http requests find size on main thread

https://reviewboard.mozilla.org/r/136678/#review141284

::: netwerk/base/nsStreamTransportService.cpp:562
(Diff revision 5)
>      mPool = nullptr;
>    }
>    return NS_OK;
>  }
>  
> +class AvailableEvent : public Runnable

final?

::: netwerk/protocol/http/nsHttpChannel.cpp:528
(Diff revision 5)
> +    MOZ_ASSERT(NS_IsMainThread(), "Wrong thread.");
> +    LOG(("nsHttpChannel::OnInputAvailableComplete %x\n", status));
> +    if (NS_SUCCEEDED(status)) {
> +        mReqContentLength = size;
> +    } else {
> +        // fall back to synchronous on the error path. should not happen.

How strong is this "should not happen"? Like, every time I see that, I think "this should really have an assert with it".

::: netwerk/protocol/http/nsHttpChannel.cpp:548
(Diff revision 5)
> +
> +// nsIFileStream needs to be sent to a worker thread
> +// to do Available() as it may cause disk/IO. Unfortunately
> +// we have to look at the streams wrapped by a few other
> +// abstractions to be sure.
> +static bool isFileStream(nsIInputStream *stream)

nit: function name/arg list on new line
Attachment #8865021 - Flags: review?(hurley) → review+
Comment on attachment 8865067 [details]
Bug 1362388 - Remove nsAHttpTransaction::Available as footgun

https://reviewboard.mozilla.org/r/136748/#review141290

One thing to do in the commit message. Code looks good, though.

::: netwerk/protocol/http/Http2Push.h:116
(Diff revision 4)
>                                          uint32_t *countWritten);
>    void SetPushStream(Http2PushedStream *stream) { mPushStream = stream; }
>  
>  private:
>    virtual ~Http2PushTransactionBuffer();
> +  uint64_t Available();

Please add a comment in the commit message explaining this part explicitly. When looking at just the diff, seeing a commit that says "remove Available" that then adds a declaration of "Available" is exceedingly confusing. Would be best to call that out explicitly.
Attachment #8865067 - Flags: review?(hurley) → review+
(Assignee)

Comment 17

13 days ago
(In reply to Ted Mielczarek [:ted.mielczarek] from comment #14)
> If this winds up being tricky to fix we could also presumably just fix
> CrashSubmit.jsm to use io.File to read the minidump file contents
> asynchronously and then post that instead.

thanks - the actual file i/o is done async already with the streamTransportService, but a call to Available() to get its size is what triggered the disk IO on the main thread.
(Assignee)

Comment 18

13 days ago
mozreview-review-reply
Comment on attachment 8865021 [details]
Bug 1362388 - dont let File backed http requests find size on main thread

https://reviewboard.mozilla.org/r/136678/#review141284

> How strong is this "should not happen"? Like, every time I see that, I think "this should really have an assert with it".

its an xpcom interface, you need to handle the error in case someone does something insane. So I think the code is ok.
Comment hidden (mozreview-request)
Comment hidden (mozreview-request)

Comment 21

13 days ago
Pushed by mcmanus@ducksong.com:
https://hg.mozilla.org/integration/autoland/rev/a418e4a81c02
dont let File backed http requests find size on main thread r=nwgh
https://hg.mozilla.org/integration/autoland/rev/fef09999e003
Remove nsAHttpTransaction::Available as footgun r=nwgh
Backed out for build bustage from netwerk/protocol/http/nsHttpChannel.cpp:597 not being declared:

https://hg.mozilla.org/integration/autoland/rev/60909a5ac021fd2e998ca010d0d1f0c21127f47b
https://hg.mozilla.org/integration/autoland/rev/caa75fa65be625a5cf166ef52d89950b956dc83f

Push with failures: https://treeherder.mozilla.org/#/jobs?repo=autoland&revision=fef09999e00338ba3b6e54d97a9c0c8749e03dc2&filter-resultStatus=testfailed&filter-resultStatus=busted&filter-resultStatus=exception&filter-resultStatus=retry&filter-resultStatus=usercancel&filter-resultStatus=runnable
Failure log: https://treeherder.mozilla.org/logviewer.html#?job_id=98418008&repo=autoland

[task 2017-05-11T15:53:40.057921Z] 15:53:40     INFO -  In file included from /home/worker/workspace/build/src/obj-firefox/netwerk/protocol/http/Unified_cpp_protocol_http1.cpp:101:0:
[task 2017-05-11T15:53:40.058095Z] 15:53:40     INFO -  /home/worker/workspace/build/src/netwerk/protocol/http/nsHttpChannel.cpp: In member function 'void mozilla::net::nsHttpChannel::DetermineContentLength()':
[task 2017-05-11T15:53:40.058275Z] 15:53:40     INFO -  /home/worker/workspace/build/src/netwerk/protocol/http/nsHttpChannel.cpp:597:31: error: 'kStreamTransportServiceCID' was not declared in this scope
[task 2017-05-11T15:53:40.058399Z] 15:53:40     INFO -           !(sts = do_GetService(kStreamTransportServiceCID))) {
[task 2017-05-11T15:53:40.058587Z] 15:53:40     INFO -                                 ^
[task 2017-05-11T15:53:40.059192Z] 15:53:40     INFO -  /home/worker/workspace/build/src/config/rules.mk:1059: recipe for target 'Unified_cpp_protocol_http1.o' failed
[task 2017-05-11T15:53:40.059235Z] 15:53:40     INFO -  gmake[5]: *** [Unified_cpp_protocol_http1.o] Error 1
Flags: needinfo?(mcmanus)
(Assignee)

Comment 23

13 days ago
thx.. at first glance there is a try run for that build config. weird. but I'll sort it out.
Flags: needinfo?(mcmanus)
Assignee: nobody → mcmanus
Whiteboard: [qf] → [qf][necko-active]
(Assignee)

Comment 24

13 days ago
oh - it was just bitrotted by landing of bug 1362498 in a way autoland didn't notice.
Comment hidden (mozreview-request)
Comment hidden (mozreview-request)

Comment 27

12 days ago
Pushed by mcmanus@ducksong.com:
https://hg.mozilla.org/integration/autoland/rev/446ecc3f5715
dont let File backed http requests find size on main thread r=nwgh
https://hg.mozilla.org/integration/autoland/rev/f5b4fbe31c01
Remove nsAHttpTransaction::Available as footgun r=nwgh
Backed out for android bustage like https://treeherder.mozilla.org/logviewer.html#?job_id=98787688&repo=autoland

https://hg.mozilla.org/integration/autoland/rev/ebc9697dd7f2
Flags: needinfo?(mcmanus)
Comment hidden (mozreview-request)
Comment hidden (mozreview-request)

Comment 31

12 days ago
Pushed by mcmanus@ducksong.com:
https://hg.mozilla.org/integration/autoland/rev/11b8084a6cea
dont let File backed http requests find size on main thread r=nwgh
https://hg.mozilla.org/integration/autoland/rev/80b6cb6d9ee7
Remove nsAHttpTransaction::Available as footgun r=nwgh
https://hg.mozilla.org/mozilla-central/rev/11b8084a6cea
https://hg.mozilla.org/mozilla-central/rev/80b6cb6d9ee7
Status: NEW → RESOLVED
Last Resolved: 10 days ago
status-firefox55: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → mozilla55
Pat, do you think this fixes bug 690633 too?
You need to log in before you can comment on or make changes to this bug.