988464 - Flag threads that aren't shut down before nsThreadManager::Shutdown()

Status: ASSIGNED

(Core :: XPCOM, defect)

Description

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

This is to catch nsThread leaks like the one in bug 986764.  Threads should be shut down in xpcom-shutdown-threads.

However, this may not be always worthwhile (and will cost code just for cleanup), so we could easily mark known-want-to-shutdown-at-threadmanager-shutdown threads so they don't get flagged and just ::Shutdown().

Comment 1

[Benjamin Smedberg]

It's an API contract that client code must shut down all threads by the time xpcom-shutdown-threads finishes, so all of that code ought to exist already.

Comment 2

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

Attachment: log nsThreads still active at nsThreadManager::Shutdown()

Note: some threads with ShutdownNeeded() == false have PRThread pointers that go to freed memory!

Comment 3

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

https://tbpl.mozilla.org/?tree=Try&rev=8ac1c136a95f
For some reason I wasn't getting notices on Try runs with nsThread:3 in automation.py.in, though local mochitest runs do show it.  So I added an printf() for good measure.

Comment 4

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

Attachment: log nsThreads still active at nsThreadManager::Shutdown()

Comment 5

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

Attachment: Shut down MediaManager thread in xpcom-shutdown

shuts down MediaThread in xpcom-shutdown (which is before xpcom-shutdown-threads....).  Perhaps we should shut it down later in xpcom-shutdown-threads.  Also it appeared there were several extant refs to MediaManager itself

Comment 6

[(not currently active) Ted Mielczarek]

Note: automation.py is no longer used in Mochitest.

Comment 7

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

Attachment: log nsThreads still active at nsThreadManager::Shutdown()

Comment 8

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

Attachment: log nsThreads still active at nsThreadManager::Shutdown()

Comment 9

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

Comment on attachment 8398015 [details] [diff] [review]
log nsThreads still active at nsThreadManager::Shutdown()

I can remove automation.py.in if we're not using it anymore (seemed to be used for a local ./mach mochitest-plain)

Comment 10

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

Attachment: log nsThreads still active at nsThreadManager::Shutdown()

I think we need to lock around the PRThread access

Comment 11

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

https://tbpl.mozilla.org/?tree=Try&rev=e26f103ed199
(with a previous patch)

Comment 12

[(not currently active) Ted Mielczarek]

(In reply to Randell Jesup [:jesup] from comment #9)
> I can remove automation.py.in if we're not using it anymore (seemed to be
> used for a local ./mach mochitest-plain)

We're not using it for mochitest, it's still being used for reftest. It should not be used in a local mochitest run, I'm not sure where you're seeing that.

Comment 13

[Benjamin Smedberg]

Comment on attachment 8398041 [details] [diff] [review]
log nsThreads still active at nsThreadManager::Shutdown()

Why is the top part #ifdef PR_LOGGING but the lower part #ifdef DEBUG?

Is this code so performance-critical that we couldn't use PR logging in all builds and use PR_LOG_TEST to guard whether we enter those logging loops?

Comment 14

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

