Closed Bug 341384 Opened 18 years ago Closed 18 years ago

Storage very slow / hanging on shutdown

Categories

(Toolkit :: Storage, defect)

Product:
Toolkit
Component:
Storage
Platform:
x86
Linux
Type:
defect
Priority:
Not set
Severity:
major

Tracking

()

Status:
RESOLVED WORKSFORME

People

(Reporter: sayrer, Assigned: vlad)

References

Details

I'm running Ubuntu 6.06 on AMD64. mozStorage::FinishAsyncIO is very slow on shutdown, and sometimes seems to hang. Sometimes it takes 5-10 seconds, but I've let it go 30 seconds or so on a couple of occasions. Haven't caught it in a debugger in those cases.
Are you on a networked file system or anything like that? Do you have it set to clear your history when you shut down?
(In reply to comment #1)
> Are you on a networked file system or anything like that?

No.

> Do you have it set to clear your history when you shut down?

I don't believe so (the box is not in front of me, but it was a fresh OS install, and a trunk check out with no profile adjustments).
Severity: normal → major
Flags: blocking1.9a1?
Version: unspecified → Trunk
This regressed between 2006-05-10 04:00 and 2006-05-12 12:00.

http://bonsai.mozilla.org/cvsquery.cgi?treeid=default&module=PhoenixTinderbox&branch=HEAD&branchtype=match&dir=&file=&filetype=match&who=&whotype=match&sortby=Date&hours=2&date=explicit&mindate=2006-05-10+04&maxdate=2006-05-12+12&cvsroot=%2Fcvsroot

I'm guessing it was the thread manager landing since it touched the function Robert mentioned in mozStorageAsyncIO.

Hopefully Darin will know what's going on here.
I'm not sure what's going on exactly, but I suspect that the fix would be isolated to the storage component.  FinishAsyncIO should terminate.
#0  0x00002aaaadab1e22 in poll () from /lib/libc.so.6
#1  0x00002aaaad168d00 in g_main_context_check () from /usr/lib/libglib-2.0.so.0
#2  0x00002aaaad169374 in g_main_context_iteration () from /usr/lib/libglib-2.0.so.0
#3  0x00002aaaafd20396 in nsAppShell::ProcessNextNativeEvent (this=<value optimized out>, mayWait=7)
    at /home/sayrer/firefox/mozilla/widget/src/gtk2/nsAppShell.cpp:144
#4  0x00002aaaafd36c68 in nsBaseAppShell::DoProcessNextNativeEvent (this=0x6f0370, mayWait=7)
    at /home/sayrer/firefox/mozilla/widget/src/xpwidgets/nsBaseAppShell.cpp:136
#5  0x00002aaaafd36f47 in nsBaseAppShell::OnProcessNextEvent (this=0x5f5040, thr=0x554590, mayWait=0,
    recursionDepth=<value optimized out>) at /home/sayrer/firefox/mozilla/widget/src/xpwidgets/nsBaseAppShell.cpp:231
#6  0x00002aaaab30af32 in nsThread::ProcessNextEvent (this=0x554590, mayWait=1, result=0x7fffffe3ba9c)
    at /home/sayrer/firefox/mozilla/xpcom/threads/nsThread.cpp:469
#7  0x00002aaaab2b3469 in NS_ProcessNextEvent_P (thread=0x6f0370, mayWait=1) at nsThreadUtils.cpp:225
#8  0x00002aaaab30b458 in nsThread::Shutdown (this=0xd37a90) at /home/sayrer/firefox/mozilla/xpcom/threads/nsThread.cpp:442
#9  0x00002aaaaf1924d8 in mozStorageService::FinishAsyncIO (this=<value optimized out>)
    at /home/sayrer/firefox/mozilla/storage/src/mozStorageAsyncIO.cpp:557
#10 0x00002aaaaf1943bd in mozStorageService::Observe (this=0xd37930, aSubject=<value optimized out>,
    aTopic=<value optimized out>, aData=<value optimized out>)
    at /home/sayrer/firefox/mozilla/storage/src/mozStorageService.cpp:160
