I unfortunately do not have reliable STR for this, sorry. I noticed that occasionally Nightly would just sit there with 60%+ CPU usage for minutes at a time slowing everything to a crawl. I managed to capture a profile of this [1]. I am on Windows 10 using the latest Nightly. Please let me know if there is anything else I can do to help resolve this. [1] https://perfht.ml/2wt9pGA

Quite some IndexedDB stuff for kinto (whatever that is).

Mathieu Leplatre is who I'd ask about Kinto, but he's on PTO right now. Florian has dabbled in Kinto stuff, and reviewed some patches for the client in Firefox... any idea what the Kinto client might be doing so frequently on the main thread, Florian?

In the profile from comment 0, at least 20% of the time is spent in a library called hmpalert_x64_x64.dll that interferes with the event loop. This is part of HitmanPro.Alert, apparently an anti-malware. I don't know what Kinto does or tries to do here. Trevor, if you find a way to reproduce with HitmanPro.Alert disabled, it would be interesting if you could capture another profile.

In this case, HitmanPro.Alert is coming from the the Sophos Home Antivirus and Cybersecurity Suite[1]. I'll try disabling Sophos and see if the issue still occurs. [1] https://home.sophos.com/

Here is a profile[1] with Sophos Home disabled. The Kinto offline client still seems to be consuming a considerable amount of time. [1] https://perfht.ml/2on7tfb