(In reply to Benjamin Smedberg  [:bsmedberg] from comment #13)
> Comment on attachment 8398041 [details] [diff] [review]
> log nsThreads still active at nsThreadManager::Shutdown()
> 
> Why is the top part #ifdef PR_LOGGING but the lower part #ifdef DEBUG?

History of how I wrote it; originally it was leeching off nsThread's logs.  It should be PR_LOGGING I think

> Is this code so performance-critical that we couldn't use PR logging in all
> builds and use PR_LOG_TEST to guard whether we enter those logging loops?

It's not perf-critical, and only does two PR_Log() calls anyways in shutdown.  (Partly I was initially cautious about letting this code run in opt/release builds because I know half-shut-down is a tricky state.)  And there should be few or no threads here anyways.)  We can use PR_LOG_TEST, but I don't think it's important here.

Comment 15

[Benjamin Smedberg]

Comment on attachment 8398041 [details] [diff] [review]
log nsThreads still active at nsThreadManager::Shutdown()

ok r=me with #ifdef PR_LOGGING instead of DEBUG

Comment 16

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

Attachment: log nsThreads still active at nsThreadManager::Shutdown()

unbitrot

Comment 17

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

Comment on attachment 8457444 [details] [diff] [review]
log nsThreads still active at nsThreadManager::Shutdown()

Corry r+ forward

Comment 18

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

https://hg.mozilla.org/integration/mozilla-inbound/rev/3325b46334d9

Comment 19

[Carsten Book [:Tomcat]]

sorry had to back out this changes, seems this caused xpcshell test failures like 

https://tbpl.mozilla.org/php/getParsedLog.php?id=43999486&tree=Mozilla-Inbound

TEST-UNEXPECTED-FAIL | /builds/slave/talos-slave/test/build/tests/xpcshell/tests/toolkit/modules/tests/xpcshell/test_sqlite.js | test failed (with xpcshell return code: 1), see following log:
PROCESS-CRASH | /builds/slave/talos-slave/test/build/tests/xpcshell/tests/toolkit/modules/tests/xpcshell/test_sqlite.js | application crashed [@ 0x7fff82857c00]


Operating system: Mac OS X
23:48:35     INFO -                    10.6.8 10K549
23:48:35     INFO -  CPU: amd64
23:48:35     INFO -       family 6 model 23 stepping 10
23:48:35     INFO -       2 CPUs
23:48:35     INFO -  Crash reason:  EXC_BAD_ACCESS / 0x0000000d
23:48:35     INFO -  Crash address: 0x0
23:48:35     INFO -  Thread 0 (crashed)
23:48:35     INFO -   0  0x7fff82857c00
23:48:35     INFO -      rbx = 0x0000000000000008   r12 = 0x0000000000000002
23:48:35     INFO -      r13 = 0x74537a6f6d206461   r14 = 0x74537a6f6d206461
23:48:35     INFO -      r15 = 0x00007fff829a5da4   rip = 0x00007fff82857c00
23:48:35     INFO -      rsp = 0x00007fff5fbfd228   rbp = 0x00007fff5fbfd250
23:48:35     INFO -      Found by: given as instruction pointer in context
23:48:35     INFO -  Thread 1
23:48:35     INFO -   0  0x7fff8286dc0a
23:48:35     INFO -      rbx = 0x0000000106280e50   r12 = 0x00007fff7037a998
23:48:35     INFO -      r13 = 0x00007fff7037ad68   r14 = 0xffffffffffffffff
23:48:35     INFO -      r15 = 0x00007fff7037ada8   rip = 0x00007fff8286dc0a
23:48:35     INFO -      rsp = 0x0000000106280ce8   rbp = 0x0000000106280e90
23:48:35     INFO -      Found by: given as instruction pointer in context
23:48:35     INFO -  Thread 2
23:48:35     INFO -   0  0x7fff8286ea2a
23:48:35     INFO -      rbx = 0x0000000106704000   r12 = 0x00000001061593c0
23:48:35     INFO -      r13 = 0x0000000106165000   r14 = 0x0000000106704000
23:48:35     INFO -      r15 = 0x0000000000000000   rip = 0x00007fff8286ea2a
23:48:35     INFO -      rsp = 0x0000000106703f28   rbp = 0x0000000106703f50
23:48:35     INFO -      Found by: given as instruction pointer in context
23:48:35     INFO -  Thread 3
23:48:35     INFO -   0  0x7fff8286dc0a
23:48:35     INFO -      rbx = 0x0000000106147490   r12 = 0x0000000106127000
23:48:35     INFO -      r13 = 0x0000000106126800   r14 = 0x0000000106147490
23:48:35     INFO -      r15 = 0x0000000000000001   rip = 0x00007fff8286dc0a
23:48:35     INFO -      rsp = 0x0000000107280ac8   rbp = 0x0000000107280b30
23:48:35     INFO -      Found by: given as instruction pointer in context
23:48:35     INFO -  Thread 4
23:48:35     INFO -   0  0x7fff8288fa6a
23:48:35     INFO -      rbx = 0x0000000107f81000   r12 = 0x0000000106117308

Comment 20

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

I should dig out the cause and re-land this

Comment 21

[Ben Turner (not reading bugmail, use the needinfo flag!)]

We need to get this landed again. We're leaking threads in async storage and we didn't notice...

Comment 22

[Andrew McCreight [:mccr8]]

Attachment: log nsThreads still active at nsThreadManager::Shutdown()

Minor unbitrotting of jesup's patch.

Comment 23

[Andrew McCreight [:mccr8]]

That sql XPCshell test still fails.  Locally, the log contains a bunch of lines that look like this:

0:04.76 LOG: Thread-1 INFO "CONSOLE_MESSAGE: (warn) [JavaScript Error: "Warning: Sqlite connection 'gc_99.sqlite#0' was not properly closed. Auto-close triggered by garbage collection.
" {file: "resource://gre/modules/Sqlite.jsm" line: 67}]"

The OSX crash report says that there's a stack overflow, though I'm not sure in what.

Comment 24

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

FYI, this is the bug we were discussing at Whistler

Comment 25

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

Attachment: log nsThreads still active at nsThreadManager::Shutdown()

Simplified version of the patch, which simply NS_ASSERTION()s on any leaked nsThread.  Note that simple tests (load Youtube, quit (linux)) show 2 leaked threads: Image Scaler, and FileBlockCache (which helpfully doesn't set the threadname; I'll file a bug on that).  We likely won't want to land this without fixing those.  Note that GDB shows that FileBlockCache::Close() isn't even being called in my test.

Comment 26

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

cpearce, bholley - note comment 25 about FileBlockCache leaking

Comment 27

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

https://treeherder.mozilla.org/#/jobs?repo=try&revision=c2a8c5cf4b35

Mostly green; several C++ unit tests and XPCShell tests don't bother to shut down some of their threads.  Interesting that in mochitests, timing works out that Image Scaler and FileBlockCache get shut down (albeit with a sample size of only 1 run), while running a local linux64 debug build they fail always when closing a window after a simple test of Youtube.  I can't say I'm surprised at some of our thread shutdowns having timing races, though - one of the bugs that poked me to push this forward again has a strongly implied timing-caused thread leak.  Wouldn't be shocked if turning this on exposed a handful of intermittents in automation.

Right now it just uses NS_ASSERTION; we could make it log in opt builds (though I'd prefer something that caused orange/red on treeherder; perhaps use some env var to react more harshly if we're in a mochitest).  MOZ_CRASH would seem overkill however.

Comment 28

[Nathan Froyd [:froydnj]]

Comment on attachment 8649759 [details] [diff] [review]
log nsThreads still active at nsThreadManager::Shutdown()

Review of attachment 8649759 [details] [diff] [review]:
-----------------------------------------------------------------

r=me with changes below.

::: xpcom/threads/nsThread.h
@@ +173,5 @@
>      }
>    };
>  
> +  // This lock protects access to mObserver, mEvents and mEventsAreDoomed
> +  // and mShutdownRequired.  All of those fields (except mShutdownRequired)

Nit: this should now read "...mEvents, mEventsAreDoomed, and mShutdownRequired"  Feel free to rewrap the comment if necessary.

::: xpcom/threads/nsThreadManager.cpp
@@ +3,5 @@
>  /* This Source Code Form is subject to the terms of the Mozilla Public
>   * License, v. 2.0. If a copy of the MPL was not distributed with this
>   * file, You can obtain one at http://mozilla.org/MPL/2.0/. */
>  
> +#include "prprf.h"

Can we just use mozilla/Snprintf.h and use snprintf_literal directly below?  Best to avoid introducing more NSPR-isms.

Comment 29

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

(In reply to Nathan Froyd [:froydnj][:nfroyd] from comment #28)
> Can we just use mozilla/Snprintf.h and use snprintf_literal directly below? 
> Best to avoid introducing more NSPR-isms.

Sure!  I hadn't noticed that had landed; good!

Comment 30

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

https://treeherder.mozilla.org/#/jobs?repo=try&revision=3dc899f68172 with the fix for bug 1271402 (in review) and bug 1270575 (landed)

Comment 31

[Worcester12345]

"PERF" key word?