Georg, Alessio and I decided that even though there's not yet any smoke, there's enough heat that we should ensure things don't catch fire in the future - so we should batch the sync ping submissions. We've come up with a plan that we think will help the backend significantly while still giving us the metrics we want and without too much client-side effort. Basic strategy is that we buffer the pings and send them a minimum of once per day (or maybe twice per day?) * Sync "payloads" are all buffered in memory rather than immediately submitted. * We impose an upper limit on the number of such records we keep in memory (and thus the number we actually submit.) Sync typically runs once every 10 minutes, which corresponds to 144 Syncs per day. However, operations performed by the browser may cause it to Sync more often. A guideline is that the max ping size is around 1MB including metadata, so I propose we limit this to 500 syncs. After this limit we count the syncs we discarded and include that count in the payload, as this still allows us to detect clients doing an insane number of syncs. (There's an open question on the above re detecting when our payload still exceeds the maximum size imposed by telemetry even with this 500 limit in place. I think we would want to know if that happened, but we can consider doing that in a different bug, as it probably requires assistance from the telemetry modules - IIUC, they just throw oversized pings on the floor) * On startup, schedule a timer that fires every 24 hours (12 hours?) and an observer for quit-application. Actually, we probably want just an "interval" that we re-create each time it fires - we want to make sure that, say, when a device is asleep for a few days before waking up, we (a) correctly submit the ping immediately but (b) don't see the timer fire immediately multiple times to account for every 24/12 hours the device was asleep for. I *think* using an interval will do the right thing here, which we should check. A fallback would be listening for a "wake_notification" observer. * On either that timer or observer firing, put the payload together and send it to telemetry. It will manage the persisting of the payload even when called during shutdown. Thus, Sync never needs to actually persist anything. * We will lose pings due to a crash, which probably doesn't matter. We *might* later want to know we lost such pings (eg, so we can exclude those clients from analysis), but we can add stuff to the schema later if necessary via a different bug. * The ping format changes in such a way that it is consistent regardless of how many submissions we make and how many pings are in it. Something like: Existing: {"type": "sync", ..., "payload": { "when": 1470908281556, ... } } Changes to: { type: "sync", ... payload: { syncs: [array of existing payload objects], numDiscarded: integer - the number of Sync records we discarded due to rate limiting why: string, either "scheduled" or "shutdown", } * We don't bother bumping the schema version. We uplift this patch to Aurora. Analysis done against Aurora will need to take these 2 different formats into account, but that's doable. There will only be a single format once it hits beta/release, which is what we really care about anyway.

(In reply to Mark Hammond [:markh] from comment #0) > * We impose an upper limit on the number of such records we keep in memory > (and thus the number we actually submit.) Sync typically runs once every 10 > minutes, which corresponds to 144 Syncs per day. However, operations > performed by the browser may cause it to Sync more often. A guideline is > that the max ping size is around 1MB including metadata, so I propose we > limit this to 500 syncs. After this limit we count the syncs we discarded > and include that count in the payload, as this still allows us to detect > clients doing an insane number of syncs. You could probably get the 95th/99th percentile of "number of syncs per client" from the sync server data and choose a number that fits this? 1MB is very large already, and was rather arbitrarily chosen for heavier ping types. 10KB is probably a better guideline. > (There's an open question on the above re detecting when our payload still > exceeds the maximum size imposed by telemetry even with this 500 limit in > place. I think we would want to know if that happened, but we can consider > doing that in a different bug, as it probably requires assistance from the > telemetry modules - IIUC, they just throw oversized pings on the floor) With a hard limit like above you should be safe. > * On startup, schedule a timer that fires every 24 hours (12 hours?) and an > observer for quit-application. Actually, we probably want just an "interval" > that we re-create each time it fires - we want to make sure that, say, when > a device is asleep for a few days before waking up, we (a) correctly submit > the ping immediately but (b) don't see the timer fire immediately multiple > times to account for every 24/12 hours the device was asleep for. I *think* > using an interval will do the right thing here, which we should check. A > fallback would be listening for a "wake_notification" observer. I would not rely on those timers without confirming, we already ran into problems with this: https://dxr.mozilla.org/mozilla-central/rev/6e191a55c3d23e83e6a2e72e4e80c1dc21516493/toolkit/components/telemetry/TelemetrySession.jsm#412 > * The ping format changes in such a way that it is consistent regardless of > how many submissions we make and how many pings are in it. Something like: > * We don't bother bumping the schema version. We uplift this patch to > Aurora. Analysis done against Aurora will need to take these 2 different > formats into account, but that's doable. There will only be a single format > once it hits beta/release, which is what we really care about anyway. You can filter the previous ping version out by buildid, so that will be fine.

(In reply to Georg Fritzsche [:gfritzsche] from comment #1) > I would not rely on those timers without confirming, we already ran into > problems with this: > https://dxr.mozilla.org/mozilla-central/rev/ > 6e191a55c3d23e83e6a2e72e4e80c1dc21516493/toolkit/components/telemetry/ > TelemetrySession.jsm#412 To keep this bug as simple as possible, how about we add an observer notification at https://dxr.mozilla.org/mozilla-central/rev/6e191a55c3d23e83e6a2e72e4e80c1dc21516493/toolkit/components/telemetry/TelemetrySession.jsm#475 and have the Sync telemetry module listen for that instead of a timer? Reinventing a new scheduler sounds like a bad idea - Sync already has a bad one, and it doesn't need another ;) That makes the 12v24 hour decision for us, but that's OK to get the change landed.

I think thats rather easy to add, while i don't think offering synchronous notifications from Telemetry modules is a good idea here.

I think its a shame the existing telemetry scheduler can't help us schedule telemetry, but no probs - we'll find the simplest thing that works on the Sync side of the world.

Comment on attachment 8782510 [details] Bug 1295058 - Make sync ping only submit every 12 hours or on browser shutdown Getting this up for early feedback.

Comment on attachment 8782510 [details] Bug 1295058 - Make sync ping only submit every 12 hours or on browser shutdown https://reviewboard.mozilla.org/r/72654/#review70314 Note that this still needs to update the sync-ping.rst documentation and the test code. I also tried a variant where I checked after each sync if it had been 12 hours (which also avoids the possibility we ever submit empty pings -- not that that's a source of much complexity). This appears to be simpler, but mainly because getting a reliable monotonic timestamp is nontrivial. ::: services/sync/modules/telemetry.js:349 (Diff revision 1) > + // Note that we might be in the middle of a sync right now, and so we don't > + // want to touch this.current. > + let result = this.getPingJSON(reason); > + this.payloads = []; > + this.discarded = 0; > + this.submit(result); I'm not certain, but it might be worth handling the case where JSON.stringify(result) is greater than 1MB (or whatever telemetry's max is). A simple-ish method of doing so would be to throw out half of the payloads in a loop until it's a small enough count (adding the count we threw out to discarded) and add a flag in the sync ping which would indicate that our maxPayloadCount value is likely to high -- which I suspect 500 is. Whether or not this is worthwhile would probably depend on how telemetry handles records that are too big. If it just throws them away, it sounds like it might be worht doing, since we'd probably never see the `discarded` values. But... this might not be worth it at all, even then. ::: services/sync/modules/telemetry.js:404 (Diff revision 1) > } > this.current.finished(error); > - let current = this.current; > + if (this.payloads.length < this.maxPayloadCount) { > + this.payloads.push(this.current); > + } else { > + ++this.discarded; It's tempting to add some code here that throws out meaningless payloads if the current payload has validation or error information, but... it's probably more complexity than is warranted.

Comment on attachment 8782510 [details] Bug 1295058 - Make sync ping only submit every 12 hours or on browser shutdown Feel free to weigh in if you have any comments, would rather know any problems now before I fix all the test code that cares about the ping.

Comment on attachment 8782510 [details] Bug 1295058 - Make sync ping only submit every 12 hours or on browser shutdown https://reviewboard.mozilla.org/r/72654/#review70532 That looks good to me! ::: services/sync/modules/telemetry.js:201 (Diff revision 1) > this.engines = []; > // The engine that has started but not yet stopped. > this.currentEngine = null; > } > > // toJSON returns the actual payload we will submit. I guess this comment should be tweaked. ::: services/sync/modules/telemetry.js:327 (Diff revision 1) > this.setupObservers(); > + > + this.payloads = []; > + this.discarded = 0; > + this.maxPayloadCount = Svc.Prefs.get("telemetry.maxPayloadCount", 500); > + let submissionInterval = Svc.Prefs.get("telemetry.submissionInterval", 12 * 60 * 60); While it obviously doesn't hurt, in general we don't bother specifying a fallback value for when a pref exists (it doesn't hurt, but there is lots of code in Firefox that does Services.prefs.getBoolPref(...) without a try/catch under the assumption the pref doesn't exist. ::: services/sync/modules/telemetry.js:328 (Diff revision 1) > + > + this.payloads = []; > + this.discarded = 0; > + this.maxPayloadCount = Svc.Prefs.get("telemetry.maxPayloadCount", 500); > + let submissionInterval = Svc.Prefs.get("telemetry.submissionInterval", 12 * 60 * 60); > + this.timer = Cc["@mozilla.org/timer;1"].createInstance(Ci.nsITimer); Timer.jsm might also be a good option. ::: services/sync/modules/telemetry.js:378 (Diff revision 1) > > onSyncStarted() { > if (this.current) { > log.warn("Observed weave:service:sync:start, but we're already recording a sync!"); > // Just discard the old record, consistent with our handling of engines, above. > + // XXX: Should we increment this.discarded here? I'm not sure what you are getting at with these 2 comments - the processing in onSyncFinished looks OK to me. ::: services/sync/modules/telemetry.js:404 (Diff revision 1) > } > this.current.finished(error); > - let current = this.current; > + if (this.payloads.length < this.maxPayloadCount) { > + this.payloads.push(this.current); > + } else { > + ++this.discarded; I agree that doesn't seen necessary. I was also thinking that these few lines could go into a new method, say, this.enqueue() or similar, which might make your test changes simpler - where you currently hook .submit, you could just change to .enqueue. But I'm sure you have your own ideas for tests.

Comment on attachment 8782510 [details] Bug 1295058 - Make sync ping only submit every 12 hours or on browser shutdown https://reviewboard.mozilla.org/r/72654/#review70314 Side-note: If the clients stops syncing for some reason, you would not get any pings sent with the alernative variant. > I'm not certain, but it might be worth handling the case where JSON.stringify(result) is greater than 1MB (or whatever telemetry's max is). > > A simple-ish method of doing so would be to throw out half of the payloads in a loop until it's a small enough count (adding the count we threw out to discarded) and add a flag in the sync ping which would indicate that our maxPayloadCount value is likely to high -- which I suspect 500 is. > > Whether or not this is worthwhile would probably depend on how telemetry handles records that are too big. If it just throws them away, it sounds like it might be worht doing, since we'd probably never see the `discarded` values. > > But... this might not be worth it at all, even then. I think this is not worth the effort. If you have hard-limits like "max. 500 entries", then you should never hit this limit.

Comment on attachment 8782510 [details] Bug 1295058 - Make sync ping only submit every 12 hours or on browser shutdown https://reviewboard.mozilla.org/r/72652/#review70622 ::: services/sync/modules/telemetry.js:329 (Diff revision 1) > + this.timer.initWithCallback(() => this.finish("schedule"), > + submissionInterval * 1000, > + timer.TYPE_REPEATING_SLACK); Have you checked that this fires as expected after sleep on Mac & Linux? Context: https://dxr.mozilla.org/mozilla-central/rev/6e191a55c3d23e83e6a2e72e4e80c1dc21516493/toolkit/components/telemetry/TelemetrySession.jsm#412 A scenario you might run into: * the timer runs for 6h * the computer goes to sleep for 10h * after wakeup: - the timer fires immediately on windows - the timer fires in 6h on Mac & Linux ::: services/sync/modules/telemetry.js:339 (Diff revision 1) > + getPingJSON(reason) { > + return { > + why: reason, > + discarded: this.discarded || undefined, > + version: PING_FORMAT_VERSION, > + payloads: this.payloads.map(payload => payload.toJSON()), Out of curiosity: Why not store the JSON style objects in `this.payloads` already when you record the events? ::: services/sync/modules/telemetry.js:369 (Diff revision 1) > } > > submit(record) { > + // We still call submit() with possibly illegal payloads so that tests can > + // know that the ping was built. We don't end up submitting them, however. > + if (record.payloads.length) { So the plan now is to not send a ping if there were no syncs? This is a good thing to explicitly call out in the documentation.

Comment on attachment 8782510 [details] Bug 1295058 - Make sync ping only submit every 12 hours or on browser shutdown https://reviewboard.mozilla.org/r/72652/#review70628

Comment on attachment 8782510 [details] Bug 1295058 - Make sync ping only submit every 12 hours or on browser shutdown https://reviewboard.mozilla.org/r/72654/#review70314 AIUI we'd still send them on shutdown as long as we shut down gracefully, but it might be quite a bit late.

Comment on attachment 8782510 [details] Bug 1295058 - Make sync ping only submit every 12 hours or on browser shutdown https://reviewboard.mozilla.org/r/72654/#review72242 The code itself looks good to me, but I think we can make the test changes less intrusive while also keeping those tests clearer (ie, it's not going to be immediately clear to callers that syncs[0] is what they should use and there should never be a syncs[1]) ::: services/sync/modules/telemetry.js:201 (Diff revision 3) > this.engines = []; > // The engine that has started but not yet stopped. > this.currentEngine = null; > } > > // toJSON returns the actual payload we will submit. It looks like my previous comments weren't addressed. This comment should change (as it's not what we submit) ::: services/sync/modules/telemetry.js:326 (Diff revision 3) > this.current = null; > this.setupObservers(); > + > + this.payloads = []; > + this.discarded = 0; > + this.maxPayloadCount = Svc.Prefs.get("telemetry.maxPayloadCount", 500); I think you should remove the defaults here seeing you added the prefs (or alternatively, don't add the prefs, so the default is necessary) ::: services/sync/tests/unit/test_corrupt_keys.js:144 (Diff revision 3) > do_check_eq(hmacErrorCount, 0); > > _("HMAC error count: " + hmacErrorCount); > // Now syncing should succeed, after one HMAC error. > let ping = yield wait_for_ping(() => Service.sync(), true); > - equal(ping.engines.find(e => e.name == "history").incoming.applied, 5); > + equal(ping.syncs[0].engines.find(e => e.name == "history").incoming.applied, 5); I think we should consider having wait_for_ping and sync_and_validate_telem just return ping.syncs[0] rather than the entire ping (and probably asserting that there really only is 1) - it makes no sense for callers of these methods to get multiple pings. There are some tests where you do assert there's only 1, so I think rolling that up into the helper makes sense and avoid almost all of those test changes. There's 1 new test where you do need to check the entire payload, but in that case you can just "inline" sync_and_validate_telem to get the entire payload.

Comment on attachment 8782510 [details] Bug 1295058 - Make sync ping only submit every 12 hours or on browser shutdown https://reviewboard.mozilla.org/r/72654/#review73114 So if i understand this right, pings are only triggered after a sync now? This change would have been helpful to call out in a comment on the new review request. Note that with this change and the `record.syncs.length`, you will never see any pings if no sync occured (e.g. because of misconfiguration, bugs, ...). That can be fine if you don't need that, but worth considering. ::: services/sync/modules/telemetry.js:328 (Diff revision 3) > + // This isn't monotonic, but neither is the timer TelemetrySession uses, so we should be fine. > + this.lastSubmissionTime = Date.now(); As commented below, you could use `Services.telemetry.msSinceProcessStart()`. `TelemetrySession` is not necessarily bug-free. ::: services/sync/modules/telemetry.js:401 (Diff revision 3) > + this.payloads.push(this.current.toJSON()); > + } else { > + ++this.discarded; > + } > this.current = null; > - this.submit(current.toJSON()); > + if ((Date.now() - this.lastSubmissionTime) > this.submissionInterval) { If you want to use a stable monotic clock, you can use `Services.telemetry.msSinceProcessStart()` for these values.

Comment on attachment 8782510 [details] Bug 1295058 - Make sync ping only submit every 12 hours or on browser shutdown https://reviewboard.mozilla.org/r/72654/#review73122

(In reply to Georg Fritzsche [:gfritzsche] from comment #17) > Note that with this change and the `record.syncs.length`, you will never see > any pings if no sync occured (e.g. because of misconfiguration, bugs, ...). > That can be fine if you don't need that, but worth considering. Yeah - a signal from the telemetry scheduler would make sending empty-pings attractive, but I don't think we should bother now - IMO, this patch is a good compromise given we expect a sync every 10 minutes. > If you want to use a stable monotic clock, you can use > `Services.telemetry.msSinceProcessStart()` for these values. I don't think a "when" that resets as the process starts is any good here (unless I misunderstand you?) Thanks.

(In reply to Mark Hammond [:markh] from comment #19) > > If you want to use a stable monotic clock, you can use > > `Services.telemetry.msSinceProcessStart()` for these values. > > I don't think a "when" that resets as the process starts is any good here > (unless I misunderstand you?) I think that's no different to the current implementation? It initializes with `this.lastSubmissionTime = Date.now()`.

(In reply to Georg Fritzsche [:gfritzsche] from comment #20) > I think that's no different to the current implementation? > It initializes with `this.lastSubmissionTime = Date.now()`. Yeah, agreed - IMO, monotonic isn't useful here unless it survives process restarts. While that's unfortunate, does this patch make the situation worse? I think Date.now() everywhere is likely the improvement we are looking for here...

Date.now() can jump backwards and forwards in time, e.g. when changing your date or timezone, when your clock is broken, ... I don't understand why this would be a problem over process restarts. Using relative time with Date.now() or msSinceProcessStart() doesn't seem different? It's probably not important here for your scheduling, but good to call it out that this might not be a stable scheduling for all clients.

Sorry, I was conflating the scheduling with the "when" field - I agree msSinceProcessStart is the best option for the scheduler.

The reason I don't use msSinceProcessStart is that it can fail in some cases -- e.g. when the value may be inconsistent (it boils down to calling https://dxr.mozilla.org/mozilla-central/source/mozglue/misc/TimeStamp.cpp#72-76 and throwing if aIsInconsistent is true). It's not obvious to me how rare this is, so it seems like something that would need to be handled. Initially I had some code that fell back to Date.now when this happened (and made sure not to mix Date.now with msSinceProcessStart), but after looking to see what telemetry's own scheduler does in this case, it appears to just use `Policy.now().getTime()` (see https://dxr.mozilla.org/mozilla-central/source/toolkit/components/telemetry/TelemetrySession.jsm#498 and elsewhere in the same file), which is just `new Date().getTime()`, or effectively the same as `Date.now()`. But just repacing the call with msSinceProcessStart doesn't really bother me either.

Comment on attachment 8782510 [details] Bug 1295058 - Make sync ping only submit every 12 hours or on browser shutdown https://reviewboard.mozilla.org/r/72654/#review73862 I think that looks great, thanks. ::: services/sync/modules/telemetry.js:327 (Diff revision 4) > + > + this.payloads = []; > + this.discarded = 0; > + this.maxPayloadCount = Svc.Prefs.get("telemetry.maxPayloadCount"); > + this.submissionInterval = Svc.Prefs.get("telemetry.submissionInterval") * 1000; > + // This isn't monotonic, but neither is the timer TelemetrySession uses, so we should be fine. It might be better to reframe this comment as something like "Use telemetry's concept of time for scheduling" or the comment may become stale if that gets improved.

Comment on attachment 8782510 [details] Bug 1295058 - Make sync ping only submit every 12 hours or on browser shutdown https://reviewboard.mozilla.org/r/72654/#review74054 Looks good to me. I don't know how you handle documentation updates, but that still needs to happen. ::: services/sync/modules/telemetry.js:327 (Diff revisions 3 - 4) > > this.payloads = []; > this.discarded = 0; > - this.maxPayloadCount = Svc.Prefs.get("telemetry.maxPayloadCount", 500); > - this.submissionInterval = Svc.Prefs.get("telemetry.submissionInterval", 12 * 60 * 60) * 1000; > + this.maxPayloadCount = Svc.Prefs.get("telemetry.maxPayloadCount"); > + this.submissionInterval = Svc.Prefs.get("telemetry.submissionInterval") * 1000; > // This isn't monotonic, but neither is the timer TelemetrySession uses, so we should be fine. `msSinceProcessStart()` is monotonic, you should update the comment.

Comment on attachment 8782510 [details] Bug 1295058 - Make sync ping only submit every 12 hours or on browser shutdown https://reviewboard.mozilla.org/r/72654/#review74054 I'm pretty sure the documentation update (e.g. from the rst) is handled automatically, unless that's not what you mean.

I overlooked the documentation updates from previous reviewboard diffs, which look fine.

Pushed by archaeopteryx@coole-files.de: https://hg.mozilla.org/integration/autoland/rev/705cb7ff8360 Make sync ping only submit every 12 hours or on browser shutdown r=gfritzsche,markh

[Tracking Requested - why for this release]: Firefox 50 in the release channel may generate a volume of sync pings that causes issues for the telemetry servers. We should try and uplift this (and dependent bugs) before then.

Comment on attachment 8782510 [details] Bug 1295058 - Make sync ping only submit every 12 hours or on browser shutdown Approval Request Comment [Feature/regressing bug #]: bug 1267919 (which is on 50) [User impact if declined]: Greater than expected "ping" traffic for the telemetry back end. [Describe test coverage new/current, TreeHerder]: Tests pass, been on 51 for some time. [Risks and why]: Fairly low risk - limited to sync [String/UUID change made/needed]: None Note bug 1301289 should be uplifted with this.

Hi Mark, Georg, who from the telemetry team might be able to confirm that this and dependent fixes are indeed helping to alleviate the problems that were caused by too many sync (unbatched) pings? Without that I'd be less inclined to uplift this fix in Fx51. It seems like a decent amount of code change and I'd like for us to be sure of the value before uplifting it. Thanks for your help!

You can see the drop of "other" pings for Nightly starting 2016-09-02 here: https://metrics.services.mozilla.com/telemetry-budget-dashboard/ This comes down to a reduction of "other" ping data of nearly 90%. Scaling this to the release population size, this has non-trivial impact.

Hi Ritu, I hope Georg's response is what you were after. I apologize for leaving this so late, but I requested tracking for 51 on this bug nearly 2 weeks ago in the hope the tracking process would prompt me to remember before it hit beta. Is it normal for tracking requests to be left unanswered as the release in question moves into beta?

(In reply to Mark Hammond [:markh] from comment #37) > Hi Ritu, I hope Georg's response is what you were after. Thanks Georg for the confirmation that based on Nightly data this fix is indeed helping. I'll approve the Beta uplift now. I apologize for > leaving this so late, but I requested tracking for 51 on this bug nearly 2 > weeks ago in the hope the tracking process would prompt me to remember > before it hit beta. Is it normal for tracking requests to be left unanswered > as the release in question moves into beta? Hi Mark, I try to keep up with the tracking noms but sometimes I fall behind. Sorry about that. I appreciate your heads up in this case via the 50:? nom.

Comment on attachment 8782510 [details] Bug 1295058 - Make sync ping only submit every 12 hours or on browser shutdown Telemetry team has verified that this fix has reduced the load on the server based on Nightly51 data, Beta50+

Needs rebasing for Beta.

Not sure if this was the right way to do this, let me know if I'm missing something! Try run -- not yet finished: https://treeherder.mozilla.org/#/jobs?repo=try&revision=d8396ea9c5b0