534698 - nsTransportEventSinkProxy implementation eats event notifications

Status: RESOLVED FIXED

(Core :: Networking: HTTP, defect)

Description

[Honza Bambas (:mayhemer)]

Attachment: v1

Http transport event sink proxy is setup to coalesce all events coming from the connection. It might lead to loose of some event notifications, often happens with STATUS_CONNECTED_TO, that is vital for successful logging. This happens because when there is still a pending event we simply do not fire (queue) a new event even it has a different status notification. It might make sense only for protocols other then http.

This bug is there from the beginning, see:
http://bonsai.mozilla.org/cvsblame.cgi?file=mozilla/netwerk/protocol/http/src/nsHttpTransaction.cpp&rev=1.104#184
http://bonsai.mozilla.org/cvsblame.cgi?file=mozilla/netwerk/base/src/nsTransportUtils.cpp&rev=1.4#139

and the attachment.

Comment 1

[Boris Zbarsky [:bzbarsky]]

1) The comment is now incorrect, yes?
2) What is the practical impact on the number and type of events delivered as a
   result of this patch?  Can you give me some statistics for some typical
   websites?

Comment 2

[Honza Bambas (:mayhemer)]

(In reply to comment #1)
> 1) The comment is now incorrect, yes?

Yes

> 2) What is the practical impact on the number and type of events delivered as a
>    result of this patch? 

We get all events that can be used for logging in software like Firebug or just for correct receive of all expected chain of events when observing the transport notifications.

> Can you give me some statistics for some typical
>    websites?

I was trying to load (uncached) four web sites: www.google.cz, www.seznam.cz, www.mozilla.org and www.mozilla.com. I get 307 notification w/ this patch and 250 w/o this patch. It's about 23% raise. We have 6 states and this might indicate we were getting only 5 of them, now we get all.

Comment 3

[Boris Zbarsky [:bzbarsky]]

What do the numbers look like on www.cnn.com?

What about gmail?

Comment 4

[Honza Bambas (:mayhemer)]

(In reply to comment #3)
> What do the numbers look like on www.cnn.com?
> 

296 to 356 (~20% diff).

> What about gmail?

I unfortunately don't have a gmail account to test...

Comment 5

[Honza Bambas (:mayhemer)]

And to correct the description: we do fire next event, but overwrite the current (delete it). So, we replace (coalesce) CONNECTED_TO with e.g. SENDING_TO or such an event.

Comment 6

[Boris Zbarsky [:bzbarsky]]

> 296 to 356 (~20% diff).

Another question.  Any estimate on how long each event takes to handle?

Comment 7

[Honza Bambas (:mayhemer)]

(In reply to comment #6)
> Another question.  Any estimate on how long each event takes to handle?

nsHttpChannel::OnTransportStatus: about 51ms on my 2.4 GHz Athlon64, debug build.

Comment 8

[Boris Zbarsky [:bzbarsky]]

So 50 extra events is 2.5 seconds?  What about opt build?

Comment 9

[Honza Bambas (:mayhemer)]

It will take some time to test.

What to do when there is a high performance impact with this patch? Should we leave the event sink code actually 'broken'?

Comment 10

[Boris Zbarsky [:bzbarsky]]

Well, whether it's broken depends on what promises it makes....

If there's a high performance impact, then we should see where it's coming from.  If it's something fundamental, then perhaps we should have different modes for the events: a tracing mode for cases when we need every single event and a normal mode for what users normally need.

Comment 11

[Honza Bambas (:mayhemer)]

(In reply to comment #8)
> So 50 extra events is 2.5 seconds?  What about opt build?

PerformanceCounter on windows tells me 0 for a release build, really a jump...

(In reply to comment #10)
> Well, whether it's broken depends on what promises it makes....
> 
> If there's a high performance impact, then we should see where it's coming
> from.  If it's something fundamental, then perhaps we should have different
> modes for the events: a tracing mode for cases when we need every single event
> and a normal mode for what users normally need.

We could use nsIHttpActivityObserver.isActive attribute for this, it's being checked right under the event sink initiation (coalesce = !isActive).

Comment 12

[Honza Bambas (:mayhemer)]

Attachment: v2

Using activity distributor isActive attribute to decide if to coalesce events or not. No impact to normal usage, developers gets all notifications as would expect.

Comment 13

[Boris Zbarsky [:bzbarsky]]

Comment on attachment 419330 [details] [diff] [review]
v2

>     // create transport event sink proxy that coalesces all events

This comment needs to be right above the net_NewTransportEventSinkProxy call, and probably be changed to reflect the new reality.

>+    PRBool active = PR_FALSE;

I'd actually prefer we just set active to false in the else branch here (the one where we land if NS_FAILED(rv)).

And maybe rename this to activityDistributorActive?

r=me with those changes.

Comment 14

[Honza Bambas (:mayhemer)]

Attachment: v2.1 [Checkin comment 15]

Updated patch ready to land.

Comment 15

[Honza Bambas (:mayhemer)]

Comment on attachment 423393 [details] [diff] [review]
v2.1 [Checkin comment 15]

http://hg.mozilla.org/mozilla-central/rev/79745cb186d5

Comment 16

[Honza Bambas (:mayhemer)]

Comment on attachment 423393 [details] [diff] [review]
v2.1 [Checkin comment 15]

For Firebug this would be nice to have also on 1.9.2.x (Fx3.6).  This is complementary fix to bug 488270 that has landed on 1.9.2.

Comment 17

[Daniel Veditz [:dveditz]]

Comment on attachment 423393 [details] [diff] [review]
v2.1 [Checkin comment 15]

Didn't make 1.9.2.2, we'll look at next time.

Comment 18

[Daniel Veditz [:dveditz]]

Comment on attachment 423393 [details] [diff] [review]
v2.1 [Checkin comment 15]

Clearing old approval requests now that 1.9.2.4 has shipped. If you believe this patch is still necessary on the 1.9.2 branch please re-request approval along with a risk/benefit analysis explaining why we need it.