#11 0x00002aaaab2c2d40 in nsObserverList::NotifyObservers (this=0x8ffd20, aSubject=0x0,
    aTopic=0x2aaaab33caab "xpcom-shutdown-threads", someData=0x0) at /home/sayrer/firefox/mozilla/xpcom/ds/nsObserverList.cpp:128
#12 0x00002aaaab2c3e07 in nsObserverService::NotifyObservers (this=<value optimized out>, aSubject=0x0,
    aTopic=0x2aaaab33caab "xpcom-shutdown-threads", someData=0x0)
    at /home/sayrer/firefox/mozilla/xpcom/ds/nsObserverService.cpp:174
#13 0x00002aaaab2b72cf in NS_ShutdownXPCOM_P (servMgr=0x570a18) at /home/sayrer/firefox/mozilla/xpcom/build/nsXPComInit.cpp:720
#14 0x00002aaaaace3252 in ~ScopedXPCOMStartup (this=0x7fffffe3bec0)
    at /home/sayrer/firefox/mozilla/toolkit/xre/nsAppRunner.cpp:553
#15 0x00002aaaaace8575 in XRE_main (argc=<value optimized out>, argv=<value optimized out>, aAppData=<value optimized out>)
    at /home/sayrer/firefox/mozilla/toolkit/xre/nsAppRunner.cpp:2384
#16 0x0000000000400788 in main (argc=7275376, argv=0x7) at /home/sayrer/firefox/mozilla/browser/app/nsBrowserApp.cpp:61

I had the location of the hang wrong in IRC, it's here:

http://lxr.mozilla.org/seamonkey/source/storage/src/mozStorageAsyncIO.cpp#551

The hang happens before AsyncWriteThread::Run() gets a chance to execute.
> The hang happens before AsyncWriteThread::Run() gets a chance to execute.

Very interesting.  That's confusing because the stack makes it look like AsyncWriteThread::Run is refusing to exit.
bt from all the threads


Thread 24 (Thread 1140881760 (LWP 21985)):
#0  0x00002aaaaabcac8f in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib/libpthread.so.0
#1  0x00002aaaab6bf5fd in pt_TimedWait (cv=0xbc20d8, ml=0xbc2128, timeout=0) at /home/sayrer/firefox/mozilla/nsprpub/pr/src/pthreads/ptsynch.c:280
#2  0x00002aaaab6bfd93 in PR_WaitCondVar (cvar=0xbc20d0, timeout=60000) at /home/sayrer/firefox/mozilla/nsprpub/pr/src/pthreads/ptsynch.c:407
#3  0x00002aaaab6c048d in PR_Wait (mon=0xbc2120, timeout=60000) at /home/sayrer/firefox/mozilla/nsprpub/pr/src/pthreads/ptsynch.c:584
#4  0x00002aaaab2e4645 in nsAutoMonitor::Wait (this=<value optimized out>, interval=1140881760) at nsAutoLock.h:286
#5  0x00002aaaab30e719 in nsThreadPool::Run (this=0xbc2060) at /home/sayrer/firefox/mozilla/xpcom/threads/nsThreadPool.cpp:200
#6  0x00002aaaab30afea in nsThread::ProcessNextEvent (this=0x27a5b60, mayWait=1, result=0x4400716c) at /home/sayrer/firefox/mozilla/xpcom/threads/nsThread.cpp:482
#7  0x00002aaaab2b3469 in NS_ProcessNextEvent_P (thread=0xbc20dc, mayWait=1) at nsThreadUtils.cpp:225
#8  0x00002aaaab30b14f in nsThread::ThreadFunc (arg=<value optimized out>) at /home/sayrer/firefox/mozilla/xpcom/threads/nsThread.cpp:251
#9  0x00002aaaab6c5c24 in _pt_root (arg=<value optimized out>) at /home/sayrer/firefox/mozilla/nsprpub/pr/src/pthreads/ptthread.c:220
#10 0x00002aaaaabc80fa in start_thread () from /lib/libpthread.so.0
#11 0x00002aaaadabace2 in clone () from /lib/libc.so.6
#12 0x0000000000000000 in ?? ()

