671875 - Ensure transport events are correctly propagated with the new pipelining code

Status: RESOLVED FIXED

(Core :: Networking: HTTP, defect)

Description

[Honza Bambas (:mayhemer)]

See top of https://bugzilla.mozilla.org/show_bug.cgi?id=447866#c43

We have to check and fix all the (not only?) socket transport notification, which go through nsHttpConnection object and are influenced by an inserted nsHttpPipeline object, gets correctly to nsHttpTransaction objects in order and time expected.

This is vital for Firebug, telemetry, progress indicators.

Added dep on bug 447866 as it is the first that might break this when landed on mozilla-central.

Comment 1

[Patrick McManus [:mcmanus]]

Honza, do you have further details on what events should be included here? I have a pach that adds

+    case NS_NET_STATUS_WAITING_FOR:

but your comments indicate in needs more to be complete.

Comment 2

[Honza Bambas (:mayhemer)]

First, I don't agree with sending STATUS_WAITING_FOR only to the first receiving transaction (first Response).  In a nut shell, all transactions in the Responses queue have to know their data has been sent out and are now waiting for the response.

Here https://bugzilla.mozilla.org/show_bug.cgi?id=447866#c36, if I understand correctly, you are trying to deliver the state (what is now missing), but not to all transactions which expect it.

My suggestion with some outline:

- STATUS_WAITING_FOR is sent when a transaction finished sending all its data to the socket (done from nsHttpConnection::OnSocketWritable thought mTransaction->ReadSegments when 0 bytes has been sent)
- in case there is pipelining injected, WAITING_FOR is sent when pipeline has sent all the mSendBufIn data out
- we fill the send buffer (mSendBufIn/Out pipe) only when the buffer is empty (mSendBufIn is null [=never created] or mSendBufIn->Available returns 0 [=has been sent out fully])
- during the buffer filling we move all Requests that fit to the buffer to Responses
- if a transaction doesn't fit, mRequestIsPartial is flagged and that last transaction is not moved to Responses
- then we are sending this buffer out and do not put more data (even there may be more Requests) to the buffer
- now all these transactions (Responses) must get their SENDING_TO state (this is currently missing, only the first does) when we are pushing their data out
- all these transactions (Responses) must get their WAITING_FOR state after all merged buffer data has been sent out to measure the delay between sending the request out and receiving the response from the server, this is needed for monitoring (Web Console, Firebug)
-> with your patch only the first transaction (Response(0)) will get its WAITING_FOR

Perfect would be to send SENDING_TO a particular transaction when we start sending exactly its data and status WAITING_FOR at the moment we are done with its and only its data, but that is IMO too complicated (you have to record data offset for each transaction) and the timing difference could be relatively insignificant.  But it would be very precise and I would be very happy ;)

With the simple proposed approach (notify SENDING_TO resp WAITING_FOR to all Responses during resp after the buffer sends out) we must make sure transactions won't get first RECEIVING_FROM and then WAITING_FOR when data from the server start coming sooner then we send the whole buffer out.  It can actually happen only for Response(0) I think.  It can be avoided by adding logic to nsHttpPipeline preventing notification of WAITING_FOR to Response(0) when Response(0) has received some data.

Then, with the current code (w/o any of your patches) it is OK to forward notifications of RESOLVING, RESOLVED, CONNECTING, CONNECTED to all Requests because there will always be just one.  But with the "bursty" patch this must change - we must send these just to Response(0) || Request(0) since you are filling the Request queue with multiple transaction from the very start.  Then it will correspond to the line of notifications we have now w/o pipelining.

Then, RECEIVING_FROM is missing when Response(0) pushes data back.  nsHttpPushBackWriter::OnWriteSegment must notify this state to Response(0) (or to the pipeline that will take care) because nsHttpPushBackWriter fakes the role of calling to nsHttpConnection::OnWriteSegment that calls nsSocketInputStream::Read that notifies the state to its transaction (here the pipeline).

Otherwise RECEIVING_FROM seems to be forwarded correctly - only to Response(0).

Comment 3

[Patrick McManus [:mcmanus]]

I think sending_to and waiting_for is going to require a map.

we can't send it before being connected (196827).. and sending it in fillsendbuf instead of when the network send happens is likely to give odd looking reports in firebug (showing parallelism where there is really small blocking).. there might be significant delays between different members of the pipeline due to TCP initial windows constraints and I'd like to be able to see that. Indeed I think if we generated SEND_TO/WAIT_FOR when the buffer emptied out inside the pipeline we would generate timestamps for WAIT_FOR before the connection was complete in some cases.

