[net] Add AsyncDNS.TTL histogram.

[net] Add AsyncDNS.TTL histogram.

Counts of TTL obtained in DNS response. Counted when the address is used.



Committed: http://src.chromium.org/viewvc/chrome?view=rev&revision=162329

[szym, 2012-10-08 20:25:41]

I opted to count the TTL whenever the result is used. The resulting distribution
should (in theory) be largely unaffected by the specific caching policy.

It won't allow direct prediction of cache hit rate because of high
auto-correlation in arrival of requests for the same hostname, but it should
give us an idea of what we are trying to cache.

To measure the inter-arrival time of same-hostname requests we'd need an 
experiment like the "infinite cache". I'm concerned of the cost of such
experiment.

[cbentzel, 2012-10-11 18:27:30]

I like and agree with how you are measuring the TTL distribution.

Some interface complexity concerns with your implementation, though.

http://codereview.chromium.org/11065052/diff/5001/net/base/host_cache.h
File net/base/host_cache.h (right):

http://codereview.chromium.org/11065052/diff/5001/net/base/host_cache.h#newco...
net/base/host_cache.h:77: base::TimeDelta ttl);
Could this just take a base::TimeDelta original_ttl argument, or even a boolean
for "real ttl", that becomes part of Entry()? 

Then you wouldn't need to change ExpiringCache, and this would still return
void.

http://codereview.chromium.org/11065052/diff/5001/net/base/host_resolver_impl.cc
File net/base/host_resolver_impl.cc (right):

http://codereview.chromium.org/11065052/diff/5001/net/base/host_resolver_impl...
net/base/host_resolver_impl.cc:1471: CompleteRequests(net_error, addr_list,
base::TimeDelta::FromSeconds(-1));
At the point that the kNegativeCacheEntry/kCacheEntry replacement is done in
CompleteRequests, you lose a lot of context for why this is done.

It might be better to add an original_ttl or "real_ttl" arguments to
CompleteRequests to make it clearer.

[szym, 2012-10-11 18:33:21]

http://codereview.chromium.org/11065052/diff/5001/net/base/host_cache.h
File net/base/host_cache.h (right):

http://codereview.chromium.org/11065052/diff/5001/net/base/host_cache.h#newco...
net/base/host_cache.h:77: base::TimeDelta ttl);
On 2012/10/11 18:27:30, cbentzel wrote:
> Could this just take a base::TimeDelta original_ttl argument, or even a
boolean
> for "real ttl", that becomes part of Entry()? 
> 
> Then you wouldn't need to change ExpiringCache, and this would still return
> void.

The rationale was that changing the signature of Set() will require updating all
host_cache_unittest, and I was being a bit lazy in case we needed to add some
extra fields in the future.

I'll change the signature.

[szym, 2012-10-12 16:16:54]

I moved the default TTL logic back to OnProcTaskComplete and made HostCache::Set
accept a HostCache::Entry (HostCache is transparent with respect to Entry
anyway).
PTAL.

[cbentzel, 2012-10-13 10:50:45]

LGTM, with some nits.

http://codereview.chromium.org/11065052/diff/23001/net/base/host_cache.h
File net/base/host_cache.h (right):

http://codereview.chromium.org/11065052/diff/23001/net/base/host_cache.h#newc...
net/base/host_cache.h:27: // As above, but sets |ttl| to negative.
This comment actually confuses things a bit - it's clearer if it says that the
entry has no actual TTL, and then comment the ttl field to specify that negative
values mean no ttl.

http://codereview.chromium.org/11065052/diff/23001/net/base/host_resolver_imp...
File net/base/host_resolver_impl.cc (right):

http://codereview.chromium.org/11065052/diff/23001/net/base/host_resolver_imp...
net/base/host_resolver_impl.cc:209: UMA_HISTOGRAM_CUSTOM_COUNTS("AsyncDNS.TTL",
ttl.InSeconds(), 1, 86400, 100);
Should be UMA_HISTOGRAM_CUSTOM_TIMES?

http://codereview.chromium.org/11065052/diff/23001/net/base/host_resolver_imp...
net/base/host_resolver_impl.cc:1371: CompleteRequests(OK, addr_list,
base::TimeDelta(), false /* true_ttl */);
Would it make sense to change to CompleteRequests(addr_list, base::TimeDelta())
and have a CompleteRequestsHelper which both that and CompleteRequestsWithError
call?

