387830 - shutdown after IE import can take a long time due to mozStorageService::FlushAsyncIO() / nsUrlClassifierDBService::Shutdown()

Status: VERIFIED FIXED

(Toolkit :: Safe Browsing, defect, P5)

Description

[(not reading, please use [e-mail] instead)]

shutdown after IE import can take a long time due to mozStorageService::FlushAsyncIO() / nsUrlClassifierDBService::Shutdown()

to reproduce:

1) create a new profile
2) File | Import from IE
3) exit
4) firefox.exe will take a long time to shutdown

(if you try to start up another instance during shutdown, you'll see this alert:

https://bugzilla.mozilla.org/attachment.cgi?id=270798

We appear to be in
nsUrlClassifierDBServiceWorker::CloseDb() which calls
mozStorageService::FlushAsyncIO()

Here are the stack traces for three of my threads:

        ntdll.dll!7c90eb94()    
        [Frames below may be incorrect and/or missing, no symbols loaded for
ntdll.dll] 
        ntdll.dll!7c90e9c0()    
        kernel32.dll!7c8025cb()         
        msvcr80d.dll!malloc(unsigned int nSize=848)  Line 152 + 0x15 bytes     
C++
        kernel32.dll!7c802532()         
        nspr4.dll!_PR_MD_WAIT_CV(_MDCVar * cv=0x05f5f65c, _MDLock *
lock=0x05e27344, unsigned int timeout=4294967295)  Line 280 + 0x14 bytes    C
        nspr4.dll!_PR_WaitCondVar(PRThread * thread=0x05c15100, PRCondVar *
cvar=0x05f5f5e8, PRLock * lock=0x05e27328, unsigned int timeout=4294967295) 
Line 204 + 0x17 bytes  C
        nspr4.dll!PR_WaitCondVar(PRCondVar * cvar=0x05f5f5e8, unsigned int
timeout=4294967295)  Line 551 + 0x17 bytes   C
        strgcmps.dll!mozStorageService::FlushAsyncIO()  Line 581 + 0xc bytes   
C++
        strgcmps.dll!mozStorageConnection::~mozStorageConnection()  Line 91    
C++
        strgcmps.dll!mozStorageConnection::`scalar deleting destructor'()  +
0xf bytes  C++
        strgcmps.dll!mozStorageConnection::Release()  Line 68 + 0xce bytes     
C++
        tkitcmps.dll!nsUrlClassifierDBServiceWorker::CloseDb()  Line 513 + 0x14
bytes   C++
        xpcom_core.dll!NS_InvokeByIndex_P(nsISupports * that=0x00000009,
unsigned int methodIndex=0, unsigned int paramCount=0, nsXPTCVariant *
params=0x06a2ff04)  Line 102    C++
        xpcom_core.dll!nsProxyObjectCallInfo::Run()  Line 181 + 0x2d bytes     
C++
        xpcom_core.dll!nsProxyObjectCallInfo::Run()  Line 181 + 0x2d bytes     
C++
        xpcom_core.dll!nsThread::ProcessNextEvent(int mayWait=1, int *
result=0x06a2ff1c)  Line 491     C++
        xpcom_core.dll!NS_ProcessNextEvent_P(nsIThread * thread=0x05c14b78, int
mayWait=1)  Line 227 + 0x16 bytes       C++
        xpcom_core.dll!nsThread::ThreadFunc(void * arg=0x05c14b78)  Line 254 +
0xb bytes        C++
        nspr4.dll!_PR_NativeRunThread(void * arg=0x05c15100)  Line 436 + 0xf
bytes      C
        nspr4.dll!pr_root(void * arg=0x05c15100)  Line 122 + 0xf bytes  C
        msvcr80d.dll!_callthreadstartex()  Line 348 + 0xf bytes C
        msvcr80d.dll!_threadstartex(void * ptd=0x05c15aa0)  Line 331    C
        kernel32.dll!7c80b683()         



        ntdll.dll!7c90eb94()    
        [Frames below may be incorrect and/or missing, no symbols loaded for
ntdll.dll] 
        user32.dll!7e4193e9()   
        user32.dll!7e4193a8()   
        user32.dll!7e419402()   
        gkwidget.dll!PeekKeyAndIMEMessage(tagMSG * msg=0x0012f8c8, HWND__ *
hwnd=0x00000000)  Line 53 + 0x18 bytes      C++
        gkwidget.dll!nsAppShell::ProcessNextNativeEvent(int mayWait=0)  Line
142 + 0xb bytes    C++
        gkwidget.dll!nsBaseAppShell::DoProcessNextNativeEvent(int mayWait=0) 
Line 137 + 0x11 bytes     C++
        gkwidget.dll!nsBaseAppShell::OnProcessNextEvent(nsIThreadInternal *
thr=0x00b9dc38, int mayWait=1, unsigned int recursionDepth=0)  Line 225 + 0xd
bytes C++
        xpcom_core.dll!nsThread::ProcessNextEvent(int mayWait=1, int *
result=0x0012f988)  Line 480     C++
        xpcom_core.dll!NS_ProcessNextEvent_P(nsIThread * thread=0x00b9dc38, int
mayWait=1)  Line 227 + 0x16 bytes       C++
        xpcom_core.dll!nsThread::Shutdown()  Line 445 + 0xb bytes       C++
        tkitcmps.dll!nsUrlClassifierDBService::Shutdown()  Line 1030    C++
        tkitcmps.dll!nsUrlClassifierDBService::Observe(nsISupports *
aSubject=0x0490c858, const char * aTopic=0x10036698, const unsigned short *
aData=0x10036d30)  Line 1000   C++
        xpcom_core.dll!nsObserverList::NotifyObservers(nsISupports *
aSubject=0x0490c858, const char * aTopic=0x10036698, const unsigned short *
someData=0x10036d30)  Line 129 C++
        xpcom_core.dll!nsObserverService::NotifyObservers(nsISupports *
aSubject=0x0490c858, const char * aTopic=0x10036698, const unsigned short *
someData=0x10036d30)  Line 184      C++
        xul.dll!nsXREDirProvider::DoShutdown()  Line 766        C++
        xul.dll!ScopedXPCOMStartup::~ScopedXPCOMStartup()  Line 819     C++
        xul.dll!XRE_main(int argc=2, char * * argv=0x00b99850, const
nsXREAppData * aAppData=0x00b9aaa0)  Line 3003     C++
        firefox.exe!main(int argc=2, char * * argv=0x00b99850)  Line 87 + 0x12
bytes    C++
        firefox.exe!__tmainCRTStartup()  Line 586 + 0x19 bytes  C
        firefox.exe!mainCRTStartup()  Line 403  C
        kernel32.dll!7c816fd7()


        ntdll.dll!7c90eb94()    
        [Frames below may be incorrect and/or missing, no symbols loaded for
ntdll.dll] 
        ntdll.dll!7c90d9d6()    
        kernel32.dll!7c81268b()         
        strgcmps.dll!winSync(OsFile * id=0x00d8b1a8, int dataOnly=0)  Line
16081 + 0xd bytes    C
>	strgcmps.dll!ProcessOneMessage(AsyncMessage * aMessage=0x0602f4b8)  Line 1401 + 0x11 bytes	C++
        strgcmps.dll!ProcessAsyncMessages()  Line 1534 + 0x9 bytes      C++
        strgcmps.dll!AsyncWriteThread::Run()  Line 475  C++
        xpcom_core.dll!nsThread::ProcessNextEvent(int mayWait=1, int *
result=0x041aff1c)  Line 491     C++
        xpcom_core.dll!NS_ProcessNextEvent_P(nsIThread * thread=0x00ee5878, int
mayWait=1)  Line 227 + 0x16 bytes       C++
        xpcom_core.dll!nsThread::ThreadFunc(void * arg=0x00ee5878)  Line 254 +
0xb bytes        C++
        nspr4.dll!_PR_NativeRunThread(void * arg=0x03d756c8)  Line 436 + 0xf
bytes      C
        nspr4.dll!pr_root(void * arg=0x03d756c8)  Line 122 + 0xf bytes  C
        msvcr80d.dll!_callthreadstartex()  Line 348 + 0xf bytes C
        msvcr80d.dll!_threadstartex(void * ptd=0x03d14a00)  Line 331    C
        kernel32.dll!7c80b683()

Comment 1

[Tony Chang (Google)]

A lot of this is changing in bug 387196.  A random guess is a big rollback is happening because of a canceled download, which should be less likely to happen with the new protocol (it downloads smaller chunks).

Comment 2

[Shawn Wilsher :sdwilsh]

eh, might not be safe browsing - it could just be the unlucky one here.  I'm assuming the import code adds a bunch of bookmarks?  Please tell me that that is wrapped in a transaction (if it isn't, I bet that's our problem)

Comment 3

[Tracy Walker [:tracy]]

Seth, I believe this is affecting Migration as well..  It took well over 3 minutes for the browser to start after migration from IE "Finish" was clicked.  During the wait, firefox.exe is taking 99% of CPU.  

Should it be a separate bug?

Comment 4

[Tracy Walker [:tracy]]

ispiked mentioned in irc that what I'm seeing with slowness in Migration and Import is a bd issue and likely the same thing.  

don't need another bug... and bug 387137 covers the lost bookmarks which I failed to mention previously

Comment 5

[(not reading, please use [e-mail] instead)]

> Please tell me that that is wrapped in a transaction (if it isn't, I bet 
> that's our problem)

shawn, it is not, and I think you are right.  see bug #392003.

With the patch in that bug, this is not an issue on shutdown after ie import,
as I'm using a transaction (via RunInBatchMode)

> Should it be a separate bug?

twalker, see bug #392003.

Comment 6

[(not reading, please use [e-mail] instead)]

twalker and others:  with the fix for bug #392003, the steps in comment #0 are no longer cause the original problem, but that doesn't mean the underlying issue is fixed.

Comment 7

[Martijn Wargers (dead)]

What is the underlying issue? Something in mozStorage or something?
I think I still suffer from this occasionally (although it's not that bad as it was, originally).
Firefox->Phishing Protection doesn't seem like the correct component for this, is it?

Comment 8

[Mike Connor [:mconnor]]

Seth, I think we should file a clean bug on the underlying issue and resolve this.

Comment 9

[Mike Connor [:mconnor]]

Fixed as reported, please file bugs on any deeper issues

Comment 10

[Martijn Wargers (dead)]

Seth, can you file a bug on the underlying issue and mark it blocking-firefox3?
I think I still suffer from this occasionally, although the shutdown doesn't take normally longer than 10s or so, but I still think that's unacceptable. 

Comment 11

[Hasham]

Was there ever a bug filed for the underlying issue? If so, I can close this bug down as verified. Doesn't show up in RC2.

Comment 12

[Shawn Wilsher :sdwilsh]

AsyncIO was remove from storage, which probably took care of this.  I think that was the underlying issue?

Comment 13

[Hasham]

Cool. Marking as verified.