1325322 - Change HTTP_NET_VS_CACHE_ probes to cover bigger time span

Status: RESOLVED FIXED

(Core :: Networking: Cache, defect)

Description

[Michal Novotny [:michal]]

The current range +-500ms is insufficient. Around 30% of samples are out of bounds and the worst case is HTTP_NET_VS_CACHE_ONSTART_QBIG_NORMALPRI with 70% of samples. We should also reconsider limits for small, medium and big cache IO queue length. Ideally we would find such limit for big queue length where network starts to win over the cache.

Comment 1

[Junior [inactive]]

What came to my mind is to save a math log time.
That is, after we get a diff in ms, we save log_2(diff) + 20 with "high" = 40 and "n_bucket" = 40.

We can gather +/- 10 minutes data and do not waste much space for large time diff.

Comment 2

[Junior [inactive]]

IMO we can do this after we reduce the probes in Bug 1325090

Comment 3

[Junior [inactive]]

I'd like to add one more probe with every HTTP_NET_VS_CACHE_*

Taking HTTP_NET_VS_CACHE_ON_START_QSMALL_HIGHPRI as example,
I'd like to add one more probe HTTP_NET_VS_CACHE_ON_START_QSMALL_HIGHPRI_LOG2,
which record the time described in Comment 1.

FWIW, 16 probes are left in current implementation of Bug 1325090.

What do you think, Michal?

Comment 4

[Junior [inactive]]

Attachment: time_span-WIP-v1

What do you think about this approach, michal?

TODO: add HTTP_NET_VS_CACHE_*_LOG2 for each probe

Comment 5

[Michal Novotny [:michal]]