[szym, 2012-10-15 19:45:36]

I'm seeing a reproducible crash when refreshing chrome://histograms

[17509:17528:1015/121808:FATAL:histogram.cc(552)] Check failed: samples.sum() ==
0 (758061727743 vs. 0)
Backtrace:
        base::debug::StackTrace::StackTrace() [0x7f93a747218e]
        logging::LogMessage::~LogMessage() [0x7f93a749c171]
        base::Histogram::WriteAsciiHeader() [0x7f93a74ab6cd]
        base::Histogram::WriteAsciiImpl() [0x7f93a74ab006]
        base::Histogram::WriteHTMLGraph() [0x7f93a74a9313]
        base::StatisticsRecorder::WriteHTMLGraph() [0x7f93a74af2c8]
        content::AboutHistogram() [0x7f93a7d385ba]
        content::HistogramInternalsRequestJob::GetData() [0x7f93a7d3863c]
        net::URLRequestSimpleJob::StartAsync() [0x7f93a7a38bc4]
        base::internal::RunnableAdapter<>::Run() [0x7f93a7a393aa]
        base::internal::InvokeHelper<>::MakeItSo() [0x7f93a7a39283]
        base::internal::Invoker<>::Run() [0x7f93a7a39185]
        base::Callback<>::Run() [0x7f93a682b71b]
        MessageLoop::RunTask() [0x7f93a74a018d]
        MessageLoop::DeferOrRunPendingTask() [0x7f93a74a02a8]
        MessageLoop::DoWork() [0x7f93a74a0b3f]
        base::MessagePumpLibevent::Run() [0x7f93a7462f59]
        MessageLoop::RunInternal() [0x7f93a749fd91]
        MessageLoop::RunHandler() [0x7f93a749fc48]
        base::RunLoop::Run() [0x7f93a74c6ed0]
        MessageLoop::Run() [0x7f93a749f57c]
        base::Thread::Run() [0x7f93a74ffca4]
        content::BrowserThreadImpl::IOThreadRun() [0x7f93a7b17c23]
        content::BrowserThreadImpl::Run() [0x7f93a7b17deb]
        base::Thread::ThreadMain() [0x7f93a74ffe2f]
        base::(anonymous namespace)::ThreadFunc() [0x7f93a74f516b]
        start_thread [0x7f93a20d2e9a]
        0x7f93a0171dbd

http://codereview.chromium.org/11065052/diff/23001/net/base/host_resolver_imp...
File net/base/host_resolver_impl.cc (right):

http://codereview.chromium.org/11065052/diff/23001/net/base/host_resolver_imp...
net/base/host_resolver_impl.cc:209: UMA_HISTOGRAM_CUSTOM_COUNTS("AsyncDNS.TTL",
ttl.InSeconds(), 1, 86400, 100);
On 2012/10/13 10:50:45, cbentzel wrote:
> Should be UMA_HISTOGRAM_CUSTOM_TIMES?

I initially used _TIMES, but then I looked at the histogram results and didn't
like the non-round number of milliseconds on the bucket boundaries. I don't
think it makes any difference so I'll make it _TIMES of TimeDelta.

http://codereview.chromium.org/11065052/diff/23001/net/base/host_resolver_imp...
net/base/host_resolver_impl.cc:1371: CompleteRequests(OK, addr_list,
base::TimeDelta(), false /* true_ttl */);
On 2012/10/13 10:50:45, cbentzel wrote:
> Would it make sense to change to CompleteRequests(addr_list,
base::TimeDelta())
> and have a CompleteRequestsHelper which both that and
CompleteRequestsWithError
> call?

I don't see the benefit. Wouldn't this be the only place where it is used? The
other places need to pass a custom net_error or custom true_ttl.

[cbentzel, 2012-10-15 21:56:27]

On 2012/10/15 19:45:36, szym wrote:
> I'm seeing a reproducible crash when refreshing chrome://histograms

Stack trace looks totally independent of this CL. What happens if you just try
without this patch?

[jar (doing other things), 2012-10-16 01:35:03]

Histograms have some redundant data calculations that are used to diminish
spam in recorded data.  The most common cause is errant pointer memory
smashers, but it can also be induced by bad RAM.  Some DCHECKs can be
caused by a race, but that is super rare (and certainly should not
reproducible on your machine).

