707173 - SPDY Telemetry for Connection Management

Status: RESOLVED FIXED

(Core :: Networking: HTTP, defect)

Description

[Patrick McManus [:mcmanus]]

This was originally patch 20 in bug 528288, but the rest of that series has landed and that bug should be closed so it is being split into its own bug.

From comment 153 in that bug

TCP connection management is really the focus of SPDY, so I have created a patch to help us analyze through telemetry whether or not we are making progress.

(fun aside - yahoo! just published a paper saying their servers see a median connection with 2.5 requests and just 10KB of data transferred. That's a nightmare).

the patch tracks:

* the number of requests per connection broken down to http/1 vs spdy (and it fixes a typo in the range of the existing spdy telemetry for this)

* the amount of data transferred per connection broken down to http/1 vs spdy

* how often we try and coalesce and how often that succeeds

Comment 1

[Patrick McManus [:mcmanus]]

Attachment: patch rev 0

This is the same as patch 20 rev 0 in the 528288 bug, just moved here so that bug can be closed

Comment 2

[Honza Bambas (:mayhemer)]

Comment on attachment 578582 [details] [diff] [review]
patch rev 0

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

::: netwerk/protocol/http/nsHttpConnection.cpp
@@ +118,5 @@
> +    if (mHttp1xTransactionCount) {
> +        LOG(("nsHttpConnection %p performed %d HTTP/1.x transactions\n",
> +             this, mHttp1xTransactionCount));
> +        mozilla::Telemetry::Accumulate(
> +            mozilla::Telemetry::HTTP_REQUEST_PER_CONN, mHttp1xTransactionCount);

Just for curiosity, why don't you also want to report 0 ?  Of course just in case it never used spdy.

@@ +122,5 @@
> +            mozilla::Telemetry::HTTP_REQUEST_PER_CONN, mHttp1xTransactionCount);
> +    }
> +
> +    if (mTotalBytesRead) {
> +        PRUint32 totalKBRead = mTotalBytesRead >> 10;

Not sure this generates potential data loss warning or not, maybe worth to do an explicit type cast.

@@ +130,5 @@
> +            mozilla::Telemetry::Accumulate(
> +                mozilla::Telemetry::SPDY_KBREAD_PER_CONN, totalKBRead);
> +        else
> +            mozilla::Telemetry::Accumulate(
> +                mozilla::Telemetry::HTTP_KBREAD_PER_CONN, totalKBRead);

mozilla::Telemetry::HTTP_KBREAD_PER_CONN et al is an ID of type mozilla::Telemetry::ID.  You may try using a ternary op on mEverUsedSpdy to distinguish, the code might be more readable then.

@@ +215,5 @@
>      LOG(("nsHttpConnection::EnsureNPNComplete %p negotiated to '%s'",
>           this, negotiatedNPN.get()));
>      
>      if (negotiatedNPN.Equals(NS_LITERAL_CSTRING("spdy/2"))) {
>  

This blank line could be removed..

@@ +408,5 @@
>              mSocketTransport->Close(reason);
>          }
>          mKeepAlive = false;
>      }
> +

Remove this arbitrary blank line.

::: netwerk/protocol/http/nsHttpConnection.h
@@ +220,5 @@
>      bool                            mCompletedProxyConnect;
>      bool                            mLastTransactionExpectedNoContent;
>      bool                            mIdleMonitoring;
>  
> +    PRUint32                        mHttp1xTransactionCount;

Please add a comment what this means (maybe just copy relevant parts from nsAHttpTransaction).

Maybe call this HttpVer10and11TransactionCount ?  Or something more descriptive, the current name is quit cryptic.

::: netwerk/protocol/http/nsHttpConnectionMgr.cpp
@@ +661,5 @@
>               "Host %s cannot be confirmed to be joined "
>               "with %s connections",
>               preferred->mConnInfo->Host(), aOriginalEntry->mConnInfo->Host()));
> +        mozilla::Telemetry::Accumulate(mozilla::Telemetry::SPDY_NPN_JOIN,
> +                                       false);