Thread 18 (Thread 1140881760 (LWP 21985)):
#0  0x00002aaaaabcac8f in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib/libpthread.so.0
#1  0x00002aaaab6bf5fd in pt_TimedWait (cv=0xbc20d8, ml=0xbc2128, timeout=0) at /home/sayrer/firefox/mozilla/nsprpub/pr/src/pthreads/ptsynch.c:280
#2  0x00002aaaab6bfd93 in PR_WaitCondVar (cvar=0xbc20d0, timeout=60000) at /home/sayrer/firefox/mozilla/nsprpub/pr/src/pthreads/ptsynch.c:407
#3  0x00002aaaab6c048d in PR_Wait (mon=0xbc2120, timeout=60000) at /home/sayrer/firefox/mozilla/nsprpub/pr/src/pthreads/ptsynch.c:584
#4  0x00002aaaab2e4645 in nsAutoMonitor::Wait (this=<value optimized out>, interval=1140881760) at nsAutoLock.h:286
#5  0x00002aaaab30e719 in nsThreadPool::Run (this=0xbc2060) at /home/sayrer/firefox/mozilla/xpcom/threads/nsThreadPool.cpp:200
#6  0x00002aaaab30afea in nsThread::ProcessNextEvent (this=0x27a5b60, mayWait=1, result=0x4400716c) at /home/sayrer/firefox/mozilla/xpcom/threads/nsThread.cpp:482
#7  0x00002aaaab2b3469 in NS_ProcessNextEvent_P (thread=0xbc20dc, mayWait=1) at nsThreadUtils.cpp:225
#8  0x00002aaaab30b14f in nsThread::ThreadFunc (arg=<value optimized out>) at /home/sayrer/firefox/mozilla/xpcom/threads/nsThread.cpp:251
#9  0x00002aaaab6c5c24 in _pt_root (arg=<value optimized out>) at /home/sayrer/firefox/mozilla/nsprpub/pr/src/pthreads/ptthread.c:220
#10 0x00002aaaaabc80fa in start_thread () from /lib/libpthread.so.0
#11 0x00002aaaadabace2 in clone () from /lib/libc.so.6
#12 0x0000000000000000 in ?? ()

Thread 9 (Thread 1107310944 (LWP 21962)):
#0  0x00002aaaaabcd9cb in __fsync_nocancel () from /lib/libpthread.so.0
#1  0x00002aaaaf995aca in full_fsync (fd=46, fullSync=0, dataOnly=2) at /home/sayrer/firefox/mozilla/db/sqlite3/src/os_unix.c:1075
#2  0x00002aaaaf995ae5 in unixSync (id=<value optimized out>, dataOnly=0) at /home/sayrer/firefox/mozilla/db/sqlite3/src/os_unix.c:1103
#3  0x00002aaaaf971d69 in ProcessOneMessage (aMessage=0x29fa860) at /home/sayrer/firefox/mozilla/storage/src/mozStorageAsyncIO.cpp:1317
#4  0x00002aaaaf972097 in ProcessAsyncMessages () at /home/sayrer/firefox/mozilla/storage/src/mozStorageAsyncIO.cpp:1430
#5  0x00002aaaaf972db8 in AsyncWriteThread::Run (this=0xf72440) at /home/sayrer/firefox/mozilla/storage/src/mozStorageAsyncIO.cpp:447
#6  0x00002aaaab30afea in nsThread::ProcessNextEvent (this=0xf63ad0, mayWait=1, result=0x4200316c) at /home/sayrer/firefox/mozilla/xpcom/threads/nsThread.cpp:482
#7  0x00002aaaab2b3469 in NS_ProcessNextEvent_P (thread=0x2e, mayWait=1) at nsThreadUtils.cpp:225
#8  0x00002aaaab30b14f in nsThread::ThreadFunc (arg=<value optimized out>) at /home/sayrer/firefox/mozilla/xpcom/threads/nsThread.cpp:251
#9  0x00002aaaab6c5c24 in _pt_root (arg=<value optimized out>) at /home/sayrer/firefox/mozilla/nsprpub/pr/src/pthreads/ptthread.c:220
#10 0x00002aaaaabc80fa in start_thread () from /lib/libpthread.so.0
#11 0x00002aaaadabace2 in clone () from /lib/libc.so.6
#12 0x0000000000000000 in ?? ()

