Opened 6 months ago

Closed 13 days ago

#6050 closed defect (rejected)

[webextension] Frequent large disk writes since 3.0

Reported by: krestin Assignee:
Priority: P1 Milestone:
Module: Platform Keywords:
Cc: sebastian, kzar, mapx, Ross, jeen, athornburgh, tschuster 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 6 months ago.
6050-ffwrites-processmonitor.jpg (2.1 MB) - added by Ross 6 months ago.

Download all attachments as: .zip

Change History (32)

comment:1 Changed 6 months ago by mapx

  • Cc trev sebastian kzar mapx added

comment:2 Changed 6 months 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 6 months 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 6 months 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 6 months 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 6 months ago by krestin (previous) (diff)

comment:6 Changed 6 months 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 6 months ago by mapx (previous) (diff)

Changed 6 months ago by mapx

comment:7 Changed 6 months 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 6 months ago by Ross

comment:8 Changed 6 months 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 6 months 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 6 months ago by mapx (previous) (diff)

comment:10 Changed 6 months 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 6 months 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 6 months 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 6 months 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 6 months 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 6 months 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 6 months 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 6 months ago by trev

  • Description modified (diff)

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

comment:18 Changed 6 months ago by kzar

  • Priority changed from Unknown to P1
  • Ready set

comment:19 Changed 6 months 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 6 months ago by kzar

  • Ready unset

comment:21 Changed 6 months ago by kzar

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

comment:22 Changed 6 months ago by kzar

  • Owner set to kzar

comment:23 Changed 6 months ago by kzar

  • Status changed from reviewing to reopened

comment:24 Changed 6 months ago by kzar

  • Owner kzar deleted

comment:25 Changed 5 months ago by fhd

  • Cc trev removed

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

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

comment:27 Changed 2 weeks ago by krestin

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

comment:28 Changed 2 weeks ago by sebastian

  • Cc tschuster added

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.

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

comment:30 Changed 13 days ago by sebastian

  • Resolution set to rejected
  • Status changed from reopened to closed
Note: See TracTickets for help on using tickets.