[webextension] Frequent large disk writes since 3.0

[krestin]

Environment

Ubuntu 16.04 64-bit
Firefox 57.0 64-bit
Adblock Plus 3.0.1

How to reproduce

1. Enable Adblock Plus
2. Run iotop, sort by 'Disk Write' column

Observed behaviour

Command 'firefox [DOM Worker]' writes several MBs every minute. After disabling Adblock Plus the writes are no longer seen. After re-enabling Adblock Plus the writes are seen again.

Expected behaviour

Adblock Plus does not cause excessive disk writes. I don't remember seeing this with versions < 3.0.

Background

See #5769

What to change

Switch to localStorage for the prefs backend, Gecko builds only. Make sure that existing prefs data from storage.local is imported (set flag after successful import to prevent further attempts).

[kzar]

Thanks for the great bug report.

Which filter subscriptions and custom filters do you have enabled? Do you still observe the excessive writes when all filters and subscriptions are disabled? If not are you able to narrow down the problem to a specific filter or subset of filters?

[krestin]

I disabled all subscriptions and the 'firefox [DOM Worker]' writes virtually stopped. Then I enabled 'Adblock Warning Removal List' and 'EasyList' and the writes were still rare and small. Then I enabled 'EasyPrivacy' and the writes became more regular and larger. About half were 20-30 KB and the other half 3-4 MB. I enabled the rest of the subscriptions (Facebook Privacy List and Fanboy lists) and the frequency and size stayed about the same.

For whatever reason it's currently not as regular as what I was seeing before, which was 3-4 MB writes exactly every minute. Now it's more like every 30-120 seconds and some of the writes are only about 20-30 KB.

Edit: I'm seeing this behaviour with Gmail open and an otherwise idle browser. I imagine that background activity in Gmail is triggering the regular writes.

[mapx]

It's definitely something wrong:

• I'm using windows 10, I opened resource monitor.
• in my FF 57 (ABP beta build, easylist, easyprivacy, etc) keeping google page
• when I refresh the page => the storage.js file is rewritten entirely or at least partially - the timestamp changes and in resource monitor I can see a lot of data is written in \browser-extension-data\{d10d0bf8-f5b5-c8b4-a8b2-2b9879e08c5d} folder (where storage.js is placed)

• see the attached file
• I repeated the test using uBo => storage.js remains with the same timestamp even refreshing the page (even if uBo use storage.js only for some prefs and the filters are written using indexedDB)
• does ABP write some weird statistic bytes ? If it's about writting the total number of ads is just bad updating such counter for every visited page. It should be something like every 5 minutes (or better: at the end of session) just to update a similar (useless) counter.

[Ross]

I've reproduced this too on Ubuntu and Windows (Firefox 57/ABP 3.0.1). Attached screenshot shows updating lists and then general browsing on Windows.

[trev]

For reference, what you see is the current state after #5769. The root issue here is that storage implementation in Firefox is very suboptimal, large writes being triggered by a change of a single small value. We could consider IndexedDB again of course, but it might cause more harm than good.

[mapx]

Now the ad counter is updated every 60 seconds, right ? Why - waiting mozilla much intelligent design - not increasing to every 10 minutes or even end of session updating ?

However, it does not seem to be 60 seconds => refreshing the page seems updating immediately the storage.js

[trev]

Browsers are shut down occasionally. If we wait too long with saving that data, we might not get a chance to do it.

[mapx]

Yes, I know, but only as a temporary solution.

Are you sure this code is working fine ? Why simply refreshing the page the counter is quickly updated (without waiting 60 seconds) ? And how is working for chromium / chrome ? I see no test ..

if (__webpack_require__(3).platform == "gecko")
{
  // Saving one storage value causes all others to be saved as well on Gecko.
  // Make sure that updating ad counter doesn't cause the filters data to be
  // saved frequently as a side-effect.
  const MIN_UPDATE_INTERVAL = 60 * 1000;
  let lastUpdate = -MIN_UPDATE_INTERVAL;
  let updateScheduled = false;
  customSave.set("blocked_total", pref =>
  {
    if (updateScheduled)
      return;

    let callback = () =>
    {
      lastUpdate = performance.now();
      updateScheduled = false;
      savePref(pref);
    };

    let timeElapsed = performance.now() - lastUpdate;
    if (timeElapsed < MIN_UPDATE_INTERVAL)
    {
      setTimeout(callback, MIN_UPDATE_INTERVAL - timeElapsed);
      updateScheduled = true;
    }
    else
      callback();
  });
}

[trev]

The counter is updated frequently but only stored at most once every 60 seconds. This isn't an issue in Chrome because Chrome will only store this one value when necessary - it won't rewrite all the filters.

[mapx]

I'm not talking about displaying the counter, I'm talking about the storage.js content. That one (in the file !) is updated immediately ! not every 60 seconds => from this behaviour my doubt the code above is working correctly.