Thread 6 (Thread 1107310944 (LWP 21962)):
#0  0x00002aaaaabcd9cb in __fsync_nocancel () from /lib/libpthread.so.0
#1  0x00002aaaaf995aca in full_fsync (fd=46, fullSync=0, dataOnly=2) at /home/sayrer/firefox/mozilla/db/sqlite3/src/os_unix.c:1075
#2  0x00002aaaaf995ae5 in unixSync (id=<value optimized out>, dataOnly=0) at /home/sayrer/firefox/mozilla/db/sqlite3/src/os_unix.c:1103
---Type <return> to continue, or q <return> to quit---
#3  0x00002aaaaf971d69 in ProcessOneMessage (aMessage=0x29fa860) at /home/sayrer/firefox/mozilla/storage/src/mozStorageAsyncIO.cpp:1317
#4  0x00002aaaaf972097 in ProcessAsyncMessages () at /home/sayrer/firefox/mozilla/storage/src/mozStorageAsyncIO.cpp:1430
#5  0x00002aaaaf972db8 in AsyncWriteThread::Run (this=0xf72440) at /home/sayrer/firefox/mozilla/storage/src/mozStorageAsyncIO.cpp:447
#6  0x00002aaaab30afea in nsThread::ProcessNextEvent (this=0xf63ad0, mayWait=1, result=0x4200316c) at /home/sayrer/firefox/mozilla/xpcom/threads/nsThread.cpp:482
#7  0x00002aaaab2b3469 in NS_ProcessNextEvent_P (thread=0x2e, mayWait=1) at nsThreadUtils.cpp:225
#8  0x00002aaaab30b14f in nsThread::ThreadFunc (arg=<value optimized out>) at /home/sayrer/firefox/mozilla/xpcom/threads/nsThread.cpp:251
#9  0x00002aaaab6c5c24 in _pt_root (arg=<value optimized out>) at /home/sayrer/firefox/mozilla/nsprpub/pr/src/pthreads/ptthread.c:220
#10 0x00002aaaaabc80fa in start_thread () from /lib/libpthread.so.0
#11 0x00002aaaadabace2 in clone () from /lib/libc.so.6
#12 0x0000000000000000 in ?? ()

Thread 3 (Thread 1090525536 (LWP 21956)):
#0  0x00002aaaaabcac8f in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib/libpthread.so.0
#1  0x00002aaaab6bf5fd in pt_TimedWait (cv=0x5546f8, ml=0x565b40, timeout=951) at /home/sayrer/firefox/mozilla/nsprpub/pr/src/pthreads/ptsynch.c:280
#2  0x00002aaaab6bfd93 in PR_WaitCondVar (cvar=0x5546f0, timeout=869951) at /home/sayrer/firefox/mozilla/nsprpub/pr/src/pthreads/ptsynch.c:407
#3  0x00002aaaab31075e in TimerThread::Run (this=0x565a50) at /home/sayrer/firefox/mozilla/xpcom/threads/TimerThread.cpp:321
#4  0x00002aaaab30afea in nsThread::ProcessNextEvent (this=0x6a10a0, mayWait=1, result=0x4100116c) at /home/sayrer/firefox/mozilla/xpcom/threads/nsThread.cpp:482
#5  0x00002aaaab2b3469 in NS_ProcessNextEvent_P (thread=0x5546fc, mayWait=1) at nsThreadUtils.cpp:225
#6  0x00002aaaab30b14f in nsThread::ThreadFunc (arg=<value optimized out>) at /home/sayrer/firefox/mozilla/xpcom/threads/nsThread.cpp:251
#7  0x00002aaaab6c5c24 in _pt_root (arg=<value optimized out>) at /home/sayrer/firefox/mozilla/nsprpub/pr/src/pthreads/ptthread.c:220
#8  0x00002aaaaabc80fa in start_thread () from /lib/libpthread.so.0
#9  0x00002aaaadabace2 in clone () from /lib/libc.so.6
#10 0x0000000000000000 in ?? ()