In this case, I suspect it is an errant pointer smashing the contents of a
histogram array, resetting a sum to zero.  The CHECK fires when you get
around to trying to display the histogram via about:histograms.

The stack shows that a histogram was encountered, for which there count of
samples is still zero, but yet the sum of the samples is
(in your example) 758061727743. My bet is that someone cleared out the sum
slot.

I guess it could be that you gathered far in excess of 2^32 samples... and
happened to to try to snapshot the histogram at exactly that point in
time... but I'd call that rather unlikely (and again, hard to repro).

YMMV... and it could also be a new bug in the code (which has been
changing).... but at least the above is how it should work.

Jim

p.s., I've copied Kai, who has been hacking some of the code of recent, in
case he has a different perspective.


On Mon, Oct 15, 2012 at 12:45 PM, <szym@chromium.org> wrote:

> I'm seeing a reproducible crash when refreshing chrome://histograms
>
> [17509:17528:1015/121808:**FATAL:histogram.cc(552)] Check failed:
> samples.sum() ==
> 0 (758061727743 vs. 0)
> Backtrace:
>         base::debug::StackTrace::**StackTrace() [0x7f93a747218e]
>         logging::LogMessage::~**LogMessage() [0x7f93a749c171]
>         base::Histogram::**WriteAsciiHeader() [0x7f93a74ab6cd]
>         base::Histogram::**WriteAsciiImpl() [0x7f93a74ab006]
>         base::Histogram::**WriteHTMLGraph() [0x7f93a74a9313]
>         base::StatisticsRecorder::**WriteHTMLGraph() [0x7f93a74af2c8]
>         content::AboutHistogram() [0x7f93a7d385ba]
>         content::**HistogramInternalsRequestJob::**GetData()
> [0x7f93a7d3863c]
>         net::URLRequestSimpleJob::**StartAsync() [0x7f93a7a38bc4]
>         base::internal::**RunnableAdapter<>::Run() [0x7f93a7a393aa]
>         base::internal::InvokeHelper<>**::MakeItSo() [0x7f93a7a39283]
>         base::internal::Invoker<>::**Run() [0x7f93a7a39185]
>         base::Callback<>::Run() [0x7f93a682b71b]
>         MessageLoop::RunTask() [0x7f93a74a018d]
>         MessageLoop::**DeferOrRunPendingTask() [0x7f93a74a02a8]
>         MessageLoop::DoWork() [0x7f93a74a0b3f]
>         base::MessagePumpLibevent::**Run() [0x7f93a7462f59]
>         MessageLoop::RunInternal() [0x7f93a749fd91]
>         MessageLoop::RunHandler() [0x7f93a749fc48]
>         base::RunLoop::Run() [0x7f93a74c6ed0]
>         MessageLoop::Run() [0x7f93a749f57c]
>         base::Thread::Run() [0x7f93a74ffca4]
>         content::BrowserThreadImpl::**IOThreadRun() [0x7f93a7b17c23]
>         content::BrowserThreadImpl::**Run() [0x7f93a7b17deb]
>         base::Thread::ThreadMain() [0x7f93a74ffe2f]
>         base::(anonymous namespace)::ThreadFunc() [0x7f93a74f516b]
>         start_thread [0x7f93a20d2e9a]
>         0x7f93a0171dbd
>
>
>
> http://codereview.chromium.**org/11065052/diff/23001/net/**
>
base/host_resolver_impl.cc<http://codereview.chromium.org/11065052/diff/23001/net/base/host_resolver_impl.cc>
> File net/base/host_resolver_impl.cc (right):
>
> http://codereview.chromium.**org/11065052/diff/23001/net/**
>
base/host_resolver_impl.cc#**newcode209<http://codereview.chromium.org/11065052/diff/23001/net/base/host_resolver_impl.cc#newcode209>
> net/base/host_resolver_impl.**cc:209:
> UMA_HISTOGRAM_CUSTOM_COUNTS("**AsyncDNS.TTL", ttl.InSeconds(), 1, 86400,
> 100);
> On 2012/10/13 10:50:45, cbentzel wrote:
>
>> Should be UMA_HISTOGRAM_CUSTOM_TIMES?
>>
>
> I initially used _TIMES, but then I looked at the histogram results and
> didn't like the non-round number of milliseconds on the bucket
> boundaries. I don't think it makes any difference so I'll make it _TIMES
> of TimeDelta.
>
>
> http://codereview.chromium.**org/11065052/diff/23001/net/**
>
base/host_resolver_impl.cc#**newcode1371<http://codereview.chromium.org/11065052/diff/23001/net/base/host_resolver_impl.cc#newcode1371>
> net/base/host_resolver_impl.**cc:1371: CompleteRequests(OK, addr_list,
> base::TimeDelta(), false /* true_ttl */);
> On 2012/10/13 10:50:45, cbentzel wrote:
>
>> Would it make sense to change to CompleteRequests(addr_list,
>>
> base::TimeDelta())
>
>> and have a CompleteRequestsHelper which both that and
>>
> CompleteRequestsWithError
>
>> call?
>>
>
> I don't see the benefit. Wouldn't this be the only place where it is
> used? The other places need to pass a custom net_error or custom
> true_ttl.
>
>
http://codereview.chromium.**org/11065052/<http://codereview.chromium.org/110...
>