(In reply to Junior[:junior] from comment #3)
> I'd like to add one more probe with every HTTP_NET_VS_CACHE_*
> 
> Taking HTTP_NET_VS_CACHE_ON_START_QSMALL_HIGHPRI as example,
> I'd like to add one more probe
> HTTP_NET_VS_CACHE_ON_START_QSMALL_HIGHPRI_LOG2,
> which record the time described in Comment 1.
> 
> FWIW, 16 probes are left in current implementation of Bug 1325090.
> 
> What do you think, Michal?

I don't think it's worth collecting both, linear and logarithmic values. Also the logarithmic resolution wouldn't be ideal for us, it's too fine for the first few buckets and then too coarse. Maybe we could grow the intervals of the buckets in steps. Something like 10ms from 0 to 100ms, 50ms from 100ms to 1000ms, etc...

Comment 6

[Junior [inactive]]

After considering the resolution and readability, I'd like to implement as following:

bucket 4 to 39 indicates net-win; 40 to 76 for cache-win.

Let's focus on cache-win case first,
40 to 49 divide 0 to 100 ms, step by 10ms.
50 is reserved
51 to 59 divide 100 to 1000 ms, step by 100ms.
60 is reserved.
61 to 69 divide 1s to 10s, step by 1 sec.
70 is reserved.
71 to 75 divide 10s to 1m, step by 10 seconds.

And reflection for the net-win case.
39 to 30 for -1 to -100ms
29 is reserved
28 to 20 for -100 to -1second
19 is reserved
18 to 10 for -1s to -10s,
9 is reserved
8 to 4 for -10s to -1m
0 to 3 are reserved

Comment 7

[Junior [inactive]]

maybe 76 for cache-win by more than 1 minute,
3 for net-win by 1 minute

Comment 8

[Junior [inactive]]

Attachment: time_span-WIP-v2

Implement by last two comments.
Only do for one probe in this patch.

Comment 9

[Michal Novotny [:michal]]

Comment on attachment 8830666 [details] [diff] [review]
time_span-WIP-v2

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

(In reply to Junior[:junior] from comment #6)
> After considering the resolution and readability, I'd like to implement as
> following:
> 
> bucket 4 to 39 indicates net-win; 40 to 76 for cache-win.
> 
> Let's focus on cache-win case first,
> 40 to 49 divide 0 to 100 ms, step by 10ms.
> 50 is reserved

I don't like these holes and also I don't think it makes the data more readable.

> And reflection for the net-win case.
> 39 to 30 for -1 to -100ms

This is not true. The function returns 39 for 0, 38 for -10, 28 for -100, ...

We should have it symmetrical. Let's have bucket 40 for 0, 41 for 1 to 10, 39 for -1 to -10, etc. To have it really symmetrical we need 81 buckets.

Comment 10

[Junior [inactive]]

Attachment: time_span-v3

Tend to sync with other probes in the next patch.

Comment 11

[Michal Novotny [:michal]]

Comment on attachment 8834329 [details] [diff] [review]
time_span-v3

This looks good to me.

Comment 12

[Junior [inactive]]

Attachment: time_span-v4

Comment 13

[Michal Novotny [:michal]]

Comment on attachment 8834737 [details] [diff] [review]
time_span-v4

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

Looks good. We need a data review for this...

Comment 14

[Junior [inactive]]

Comment on attachment 8834737 [details] [diff] [review]
time_span-v4

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

::: netwerk/protocol/http/nsHttpChannel.cpp
@@ +8322,5 @@
> +{
> +	int64_t absBucketIndex =
> +		std::lower_bound(positiveBucketLevels,
> +	                     positiveBucketLevels + kPositiveBucketNumbers,
> +	                     abs(difftime_ms))

I'm not sure which is better, std::abs or mozilla:Abs, but I'll add a namespace-specifier before landed.

Comment 15

[Benjamin Smedberg]

Comment on attachment 8834737 [details] [diff] [review]
time_span-v4

A little hard to review because raw patches of JSON are dump, but this looks fine. Just don't rely on any automated alerts for these metrics: it won't work for nonscalar values.

Comment 16

[Junior [inactive]]

Attachment: time_span-v5

Fix a nit, carry r+
tree result
 https://treeherder.mozilla.org/#/jobs?repo=try&revision=f273810983b7bf90da7409a9a6becb4266ae1da6

Comment 17

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/81388598aeac
add HTTP_NET_VS_CACHE_* for large time span, r=michal

Comment 18

[Sebastian Hengst [:aryx] (needinfo me if it's about an intermittent or backout)]

Backed out for build bustage, at least on Windows:

https://hg.mozilla.org/integration/mozilla-inbound/rev/28ed47ff51b2dfec519b56d6d676dcbf27d47c39

Push with bustage: https://treeherder.mozilla.org/#/jobs?repo=mozilla-inbound&revision=a30525f7b3955104c0111bc190d46eb30e5416a7&
Failure log: https://treeherder.mozilla.org/logviewer.html#?job_id=76803104&repo=mozilla-inbound

12:06:02     INFO -  z:/build/build/src/sccache2/sccache.exe z:/build/build/src/vs2015u3/VC/bin/amd64_x86/cl.exe -Fovp8_enc_stubs_sse2.obj -c  -DNDEBUG=1 -DTRIMMED=1 -DHAVE_CONFIG_H=vpx_config.h -DSTATIC_EXPORTABLE_JS_API -DMOZ_HAS_MOZGLUE -DMOZILLA_INTERNAL_API -DIMPL_LIBXUL -Iz:/build/build/src/media/libvpx -Iz:/build/build/src/obj-firefox/media/libvpx  -Iz:/build/build/src/obj-firefox/dist/include  -Iz:/build/build/src/obj-firefox/dist/include/nspr -Iz:/build/build/src/obj-firefox/dist/include/nss        -MD -FI z:/build/build/src/obj-firefox/mozilla-config.h -DMOZILLA_CLIENT -deps.deps/vp8_enc_stubs_sse2.obj.pp  -TC -nologo -wd4091 -D_HAS_EXCEPTIONS=0 -W3 -Gy -Zc:inline -utf-8 -arch:SSE2 -FS -Gw -wd4244 -wd4267 -we4553  -Z7 -O1 -Oi -Oy- -Iz:/build/build/src/media/libvpx/config/win/ia32/ -Iz:/build/build/src/media/libvpx/libvpx -Iz:/build/build/src/media/libvpx/config   z:/build/build/src/media/libvpx/libvpx/vp8/encoder/x86/vp8_enc_stubs_sse2.c
12:06:02     INFO -  Unified_cpp_protocol_http1.cpp
12:06:02     INFO -  z:\build\build\src\vs2015u3\VC\include\xstddef(324): error C2220: warning treated as error - no 'object' file generated
12:06:02     INFO -  z:\build\build\src\vs2015u3\VC\include\algorithm(2178): note: see reference to function template instantiation 'bool std::less<void>::operator ()<const int64_t&,const _Ty&>(_Ty1,_Ty2) const' being compiled
12:06:02     INFO -          with
12:06:02     INFO -          [
12:06:02     INFO -              _Ty=mozilla::detail::AbsReturnType<__int64>::Type,
12:06:02     INFO -              _Ty1=const int64_t &,
12:06:02     INFO -              _Ty2=const mozilla::detail::AbsReturnType<__int64>::Type &
12:06:02     INFO -          ]
12:06:02     INFO -  z:\build\build\src\vs2015u3\VC\include\algorithm(2198): note: see reference to function template instantiation '_FwdIt std::_Lower_bound_unchecked<_Iter,_Ty,_Pr>(_FwdIt,_FwdIt,const _Ty &,_Pr &)' being compiled
12:06:02     INFO -          with
12:06:02     INFO -          [
12:06:02     INFO -              _FwdIt=const int64_t *,
12:06:02     INFO -              _Iter=const int64_t *,
12:06:02     INFO -              _Ty=mozilla::detail::AbsReturnType<__int64>::Type,
12:06:02     INFO -              _Pr=std::less<void>
12:06:02     INFO -          ]
12:06:02     INFO -  z:\build\build\src\vs2015u3\VC\include\algorithm(2206): note: see reference to function template instantiation '_FwdIt *std::lower_bound<_FwdIt,_Ty,std::less<void>>(_FwdIt,_FwdIt,const _Ty &,_Pr)' being compiled
12:06:02     INFO -          with
12:06:02     INFO -          [
12:06:02     INFO -              _FwdIt=const int64_t *,
12:06:02     INFO -              _Ty=mozilla::detail::AbsReturnType<__int64>::Type,
12:06:02     INFO -              _Pr=std::less<void>
12:06:02     INFO -          ]
12:06:02     INFO -  z:/build/build/src/netwerk/protocol/http/nsHttpChannel.cpp(8344): note: see reference to function template instantiation '_FwdIt std::lower_bound<const int64_t*,mozilla::detail::AbsReturnType<__int64>::Type>(_FwdIt,_FwdIt,const _Ty &)' being compiled
12:06:02     INFO -          with
12:06:02     INFO -          [
12:06:02     INFO -              _FwdIt=const int64_t *,
12:06:02     INFO -              _Ty=mozilla::detail::AbsReturnType<__int64>::Type
12:06:02     INFO -          ]
12:06:02     INFO -  Warning: C4018 in z:\build\build\src\vs2015u3\VC\include\xstddef: '<': signed/unsigned mismatch
12:06:02     INFO -  z:\build\build\src\vs2015u3\VC\include\xstddef(324): warning C4018: '<': signed/unsigned mismatch
12:06:02     INFO -  z:/build/build/src/config/rules.mk:1016: recipe for target 'Unified_cpp_protocol_http1.obj' failed
12:06:02     INFO -  mozmake.EXE[5]: *** [Unified_cpp_protocol_http1.obj] Error 2

Comment 19

[Junior [inactive]]

Attachment: time_span-v6

I believe I miss the header file.
Let's see the treeherder
 https://treeherder.mozilla.org/#/jobs?repo=try&revision=2873382c8148c54d139cd938a64d4a2cef9eaf52

Comment 20

[Junior [inactive]]

Oops...
Try again for the warning as error
https://treeherder.mozilla.org/#/jobs?repo=try&revision=2c02e5f774fe64f366ca05ac494b42fdd79f197c

Comment 21

[Junior [inactive]]

Attachment: time_span-v7

Fix bustage

Comment 22

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/15aaabd6d6d6
add HTTP_NET_VS_CACHE_* for large time span, r=michal

Comment 23

[Wes Kocher (:KWierso) (Not reading bugmail; email directly if needed)]

https://hg.mozilla.org/mozilla-central/rev/15aaabd6d6d6