the map won't be that big of a deal - just need an interface to find out what the byte counter on the socket is when we start (could be a pconn reuse, or perhaps a CONNECT was sent). Then I'll probably put the boundary sequence number in a different data strucutre that ref counts the nsahttptransaction.. I could just change what mRequestQ and mResponseQ store (to be a struct with the seq) but that would change a lot more code and break all my patches :(..

Comment 4

[Patrick McManus [:mcmanus]]

(In reply to Patrick McManus from comment #3)
> I think sending_to and waiting_for is going to require a map.
> 

After sleeping on it, I have changed my mind. No map required: sending_to, waiting_for can be generated out of the pipeline fillsendbuf() code.

My concern about CONNECTED_TO is invalid - that event is handled while the transaction is still in the connection manager and no write has yet been done (which means fillsendbuf() has not been called). So it is moot.

My concerns about the timing differences between requests are theoretically valid, but realistically invalid because of the OS level socket buffers. The sending_to/waiting_for event is generated when the necessary amount of data has been sent to the socket buffer, not necessarily to the network. That buffer is going to sop up any differences in timestamps on us unless our requests were really massive - and given that we don't pipeline anything with a request body that really isn't a possibility.

The one thing I am still concerned about is that we don't generate a sending_to/waiting_for before the socket layer has generated the first sending_to beacuse of 196287. But that should be easy enough to do with a piece of state in nshttppipeline. The enablement of spdy will make this moot, because the ssl handshake will be done before the fillsendbuf call due to npn, but it isn't hard to make it work now.

I wonder what I'm missing.

Comment 5

[Patrick McManus [:mcmanus]]

Attachment: patch 0

this patch is totally untested beyond compilation - I'm traveling for the holiday and am somewhat limited in my setup until sunday or monday. So I'm asking feedback? instead of r? - but testing is the only reason.

I am eager to see what you think of the approach and make some progress on this bug as its a blocker for landing pipeline stuff.

Honza, thanks again for your tremendous comment - it really helped me understand what the underlying issue was.

Comment 6

[Patrick McManus [:mcmanus]]

Comment on attachment 576759 [details] [diff] [review]
patch 0

try-server likes this patch and it tests fine by hand as well.

It is a new-pipelining pre-req and fixes bugs in the current pipelining code.

Comment 7

[Honza Bambas (:mayhemer)]

Comment on attachment 576759 [details] [diff] [review]
patch 0

Review of attachment 576759 [details] [diff] [review]:
-----------------------------------------------------------------

r=honzab with following comments:

8-lines context please, .hgrc:
[defaults]
diff=-U 8 -p
qdiff=-U 8

[diff]
git=true
showfunc=true
unified=8


OK, so the order is now definitely correct.  

Timing of activity distributor and web timing API will be untuned, hard to say which one will be correct since there is the pipeline buffer in between.  The correct timing proposal in comment 1 could fix it.

Progress is sent probably wrong, but it is hard to say whether it is correct even in non-pipelined case ; also it is ignored by transactions, so no problem.


Patrick, please address the comments bellow for this patch.

Timing issues, if found significant, should be fixed in a different bug (may be a good first or second bug).


We can land this patch now.

::: netwerk/protocol/http/nsHttpPipeline.cpp
@@ +440,5 @@
> +                                               NS_NET_STATUS_WAITING_FOR,
> +                                               progress);
> +            }
> +            if (mRequestIsPartial && Request(0))
> +                Request(0)->OnTransportStatus(transport, status, progress);

Maybe instead of 'status' use NS_NET_STATUS_SENDING_TO to make it more clear on the first sight what we are doing here.

::: netwerk/protocol/http/nsHttpPipeline.h
@@ +114,5 @@
>      PRUint32  mPushBackLen;
>      PRUint32  mPushBackMax;
> +
> +    // For support of OnTransportStatus()
> +    nsRefPtr<nsITransport> mTransport;

I'm against adding refs like these.  nsHttpPipeline refers nsAHttpConnection (nsHttpConnection) that refers the transport already.  

Please, create an accessor to mSocketTransport on nsAHttpConnection class and use it to pass it to OnTransportStatus.

I'm worried about leaks, rather add a new method then spend time checking for potential reference cycles.

@@ +116,5 @@
> +
> +    // For support of OnTransportStatus()
> +    nsRefPtr<nsITransport> mTransport;
> +    PRUint64  mReceivingFromProgress;
> +    PRUint64  mSendingProgress;

Maybe mSendingToProgress for consistency with status names?

Comment 8

[Patrick McManus [:mcmanus]]

https://hg.mozilla.org/integration/mozilla-inbound/rev/cf628f56ca79

Comment 9

[Matt Brubeck (:mbrubeck)]

https://hg.mozilla.org/mozilla-central/rev/cf628f56ca79