Closed Bug 1362388 Opened 7 years ago Closed 7 years ago

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

Categories

(Core :: Networking: HTTP, enhancement)

Product:
Core
Component:
Networking: HTTP
Platform:
x86_64
Windows 10
Type:
enhancement
Priority:
Not set
Severity:
normal

Tracking

()

Status:
RESOLVED FIXED
Milestone:
mozilla55
Project Flags:
Performance Impact ?
Tracking Flags:
Tracking Status
firefox55 --- fixed

People

(Reporter: florian, Assigned: mcmanus)

Details

(Whiteboard: [necko-active])

Attachments

(2 files)

Bug 1362388 - dont let File backed http requests find size on main thread
59 bytes, text/x-review-board-request
u408661
: review+
Details
Bug 1362388 - Remove nsAHttpTransaction::Available as footgun
59 bytes, text/x-review-board-request
u408661
: review+
Details 
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.
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.
(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?
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
(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.
Summary: POST'ing files with an async XHR does main thread IO → POST'ing with file backed input does main thread IO via Available()
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+
(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.
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.
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)
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]
oh - it was just bitrotted by landing of bug 1362498 in a way autoland didn't notice.
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
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
Pat, do you think this fixes bug 690633 too?
(In reply to Jason Duell [:jduell] (needinfo me) from comment #33)
> Pat, do you think this fixes bug 690633 too?

no.. but istm you can use similar logic to this patch to use the STS. (this patch only impacts Available())
Flags: needinfo?(mcmanus)
Performance Impact: --- → ?
Whiteboard: [qf][necko-active] → [necko-active]
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: