1440832 - "Clamped larged numeric value." error is logged in the browser console every one minute

Status: RESOLVED FIXED

(Toolkit :: Telemetry, defect, P1)

Description

[magicp]

Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:60.0) Gecko/20100101 Firefox/60.0 ID:20180223100113

Steps to reproduce:
1. Launch Nightly on Windows
2. Open the Browser Console (Ctrl+Shift+J)
3. Waiting a few minutes

Actual results:
The following error is logged in the browser console every one minute. I can reproduce on Windows 7 and 10.

Clamped larged numeric value. (unknown)


Expected results:
No error


Regression range:
https://hg.mozilla.org/integration/mozilla-inbound/pushloghtml?fromchange=4560309df57b52d4946e309d12c150ddef61ef66&tochange=ba1d6f897a923b561bd9458f77bd3f7f63b99573

Comment 1

[Cristina Badescu [:cbadescu], Experiments QA]

User Agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:60.0) Gecko/20100101 Firefox/60.0

Hello,

I have tested this issue on latest Nightly build 60.0a1 (2017-02-28)and managed to reproduce it. 
Moreover, I obtained the same pushlog result.

I did not manage to reproduce this issue on Mac 10.13.3 and Ubuntu 14.04 x64.

Gijs, can you please take a look at this issue?

Comment 2

[:Gijs (he/him)]

This is a change from telemetry, which is bug 1438335. The pushlog must be wrong. Maybe mozregression isn't picking the right branch to look at or whatever.

The number of errors we get in the wild from this makes me pretty apprehensive about uplifting this change to beta. What's the benefit of logging something to the console here?

Comment 3

[Chris H-C :chutten]

Generally speaking, we introduced this error logging to ensure devs adding new Telemetry measures are aware that they are doing something wrong by accumulating too-large-values to their histograms. That way it can be fixed before analysis is performed on clamped data.

ni?gfritzsche for any comments he wishes to add.

Comment 4

[:Gijs (he/him)]

The telemetry dist viewer shows half a million hits (!) for HTTP_CACHE_IO_QUEUE_2_EVICT over the course of less than 1 week. There's some other ones as well.

Comment 5

[Chris H-C :chutten]

Oh, and these _particular_ logs are from virtual memory size measurements. The plan for them is under discussion in bug 1436914

Comment 6

[Chris H-C :chutten]

(In reply to :Gijs from comment #4)
> The telemetry dist viewer shows half a million hits (!) for
> HTTP_CACHE_IO_QUEUE_2_EVICT over the course of less than 1 week. There's
> some other ones as well.

The plan for analysing these hits and notifying users is bug 1438885

Comment 7

[:Gijs (he/him)]

(In reply to Chris H-C :chutten from comment #3)
> Generally speaking, we introduced this error logging to ensure devs adding
> new Telemetry measures are aware that they are doing something wrong by
> accumulating too-large-values to their histograms. That way it can be fixed
> before analysis is performed on clamped data.
> 
> ni?gfritzsche for any comments he wishes to add.

Can we do this just on automation and local builds? That would avoid this kind of stuff affecting release users. Logging messages to the console the way it happens here is not really cheap, and once we ship this in a nightly / beta / release build there's nothing users can do about it.

Comment 8

[:Gijs (he/him)]

FWIW, these messages are currently the #4-most-common error message as reported through the nightly error reporter, with all the ones above it being related to add-ons.

Comment 9

[Chris H-C :chutten]

I'm amenable to wrapping it in `#ifdef DEBUG` so long as there isn't a case Georg can come up with against it. I think given our recording of counts of affected probes in the scalar telemetry.accumulate_clamped_values we should be able to do that.

Comment 10

[Chris H-C :chutten]

Attachment: bug 1440832 - Only log when clamping on debug builds

Review commit: https://reviewboard.mozilla.org/r/224006/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/224006/

Comment 11

[Georg Fritzsche [:gfritzsche]]

Comment on attachment 8954856 [details]
bug 1440832 - Only log when clamping on debug builds

https://reviewboard.mozilla.org/r/224006/#review230046

I'm wondering how developers should discover when they introduce measurements in the futures.
Turning this on specifically in testing or ignoring the existing problematic probes might improve this.

For now this is causing disruption though.
So yes, let's limit the impact and think about a better solution.

Comment 12

[:Gijs (he/him)]

Given that bug 1438335 was uplifted, does this need to be uplifted too?

Comment 13

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/f262f531263f
Only log when clamping on debug builds r=gfritzsche

Comment 14

[Chris H-C :chutten]

(In reply to :Gijs from comment #12)
> Given that bug 1438335 was uplifted, does this need to be uplifted too?

After it is verified on Nightly, yup.

Comment 15

[Tiberius Oros[:tiberius_oros]]

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

Comment 16

[erosman]

"Clamped large numeric value" log still occurs in Firefox 60.0a1 (2018-03-02) (64-bit)

Comment 17

[Chris H-C :chutten]

Oh darn, so it is. This is likely to be a bad rebase interaction with bug 1428893.

Comment 18

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/d4e9a7bee582
Only log on debug builds when clamping. r=gfritzsche

Comment 19

[Cristian Brindusan [:cbrindusan]]

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

Comment 20

[magicp]

Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:60.0) Gecko/20100101 Firefox/60.0 ID:20180302190033
"Clamped large numeric value" occurs in Firefox Developer Edition 60.0b1 (20180302190033)

Comment 21

[:Gijs (he/him)]

(In reply to magicp from comment #20)
> Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:60.0) Gecko/20100101
> Firefox/60.0 ID:20180302190033
> "Clamped large numeric value" occurs in Firefox Developer Edition 60.0b1
> (20180302190033)

That has a buildid for March 2, and the merge comment to central at comment #19 is March 3, so for sure this wasn't in beta a day earlier. Can you check b2, which off-hand I'd expect to have the code changes from here ?

Comment 22

[magicp]

(In reply to :Gijs from comment #21)
> (In reply to magicp from comment #20)
> > Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:60.0) Gecko/20100101
> > Firefox/60.0 ID:20180302190033
> > "Clamped large numeric value" occurs in Firefox Developer Edition 60.0b1
> > (20180302190033)
> 
> That has a buildid for March 2, and the merge comment to central at comment
> #19 is March 3, so for sure this wasn't in beta a day earlier. Can you check
> b2, which off-hand I'd expect to have the code changes from here ?

Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:60.0) Gecko/20100101 Firefox/60.0 ID:20180307142707
Ah! It works fine in 60.0b2 (20180307142707). Thanks!