(In reply to Trevor Rowbotham [:rowbot] from comment #5) > Here is a profile[1] with Sophos Home disabled. The Kinto offline client > still seems to be consuming a considerable amount of time. > > [1] https://perfht.ml/2on7tfb Thanks for this new profile. It shows a pretty different picture: now the browser is responsive; but the excessive CPU use remains. Near the end of the profile, I see _filterEntries from resource://services-settings/remote-settings.js:547, so I would guess all the kinto usage is due to updating remote settings. I don't know enough about remote settings to know if this is the usual behavior (I hope not) or if you are hitting an edge case where it's misbehaving.

I think Benson Wong has his hands in remote settings - maybe he knows?

I discussed this bug in #storage with :rowbot on 2018-08-29. I thought at the time that remote-settings was the most likely culprit (I think it's the only use of kinto.js in Firefox that uses the IndexedDB backend at present), and the new profile is even more conclusive. The problem with the profiles I saw before is that they mostly started after the symptoms had already started (we're chewing through an IDB store), and didn't capture the initial cause. This profile is the same -- I don't see anything at the beginning that seems like it would start any IDB requests. In particular, I'd love to know if this is happening because of a RemoteSettings#maybeSync, and if so on what collections, or if it's happening because of something calling RemoteSettings#get() in a way that we didn't expect. In IRC, it seemed like you weren't able to definitively link the events to remote-settings syncing. I still think that's the most promising avenue of inquiry. remote-settings doesn't really log anything that I can see, but it does report uptake telemetry. To see that, you can go to about:telemetry, under Keyed Histograms, matching "UPTAKE". I think each key represents a kind of thing that has updated, and the histogram represents what result it had when it tried to update. If you could get a copy of that from before the bug happens and again afterwards, that may help narrow it down to a specific collection (assuming it really is maybeSync).

:glasserc, I'll try to see if I can capture a profile that shows the starting point, but it will be challenging since I don't know its occurring until the CPU usage spikes. I'll also take a look at those Histograms to see if I can get some useful information for you. Do you guys want me to file a bug with Sophos about HitmanPro.Alert messing with the event loop or does Mozilla happen to have a contact at Sophos that can raise this internally with the Sophos Home team?

(In reply to Trevor Rowbotham [:rowbot] from comment #9) > :glasserc, I'll try to see if I can capture a profile that shows the > starting point, but it will be challenging since I don't know its occurring > until the CPU usage spikes. I'll also take a look at those Histograms to see > if I can get some useful information for you. Increasing the size of the profiler buffer (and keeping the profiler enabled) may help you capture the beginning. > Do you guys want me to file a bug with Sophos about HitmanPro.Alert messing > with the event loop or does Mozilla happen to have a contact at Sophos that > can raise this internally with the Sophos Home team? Sylvestre, do you know the answer to this question, or know who knows the answer?

Here is an image of the telemetry pings showing up for "UPTAKE" on 8/29/18 7:25 PM. Not sure which ones are relevant, so I included them all. Hopefully it contains some useful info.

Here is a profile[1] that I *think* may have captured whatever is kicking off the IndexedDB calls. [1] https://perfht.ml/2PW17zM

> Here is an image of the telemetry pings showing up for "UPTAKE" on 8/29/18 7:25 PM. Not sure which ones are relevant, so I included them all. Hopefully it contains some useful info. The only insight I get from this is that apparently the `focus-experiments` collection is not successfully synchronized. Even if pulling data about focus should be successful, efficient and transparent, this data is not supposed to be synchronized at all on Desktop, so I'll have to investigate a bit. > Here is a profile[1] that I *think* may have captured whatever is kicking off the IndexedDB calls. I'm not in the best conditions to analyze this, and I'm not sure how to look at this. A potential candidate could be the ActivityStream Tippytop icons, which iterates a ~1K records list and fetches remote icons (resource://activity-stream/lib/TopSitesFeed.jsm:215) The IndexedDB part should run during a few milliseconds though.

Florian, we have a bunch of contacts! I sent them to you by emails (marco is cced)

FWIW, I opened a support ticket with Sophos about HitmanPro.Alert. The ID number is 13873.

Is there anything else I can do to help narrow down the cause here?

Hi Guy's Ronny here from the SurfRight team, the creators of HitmanPro.Alert. Can you try a few things so we can narrow this down to a specific module. Disable the keystroke encryption and see if that makes a difference? And the second test, can you uninstall Sophos Home and try the latest HitmanPro.Alert build directly. https://dl.surfright.nl/hmpalert3.exe And see if that has similar issues, if so also please try to check by disabling keystroke encryption. Switch GUI to advanced (via gear icon), orange icon risk reduction -> keystroke encryption -> disabled. If possible a step-by-step on how to reproduce would be nice.

(In reply to Mathieu Leplatre from comment #13) > I'm not in the best conditions to analyze this, and I'm not sure how to look > at this. A potential candidate could be the ActivityStream Tippytop icons, > which iterates a ~1K records list and fetches remote icons > (resource://activity-stream/lib/TopSitesFeed.jsm:215) > The IndexedDB part should run during a few milliseconds though. It's possible that something that should usually be relatively quick is accidentally done many times in a row. Ed, could you please have a look at this profile? https://perfht.ml/2PMqXWr The first piece of JS code that runs is from nsPlacesExpiration.js, and then there's about 500ms of JS code from (mostly) Activity Stream. And then we have LOTS of 'success' dom events for more than ten seconds. Can it be something in the Activity Stream code that triggers the 10+s of IndexedDB activity? Like in bug 1488462, I see we have several 'message' DOM events that seem to be starting things on the main thread.

Hi Ronny, I don't see anywhere in Sophos Home that has a place to disable keystroke encryption. Is it called something else in the Sophos Home settings? The only setting that I see that might be related is the "Protect against Keyloggers" option, which is under Protection -> Web -> Safe Online Banking.

(In reply to Trevor Rowbotham [:rowbot] from comment #19) > Hi Ronny, > > I don't see anywhere in Sophos Home that has a place to disable keystroke > encryption. Is it called something else in the Sophos Home settings? The > only setting that I see that might be related is the "Protect against > Keyloggers" option, which is under Protection -> Web -> Safe Online Banking. That's the one.

fxperf:p2 to investigate further, at least - though it's not yet clear if this is a frontend issue or what the core reason here is.

I apologize for the long delay in getting back to this. I can no longer reproduce the issues I was seeing with the IndexedDB activity. The only thing that I have actively done that may have resolved this, was clicking on the "Verify Integrity" in about:support for the Places Database. Is clicking this button something that could have realistically resolved this? Since I can no longer produce the IndexedDB activity, I never saw HitmanPro.Alert consume more than 2% of any of my recent profiling attempts, with any combitnation of Sophos or the standalone version of HitmanPro.Alert with Key Encryption enabled/disabled.

Not sure if this bug is worksforme now, but it got me wondering… nanj, are there RemoteSettings events that cause activity stream to trigger updates? Does the structure of how we store the data, e.g., tippy top having individual records (??), result in many small events that we should debounce?

(In reply to Ed Lee :Mardak (PTO Sep 15 - Oct 7) from comment #23) > nanj, are there RemoteSettings events that cause activity stream to trigger > updates? Activity stream completely relies on the default sync behavior of RS (RemoteSettings), and it doesn't observe any event from RS, hence it won't trigger any update by itself. > Does the structure of how we store the data, e.g., tippy top having > individual records (??), result in many small events that we should debounce? Yes, this is likely. As leplatrem mentioned earlier, we have a thousand-record bucket for TippyTop on RS, and the last TippyTop release was published on July 31, there were hundreds of records got updated/deleted. That change might have caused RS to do some downloading in the background, though not sure how it handled that workload exactly.

I just hit this myself. Here's another profile: https://perfht.ml/2EhltC7

> I just hit this myself. Here's another profile: https://perfht.ml/2EhltC7 I don't know exactly how to make good use of those profiles, but if I understand correctly the flames are mostly related to XUL calls, which AFAIK isn't related to Remote Settings. There are some places where RS can be resource consuming on large collections: - computing content signatures on sync - filtering records with JEXL rules (not used here) - filtering records on arbitrary attributes (ie. without idb index we loop over 1k records) I can't figure out how to track those in the profile :( > Activity stream completely relies on the default sync behavior of RS (RemoteSettings) What do you mean by "sync behavior" ?

This is basically the code that ActivityStream uses to leverage RemoteSettings. After a quick try on my machine it never takes more than 220ms. ```js const {RemoteSettings} = ChromeUtils.import("resource://services-settings/remote-settings.js", {}); const c = RemoteSettings("tippytop"); (async function() { for(let i=0; i<10; i++) { console.time(`${i} filtered RS list`); await c.get({filters: {domain: "unknown-domain.com"}}); console.timeEnd(`${i} filtered RS list`); } })(); ``` Same goes with a domain that matches, full listing, raw IDB etc.: ``` (async function() { for(let i=0; i<10; i++) { console.time(`${i} matched`); await c.get({filters: {domain: "amazon.es"}}); console.timeEnd(`${i} matched`); console.time(`${i} unfiltered RS list`); await c.get(); console.timeEnd(`${i} unfiltered RS list`); console.time(`${i} raw IDB list`); const col = await c.openCollection(); await col.list(); console.timeEnd(`${i} raw IDB list`); } })(); ``` Let me know if I can help! It seems that our usage of IndexedDB in RemoteSettings is sound, but IDB always has some wonders to unveil ;)

Some notes from looking at the profile: - There's a bunch of IPC in that profile. I don't understand why we're having to use IPC for indexeddb access (seems like a question for indexeddb folks). It's adding a bunch of overhead for structured clones of the data etc. - AFAICT the cursorHandlers `all()` method/helper effectively uses a cursor to get all the objects, and then filter them. This should be using `getAll` - the filtering in .all() already requires creating the lazily-evaluated cursor.value object, so we might as well get all of them in one go instead of having paying loads of IPC overhead for creating all the items one at a time, then going back for the next one, etc. - we should really figure out what operation is calling cursorHandlers.all() where we get stuck so badly (so we can perhaps improve that, or make it use an index, or something), but the latest profile doesn't seem to contain this information. Looking at the earlier profiles, it's plausible it's the tippytop stuff, but there are other parts of about:newtab that also use remote settings, and because the code is all async-ified it's not clear to me how we're correlating this to the tippytop code. Mathieu, does that help? Do you see worse behavior if you run two queries simultaneously or something? What about if you use an empty string as the target domain?

(In reply to Mathieu Leplatre [:leplatrem] from comment #26) > > Activity stream completely relies on the default sync behavior of RS (RemoteSettings) > > What do you mean by "sync behavior" ? Activity Stream doesn't require the up-to-date tippytop data, hence it won't proactively issue any sync request to the RS backend, but let the RS client decide when & how to do so.

Thanks Gijs for your insights! According to MDN docs using cursors is fine :) If it's not, we should probably add warnings or advise against using them. BTW there is a note about `getAll()`, it does not mention performance and is not entirely encouraging people to use it: https://developer.mozilla.org/en-US/docs/Web/API/IndexedDB_API/Using_IndexedDB#Using_a_cursor On a fresh profile, the operations posted above take around 1sec indeed. I really don't grasp how iterating on a list of 951 records would take more 1 second on a modern laptop. Can someone closer to IndexedDB have a look? Who should we ping? In the mean time, we can add a `count` option in our API to limit the search to a number of results, and investigate if `.getAll()` is something we want (we have to iterate on the list anyway). We also have the ability to redesign the data and use the domain as the record ID. But I don't want to sweep dust under the carpet, I suspect there's some huge win elsewhere in IDB. > Do you see worse behavior if you run two queries simultaneously or something? Yes, I could make it last up to 4 seconds by running a few of them in parallel. > What about if you use an empty string as the target domain? That didn't affect the perfs. The filtering part does not seem to be the most consuming one. Thanks ;)

(In reply to Mathieu Leplatre [:leplatrem] from comment #30) > > On a fresh profile, the operations posted above take around 1sec indeed. I > really don't grasp how iterating on a list of 951 records would take more 1 > second on a modern laptop. Can someone closer to IndexedDB have a look? Who > should we ping? > Let's see what asuth thinks.

To sort of cover various covered issues: - All IndexedDB disk access happens in the parent process. Every request travels to the parent via PBackground and then gets routed to the relevant I/O thread from there. - Cursors do not currently doing any predictive pre-fetching or pre-loading. Bug 1168606 covered making cursors do this, because it's an obvious improvement but it didn't quite stick/complete the landing. I've just re-prioritized the bug because we absolutely need to address this. But in the meantime, this means if you call next() 1000 times, you're dealing with 1000 roundtrips that end up serialized without any pipelining. - getAll() is indeed fine to use if you bound the amount of data you retrieve by providing a count or a sufficiently bounded key-range that you can reason about how much data is going to come back. If the count is reached, you can then adjust your IDBKeyRange based on the highest key/unique value of the thing you retrieved/whatever to request another batch's worth starting from there. If you do this in the same read transaction, you're guaranteed correctness because writers can't sneak in. - The concern about getAll() is that it's possible to do very dumb things with it. While we've taken some steps to avoid this managing to OOM the parent or content processes, these steps mean that we'll fail the request after doing a tremendous amount of I/O. - You're better off using getAll() and getAllKeys() and stitching them together than using a cursor to accomplish the same thing. - IDB indexes are pretty great, but we use WITHOUT ROWID storage in the underlying SQLite which means storage is lexicographically ordered inside the btree, so index-based lookups will amount to scatter-gather reads whereas objectStore.getAll() reads will be contiguous(). You'd want to involve an index if your records are large or you're expecting to discard >50% of the records. And in general the best strategy is just to use clever keys like you would for LevelDB or any other lexicographically ordered kv-store.

Thanks, asuth. Does this give us something to move towards, leplatrem?

Thanks for this awesome explanation :) > Does this give us something to move towards, leplatrem? - I'm surprised by the obtained performance TBH. It seems that we use the official way of retrieving all objects from a store, or at least the one presented in MDN docs. I will investigate if it's specific to using IndexedDB in Chrome, or if it happens in Web content too, and how other browsers perform etc. Based on the technical level of what asuth explained, I don't think this issue is specific to RemoteSettings after all. - If the performance impact of cursor «scanning» is the same everywhere (Chrome, Web pages, and other browsers) I would be in favor of switching to `getAllKeys()` / `getAll()` / post filtering/iteration. What reassures me is that getAll() seems officially supported, contrary to what the introductory docs say. - Also, for this particular use-case of "tippytop" we could follow asuth's advice and use clever keys, where websites domains could be the record keys. Looking up a single domain would then be super fast. It would require a minimal server change to allow "dots" in record ids though. - For other use-cases, this is a bit more annoying. RemoteSettings is meant to be a generic solution for arbitrary data, and unless we develop a whole new high-level API for this, we can't define indexes on specific fields. We have one local database and the index is on [collection name, record id] only, which implies some IndexedBD code that is complex enough IHMO for what it does... [0] [0] https://github.com/Kinto/kinto.js/blob/master/src/adapters/IDB.js

After some investigations, Firefox is the only one to suffer a lot with the cursor iteration. Chrome and Safari both stay under 200ms. I submitted Bug 1499550 to keep track of this specifically. Switching to getAll() makes no big difference on other browsers, but on Firefox it can be up to 10X faster. I will submit a patch here that will fix the issue for the tippytop usecase (only). It should drop to <70ms. I will open another bug, specific to tippytop, to investigate if we can use domains as records IDs. We could go from 70ms to 2ms.

(In reply to Mathieu Leplatre [:leplatrem] from comment #34) > - I'm surprised by the obtained performance TBH. It seems that we use the > official way of retrieving all objects from a store, or at least the one > presented in MDN docs. I will investigate if it's specific to using > IndexedDB in Chrome, or if it happens in Web content too, and how other > browsers perform etc. Based on the technical level of what asuth explained, > I don't think this issue is specific to RemoteSettings after all. Thank you for your investigation in comment 35. Indeed, Gecko's IndexedDB's implementation's failure to optimize cursor traversal is a real problem. Using cursors should be the preferred/recommended mechanism because it allows for memory and disk-efficient pipelining. Thank you for bringing attention to and refocusing us on the issue! The Workers & Storage team has recently gained the engineers to be able to make forward progress on this important issue. > - For other use-cases, this is a bit more annoying. RemoteSettings is meant > to be a generic solution for arbitrary data, and unless we develop a whole > new high-level API for this, we can't define indexes on specific fields. We > have one local database and the index is on [collection name, record id] > only, which implies some IndexedBD code that is complex enough IHMO for what > it does... [0] It might be better to arrange a vidyo call to discuss this, but assuming you want to maintain use of only a single object store for all the collections in a database, probably the simplest thing to do is to stash the values you'd like to be treated as index keys inside the object you put(), and use a multiEntry index and 'structured' keys to achieve the desired partitioning. Example pseudocode: ```js objectStore.createIndex("app_indices", "appIndices", { multiEntry: true }); function fancyPut(idbDataStore, collectionName, collectionIndicesMap, appObj) { const appIndices = collectionIndicies.map([indexName, indexEvalPath]) => { // for the example, assume the key is not nested... const appVal = appObj[indexEvalPath]; if (Array.isArray(appVal)) { throw new Error("The value can't be an array for our current bounds cleverness."); } // Create an index key that's array-structured so we can bound its // key-space. return [collectionName, indexName, appVal]; }); const wrappedObj = { actualObj: appObj appIndices }; return idbDataStore.put(wrappedObj); } async function findWithIndex(idbDataStore, collectionName, indexName, appExact, [appLow, appHigh]) { // [collectionName, indexName] lower-bounds all [collectionName, indexName, ...] // because a shorter array is by definition less than a longer array that is // equal up to their shared length. // [collectionName, indexName, []] upper-bounds all [collectionName, indexName, ...] // because arrays are always greater than strings/dates/numbers. So as long // as the other contents of the index are non-arrays, we're good. const wholeIndexBounds = IDBKeyRange.bound( [collectionName, indexName], [collectionName, indexName, []], true, true); // exclusive range for the edge-case values. const exactIndexBounds = IDBKeyRange.only([collectionName, indexName, appValue]); const rangeBounds = IDBKeyRange.bound( [collectionName, indexName, appLow], [collectionName, indexName, appHigh], false, false); // assume caller meant inclusive. // DO ACTUAL INDEX STUFF return wrappedObj.actualObj; } ``` The downside to this approach is that the data stored on disk will be slightly bloated, but there's not much to be done about that if the Kinto.js ORM layer explicitly avoids using IndexedDB's schema support. Given that Gecko is likely to only ever ship SQLite, IndexedDB, and rkv, I think there's a case to be made for leaning more into the underlying implementation choice made. But that said, the above should work fine unless there's a ton of indices involved.

Uh, and just as an aside, it's weird that kinto.js creates an index that exactly duplicates the primary key: https://github.com/Kinto/kinto.js/blob/b9ecdf53a1ad4562b9444f1cb781ea9f3b516933/src/adapters/IDB.js#L266 const recordsStore = db.createObjectStore("records", { keyPath: ["_cid", "id"], }); ... recordsStore.createIndex("id", ["_cid", "id"]);

Iterating an IDB cursor generates a lot of overhead. In this patch, we upgrade the kinto-offline to its latest version that uses `getAll()` when no filter is specified. We leverage this change in tippytop, by omitting the filter and filtering the whole list there instead. This allowed us to go from ~1sec on a 1000 entries to ~70ms.

Pushed by mleplatre@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/9a05c09af377 Fetch tippytop collection in one bulk with getAll() r=asuth,nanj

Just a quick update, to minimize the performance impact, we've downsized the Tippytop collection from 985 entries to 120 in RemoteSettings, and we won't restore it to its normal size unless bug 1499738 gets fixed.