HUGE amount of writes by storage.js.temp. Possible LZ4 archivation or less frequent rewrite?

[AjvarXX]

Steps to reproduce

1. Freshly launched Firefox 56 with 20 startup tabs but only few actually been loaded at least once.
2. 4 hours of launched Firefox where light browsing took 2 hours (4 active tabs max), 2 hours of inactivity.
3. ...
4. PROFIT!

Expected behavior

For such a light session of 4 hours Adguard shouldn't have written whopping 461MB

Actual behavior

Looks like Adguard extension rewrites non-archieved storage.js.tmp file over and over again. This alone would provide up to 4GB of writes per day on SSD.

Screenshot:

<>
I noticed that Firefox had same problem with sessionrestore (sessionrestore.js, recovery.js) and now they "bandaged over" it with including LZ4 archieving which cuts up from 30% to 90% depending on what's inside. Also you can reduce frequency from default 15 seconds of backing up session.
https://bugzilla.mozilla.org/show_bug.cgi?id=1304389
https://bugzilla.mozilla.org/show_bug.cgi?id=934967

Screenshot of the browser console:

Your environment

• Adguard AdBlocker extension version: 2.7.3
• Environment name and version: Firefox 64bit v.56.0.2
• Filters you use in Adguard: English, Counter and Analitics, widgets from social networks, Russian, Japaneese. Adguard shows number of blocked adverts.
• Any other browser extensions you have installed:

Addons:

<>

[wdbw]

I cannot provide any data, but I can confirm that the timestamp of storage.js is updated very often (-> disk writes).

It's probably related to updating the block counter whenever something has been blocked.

[ameshkov]

This is actually an important issue caused by the way FF implemented browser.storage API.

We will fix it asap.

[AjvarXX]

Oh, I am glad I helped. And thank you guys for working on it.

[wdbw]

Any news? The issue was fixed long ago, but even a month later there is no new point release available.

[zebrum]

@wdbw it's in beta channel here: https://addons.mozilla.org/en-US/firefox/addon/adguard-adblocker/versions/beta?page=1#version-2.8.1beta

[wdbw]

@AjvarXX Can you confirm whether this issue is fixed or not?

While using the program FileActivityWatch I saw that several MB were written to the .js.tmp file after opening a website (on YouTube I even got multiple writes).

Adguard extension 2.8.6 and Firefox 64bit v.60b9

[AjvarXX]

Absolutely positive that it is fixed for me.
Latest Waterfox (fork of Firefox) and latest Adguard 2.8.6

[wdbw]

What do you see instead? When do writes occur? For me the storage file (~5MB) is rewritten on every page load, and that can add up quickly.

I would like to test with blocking statistics disabled, but there is no option for that.

[wdbw]

I have disabled the storage of the total block count, and that eliminates the writes.

https://github.com/AdguardTeam/AdguardBrowserExtension/blob/master/Extension/lib/utils/page-stats.js#L85

Why is this call not done on shutdown only?

[wdbw]

After upgrading to version 2.9.2 I took a closer look at the read/writes. Playing a three and a half minute YouTube video resulted in ~150MB of data written to the storage file.

@ameshkov Any idea why this issue is not fixed for me? I doubt that this is the intended behavior.

[ameshkov]

Why is this call not done on shutdown only?

That wouldn't be reliable.

Look at the save method, it can't be called more often than once in a second:
https://github.com/AdguardTeam/AdguardBrowserExtension/blob/master/Extension/lib/utils/page-stats.js#L49

Also, it seems that the fix of this issue is under review right now:
https://bugzilla.mozilla.org/show_bug.cgi?id=1406181

For me the storage file (~5MB) is rewritten on every page load, and that can add up quickly.

Why is it THAT HUGE in your case? It should be a couple of kilobytes max.

Please try reinstalling AdGuard from scratch, maybe the old data is still there.

[wdbw]

Look at the save method, it can't be called more often than once in a second:
https://github.com/AdguardTeam/AdguardBrowserExtension/blob/master/Extension/lib/utils/page-stats.js#L49

It was called on YouTube while playing a video every ~7 seconds.

Why is it THAT HUGE in your case? It should be a couple of kilobytes max.

