Excessive storage.sync activity after VT switch on X server

[WGH-]

Short description

After unlocking desktop session on Linux, TreeStyleTab inserts large amount of data into storage.sync. Presumably, it tries to insert all the inserts that were missed when the desktop was locked, even if nothing's really changed except data timestamps.

Steps to reproduce

1. Open Firefox with TST
2. Lock desktop session with dm-tool lock (I'm using LightDM, this might be reproducible with other session managers) for a while, a day or so
3. Unlock desktop session
4. Observe high writing activity to storage-sync-v2.sqlite. You can use inotifywait to see it:

% inotifywait -m . | head -n 10
Setting up watches.
Watches established.
./ MODIFY storage-sync-v2.sqlite-wal
./ MODIFY storage-sync-v2.sqlite-wal
./ MODIFY storage-sync-v2.sqlite-wal
./ MODIFY storage-sync-v2.sqlite-wal
./ MODIFY storage-sync-v2.sqlite-wal
./ MODIFY storage-sync-v2.sqlite-wal
./ MODIFY storage-sync-v2.sqlite-wal
./ MODIFY storage-sync-v2.sqlite-wal
./ MODIFY storage-sync-v2.sqlite-wal
./ MODIFY storage-sync-v2.sqlite-wal

If you look into the data, you'll see the same data being rewritten with updated timestamp:

% sqlite3 storage-sync-v2.sqlite "SELECT * FROM storage_sync_data WHERE ext_id = 'treestyletab@piro.sakura.ne.jp'"
treestyletab@piro.sakura.ne.jp|{"chunkedUserStyleRules0":"LyogU2hvdyB0aXRsZSBvZiB1bnJlYWQgdGFicyB3aXRoIHJlZCBhbmQgaXRhbGljIGZvbnQgKi8KLyoKOnJvb3Quc2lkZWJhciB0YWItaXRlbS51bnJlYWQgLmxhYmVsLWNvbnRlbnQgewogIGNvbG9yOiByZWQgIWltcG9ydGFudDsKICBmb250LXN0eWxlOiBpdGFsaWMgIWltcG9ydGFudDsKfQoqLwoKLyogQWRkIHByaXZhdGUgYnJvd3NpbmcgaW5kaWNhdG9yIHBlciB0YWIgKi8KLyoKOnJvb3Quc2lkZWJhciB0YWItaXRlbS5wcml2YXRlLWJyb3dzaW5nIHRhYi1sYWJlbDpiZWZvcmUgewogIGNvbnRlbnQ6ICLwn5W2IjsKfQoqLw==","configsVersion":25,"autoCollapseExpandSubtreeOnSelect":false,"workaroundForBug1548949DroppedTabs":"","userStyleRules":"","userStyleRules0":"","showExpertOptions":false,"autoCollapseExpandSubtreeOnAttach":false,"syncDevices":{"device-1610394205907-19995":{"id":"device-1610394205907-19995","name":"Firefox on Linux","icon":"device-desktop","timestamp":1639981643452}}}|913947
% sqlite3 storage-sync-v2.sqlite "SELECT * FROM storage_sync_data WHERE ext_id = 'treestyletab@piro.sakura.ne.jp'"
treestyletab@piro.sakura.ne.jp|{"chunkedUserStyleRules0":"LyogU2hvdyB0aXRsZSBvZiB1bnJlYWQgdGFicyB3aXRoIHJlZCBhbmQgaXRhbGljIGZvbnQgKi8KLyoKOnJvb3Quc2lkZWJhciB0YWItaXRlbS51bnJlYWQgLmxhYmVsLWNvbnRlbnQgewogIGNvbG9yOiByZWQgIWltcG9ydGFudDsKICBmb250LXN0eWxlOiBpdGFsaWMgIWltcG9ydGFudDsKfQoqLwoKLyogQWRkIHByaXZhdGUgYnJvd3NpbmcgaW5kaWNhdG9yIHBlciB0YWIgKi8KLyoKOnJvb3Quc2lkZWJhciB0YWItaXRlbS5wcml2YXRlLWJyb3dzaW5nIHRhYi1sYWJlbDpiZWZvcmUgewogIGNvbnRlbnQ6ICLwn5W2IjsKfQoqLw==","configsVersion":25,"autoCollapseExpandSubtreeOnSelect":false,"workaroundForBug1548949DroppedTabs":"","userStyleRules":"","userStyleRules0":"","showExpertOptions":false,"autoCollapseExpandSubtreeOnAttach":false,"syncDevices":{"device-1610394205907-19995":{"id":"device-1610394205907-19995","name":"Firefox on Linux","icon":"device-desktop","timestamp":1639981655462}}}|913993

It'll eventually catch up, but that takes a while. On my system, a bit less than 1 minute worth of updates is inserted in 1 second (yes, timestamps are less than 1 wall clock minute apart). It obviously wears down the disk considerably.

Environment

• Platform (OS): Gentoo Linux, LightDM display manager, i3 window manager
• Version of Firefox: 91.4.0esr
• Version (or revision) of Tree Style Tab: 3.8.17

I have Sync disabled (about:preferences#sync asks to sign in).

[piroor]

I think this is not a TST specific issue. TST calls storage.sync.set() for keyboard inputs in text fields. (Of course, to reduce too many API calls, they are throttled with 250 msec delay and suppressed for unchanged values.) This is required to save changed configs implicitly without pressing a "Save" button. Thus same "problem" may happen with any other addon using the same method.

[piroor]

And TST is designed to suppress API call of storage.sync.set() for unchanged config values.
https://github.com/piroor/webextensions-lib-configs/blob/e286d7303a02c7b8b7e153cb509170fc41d58481/Configs.js#L205-L247
So it looks odd that sync data with no change except the timestamp are produced: I think it possibly be a bug of Firefox itself.

[piroor]

I've implemented a new secret option syncEnabled: TST Options = Development => All Configs => syncEnabled. TST won't call storage.sync.set() if it is unchecked so it may become more effective workaround with minimized scope.

[piroor]

@WGH- Could you confirm that the reproducibility of this problem with another addon using same sync policy? For example these my addons use same sync policy and their options page contains text input fields:

• https://addons.mozilla.org/firefox/addon/text-link/
• https://addons.mozilla.org/firefox/addon/save-selected-tabs-to-files/
• https://addons.mozilla.org/firefox/addon/second-search/

If you see same problem with these addons, it looks should be tracked at bugzilla.mozilla.org as a problem of WebExtensions API.

[WGH-]

I'm still in process of reproducing it, as it doesn't happen immediately.

In the meantime, some clues:

• I think the more correct term is not "locking desktop session", but rather "VT switching". (in fact, dm-tool lock doesn't actually lock anything, but that's a different story). I've yet to check whether just using Ctl+Alt+F1 is enough to trigger the bug.
• A content process holding TST having occasional 100% CPU spikes when screen is "locked" is a good hint that the bug has happened, and things will get nasty once the VT is switched in.
• I don't have a compositor running (like xcompmgr), which is relatively uncommon configuration. I think all "proper" desktop environments use one.
• Although I said "eventually catch up", it isn't always the case. Sometimes both the main and content process holding TST consume 100% CPU and tens gigabytes of RAM, and Firefox eventually crashes. The screenshot below shows how it looks like. The disk activity still happens.

[github-actions]

This issue has been labeled as "stale" due to no response by the reporter within 1 month (and 7 days after last commented by someone). And it will be closed automatically 14 days later if not responded.

[WGH-]

Reproducing this isn't really that easy as I said in the original report. There must be some other factors. I don't always leave my computer "locked" for a while, so it's taking some time to reproduce.

Additionally, I tried to set a JS debug breakpoint on some of the functions related to config syncing, and I couldn't reproduce it that way even once.

[WGH-]

I have managed to capture a profile when this happened (usually the browser is completely unresponsive when this happens). It's Shift+F5 profile. I'll try to get Firefox Profiler profile next time.

profile.json.gz

[piroor]

Thanks! I've tried to import the performance profile.

It looks that the bottleneck is outside of TST. The Firefox Profiler (it is integrated to Nightly) may help you to collect effective performance profile about this problem.

[WGH-]

I managed to capture full Firefox profile when this happens. https://share.firefox.dev/354uEnu

Not sure if there's really anything useful in it. The process that contains TST is mostly idle, and there's a thread in the main process that's stuck in SQLite.

[irvinm]

@wgh I am sure @piroor will weigh in on this, but given SQLite is used by Firefox for profile storage, I am wondering if something in your SQLite DB is corrupt. One thing I was thinking you could try is to go to "about:support" and go down to the section "Places Database" and click on the "Verify Integrity" button to see if it reports any problems.

[WGH-]

A separate SQLite3 database file is used for the storage.sync though.

And I can't even imagine what kind of database corruption could lead to SQLite3 updates piling up when VT is inactive... The database opens just fine using standalone sqlite3 tool, its schema is plain and simple, there's only a couple of tuples in there.

[github-actions]

This issue has been labeled as "stale" due to no response by the reporter within 1 month (and 7 days after last commented by someone). And it will be closed automatically 14 days later if not responded.

[github-actions]

This issue has been closed due to no response within 14 days after labeled as "stale", 7 days after last reopened, and 7 days after last commented.