Opened 4 weeks ago

Last modified 3 weeks ago

#6050 reopened defect

[webextension] Frequent large disk writes since 3.0

Reported by: krestin Assignee:
Priority: P1 Milestone:
Module: Platform Keywords:
Cc: trev, sebastian, kzar, mapx, Ross, jeen, athornburgh Blocked By:
Blocking: Platform: Firefox
Ready: no Confidential: no
Tester: Unknown Verified working: no
Review URL(s):

https://codereview.adblockplus.org/29621569/

Description (last modified by trev)

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).

Attachments (2)

ff disk.PNG (21.9 KB) - added by mapx 4 weeks ago.
6050-ffwrites-processmonitor.jpg (2.1 MB) - added by Ross 4 weeks ago.

Download all attachments as: .zip

Change History (26)

comment:1 Changed 4 weeks ago by mapx

  • Cc trev sebastian kzar mapx added

comment:2 Changed 4 weeks ago by kzar

  • Cc Ross added
  • Component changed from Unknown to Platform
  • Summary changed from Frequent large disk writes since 3.0 to [webextensions] Frequent large disk writes since 3.0

comment:3 Changed 4 weeks ago by kzar

  • Summary changed from [webextensions] Frequent large disk writes since 3.0 to [webextension] Frequent large disk writes since 3.0

comment:4 Changed 4 weeks ago by 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?

comment:5 Changed 4 weeks ago by 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.

Last edited 4 weeks ago by krestin (previous) (diff)

comment:6 Changed 4 weeks ago by 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.
Last edited 4 weeks ago by mapx (previous) (diff)

Changed 4 weeks ago by mapx

comment:7 Changed 4 weeks ago by 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.

Changed 4 weeks ago by Ross

comment:8 Changed 4 weeks ago by trev

  • Description modified (diff)

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.

comment:9 Changed 4 weeks ago by 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

Last edited 4 weeks ago by mapx (previous) (diff)

comment:10 Changed 4 weeks ago by trev

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

comment:11 Changed 4 weeks ago by 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();
  });
}

comment:12 Changed 4 weeks ago by 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.

comment:13 Changed 4 weeks ago by 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.

comment:14 Changed 4 weeks ago by 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.

comment:15 Changed 4 weeks ago by kzar

  • Cc jeen athornburgh added

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?

comment:16 Changed 4 weeks ago by 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.

comment:17 Changed 4 weeks ago by trev

  • Description modified (diff)

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

comment:18 Changed 4 weeks ago by kzar

  • Priority changed from Unknown to P1
  • Ready set

comment:19 Changed 3 weeks ago by 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.

comment:20 Changed 3 weeks ago by kzar

  • Ready unset

comment:21 Changed 3 weeks ago by kzar

  • Review URL(s) modified (diff)
  • Status changed from new to reviewing

comment:22 Changed 3 weeks ago by kzar

  • Owner set to kzar

comment:23 Changed 3 weeks ago by kzar

  • Status changed from reviewing to reopened

comment:24 Changed 3 weeks ago by kzar

  • Owner kzar deleted
Note: See TracTickets for help on using tickets.