A fresh storage.js has this size: 3,60 MB (3.784.484 bytes)

My file size is slightly bigger due to having more filter lists enabled.

[ameshkov]

A fresh storage.js has this size: 3,60 MB (3.784.484 bytes)

In my case, it is 1.5 KB. What's inside?

For instance, here's what inside of mine:

$ cat storage.js
{"adguard-settings":{"app-version":"2.9.2","filters-state":"{\"1\":{\"loaded\":true,\"enabled\":true,\"installed\":true},\"2\":{\"loaded\":true,\"enabled\":true,\"installed\":true},\"3\":{\"loaded\":true,\"enabled\":true,\"installed\":true},\"4\":{\"loaded\":true,\"enabled\":true,\"installed\":true},\"10\":{\"loaded\":true,\"enabled\":true,\"installed\":true},\"216\":{\"loaded\":true,\"enabled\":false,\"installed\":true},\"238\":{\"loaded\":true,\"enabled\":false,\"installed\":true}}","filters-version":"{\"1\":{\"version\":\"2.0.2.18\",\"lastCheckTime\":1523727859962,\"lastUpdateTime\":1523718332000},\"2\":{\"version\":\"2.0.4.93\",\"lastCheckTime\":1523727860178,\"lastUpdateTime\":1523718355000},\"3\":{\"version\":\"2.0.1.23\",\"lastCheckTime\":1523727860794,\"lastUpdateTime\":1523718357000},\"4\":{\"version\":\"2.0.1.85\",\"lastCheckTime\":1523727859898,\"lastUpdateTime\":1523718358000},\"10\":{\"version\":\"2.0.0.23\",\"lastCheckTime\":1522664178690,\"lastUpdateTime\":1520616612000},\"216\":{\"version\":\"2.0.1.83\",\"lastCheckTime\":1523727859906,\"lastUpdateTime\":1523610376000},\"238\":{\"version\":\"2.0.0.22\",\"lastCheckTime\":1522664178524,\"lastUpdateTime\":1522530158000}}","client-id":"z32lgs8c64441426","safebrowsing-disabled":false,"sb-cache":"{}","page-statistic":"{\"totalBlocked\":2}","show-info-about-adguard-disabled":true,"white-list-domains":"[]","block-list-domains":"[]","detect-filters-disabled":true}}

[wdbw]

What's inside?

Mine contains the filter list entries also, and that makes the file that big.