Aren't we also interested in the reason?  I think it's worth to be more verbose here, telemetry should be recorded in JoinConnection method.

::: netwerk/protocol/http/nsHttpPipeline.cpp
@@ +120,5 @@
>      LOG(("nsHttpPipeline::AddTransaction [this=%x trans=%x]\n", this, trans));
>  
>      NS_ADDREF(trans);
>      mRequestQ.AppendElement(trans);
> +    ++mHttp1xTransactionCount;

I think we should update this number only when we actually handled the transactions (maybe even received data for it).  This might get wrong when the pipeline restarted.

::: netwerk/protocol/http/nsHttpPipeline.h
@@ +111,5 @@
>      char     *mPushBackBuf;
>      PRUint32  mPushBackLen;
>      PRUint32  mPushBackMax;
> +
> +    PRUint32  mHttp1xTransactionCount;

As in other headers.

Comment 3

[Patrick McManus [:mcmanus]]

(In reply to Honza Bambas (:mayhemer) from comment #2)
> Just for curiosity, why don't you also want to report 0 ?  Of course just in
> case it never used spdy.

I was just trying to filter out unused backup connections - they don't play much of a role in this comparison.. and the telemetry coalesces some bucket values so I wasn't 100% confident I would always be able to separate 0 from 1.

> 
> Maybe call this HttpVer10and11TransactionCount ?  Or something more
> descriptive, the current name is quit cryptic.

I'm pretty fond of mHttp1xTransactionCount but I have documented it.

> > +        mozilla::Telemetry::Accumulate(mozilla::Telemetry::SPDY_NPN_JOIN,
> > +                                       false);
> 
> Aren't we also interested in the reason?  I think it's worth to be more
> verbose here, telemetry should be recorded in JoinConnection method.

I expect this to be ~100% success but want to use this to verify it. I'd be happy to provide
feedback on a separate PSM patch that recorded failure reasons.

> 
> ::: netwerk/protocol/http/nsHttpPipeline.cpp
> @@ +120,5 @@
> >      LOG(("nsHttpPipeline::AddTransaction [this=%x trans=%x]\n", this, trans));
> >  
> >      NS_ADDREF(trans);
> >      mRequestQ.AppendElement(trans);
> > +    ++mHttp1xTransactionCount;
> 
> I think we should update this number only when we actually handled the
> transactions (maybe even received data for it).  This might get wrong when
> the pipeline restarted.
> 

you're right. I moved it to the closed/trans->isdone() logic which should avoid the aborted pipeline case.

Comment 4

[Patrick McManus [:mcmanus]]

Attachment: patch v1

Comment 5

[Honza Bambas (:mayhemer)]

Comment on attachment 579576 [details] [diff] [review]
patch v1

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

r=honzab with a nit bellow.

Thanks.

(In reply to Patrick McManus from comment #3)
> (In reply to Honza Bambas (:mayhemer) from comment #2)
> > Just for curiosity, why don't you also want to report 0 ?  Of course just in
> > case it never used spdy.
> 
> I was just trying to filter out unused backup connections - they don't play
> much of a role in this comparison.. and the telemetry coalesces some bucket
> values so I wasn't 100% confident I would always be able to separate 0 from
> 1.

This is worth to try, but I believe in the exponential mode 0s and 1s are separated.  I think adding never used connections is a good think to have.  If not here, then in other probe, but not sure what other probe should that be, this mostly covers what I wanted to do my self - number of transactions processed on a connection.

So I definitely would like to add never used connections here as well.

Comment 6

[Patrick McManus [:mcmanus]]

https://hg.mozilla.org/integration/mozilla-inbound/rev/952d14a9e508

Comment 7

[Ed Morley [:emorley]]

https://hg.mozilla.org/mozilla-central/rev/952d14a9e508

Comment 8

[Ed Morley [:emorley]]

Backed out (along with the rest of the SPDY landing) in order to stop us hitting the MSVC virtual address limit, so we can reopen the trees (bug 709193).

Sucks, but we don't really have any other choice here :-(

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

Comment 9

[Ed Morley [:emorley]]

Relanded on mozilla-central :-)

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