Closed Bug 1248389 Opened 5 years ago Closed 5 years ago

Cache index causing CPU loops

Categories

(Core :: Networking: Cache, defect)

Unspecified
Linux
defect
Not set
major

Tracking

()

RESOLVED FIXED
mozilla47
Tracking Status
firefox47 --- fixed

People

(Reporter: mayhemer, Assigned: michal)

References

Details

(Whiteboard: [necko-active])

Attachments

(2 files)

Please see comment and the log at https://bugzilla.mozilla.org/show_bug.cgi?id=1085172#c13

Seems like the index code loops or is just overwhelmed.  In 15 seconds it creates and destroys 330524 CacheIndexEntry objects.

Ulrich, please make backup of the local part of the profile where the cache lives, so we can reproduce/verify fix.  You can find out where it is in about:cache?storage=disk&context=.  It's shown as "Storage disk location".  Thanks.
I think the problem is in eviction, see comment #15 in bug 1085172.

15 seconds needed to read the index might seem a lot, but it's about 90 microseconds per record. On my computer it's around 50 microseconds on debug build, so it's not dramatically different. Anyway we should probably take a look at CacheIndex::ParseRecords() if it can be optimized...
Attached patch fixSplinter Review
Tested locally on cache with 35876 entries. Eviction of 21296 entries went down from 78 seconds to 5 seconds.
Attachment #8719601 - Flags: review?(honzab.moz)
(In reply to Honza Bambas (:mayhemer) from comment #0)
You can find out where it is in about:cache?storage=disk&context=.  It's shown as "Storage disk location". 

What I noticed is that _many_ objects have a size of zero, a fetch count of zero, and no expiration time. Some entries have an expiration time of "1970-01-01 01:00:00". Does that look strange?
Maybe some more comments: First, the high CPU load persists forever it seems (more than 45 minutes, see https://bugzilla.opensuse.org/show_bug.cgi?id=962276#c3). Then I have another strange effect: When reopening a page I had visited before (e.g. this bug) after a restart of Firefox, I see an older version of the page (not the one I had left). I have to reload the page to get an up-to-date version.
Did the cache go below the limit after 45 minutes? What's "Storage in use" value at about:cache?
Summary: HTTP Index causing CPU loops → Cache index causing CPU loops
Whiteboard: [necko-active]
Comment on attachment 8719601 [details] [diff] [review]
fix

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

::: netwerk/cache2/CacheIndex.cpp
@@ +79,5 @@
>      const CacheIndexEntry *entry = FindEntry();
>      mIndex->mIndexStats.BeforeChange(entry);
>      if (entry && entry->IsInitialized() && !entry->IsRemoved()) {
>        mOldRecord = entry->mRec;
> +      mOldFrecency = entry->mRec->mFrecency;

just to understand, mOldRecord's value of mFrecency may change?  Just wondering why not use mOldRecord->mFrecency
Attachment #8719601 - Flags: review?(honzab.moz) → review+
mOldRecord might point to freed memory in CacheIndexEntryAutoManage::~CacheIndexEntryAutoManage()
(In reply to Michal Novotny (:michal) from comment #5)
> Did the cache go below the limit after 45 minutes? What's "Storage in use"
> value at about:cache?

memory
Number of entries: 	0
Maximum storage size: 	29696 KiB
Storage in use: 	0 KiB

disk
Number of entries: 	127044
Maximum storage size: 	262144 KiB
Storage in use: 	385767 KiB
(In reply to Ulrich Windl from comment #8)
> disk
> Number of entries: 	127044
> Maximum storage size: 	262144 KiB
> Storage in use: 	385767 KiB

It would be really helpful to know whether the cache is too slow to evict when it's over the limit, i.e. if it can grow from 256MB to 376MB when you're browsing normally. Or whether you had really big cache then you changed the limit but the cache didn't shrunk to the new limit yet.

If you can, please let the browser running without browsing and just watch from time to time about:cache and wait until "Storage in use" goes under the limit. Alternatively you could delete some cache files manually while the browser is not running. In this case you should delete index file too and wait at least 60 seconds after startup until the index is rebuilt. Then when we're sure the cache is within the limit, browse normally for some time and check whether the cache size goes above the limit. It can go over the limit a little bit when we're actively caching entries, but the eviction code should keep it around that limit.
What I have now is:

memory
Number of entries: 	4
Maximum storage size: 	29696 KiB
Storage in use: 	30 KiB

disk
Number of entries: 	85520
Maximum storage size: 	262144 KiB
Storage in use: 	262054 KiB

appcache
Number of entries: 	0
Maximum storage size: 	512000 KiB
Storage in use: 	0 KiB

So it seems everything is good now, and one can assume the cache cleanup was just terribly slow? The difference between now and then is that I had many more tabs open before I repeatedly restarted Firefox (and at some point in time my "Restore previous session" got lost).
https://hg.mozilla.org/mozilla-central/rev/47eed1e76f6a
Status: NEW → RESOLVED
Closed: 5 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla47
I have a problem much like this. Firefox churns for almost two minutes and consumes 500 - 600 MB of memory at startup. Some web pages I try to load get stuck during that time. Process Monitor says that Firefox is constantly reading and rereading files from cache2. If I delete my entire cache2 folder Firefox starts quickly the next time but the problem comes back later in the day. Is there a workaround while waiting for Firefox 47?
What's you cache size limit and how much disk space the cache actually occupies when you experience this problem? I'm not sure the fix in this bug will help in your case because you're not resizing the cache. See also bug 1249304.
Duplicate of this bug: 1085172
My cache isn't full. I checked the size of the folder to make sure.

disk
Number of entries: 	5713
Maximum storage size: 	358400 KiB
Storage in use: 	70842 KiB
Storage disk location: 	C:\Users\xxxxxxxx\AppData\Local\Mozilla\Firefox\Profiles\tnxyfbbg.default\cache2
It sometimes takes 45 seconds just for about:cache to load.

disk
Number of entries: 	29832
Maximum storage size: 	358400 KiB
Storage in use: 	355474 KiB
Storage disk location: 	C:\Users\xxxxxxxx\AppData\Local\Mozilla\Firefox\Profiles\tnxyfbbg.default\cache2
Does the fix also address this issue (10 time more storage in use as configured, Firefox >100 % CPU):
Number of entries: 	856377
Maximum storage size: 	262144 KiB
Storage in use: 	2568963 KiB
Storage disk location: 	/home/user/.cache/mozilla/firefox/random.default/cache2
Would you please mind testing nightly build? The fix will help you get under the limit quickly. But I don't still understand how the cache can get to such state :-/
(In reply to Michal Novotny (:michal) from comment #19)
> Would you please mind testing nightly build? The fix will help you get under
> the limit quickly. But I don't still understand how the cache can get to
> such state :-/

I got https://archive.mozilla.org/pub/firefox/nightly/latest-mozilla-central/firefox-47.0a1.en-US.linux-x86_64.tar.bz2 and ran it:
It did output a lot of messages related to cache on the terminal. After some seconds I decoded to close it. The some different messages appeared, and at some point the messages ended but the process did not terminate. I tried an strace, and soon after that firefox crashed with segmentation fault...

Here's the strace:
strace -p 17952
Process 17952 attached
futex(0x7f768d0c28e0, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...>
+++ killed by SIGSEGV +++

And here are the last messages:
[Main Thread]: D/cache2 CacheFileChunk::~CacheFileChunk() [this=7f768011fe80]
[Main Thread]: D/cache2 CacheFileChunk::ChunkAllocationChanged() - Normal chunks usage 4608 [this=7f768011fe80]
[Main Thread]: D/cache2 CacheFileChunk::~CacheFileChunk() [this=7f76802ffc80]
[Main Thread]: D/cache2 CacheFileChunk::ChunkAllocationChanged() - Normal chunks usage 512 [this=7f76802ffc80]
[Main Thread]: D/cache2 CacheFileChunk::~CacheFileChunk() [this=7f7680798500]
[Main Thread]: D/cache2 CacheFileChunk::ChunkAllocationChanged() - Normal chunks usage 0 [this=7f7680798500]
[Main Thread]: D/cache2 CacheFileIOManager::Shutdown() [gInstance=0]

Segmentation fault
(I'll try to capture the complete terminal output in a second attempt)
After a few minutes with nightly outputting messages like mad, I still have these about:cache stats:
disk
Number of entries: 	832702
Maximum storage size: 	262144 KiB
Storage in use: 	2503704 KiB

So it seems the cache is slooooowly adjusted. Disk is not the bottleneck, but the output in gnome-terminal and "script" takes a lot of CPU power together with Firefox at the moment.
About 15 minutes later:
Number of entries: 	576210
Maximum storage size: 	262144 KiB
Storage in use: 	1734182 KiB
The cache just stopped reorganizing:

Number of entries: 	85525
Maximum storage size: 	262144 KiB
Storage in use: 	262120 KiB

Last messages on terminal were:
[Cache2 I/O]: D/cache2 CacheIndex::GetCacheSize() - returning 262147
[Cache2 I/O]: D/cache2 CacheFileIOManager::OverLimitEvictionInternal() - Cache size over limit. [cacheSize=262147, limit=262144]
[Cache2 I/O]: D/cache2 CacheIndex::GetEntryForEviction()
[Cache2 I/O]: D/cache2 CacheFileHandles::GetHandle() hash=3fa5c12a00e0c744f3193e3ff80fcdb863703180 no handle entries found
[Cache2 I/O]: D/cache2 CacheIndex::GetEntryForEviction() - returning entry from frecency array [hash=3fa5c12a00e0c744f3193e3ff80fcdb863703180, cnt=85544, frecency=1009784435]
[Cache2 I/O]: D/cache2 CacheFileIOManager::DoomFileByKeyInternal() [hash=3fa5c12a00e0c744f3193e3ff80fcdb863703180]
[Cache2 I/O]: D/cache2 CacheFileHandles::GetHandle() hash=3fa5c12a00e0c744f3193e3ff80fcdb863703180 no handle entries found
[Cache2 I/O]: D/cache2 CacheFileIOManager::DoomFileByKeyInternal() - Removing file from disk
[Cache2 I/O]: D/cache2 CacheIndex::RemoveEntry() [hash=3fa5c12a00e0c744f3193e3ff80fcdb863703180]
[Cache2 I/O]: D/cache2 CacheIndex::RemoveRecordFromFrecencyArray() [record=7fe5b97e8f10]
[Cache2 I/O]: D/cache2 CacheIndex::GetCacheSize()
[Cache2 I/O]: D/cache2 CacheIndex::GetCacheSize() - returning 262144
[Cache2 I/O]: D/cache2 CacheFileIOManager::OverLimitEvictionInternal() - Cache size and free space in limits. [cacheSize=262144kB, cacheSizeLimit=262144kB, freeSpace=177277734912, freeSpaceLimit=5242880]
When I closed Firefox, it got a segmentation fault again. The typescript with the cache operations I have is about 78MB compressed (about 1.3 GB uncompressed). Do you need it?
(In reply to Ulrich Windl from comment #20)
> And here are the last messages:
> [Main Thread]: D/cache2 CacheFileChunk::~CacheFileChunk() [this=7f768011fe80]
> [Main Thread]: D/cache2 CacheFileChunk::ChunkAllocationChanged() - Normal
> chunks usage 4608 [this=7f768011fe80]
> [Main Thread]: D/cache2 CacheFileChunk::~CacheFileChunk() [this=7f76802ffc80]
> [Main Thread]: D/cache2 CacheFileChunk::ChunkAllocationChanged() - Normal
> chunks usage 512 [this=7f76802ffc80]
> [Main Thread]: D/cache2 CacheFileChunk::~CacheFileChunk() [this=7f7680798500]
> [Main Thread]: D/cache2 CacheFileChunk::ChunkAllocationChanged() - Normal
> chunks usage 0 [this=7f7680798500]
> [Main Thread]: D/cache2 CacheFileIOManager::Shutdown() [gInstance=0]
> 
> Segmentation fault
> (I'll try to capture the complete terminal output in a second attempt)

Could you please send report ID of all recent crashes? You'll find them on about:crashes page.


(In reply to Ulrich Windl from comment #21)
> After a few minutes with nightly outputting messages like mad, I still have
> these about:cache stats:
> disk
> Number of entries: 	832702
> Maximum storage size: 	262144 KiB
> Storage in use: 	2503704 KiB
> 
> So it seems the cache is slooooowly adjusted. Disk is not the bottleneck,
> but the output in gnome-terminal and "script" takes a lot of CPU power
> together with Firefox at the moment.

I think logging NSPR to the console might slow the whole process down. Logging to a file would be probably much faster. But I would avoid specifying logfile with NSPR_LOG_FILE, because in case of a crash the last part of the log is not flushed to the file. It's better to redirect output of the process.


(In reply to Ulrich Windl from comment #24)
> When I closed Firefox, it got a segmentation fault again. The typescript
> with the cache operations I have is about 78MB compressed (about 1.3 GB
> uncompressed). Do you need it?

I'd like to have a look at the log. What's exactly in it? Is there whole cache shrinking from 2.5GB to 250MB? Does it include the crash?
(In reply to Michal Novotny (:michal) from comment #25)
[...]
> Could you please send report ID of all recent crashes? You'll find them on
> about:crashes page.

It seems I've disabled sending crash reports some time ago, because I was not sure what information is transmitted (Yes, I care about privacy). The latest crash report is dated "06/25/2015	08:14 AM", so it's not what you are looking for. Sorry.

[...]
> I'd like to have a look at the log. What's exactly in it? Is there whole
> cache shrinking from 2.5GB to 250MB? Does it include the crash?

Yes, the log contains the while Firefox session's output. The information about the crash is exactly what you can see in comment 25 (or comment 20). See the note about futex in comment 20 that may indicate some thread synchronization problem.
I've installed "ltrace" to find out more, but that brings Firefox practically to a halt.
Update: I sent a crash report (bp-b85dcce0-420b-4bd7-8776-c4abb2160302)

From ltrace the last calls before the crash were:
clock_gettime(1, 0x7fa022dfebc0, 0x7fa0262db3a0, 3 <unfinished ...>
pthread_mutex_unlock(0x7fa051c00048, 0x4000000, 0, 26 <unfinished ...>
<... clock_gettime resumed> )                    = 0
clock_gettime(1, 0x7fa022dfebc0, 0x8000000000000000, 0xffffffffff24f779) = 0
pthread_mutex_lock(0x7fa051c00048, 0x7fa022dfebc0, 0x1dd52, 24 <unfinished ...>
<... pthread_mutex_unlock resumed> )             = 0
<... pthread_mutex_unlock resumed> )             = 0
<... pthread_mutex_lock resumed> )               = 0
pthread_mutex_unlock(0x7fa051c00048, 0xfffffe20, 0x7fa016a95000, 5 <unfinished ...>
pthread_mutex_lock(0x7fa051c00048, 0x7fa02a6d8540, 0, 1 <unfinished ...>
<... pthread_mutex_unlock resumed> )             = 0
pthread_mutex_lock(0x7fa051c00048, 0x7fa045920f50, 2, 1 <unfinished ...>
<... pthread_mutex_lock resumed> )               = 0
--- UNKNOWN_SIGNAL (Real-time signal 4) ---
--- SIGSEGV (Segmentation fault) ---
clock_gettime(1, 0x7ffdbd7bb590, 0x7fa0432766f9, 0x7fa043275f96) = 0
ceil(-2.408240)                                  = -2.000000
+++ exited (status 11) +++

Terminal output was this:
[Cache2 I/O]: D/cache2 CacheFileIOManager::OpenNSPRHandle BEGIN, handle=7fa014f80a40
[Cache2 I/O]: D/cache2 CacheFileIOManager::OpenNSPRHandle END, handle=7fa014f80a40
[Cache2 I/O]: D/cache2 CacheFileMetadata::OnDataWritten() [this=7fa01527b300, handle=7fa014f80a40, result=0x00000000]
[Cache2 I/O]: D/cache2 CacheFile::OnMetadataWritten() [this=7fa0179027b0, rv=0x00000000]
[Cache2 I/O]: D/cache2 CacheFile::OnMetadataWritten() - Releasing file handle [this=7fa0179027b0]
[Cache2 I/O]: D/cache2 CacheFileIOManager::ReleaseNSPRHandle() [handle=7fa014f80a40]
[Cache2 I/O]: D/cache2 CacheStorageService::OnMemoryConsumptionChange [consumer=7fa01527b308, size=424]
[Cache2 I/O]: D/cache2 CacheFileHandle::Release() [this=7fa014f80a40, refcnt=4]
[Cache2 I/O]: D/cache2 CacheFileIOManager::ReleaseNSPRHandleInternal() [handle=7fa014f80a40]
[Cache2 I/O]: D/cache2 CacheFileHandle::Release() [this=7fa014f80a40, refcnt=3]
ExceptionHandler::WaitForContinueSignal waiting for continue signal...
ExceptionHandler::GenerateDump cloned child 23460
ExceptionHandler::SendContinueSignalToChild sent continue signal to child
[Child 22643] ###!!! ABORT: Aborting on channel error.: file /builds/slave/m-cen-l64-ntly-000000000000000/build/src/ipc/glue/MessageChannel.cpp, line 1824
[Child 22643] ###!!! ABORT: Aborting on channel error.: file /builds/slave/m-cen-l64-ntly-000000000000000/build/src/ipc/glue/MessageChannel.cpp, line 1824
(In reply to Ulrich Windl from comment #26)
> Yes, the log contains the while Firefox session's output. The information
> about the crash is exactly what you can see in comment 25 (or comment 20).
> See the note about futex in comment 20 that may indicate some thread
> synchronization problem.

The last line just shows that IO manager was already shut down [gInstance=0], so we returned early from CacheFileIOManager::Shutdown() and from CacheObserver::Observe(). I.e. it's definitely not CacheFileIOManager's mutex.
(In reply to Ulrich Windl from comment #27)
> Update: I sent a crash report (bp-b85dcce0-420b-4bd7-8776-c4abb2160302)

Unfortunately, no callstacks are present in this report. Maybe due to ltrace? Anyway, ltrace's output probably wouldn't help us. It's better to have NSPR log together with correct report including callstacks.


> [Cache2 I/O]: D/cache2 CacheFileIOManager::OpenNSPRHandle BEGIN,
> handle=7fa014f80a40
> [Cache2 I/O]: D/cache2 CacheFileIOManager::OpenNSPRHandle END,
> handle=7fa014f80a40
> [Cache2 I/O]: D/cache2 CacheFileMetadata::OnDataWritten()
> [this=7fa01527b300, handle=7fa014f80a40, result=0x00000000]
> [Cache2 I/O]: D/cache2 CacheFile::OnMetadataWritten() [this=7fa0179027b0,
> rv=0x00000000]
> [Cache2 I/O]: D/cache2 CacheFile::OnMetadataWritten() - Releasing file
> handle [this=7fa0179027b0]
> [Cache2 I/O]: D/cache2 CacheFileIOManager::ReleaseNSPRHandle()
> [handle=7fa014f80a40]
> [Cache2 I/O]: D/cache2 CacheStorageService::OnMemoryConsumptionChange
> [consumer=7fa01527b308, size=424]
> [Cache2 I/O]: D/cache2 CacheFileHandle::Release() [this=7fa014f80a40,
> refcnt=4]
> [Cache2 I/O]: D/cache2 CacheFileIOManager::ReleaseNSPRHandleInternal()
> [handle=7fa014f80a40]
> [Cache2 I/O]: D/cache2 CacheFileHandle::Release() [this=7fa014f80a40,
> refcnt=3]

This crash is different from that in comment #20. In comment #20 the Cache IO thread is already shut down. In this crash there is an activity on IO thread. I'd guess that ltrace slowed down the shutdown process and the process was killed by watchdog because the shutdown took too long.
The good thing (for you) is that Firefox crashes every time I end it:
The last message I see is:
[Main Thread]: D/cache2 CacheFileIOManager::Shutdown() [gInstance=0]
Then there are several seconds of no activity (I' watching the disk LED), then I see segmentation fault. This time I have captured a core dump:
/tmp/firefox> file core
core: ELF 64-bit LSB core file x86-64, version 1 (SYSV), too many program header sections (639)
### interesting ;-)
Core was generated by `/tmp/firefox/firefox'.
Program terminated with signal SIGSEGV, Segmentation fault.
#0  0x00007f89ce15d142 in mozilla::(anonymous namespace)::RunWatchdog(void*) () from /tmp/firefox/libxul.so
(gdb) info threads
  Id   Target Id         Frame 
  6    Thread 0x7f89b60f6700 (LWP 25894) 0x00007f89dcd1cc8d in read () from /lib64/libc.so.6
  5    Thread 0x7f89c3126700 (LWP 25876) 0x00007f89ddc9e03f in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
  4    Thread 0x7f89b18ff700 (LWP 25922) 0x00007f89dcd20bbd in poll () from /lib64/libc.so.6
  3    Thread 0x7f89ca82c700 (LWP 25872) 0x00007f89dcd20bbd in poll () from /lib64/libc.so.6
  2    Thread 0x7f89de0aa740 (LWP 25833) 0x00007f89dcd3556b in __lll_lock_wait_private () from /lib64/libc.so.6
* 1    Thread 0x7f89992b5700 (LWP 25960) 0x00007f89ce15d142 in mozilla::(anonymous namespace)::RunWatchdog(void*) () from /tmp/firefox/libxul.so

## So I guess it's not capturing terminal output via script, and not ltrace that causes the problem.
(In reply to Ulrich Windl from comment #30)
> The good thing (for you) is that Firefox crashes every time I end it:
> The last message I see is:
> [Main Thread]: D/cache2 CacheFileIOManager::Shutdown() [gInstance=0]
> Then there are several seconds of no activity (I' watching the disk LED),

This might be some variant of problem introduced by bug 1247432, see https://bugzilla.mozilla.org/show_bug.cgi?id=1251130#c7. I'm working on a fix so let's see if it helps with this crash.

> Program terminated with signal SIGSEGV, Segmentation fault.
> #0  0x00007f89ce15d142 in mozilla::(anonymous namespace)::RunWatchdog(void*)
> () from /tmp/firefox/libxul.so
> (gdb) info threads
>   Id   Target Id         Frame 
>   6    Thread 0x7f89b60f6700 (LWP 25894) 0x00007f89dcd1cc8d in read () from
> /lib64/libc.so.6
>   5    Thread 0x7f89c3126700 (LWP 25876) 0x00007f89ddc9e03f in
> pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
>   4    Thread 0x7f89b18ff700 (LWP 25922) 0x00007f89dcd20bbd in poll () from
> /lib64/libc.so.6
>   3    Thread 0x7f89ca82c700 (LWP 25872) 0x00007f89dcd20bbd in poll () from
> /lib64/libc.so.6
>   2    Thread 0x7f89de0aa740 (LWP 25833) 0x00007f89dcd3556b in
> __lll_lock_wait_private () from /lib64/libc.so.6
> * 1    Thread 0x7f89992b5700 (LWP 25960) 0x00007f89ce15d142 in
> mozilla::(anonymous namespace)::RunWatchdog(void*) () from
> /tmp/firefox/libxul.so

Can you provide backtrace of all threads?

> ## So I guess it's not capturing terminal output via script, and not ltrace
> that causes the problem.

I was talking about crash in comment 27, that one is completely different.
(In reply to Michal Novotny (:michal) from comment #31)
 
> Can you provide backtrace of all threads?

(gdb) bt
#0  0x00007f89ce15d142 in mozilla::(anonymous namespace)::RunWatchdog(void*) () from /tmp/firefox/libxul.so
#1  0x00007f89dc7dbf8f in _pt_root () from /tmp/firefox/libnspr4.so
#2  0x00007f89ddc9a0a4 in start_thread () from /lib64/libpthread.so.0
#3  0x00007f89dcd28fed in clone () from /lib64/libc.so.6
(gdb) thread 2
[Switching to thread 2 (Thread 0x7f89de0aa740 (LWP 25833))]
#0  0x00007f89dcd3556b in __lll_lock_wait_private () from /lib64/libc.so.6
(gdb) bt
#0  0x00007f89dcd3556b in __lll_lock_wait_private () from /lib64/libc.so.6
#1  0x00007f89dccba97b in _L_lock_2631 () from /lib64/libc.so.6
#2  0x00007f89dccb9e75 in __GI__IO_flush_all () from /lib64/libc.so.6
#3  0x00007f89dccb9f5f in _IO_cleanup () from /lib64/libc.so.6
#4  0x00007f89dcc7bacb in __run_exit_handlers () from /lib64/libc.so.6
#5  0x00007f89dcc7bb65 in exit () from /lib64/libc.so.6
#6  0x00007f89dcc65b0c in __libc_start_main () from /lib64/libc.so.6
#7  0x00000000004089b1 in _start ()
(gdb) thread 3
[Switching to thread 3 (Thread 0x7f89ca82c700 (LWP 25872))]
#0  0x00007f89dcd20bbd in poll () from /lib64/libc.so.6
(gdb) bt
#0  0x00007f89dcd20bbd in poll () from /lib64/libc.so.6
#1  0x00007f89d7e31e64 in ?? () from /usr/lib64/libglib-2.0.so.0
#2  0x00007f89d7e3219a in g_main_loop_run () from /usr/lib64/libglib-2.0.so.0
#3  0x00007f89d8427426 in ?? () from /usr/lib64/libgio-2.0.so.0
#4  0x00007f89d7e56f65 in ?? () from /usr/lib64/libglib-2.0.so.0
#5  0x00007f89ddc9a0a4 in start_thread () from /lib64/libpthread.so.0
#6  0x00007f89dcd28fed in clone () from /lib64/libc.so.6
(gdb) thr 4
[Switching to thread 4 (Thread 0x7f89b18ff700 (LWP 25922))]
#0  0x00007f89dcd20bbd in poll () from /lib64/libc.so.6
(gdb) bt
#0  0x00007f89dcd20bbd in poll () from /lib64/libc.so.6
#1  0x00007f89d7e31e64 in ?? () from /usr/lib64/libglib-2.0.so.0
#2  0x00007f89d7e31f7c in g_main_context_iteration () from /usr/lib64/libglib-2.0.so.0
#3  0x00007f89d7e31fb9 in ?? () from /usr/lib64/libglib-2.0.so.0
#4  0x00007f89d7e56f65 in ?? () from /usr/lib64/libglib-2.0.so.0
#5  0x00007f89ddc9a0a4 in start_thread () from /lib64/libpthread.so.0
#6  0x00007f89dcd28fed in clone () from /lib64/libc.so.6
(gdb) thr 5
[Switching to thread 5 (Thread 0x7f89c3126700 (LWP 25876))]
#0  0x00007f89ddc9e03f in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
(gdb) bt
#0  0x00007f89ddc9e03f in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
#1  0x00007f89dc7db783 in PR_WaitCondVar () from /tmp/firefox/libnspr4.so
#2  0x00007f89ccc17846 in WatchdogMain(void*) () from /tmp/firefox/libxul.so
#3  0x00007f89dc7dbf8f in _pt_root () from /tmp/firefox/libnspr4.so
#4  0x00007f89ddc9a0a4 in start_thread () from /lib64/libpthread.so.0
#5  0x00007f89dcd28fed in clone () from /lib64/libc.so.6
(gdb) thr 6
[Switching to thread 6 (Thread 0x7f89b60f6700 (LWP 25894))]
#0  0x00007f89dcd1cc8d in read () from /lib64/libc.so.6
(gdb) bt
#0  0x00007f89dcd1cc8d in read () from /lib64/libc.so.6
#1  0x00007f89dccb8950 in __GI__IO_file_underflow () from /lib64/libc.so.6
#2  0x00007f89dccae3a5 in getdelim () from /lib64/libc.so.6
#3  0x00007f89b60fa3e3 in ?? () from /usr/lib64/libspeechd.so.2
#4  0x00007f89b60fa5f0 in ?? () from /usr/lib64/libspeechd.so.2
#5  0x00007f89ddc9a0a4 in start_thread () from /lib64/libpthread.so.0
#6  0x00007f89dcd28fed in clone () from /lib64/libc.so.6
(gdb)
Ulrich, could you please try to run a build that contains fix from bug 1251130? The fix is not yet available in the latest nightly build, but there are binaries available at http://archive.mozilla.org/pub/firefox/try-builds/mnovotny@mozilla.com-0fbc500589f94b947f392f304c9ae5cb0235a7c4/

Use try-linux (32-bit) or try-linux64 (64-bit). If you can still reproduce the shutdown crash then use try-linux-debug or try-linux64-debug which are debug builds and could provide more useful call stacks.
firefox-47.0a1.en-US.linux-x86_64.tar.bz2 still crashed on exit. Personally I felt the delay between the last message output and the crash was longer than before. I'll try the debug build next.
Amazingly the debug build did not crash on exit, and it seemed to stop more quickly.
You need to log in before you can comment on or make changes to this bug.