[kaiwang, 2012-10-16 03:10:50]

Hi szym, if you feel the crash is caused by exisiting histogram code, could
you file a bug about how to reproduce? I'll be happy to debug it.
Thanks a lot!

On Mon, Oct 15, 2012 at 6:35 PM, Jim Roskind <jar@chromium.org> wrote:

> Histograms have some redundant data calculations that are used to diminish
> spam in recorded data.  The most common cause is errant pointer memory
> smashers, but it can also be induced by bad RAM.  Some DCHECKs can be
> caused by a race, but that is super rare (and certainly should not
> reproducible on your machine).
>
> In this case, I suspect it is an errant pointer smashing the contents of a
> histogram array, resetting a sum to zero.  The CHECK fires when you get
> around to trying to display the histogram via about:histograms.
>
> The stack shows that a histogram was encountered, for which there count of
> samples is still zero, but yet the sum of the samples is
> (in your example) 758061727743. My bet is that someone cleared out the sum
> slot.
>
> I guess it could be that you gathered far in excess of 2^32 samples... and
> happened to to try to snapshot the histogram at exactly that point in
> time... but I'd call that rather unlikely (and again, hard to repro).
>
> YMMV... and it could also be a new bug in the code (which has been
> changing).... but at least the above is how it should work.
>
> Jim
>
> p.s., I've copied Kai, who has been hacking some of the code of recent, in
> case he has a different perspective.
>
>
> On Mon, Oct 15, 2012 at 12:45 PM, <szym@chromium.org> wrote:
>
>> I'm seeing a reproducible crash when refreshing chrome://histograms
>>
>> [17509:17528:1015/121808:**FATAL:histogram.cc(552)] Check failed:
>> samples.sum() ==
>> 0 (758061727743 vs. 0)
>> Backtrace:
>>         base::debug::StackTrace::**StackTrace() [0x7f93a747218e]
>>         logging::LogMessage::~**LogMessage() [0x7f93a749c171]
>>         base::Histogram::**WriteAsciiHeader() [0x7f93a74ab6cd]
>>         base::Histogram::**WriteAsciiImpl() [0x7f93a74ab006]
>>         base::Histogram::**WriteHTMLGraph() [0x7f93a74a9313]
>>         base::StatisticsRecorder::**WriteHTMLGraph() [0x7f93a74af2c8]
>>         content::AboutHistogram() [0x7f93a7d385ba]
>>         content::**HistogramInternalsRequestJob::**GetData()
>> [0x7f93a7d3863c]
>>         net::URLRequestSimpleJob::**StartAsync() [0x7f93a7a38bc4]
>>         base::internal::**RunnableAdapter<>::Run() [0x7f93a7a393aa]
>>         base::internal::InvokeHelper<>**::MakeItSo() [0x7f93a7a39283]
>>         base::internal::Invoker<>::**Run() [0x7f93a7a39185]
>>         base::Callback<>::Run() [0x7f93a682b71b]
>>         MessageLoop::RunTask() [0x7f93a74a018d]
>>         MessageLoop::**DeferOrRunPendingTask() [0x7f93a74a02a8]
>>         MessageLoop::DoWork() [0x7f93a74a0b3f]
>>         base::MessagePumpLibevent::**Run() [0x7f93a7462f59]
>>         MessageLoop::RunInternal() [0x7f93a749fd91]
>>         MessageLoop::RunHandler() [0x7f93a749fc48]
>>         base::RunLoop::Run() [0x7f93a74c6ed0]
>>         MessageLoop::Run() [0x7f93a749f57c]
>>         base::Thread::Run() [0x7f93a74ffca4]
>>         content::BrowserThreadImpl::**IOThreadRun() [0x7f93a7b17c23]
>>         content::BrowserThreadImpl::**Run() [0x7f93a7b17deb]
>>         base::Thread::ThreadMain() [0x7f93a74ffe2f]
>>         base::(anonymous namespace)::ThreadFunc() [0x7f93a74f516b]
>>         start_thread [0x7f93a20d2e9a]
>>         0x7f93a0171dbd
>>
>>
>>
>> http://codereview.chromium.**org/11065052/diff/23001/net/**
>>
base/host_resolver_impl.cc<http://codereview.chromium.org/11065052/diff/23001/net/base/host_resolver_impl.cc>
>> File net/base/host_resolver_impl.cc (right):
>>
>> http://codereview.chromium.**org/11065052/diff/23001/net/**
>>
base/host_resolver_impl.cc#**newcode209<http://codereview.chromium.org/11065052/diff/23001/net/base/host_resolver_impl.cc#newcode209>
>> net/base/host_resolver_impl.**cc:209:
>> UMA_HISTOGRAM_CUSTOM_COUNTS("**AsyncDNS.TTL", ttl.InSeconds(), 1, 86400,
>> 100);
>> On 2012/10/13 10:50:45, cbentzel wrote:
>>
>>> Should be UMA_HISTOGRAM_CUSTOM_TIMES?
>>>
>>
>> I initially used _TIMES, but then I looked at the histogram results and
>> didn't like the non-round number of milliseconds on the bucket
>> boundaries. I don't think it makes any difference so I'll make it _TIMES
>> of TimeDelta.
>>
>>
>> http://codereview.chromium.**org/11065052/diff/23001/net/**
>>
base/host_resolver_impl.cc#**newcode1371<http://codereview.chromium.org/11065052/diff/23001/net/base/host_resolver_impl.cc#newcode1371>
>> net/base/host_resolver_impl.**cc:1371: CompleteRequests(OK, addr_list,
>> base::TimeDelta(), false /* true_ttl */);
>> On 2012/10/13 10:50:45, cbentzel wrote:
>>
>>> Would it make sense to change to CompleteRequests(addr_list,
>>>
>> base::TimeDelta())
>>
>>> and have a CompleteRequestsHelper which both that and
>>>
>> CompleteRequestsWithError
>>
>>> call?
>>>
>>
>> I don't see the benefit. Wouldn't this be the only place where it is
>> used? The other places need to pass a custom net_error or custom
>> true_ttl.
>>
>>
http://codereview.chromium.**org/11065052/<http://codereview.chromium.org/110...
>>
>
>