Thread 1 (Thread 46912559762448 (LWP 21949)):
#0  0x00002aaaaabcd19f in __read_nocancel () from /lib/libpthread.so.0
#1  0x00002aaab098c08a in nsAppShell::EventProcessorCallback (source=<value optimized out>, condition=<value optimized out>, data=<value optimized out>)
    at /home/sayrer/firefox/mozilla/widget/src/gtk2/nsAppShell.cpp:66
#2  0x00002aaaad165bfd in g_main_context_dispatch () from /usr/lib/libglib-2.0.so.0
#3  0x00002aaaad168ec5 in g_main_context_check () from /usr/lib/libglib-2.0.so.0
#4  0x00002aaaad169374 in g_main_context_iteration () from /usr/lib/libglib-2.0.so.0
#5  0x00002aaab098c396 in nsAppShell::ProcessNextNativeEvent (this=<value optimized out>, mayWait=-4240273) at /home/sayrer/firefox/mozilla/widget/src/gtk2/nsAppShell.cpp:144
#6  0x00002aaab09a2c68 in nsBaseAppShell::DoProcessNextNativeEvent (this=0xc, mayWait=-4240273) at /home/sayrer/firefox/mozilla/widget/src/xpwidgets/nsBaseAppShell.cpp:136
#7  0x00002aaab09a2ee9 in nsBaseAppShell::OnProcessNextEvent (this=0x578850, thr=0x554590, mayWait=1, recursionDepth=<value optimized out>)
    at /home/sayrer/firefox/mozilla/widget/src/xpwidgets/nsBaseAppShell.cpp:209
#8  0x00002aaaab30af32 in nsThread::ProcessNextEvent (this=0x554590, mayWait=1, result=0x7fffffbf4e3c) at /home/sayrer/firefox/mozilla/xpcom/threads/nsThread.cpp:469
#9  0x00002aaaab2b3469 in NS_ProcessNextEvent_P (thread=0xc, mayWait=1) at nsThreadUtils.cpp:225
#10 0x00002aaaab30b458 in nsThread::Shutdown (this=0xf63ad0) at /home/sayrer/firefox/mozilla/xpcom/threads/nsThread.cpp:442
#11 0x00002aaaaf9714d8 in mozStorageService::FinishAsyncIO (this=<value optimized out>) at /home/sayrer/firefox/mozilla/storage/src/mozStorageAsyncIO.cpp:557
#12 0x00002aaaaf9733bd in mozStorageService::Observe (this=0xf73020, aSubject=<value optimized out>, aTopic=<value optimized out>, aData=<value optimized out>)
    at /home/sayrer/firefox/mozilla/storage/src/mozStorageService.cpp:160
#13 0x00002aaaab2c2d40 in nsObserverList::NotifyObservers (this=0xbc4860, aSubject=0x0, aTopic=0x2aaaab33caab "xpcom-shutdown-threads", someData=0x0)
    at /home/sayrer/firefox/mozilla/xpcom/ds/nsObserverList.cpp:128
#14 0x00002aaaab2c3e07 in nsObserverService::NotifyObservers (this=<value optimized out>, aSubject=0x0, aTopic=0x2aaaab33caab "xpcom-shutdown-threads", someData=0x0)
    at /home/sayrer/firefox/mozilla/xpcom/ds/nsObserverService.cpp:174