{"adguard-settings":{"app-version":"2.9.2","filters-state":"{\"2\":{\"loaded\":true,\"enabled\":true,\"installed\":true},\"10\":{\"loaded\":true,\"enabled\":true,\"installed\":true}}","filters-version":"{\"2\":{\"version\":\"2.0.4.14\",\"lastCheckTime\":1523826032801,\"lastUpdateTime\":1522767910000},\"10\":{\"version\":\"2.0.0.23\",\"lastCheckTime\":1523826032816,\"lastUpdateTime\":1520616612000}}","client-id":"MBHGgXhu26036774"},"filterrules_2.txt":["! Checksum: 0gJbfZH+VzNbIKdoLKtWiA","! Title: English Filter","! Description: ... <snip>

[ameshkov]

Mine contains the filter list entries also, and that makes the file that big.

Hm, I don't understand why is it happening. Filters must be stored elsewhere in v2.9, that was the change that fixed this issue.

What exact AdGuard distr do you use? AMO or smth else?

[wdbw]

I do have the AMO version installed.

Browser console output (enabling the extension with no storage.js present):

1523832642367	addons.webextension.adguardadblocker@adguard.com	WARN	Please specify whether you want browser_style or not in your browser_action options.
XML Parsing Error: unclosed token
Location: moz-extension://7ed592f8-9840-4c32-9978-6ae3ea15ffb4/background.html
Line Number 1, Column 1:  background.html:1:1
2018-04-15T22:50:42.567Z: Adguard rulesStorage error: InvalidStateError: A mutation operation was attempted on a database that did not allow mutations.
Stack trace:
  log.js:71:9
	print moz-extension://7ed592f8-9840-4c32-9978-6ae3ea15ffb4/lib/utils/log.js:71:9
	error moz-extension://7ed592f8-9840-4c32-9978-6ae3ea15ffb4/lib/utils/log.js:91:13
	onError moz-extension://7ed592f8-9840-4c32-9978-6ae3ea15ffb4/lib/utils/rules-storage-indexeddb.js:36:9
	init/request.onblocked moz-extension://7ed592f8-9840-4c32-9978-6ae3ea15ffb4/lib/utils/rules-storage-indexeddb.js:150:13
The character encoding of the HTML document was not declared. The document will render with garbled text in some browser configurations if the document contains characters from outside the US-ASCII range. The character encoding of the page must be declared in the document or in the transfer protocol.  background.html
2018-04-15T22:50:42.580Z: Starting adguard... Version: 2.9.2. Id: adguardadblocker@adguard.com  log.js:71:9
2018-04-15T22:50:42.589Z: Filters metadata loaded  log.js:71:9
2018-04-15T22:50:42.600Z: Filters i18n metadata loaded  log.js:71:9
2018-04-15T22:50:42.669Z: Retrieved response from server for filter 2, rules count: 84878  log.js:71:9
2018-04-15T22:50:42.683Z: Retrieved response from server for filter 10, rules count: 164  log.js:71:9
NS_ERROR_NOT_AVAILABLE: Component returned failure code: 0x80040111 (NS_ERROR_NOT_AVAILABLE) [nsIWebNavigation.loadURIWithOptions] browser-child.js:359
2018-04-15T22:50:43.843Z: Starting loading filter rules from the storage  log.js:71:9
2018-04-15T22:50:44.501Z: Finished loading filter rules from the storage in 658 ms  log.js:71:9
2018-04-15T22:50:44.502Z: Starting request filter initialization. Async=false  log.js:71:9
2018-04-15T22:50:44.864Z: Cannot create rule from filter 2: @@||hdslb.com^$domain=bilibili.com,stealth, cause Unknown option: STEALTH  log.js:71:9
2018-04-15T22:50:44.865Z: Cannot create rule from filter 2: @@||iatv.tmgrup.com.tr^$script,stealth, cause Unknown option: STEALTH  log.js:71:9
2018-04-15T22:50:44.865Z: Cannot create rule from filter 2: @@||i.tmgrup.com.tr^$script,stealth, cause Unknown option: STEALTH  log.js:71:9
2018-04-15T22:50:45.229Z: Cannot create rule from filter 2: |http://$image,ping,script,stylesheet,subdocument,third-party,xmlhttprequest,domain=watchers.to, cause Unknown option: PING  log.js:71:9
2018-04-15T22:50:45.230Z: Cannot create rule from filter 2: |https://$image,ping,script,stylesheet,subdocument,third-party,xmlhttprequest,domain=watchers.to, cause Unknown option: PING  log.js:71:9
2018-04-15T22:50:45.404Z: Finished request filter initialization in 903 ms. Rules count: 80986

[ameshkov]

1. Is user filter empty?
2. What exact version of FF do you use?

The culprit is this error:
InvalidStateError: A mutation operation was attempted on a database that did not allow mutations.

It makes AG use the browser storage instead of the indexedDB

[atropnikov]

@wdbw Could you also check dom.indexedDB.enabled flag on the about:config page?

[wdbw]

60.0b12 (64-bit) + dom.indexedDB.enabled=true

I have found the cause for this problem. According to the following bug report, the usage of indexedDB is disabled in private browsing mode:

https://bugzilla.mozilla.org/show_bug.cgi?id=781982

[ameshkov]

Not sure about this. It could've been true if we had used "incognito": "split": https://developer.mozilla.org/en-US/Add-ons/WebExtensions/manifest.json/incognito

Anyway, we'll check it and get back to you soon.

[ameshkov]

Uh, sorry for the late reply. I've filed a new issue about this particular incognito problem: #1006

[maximtop]

@wdbw Could you export your firefox profile, please? I can't reproduce this issue with my configuration.

[wdbw]

I can reproduce the problem with the following steps:

1. Create a new Firefox profile
2. Open the settings page and under "Privacy & Security" switch to "Never remember history"
3. Install the extension from AMO

[maximtop]

resolved in pull request browser-extension/pull-requests/135