[commit-bot: I haz the power, 2012-10-17 01:43:37]

CQ is trying da patch. Follow status at
https://chromium-status.appspot.com/cq/szym@chromium.org/11065052/29001

[commit-bot: I haz the power, 2012-10-17 01:43:42]

Presubmit check for 11065052-29001 failed and returned exit status 1.


Running presubmit commit checks ...

** Presubmit Messages **
If this change has an associated bug, add BUG=[bug number].

** Presubmit ERRORS **
Missing LGTM from an OWNER for files in these directories:
    chrome/browser/ui/webui/net_internals

Presubmit checks took 1.2s to calculate.

[szym, 2012-10-17 01:46:07]

eroman: please approve changes to webui/net_internals

[eroman, 2012-10-17 01:48:16]

lgtm

[commit-bot: I haz the power, 2012-10-17 02:23:24]

CQ is trying da patch. Follow status at
https://chromium-status.appspot.com/cq/szym@chromium.org/11065052/29001

[commit-bot: I haz the power, 2012-10-17 03:04:26]

Sorry for I got bad news for ya.
Compile failed with a clobber build.
Your code is likely broken or HEAD is junk. Please ensure your
code is not broken then alert the build sheriffs.
Look at the try server FAQ for more details.

[commit-bot: I haz the power, 2012-10-17 06:39:54]

CQ is trying da patch. Follow status at
https://chromium-status.appspot.com/cq/szym@chromium.org/11065052/41003

[commit-bot: I haz the power, 2012-10-17 08:39:45]

Change committed as 162329