1705360 - Crash in [@ shutdownhang | NtFlushBuffersFile]

Status: RESOLVED DUPLICATE of bug 1738984

(Toolkit :: Storage, defect)

Description

[Sebastian Hengst [:aryx] (needinfo me if it's about an intermittent or backout)]

18 crashes on 10+ machines, all with Firefox 89.0a1 on Windows 10, oldest reported build ID is 20210412213434. Increase volume of crash reports from the WER changes (bug 1682516 etc.))? The signature had been around before but with less reports per release cycle.

Crash report: https://crash-stats.mozilla.org/report/index/124f4721-4c03-4d8d-8da3-cb4a80210413

MOZ_CRASH Reason: Shutdown hanging at step profile-before-change. Something is blocking the main-thread.

Top 10 frames of crashing thread:

0 ntdll.dll NtFlushBuffersFile 
1 kernelbase.dll FlushFileBuffers 
2 nss3.dll winSync third_party/sqlite3/src/sqlite3.c:45165
3 nss3.dll sqlite3PagerCommitPhaseOne third_party/sqlite3/src/sqlite3.c:58723
4 nss3.dll sqlite3BtreeCommitPhaseOne third_party/sqlite3/src/sqlite3.c:69003
5 nss3.dll sqlite3VdbeHalt third_party/sqlite3/src/sqlite3.c:81496
6 nss3.dll sqlite3VdbeExec third_party/sqlite3/src/sqlite3.c:89413
7 nss3.dll sqlite3_step third_party/sqlite3/src/sqlite3.c:84388
8 nss3.dll sqlite3_exec third_party/sqlite3/src/sqlite3.c:125282
9 softokn3.dll sdb_init security/nss/lib/softoken/sdb.c:2319

bp-480a24dc-6091-484f-b2a9-296830210415 has one more frame near the start:

ntdll.dll	NtFlushBuffersFile	
xul.dll	`anonymous namespace'::InterposedNtFlushBuffersFile(void*, _IO_STATUS_BLOCK*)	xpcom/build/PoisonIOInterposerWin.cpp:365
kernelbase.dll	FlushFileBuffers	

Comment 1

[Julien Cristau [:jcristau]]

The stacks look like they're mostly from nss/psm. Any idea what's going on here?

Comment 2

[Dana Keeler (she/her) (use needinfo) [:keeler] (on leave)]

I looked at a few of these reports - they all seemed to be of softoken trying to do some sqlite operations. These operations (e.g. opening the database) should be fast (they absolutely should not be taking 10 minutes). One thing I've seen is if another process also has the cert/key databases open, it can make softoken very slow. Unfortunately this is a "supported" "feature" of softoken. Another thing I've heard of is if some antivirus/auditing software is interposing reads/writes, it again can make softoken quite slow. Unless this is a new bug in sqlite, I'm not sure what we can do here.

Comment 3

[Pascal Chevrel:pascalc (PTO until April 26)]

Dana, Benjamin, these are shutdown hangs but their volume have exploded on beta this cycle, is there really nothing happening on our side that we should fix?

Comment 4

[Dana Keeler (she/her) (use needinfo) [:keeler] (on leave)]

Maybe backing out bug 1717559 (and potentially bug 1698592) would help us see if the sqlite upgrade(s) caused this?

Comment 5

[Ryan VanderMeulen [:RyanVM]]

The timing of the spikes doesn't seem to correlate with the SQLite upgrades from what I can see. The 3.35.4 update landed on April 4, but the first tick up in crashes here didn't appear until about a week and a half later. The 3.36.0 update landed on June 22, which again doesn't seem to fit well with the June 10 and July 9 spikes.

Comment 6

[Dana Keeler (she/her) (use needinfo) [:keeler] (on leave)]

Attachment: Bug 1705360 - "hide" NSS DBs from meddling third party software r?jschanck!,bbeurdouche!

Some crash reports appear to be indicating that initializing NSS' certificate
and key databases is taking on the order of minutes in some cases, which is
unexpected. One hypothesis is that third-party software is opening these DBs at
the same time that NSS is operating on them, causing contention and thus
slowness. This patch experimentally (in Nightly only) renames these DBs in the
hopes that third-party software might not recognize them as the DBs it's
looking for, and will thus leave them alone.

Comment 7

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/4b6b66ff77ea
"hide" NSS DBs from meddling third party software r=jschanck,bbeurdouche

Comment 8

[Atila Butkovits]

Backed out for causing failures in test_refresh_firefox.py.

Backout link: https://hg.mozilla.org/integration/autoland/rev/72594a9e5b1f6aa8f494d77661072900d83969c1

Push with failures: https://treeherder.mozilla.org/jobs?repo=autoland&resultStatus=testfailed%2Cbusted%2Cexception%2Cretry%2Cusercancel&revision=4b6b66ff77ea04cd871b46194022ab997db86ad1&selectedTaskRun=UforWD32SMmiePPjkqO12g.0

Failure log: https://treeherder.mozilla.org/logviewer?job_id=353007593&repo=autoland&lineNumber=85782

Comment 9

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/ee866eada1ad
"hide" NSS DBs from meddling third party software r=jschanck,bbeurdouche

Comment 10

[Marian-Vasile Laza]

Backed out changeset ee866eada1ad (Bug 1705360) for causing talos failures.
Backout link
Push with failures - x
Failure Log

Comment 11

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/afd3d1fef036
"hide" NSS DBs from meddling third party software r=jschanck,bbeurdouche,perftest-reviewers,sparky

Comment 12

[Narcis Beleuzu [:NarcisB]]

Backed out for causing Android Btime failures

Backout link: https://hg.mozilla.org/integration/autoland/rev/1a7d94a7a1e6d83d7b8ad4f077683ded4bf1d893
Log link: https://treeherder.mozilla.org/logviewer?job_id=353412164&repo=autoland&lineNumber=2163

Comment 13

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/b5a5e31457dc
"hide" NSS DBs from meddling third party software r=jschanck,bbeurdouche,perftest-reviewers,sparky

Comment 14

[Cristian Tuns]

https://hg.mozilla.org/mozilla-central/rev/b5a5e31457dc

Comment 15

[BugBot [:suhaib / :marco/ :calixte]]

The patch landed in nightly and beta is affected.
:keeler, is this bug important enough to require an uplift?
If not please set status_beta to wontfix.

For more information, please visit auto_nag documentation.

Comment 16

[Dana Keeler (she/her) (use needinfo) [:keeler] (on leave)]

What landed is a Nightly-only experiment to see if it helps address the issue, so this shouldn't be uplifted.

Comment 17

[Dana Keeler (she/her) (use needinfo) [:keeler] (on leave)]

Attachment: Bug 1705360 - un-do nightly experiment obsfucating NSS DB locations r?jschanck

Acording to crash reports, obsfucating the NSS DB locations did not help, so
this patch un-does the changes and un-migrates any migrated DB locations.

Comment 18

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/cc14f4a79aba
un-do nightly experiment obsfucating NSS DB locations r=jschanck,perftest-reviewers,AlexandruIonescu

Comment 19

[Norisz Fay [:noriszfay]]

https://hg.mozilla.org/mozilla-central/rev/cc14f4a79aba

Comment 20

[Jens Stutte [:jstutte]]

(In reply to Dana Keeler (she/her) (use needinfo) (:keeler for reviews) (out of office) from comment #17)

Created attachment 9247361 [details]
Bug 1705360 - un-do nightly experiment obsfucating NSS DB locations r?jschanck

Acording to crash reports, obsfucating the NSS DB locations did not help, so
this patch un-does the changes and un-migrates any migrated DB locations.

So I assume we should re-open this bug ? Or shall we continue work in the new bug 1738984 ?

Comment 21

[Dana Keeler (she/her) (use needinfo) [:keeler] (on leave)]

Yes, I meant to re-open this when I landed the second patch.

Comment 22

[Chris Peterson [:cpeterson]]

Curiously, of the 80,000+ crash reports for NtFlushBuffersFile shutdown hangs over the last six months, only two had Fission enabled, even though Fission has been enabled for about 60% of Nightly, 30% of Beta, and 0.5% of Release 92 during that period.

The Fission crash reports' stack traces don't include sqlite, so they might be unrelated. In that case, zero of 80,000+ crash reports had Fission enabled.

bp-1855ff19-f2a8-46fc-a7a5-e1b750211102
bp-35bdad88-1c7b-4a7d-b03a-59d4b0210924

Comment 23

[Randell Jesup [:jesup] (needinfo me)]

Also, a bunch of other shutdownhang|NtXxxxxx seem to disappear with fission. ~10 of the top 50 crashes in 94 in the last 3 days were Nt shutdownhangs; for the same period with fission (enabled 2 days ago, up to 16 million users today) there are no Nt shutdownhangs.

https://crash-stats.mozilla.org/search/?product=Firefox&version=94&version=94.0.1&date=%3E%3D2021-11-08T18%3A34%3A00.000Z&date=%3C2021-11-11T18%3A34%3A00.000Z&_facets=signature&_sort=-date&_columns=date&_columns=signature&_columns=product&_columns=version&_columns=build_id&_columns=platform#facet-signature

https://crash-stats.mozilla.org/search/?dom_fission_enabled=%21__null__&product=Firefox&version=94&version=94.0.1&date=%3E%3D2021-11-08T18%3A34%3A00.000Z&date=%3C2021-11-11T18%3A34%3A00.000Z&_facets=signature&_sort=-date&_columns=date&_columns=signature&_columns=product&_columns=version&_columns=build_id&_columns=platform#facet-signature

Comment 24

[Dana Keeler (she/her) (use needinfo) [:keeler] (on leave)]

Attachment: Bug 1705360 - only ever attempt to initialize NSS once r?jschanck

Comment 25

[Ryan VanderMeulen [:RyanVM]]

It's looking like the fix for bug 1738984 resolved this. No crash reports in 96.0b3+. Dana, are you good calling this bug fixed by that or are there changes you still want to land in this bug?

Comment 26

[Dana Keeler (she/her) (use needinfo) [:keeler] (on leave)]

Awesome! I don't think we need to make any more changes here.