[kzar]

I'm not able to reproduce that on Windows 10 mapx.

First of all I added logging to savePref in adblockpluschrome/lib/prefs.js: console.log("safePref", (new Date()).toString(), prefToKey(pref));

Next I kept refreshing a page with a bunch of adverts, each time I watched to see if anything was logged and also I checked the modified time of my storage.js. I found savePref was only called once a minute for the "blocked_total" preference and the modified time for storage.js only changed when savePref was called.

If you're interested the logs:

safePref Mon Nov 20 2017 15:42:28 GMT+0000 (GMT Standard Time) pref:currentVersion  adblockplus.js:1446:3
safePref Mon Nov 20 2017 15:42:34 GMT+0000 (GMT Standard Time) pref:blocked_total  adblockplus.js:1446:3
safePref Mon Nov 20 2017 15:43:26 GMT+0000 (GMT Standard Time) pref:notificationdata  adblockplus.js:1446:3
safePref Mon Nov 20 2017 15:43:34 GMT+0000 (GMT Standard Time) pref:blocked_total  adblockplus.js:1446:3
safePref Mon Nov 20 2017 15:44:34 GMT+0000 (GMT Standard Time) pref:blocked_total  adblockplus.js:1446:3
safePref Mon Nov 20 2017 15:45:34 GMT+0000 (GMT Standard Time) pref:blocked_total  adblockplus.js:1446:3
safePref Mon Nov 20 2017 15:46:34 GMT+0000 (GMT Standard Time) pref:blocked_total  adblockplus.js:1446:3
safePref Mon Nov 20 2017 15:47:34 GMT+0000 (GMT Standard Time) pref:blocked_total  adblockplus.js:1446:3
safePref Mon Nov 20 2017 15:48:34 GMT+0000 (GMT Standard Time) pref:blocked_total  adblockplus.js:1446:3
safePref Mon Nov 20 2017 15:53:24 GMT+0000 (GMT Standard Time) pref:blocked_total  adblockplus.js:1446:3
safePref Mon Nov 20 2017 15:54:24 GMT+0000 (GMT Standard Time) pref:blocked_total  adblockplus.js:1446:3
safePref Mon Nov 20 2017 15:55:24 GMT+0000 (GMT Standard Time) pref:blocked_total  adblockplus.js:1446:3
safePref Mon Nov 20 2017 15:56:24 GMT+0000 (GMT Standard Time) pref:blocked_total  adblockplus.js:1446:3

It's worth mentioning that this script is run in the background page, so the page being refreshed only usually happens when the whole extension is reloaded. It doesn't happen every time a page that the user is browsing is refreshed.

[kzar]

I wonder if the "blocked_total" preference is worth saving at all on Firefox until the performance problem is fixed? Even once a minute is quite frequent for huge writes, and our users seem wouldn't miss the share buttons anyway (#5613).

I also wonder if knowing how many adverts were blocked in total is even useful at all. I've never once cared about this number, where as knowing how many adverts were blocked on the current page is quite often useful.

Perhaps we should just remove the total blocked count feature entirely?

[trev]

Another option might be using window.localStorage for prefs backend on Firefox, assuming that it won't be cleared out when clearing browsing data. We don't have a lot of prefs data, so this shouldn't cause any noteworthy overhead.

[trev]

The consensus appears to be that localStorage is our best bet here, adjusted description accordingly.

[kzar]

Unfortunately I found clearing browsing data in Firefox (Preferences -> Privacy & Security -> Clear All Data (under Site Data)) did clear values we stored in the extension's background page using window.localStorage.

Another problem with that approach is that ​the values are converted to Strings, though we could write the preferences as JSON to workaround that I suppose.

[krestin]

It seems that something has changed in the latest versions of Firefox to reduce the large disk writes. Currently I am seeing 32 KB writes every few minutes instead of the previous 4 MB writes. If others can confirm this, perhaps this is no longer an issue.

Edit: I was wrong, the 4 MB writes are still there, they have just moved to a different thread called "StreamT~s #N", where N is a number incremented each time a new thread is created.

[krestin]

Are there any plans to address this issue? I still see the 4+ MB writes occurring exactly every minute with 3.0.4.

[sebastian]

As per the workaround implemented in #5769 and outlined in comment:11, a write operation up to once a minute would still to be expected. For reference, the underlying issue is that Firefox when a single storage value is changed writes all data in storage to disk again. Though, I remember trev saying that the performance got already much better with Firefox 57 and above.

[tschuster]

I assume Mozilla's ​Bug 1406181 would probably fix this. By internal switching to indexedDB Firefox should make use of the better underlying sqlite DB, which hopefully behaves much better. This bug seems to be under active development currently, so it hasn't even landed in Firefox 62.