#15 0x00002aaaab2b72cf in NS_ShutdownXPCOM_P (servMgr=0x570a18) at /home/sayrer/firefox/mozilla/xpcom/build/nsXPComInit.cpp:720
#16 0x00002aaaaace3252 in ~ScopedXPCOMStartup (this=0x7fffffbf5260) at /home/sayrer/firefox/mozilla/toolkit/xre/nsAppRunner.cpp:553
#17 0x00002aaaaace8575 in XRE_main (argc=<value optimized out>, argv=<value optimized out>, aAppData=<value optimized out>)
    at /home/sayrer/firefox/mozilla/toolkit/xre/nsAppRunner.cpp:2384
#18 0x0000000000400788 in main (argc=12, argv=0x7fffffbf4c6f) at /home/sayrer/firefox/mozilla/browser/app/nsBrowserApp.cpp:61
(gdb)

(In reply to comment #7)
> > The hang happens before AsyncWriteThread::Run() gets a chance to execute.
> 

I must be wrong about that...

> Very interesting.  That's confusing because the stack makes it look like
> AsyncWriteThread::Run is refusing to exit.
> 

One way to fix the problem is to change the line here:

http://lxr.mozilla.org/seamonkey/source/storage/src/mozStorageAsyncIO.cpp#1450

Currently it's

1449       // yield so the UI thread is more responsive
1450       PR_Sleep(PR_INTERVAL_NO_WAIT);

The lockup goes away with this:

1450       PR_Sleep(PR_MillisecondsToInterval(1));

I find it somewhat alarming that AsyncWriteThread::Run is being called on more than one thread.  I thought I recall Brett saying that this async flushing business does not work from multiple threads.
(In reply to comment #10)
> I find it somewhat alarming that AsyncWriteThread::Run is being called on more
> than one thread.  I thought I recall Brett saying that this async flushing
> business does not work from multiple threads.

Yes, I noticed that as well -- all the async IO setup is per-process, so there shouldn't be two seperate threads going on.  The only thing that I can think of is that something is using mozStorageService as a component and not as a service; it doesn't seem to have any protection in mozStorageService::Init against being initialized multiple times.

(In reply to comment #10)
> I find it somewhat alarming that AsyncWriteThread::Run is being called on more
> than one thread.

The threads seem to be listed twice (?). No one could tell me what this meant, so maybe a gdb bug.

Thread 24 (Thread 1140881760 (LWP 21985)):
Thread 18 (Thread 1140881760 (LWP 21985)):

Thread 9 (Thread 1107310944 (LWP 21962)):
Thread 6 (Thread 1107310944 (LWP 21962)):
(In reply to comment #10)
> I find it somewhat alarming that AsyncWriteThread::Run is being called on more
> than one thread.  I thought I recall Brett saying that this async flushing
> business does not work from multiple threads.

It used to be the case that this would be bad, but then we needed it for the anti-phishing service. It should work now, perhaps the anti-phishing service is doing something wrong?


I still see this when browser.safebrowsing.enabled is set to false. So assuming anti-phising is being completely disabled with this pref., it is not to blame for this.
*** Bug 349293 has been marked as a duplicate of this bug. ***
Blocks: 338884
This is a SWAG, but in the thread manager landing, Darin changed mozStorageService to observe shutdown on "xpcom-shutdown-threads" instead of "quit-application". http://bonsai.mozilla.org/cvsview2.cgi?diff_mode=context&whitespace_mode=show&file=mozStorageService.cpp&branch=&root=/cvsroot&subdir=mozilla/storage/src&command=DIFF_FRAMESET&rev1=1.8&rev2=1.9

I changed it back to "quit-application" and I don't see the hang anymore. This doesn't break anything obvious; e.g. history entries are still intact and I don't see any assertions, but I have no idea what other implications this has.
this works for me now... reopen otherwise
Status: NEW → RESOLVED
Closed: 18 years ago
Resolution: --- → WORKSFORME
Flags: blocking1.9a1?
You need to log in before you can comment on or make changes to this bug.