Closed Bug 517236 Opened 16 years ago Closed 16 years ago

UI hang while syncing... 100% CPU within mozilla::storage::Connection::ExecuteSimpleSQL

Categories

(Firefox :: Sync, defect)

Product:
Firefox
Component:
Sync
Platform:
x86
Windows 7
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

()

Status:
RESOLVED WORKSFORME

People

(Reporter: benjamin, Assigned: Mardak)

References

Details

I've seen the following hang on both mac and Windows with Weave 0.6 and 0.7pre2: the UI is completely unresponsive and Firefox is using 100% CPU. I attached in a debugger on Windows and all the time seems to be spent within mozilla::storage::Connection::ExecuteSimpleSQL on the main thread: sqlite3.dll!sqlite3_step(sqlite3_stmt * pStmt=0x03bac8a8) Line 49449 + 0x7 bytes C sqlite3.dll!sqlite3_exec(sqlite3 * db=0x00952608, const char * zSql=0x007bc048, int (void *, int, char * *, char * *)* xCallback=0x00000000, void * pArg=0x00000000, char * * pzErrMsg=0x00000000) Line 6496 + 0x6 bytes C xul.dll!mozilla::storage::Connection::ExecuteSimpleSQL(const nsACString_internal & aSQLStatement={...}) Line 632 + 0x1c bytes C++ xul.dll!nsNavBookmarks::AdjustIndices(__int64 aFolder=5, int aStartIndex=193, int aEndIndex=857, int aDelta=-1) Line 979 C++ xul.dll!nsNavBookmarks::MoveItem(__int64 aItemId=796, __int64 aNewParent=5, int aIndex=858) Line 2012 C++ xul.dll!NS_InvokeByIndex_P(nsISupports * that=0x0000000f, unsigned int methodIndex=3, unsigned int paramCount=4832184, nsXPTCVariant * params=0x00000000) Line 102 C++ xul.dll!XPCWrappedNative::CallMethod(XPCCallContext & ccx=, XPCWrappedNative::CallMode mode=) Line 2710 + 0x22 bytes C++ xul.dll!XPC_WN_CallMethod(JSContext * cx=0x007ed000, JSObject * obj=0x044794a0, unsigned int argc=3, int * argv=0x0567e974, int * vp=0x0049bef8) Line 1740 + 0x12 bytes C++ js3250.dll!js_Invoke(JSContext * cx=, unsigned int argc=, int * vp=, unsigned int flags=) Line 1373 + 0x13 bytes C++ js3250.dll!js_Interpret(JSContext * cx=0x007ed000) Line 2200 C++ js3250.dll!js_Invoke(JSContext * cx=0x007ed000, unsigned int argc=1, int * vp=0x03ba86ac, unsigned int flags=0) Line 1381 + 0x6 bytes C++ js3250.dll!js_fun_apply(JSContext * cx=0x007ed000, unsigned int argc=1, int * vp=0x03ba866c) Line 2023 C++ js3250.dll!js_Interpret(JSContext * cx=0x007ed000) Line 2167 + 0xc bytes C++ js3250.dll!js_Invoke(JSContext * cx=0x007ed000, unsigned int argc=1, int * vp=0x03ba76d8, unsigned int flags=0) Line 1381 + 0x6 bytes C++ js3250.dll!js_fun_apply(JSContext * cx=0x007ed000, unsigned int argc=1, int * vp=0x03ba76a0) Line 2023 C++ js3250.dll!js_Interpret(JSContext * cx=0x007ed000) Line 2167 + 0xc bytes C++ js3250.dll!js_Invoke(JSContext * cx=0x007ed000, unsigned int argc=5, int * vp=0x05681b2c, unsigned int flags=0) Line 1381 + 0x6 bytes C++ xul.dll!nsXPCWrappedJSClass::CallMethod(nsXPCWrappedJS * wrapper=0x11c66800, unsigned short methodIndex=5, const XPTMethodDescriptor * info=0x008c9ad8, nsXPTCMiniVariant * nativeParams=0x0049ca48) Line 1672 C++ xul.dll!nsXPCWrappedJS::CallMethod(unsigned short methodIndex=5, const XPTMethodDescriptor * info=0x008c9ad8, nsXPTCMiniVariant * params=0x0049ca48) Line 571 C++ xul.dll!PrepareAndDispatch(nsXPTCStubBase * self=0x0e92ab20, unsigned int methodIndex=5, unsigned int * args=0x0049cb00, unsigned int * stackBytesToPop=0x0049caf0) Line 114 + 0x15 bytes C++ xul.dll!SharedStub() Line 142 C++ xul.dll!nsHttpChannel::OnDataAvailable(nsIRequest * request=0x05b1ef10, nsISupports * ctxt=0x00000000, nsIInputStream * input=0x088d1528, unsigned int offset=69632, unsigned int count=65536) Line 5291 C++ The SQL being executed is: "UPDATE moz_bookmarks SET position = position + -1 WHERE parent = 5 AND position >= 193 AND position <= 857" There are various things being called under sqlite3_step, but one of the more common ones, which looks completely wrong, is: mozcrt19.dll!memcpy(unsigned char * dst=0x03bac930, unsigned char * src=0x04ec7000, unsigned long count=81788928) Line 354 + 0x1 bytes Asm mozcrt19.dll!malloc(unsigned int size=1955207970) Line 6160 + 0x5 bytes C > sqlite3.dll!winMutexEnter(sqlite3_mutex * p=0x748fc7c0) Line 15159 C sqlite3.dll!sqlite3_step(sqlite3_stmt * pStmt=0x03bac8a8) Line 49446 + 0x11 bytes C The assembly says winMutexEnter is calling GetCurrentThreadId, not malloc, so that's a bit confusing.
dmills suggested that I might have sqlite corruption, but if that's the case Weave managed to propagate this corruption to multiple computers (I see this same hang on Windows and Mac). Here is the shark profile of the hang on Mac. It eventually finishes syncing, after 10-15 minutes of a mostly-unresponsive browser (focus on nsNavBookmarks::AdjustIndices which is where all the time is spent): # Report 0 - Session 1 - Time Profile of firefox-bin SharkProfileViewer # Generated from the visible portion of the outline view + 100.0%, nsNavBookmarks::AdjustIndices(long long, int, int, int), XUL | + 99.9%, mozilla::storage::Connection::ExecuteSimpleSQL(nsACString_internal const&), XUL | | + 99.9%, sqlite3_exec, libsqlite3.dylib | | | + 98.7%, sqlite3_step, libsqlite3.dylib | | | | + 96.8%, sqlite3Step, libsqlite3.dylib | | | | | + 19.6%, sqlite3VdbeCursorMoveto, libsqlite3.dylib | | | | | | + 18.4%, sqlite3BtreeMovetoUnpacked, libsqlite3.dylib | | | | | | | + 6.9%, moveToChild, libsqlite3.dylib | | | | | | | | + 6.4%, getAndInitPage, libsqlite3.dylib | | | | | | | | | + 6.2%, btreePageLookup, libsqlite3.dylib | | | | | | | | | | + 5.3%, sqlite3PcacheFetch, libsqlite3.dylib | | | | | | | | | | | + 4.5%, pcache1Fetch, libsqlite3.dylib | | | | | | | | | | | | + 1.7%, pthreadMutexEnter, libsqlite3.dylib | | | | | | | | | | | | | + 1.5%, pthread_mutex_lock, libSystem.B.dylib | | | | | | | | | | | | | | 0.5%, __spin_lock, libSystem.B.dylib | | | | | | | | | | | | | | 0.0%, spin_unlock, libSystem.B.dylib | | | | | | | | | | | | | | 0.0%, dyld_stub__spin_lock, libSystem.B.dylib | | | | | | | | | | | | | | 0.0%, dyld_stub__spin_unlock, libSystem.B.dylib | | | | | | | | | | | | | | 0.0%, OSSpinLockLock, libSystem.B.dylib | | | | | | | | | | | | | 0.0%, dyld_stub_pthread_self, libsqlite3.dylib | | | | | | | | | | | | | 0.0%, dyld_stub_pthread_mutex_lock, libsqlite3.dylib | | | | | | | | | | | | | 0.0%, pthread_self, libSystem.B.dylib | | | | | | | | | | | | - 1.3%, pthread_mutex_unlock, libSystem.B.dylib | | | | | | | | | | | | 0.2%, pcache1PinPage, libsqlite3.dylib | | | | | | | | | | | | 0.1%, sqlite3_mutex_enter, libsqlite3.dylib | | | | | | | | | | | | 0.1%, sqlite3_mutex_leave, libsqlite3.dylib | | | | | | | | | | | | 0.1%, pthreadMutexLeave, libsqlite3.dylib | | | | | | | | | | | | 0.0%, dyld_stub_pthread_mutex_unlock, libsqlite3.dylib | | | | | | | | | | | 0.0%, sqlite3_mutex_enter, libsqlite3.dylib | | | | | | | | | | | 0.0%, pthreadMutexEnter, libsqlite3.dylib | | | | | | | | | | | 0.0%, pcache1PinPage, libsqlite3.dylib | | | | | | | | | | | 0.0%, sqlite3_mutex_leave, libsqlite3.dylib | | | | | | | | | | | 0.0%, pthreadMutexLeave, libsqlite3.dylib | | | | | | | | | | | 0.0%, pthread_mutex_unlock, libSystem.B.dylib | | | | | | | | | | - 0.4%, btreePageFromDbPage, libsqlite3.dylib | | | | | | | | | | 0.1%, sqlite3PagerGetExtra, libsqlite3.dylib | | | | | | | | | | 0.0%, sqlite3PagerGetData, libsqlite3.dylib | | | | | | | | | | 0.0%, pcache1Fetch, libsqlite3.dylib | | | | | | | | | 0.0%, btreePageFromDbPage, libsqlite3.dylib | | | | | | | | | 0.0%, sqlite3PcacheFetch, libsqlite3.dylib | | | | | | | | 0.0%, btreePageLookup, libsqlite3.dylib | | | | | | | - 2.5%, moveToRoot, libsqlite3.dylib | | | | | | | 1.4%, sqlite3GetVarint, libsqlite3.dylib | | | | | | | 0.2%, sqlite3Get4byte, libsqlite3.dylib | | | | | | | 0.0%, getAndInitPage, libsqlite3.dylib | | | | | | | 0.0%, pagerUnlockIfUnused, libsqlite3.dylib | | | | | | | 0.0%, sqlite3PagerUnref, libsqlite3.dylib | | | | | | | 0.0%, releasePage, libsqlite3.dylib | | | | | | 0.1%, sqlite3GetVarint, libsqlite3.dylib | | | | | | 0.0%, sqlite3Get4byte, libsqlite3.dylib | | | | | | 0.0%, moveToChild, libsqlite3.dylib | | | | | | 0.0%, moveToRoot, libsqlite3.dylib | | | | | - 13.8%, sqlite3BtreeMovetoUnpacked, libsqlite3.dylib | | | | | - 10.4%, sqlite3BtreeInsert, libsqlite3.dylib | | | | | 3.7%, sqlite3VdbeSerialType, libsqlite3.dylib | | | | | - 2.4%, sqlite3VdbeMemFromBtree, libsqlite3.dylib | | | | | 2.2%, sqlite3VdbeSerialGet, libsqlite3.dylib | | | | | - 1.9%, applyAffinity, libsqlite3.dylib | | | | | - 1.9%, sqlite3VdbeMemRelease, libsqlite3.dylib | | | | | - 1.8%, sqlite3VdbeMemMakeWriteable, libsqlite3.dylib | | | | | - 1.1%, sqlite3VdbeRecordCompare, libsqlite3.dylib | | | | | - 1.1%, sqlite3BtreeDataSize, libsqlite3.dylib | | | | | 1.0%, sqlite3VdbeSerialTypeLen, libsqlite3.dylib | | | | | 0.9%, sqlite3VarintLen, libsqlite3.dylib | | | | | 0.7%, sqlite3VdbeMemReleaseExternal, libsqlite3.dylib | | | | | - 0.6%, sqlite3BtreeKeySize, libsqlite3.dylib | | | | | 0.6%, sqlite3MemCompare, libsqlite3.dylib | | | | | - 0.5%, sqlite3VdbeMemGrow, libsqlite3.dylib | | | | | 0.4%, __memcpy, libSystem.B.dylib | | | | | - 0.4%, sqlite3VdbeMemSetInt64, libsqlite3.dylib | | | | | 0.2%, fetchPayload, libsqlite3.dylib | | | | | - 0.2%, sqlite3BtreeNext, libsqlite3.dylib | | | | | - 0.2%, sqlite3RowSetInsert, libsqlite3.dylib | | | | | 0.2%, applyNumericAffinity, libsqlite3.dylib | | | | | 0.1%, sqlite3BtreeSetCachedRowid, libsqlite3.dylib | | | | | 0.1%, sqlite3GetVarint, libsqlite3.dylib | | | | | - 0.1%, sqlite3RowSetClear, libsqlite3.dylib | | | | | 0.1%, sqlite3BtreeKeyFetch, libsqlite3.dylib | | | | | - 0.1%, moveToLeftmost, libsqlite3.dylib | | | | | 0.1%, sqlite3VdbeIntValue, libsqlite3.dylib | | | | | 0.1%, rowSetToList, libsqlite3.dylib | | | | | 0.0%, sqlite3DbFree, libsqlite3.dylib | | | | | 0.0%, sqlite3BtreeDataFetch, libsqlite3.dylib | | | | | - 0.0%, allocateCursor, libsqlite3.dylib | | | | | 0.0%, sqlite3Get4byte, libsqlite3.dylib | | | | | 0.0%, sqlite3_free, libsqlite3.dylib | | | | | 0.0%, sqlite3BtreeParseCell, libsqlite3.dylib | | | | | - 0.0%, sqlite3VdbeFreeCursor, libsqlite3.dylib | | | | | 0.0%, sqlite3BtreeParseCellPtr, libsqlite3.dylib | | | | | - 0.0%, sqlite3BtreeCursor, libsqlite3.dylib | | | | | 0.0%, dyld_stub_memcpy, libsqlite3.dylib | | | | | 0.0%, moveToChild, libsqlite3.dylib | | | | | 0.0%, allocateTempSpace, libsqlite3.dylib | | | | | 0.0%, sqlite3PutVarint, libsqlite3.dylib | | | | | 0.0%, sqlite3GetVarint32, libsqlite3.dylib | | | | | 0.0%, sqlite3PagerWrite, libsqlite3.dylib | | | | | 0.0%, cellSizePtr, libsqlite3.dylib | | | | | 0.0%, saveAllCursors, libsqlite3.dylib | | | | | 0.0%, moveToRoot, libsqlite3.dylib | | | | | 0.0%, memcpy, libSystem.B.dylib | | | | | 0.0%, checkForReadConflicts, libsqlite3.dylib | | | | | - 0.0%, sqlite3VdbeHalt, libsqlite3.dylib | | | | | 0.0%, releasePage, libsqlite3.dylib | | | | | 0.0%, clearCell, libsqlite3.dylib | | | | | - 0.0%, sqlite3VdbeMemSetRowSet, libsqlite3.dylib | | | | | 0.0%, dropCell, libsqlite3.dylib | | | | | 0.0%, sqlite3BtreeMoveto, libsqlite3.dylib | | | | | 0.0%, insertCell, libsqlite3.dylib | | | | 0.8%, sqlite3VdbeSerialTypeLen, libsqlite3.dylib | | | | 0.2%, sqlite3VdbeSerialType, libsqlite3.dylib | | | | 0.1%, sqlite3VarintLen, libsqlite3.dylib | | | | 0.1%, applyAffinity, libsqlite3.dylib | | | | 0.1%, sqlite3VdbeMemMakeWriteable, libsqlite3.dylib | | | | 0.1%, sqlite3VdbeMemReleaseExternal, libsqlite3.dylib | | | | 0.1%, sqlite3VdbeCursorMoveto, libsqlite3.dylib | | | | 0.1%, sqlite3VdbeSerialGet, libsqlite3.dylib | | | | 0.0%, sqlite3VdbeMemFromBtree, libsqlite3.dylib | | | | 0.0%, sqlite3BtreeKeySize, libsqlite3.dylib | | | | 0.0%, sqlite3VdbeMemRelease, libsqlite3.dylib | | | | 0.0%, sqlite3BtreeDataFetch, libsqlite3.dylib | | | | 0.0%, sqlite3MemCompare, libsqlite3.dylib | | | | 0.0%, fetchPayload, libsqlite3.dylib | | | | 0.0%, applyNumericAffinity, libsqlite3.dylib | | | | 0.0%, sqlite3BtreeSetCachedRowid, libsqlite3.dylib | | | | 0.0%, sqlite3BtreeInsert, libsqlite3.dylib | | | | 0.0%, sqlite3BtreeDataSize, libsqlite3.dylib | | | | 0.0%, rowSetToList, libsqlite3.dylib | | | | 0.0%, sqlite3BtreeNext, libsqlite3.dylib | | | | 0.0%, sqlite3VdbeRecordCompare, libsqlite3.dylib | | | | 0.0%, sqlite3BtreeMovetoUnpacked, libsqlite3.dylib | | | | 0.0%, __memcpy, libSystem.B.dylib | | | | 0.0%, sqlite3VdbeIntValue, libsqlite3.dylib | | | | 0.0%, sqlite3RowSetInsert, libsqlite3.dylib | | | | 0.0%, sqlite3VdbeMemSetInt64, libsqlite3.dylib | | | | 0.0%, sqlite3VdbeMemGrow, libsqlite3.dylib | | | - 1.0%, sqlite3LockAndPrepare, libsqlite3.dylib | | | - 0.1%, sqlite3VdbeFinalize, libsqlite3.dylib | - 0.0%, nsCString::AppendInt(int, int), XUL | - 0.0%, nsCString::AppendInt(long long, int), XUL | - 0.0%, nsACString_internal::~nsACString_internal(), XUL | - 0.0%, nsACString_internal::ReplaceASCII(unsigned int, unsigned int, char const*, unsigned int), XUL | 0.0%, PR_AtomicDecrement, libnspr4.dylib
Can you check the activity log to see if it was making any progress or just stuck somewhere?
Well, since sync did eventually finish without showing an error in the statusbar, I think it was making progress, just glacially slowly. What would I be looking for in the activity log?
If it was slow when downloading/creating, look for "created bookmark..." and the times it took to create them. If it was uploading.. check if it there were many "No predecessor directly before.." messages.
ok, I lied. A second sync is haning forever, seemingly. The last thing in the verbose-log.txt on disk is: 2009-09-18 11:11:27 Collection DEBUG GET request for https://sj-weave02.services.mozilla.com/0.5/bsmedberg/storage/bookmarks/?full=1&sort=index&ids={6573e4dc-204d-47de-a552-f6ca3ba1af08}9370,{6573e4dc-204d-47de-a552-f6ca3ba1af08}9195,{65... And there are no further entries being added. nsNavBookmarks::AdjustIndices is still the vast majority of the time
ping, this still is happening... is there other data I can provide? It seems like a really big deal that Weave almost-1.0 can make Firefox completely unusable.
Ed, any ideas?
Assignee: nobody → edilee
(In reply to comment #7) > Ed, any ideas? I can try to investigate this some today as well.
bsmedberg, can you run this in the error console (with weave installed)? It'll print out the item's position in the folder and its title sorted by position. Just checking if there's nothing absurdly wrong (huge indices or gaps; e.g., index 1000 then index 100). Components.utils.import("resource://weave/service.js"); b = Weave.Svc.Bookmark; function f(id) [b.getItemIndex(id), b.getItemTitle(id)]; [f(b.getItemIdForGUID(guid)) for (guid in Weave.Engines.get("bookmarks")._store.getAllIDs())].sort(function(a,b) b[0] - a[0]).join("\n")
I think the places team could probably make nsNavBookmarks::AdjustIndices faster by using a precompiled statement too. Especially if weave calls this method frequently, we should probably do that.
Turns out this was caused by some sort of nesting where bookmarks folders were contained within themself (at least as I understand what was said on IRC). After removing the cause of this nesting, weave appears to be syncing at least without hanging the browser...
Seems like this was triggered by recursive bookmarks bug 484429. Deleting the (no title) bookmark folder seems to stop Weave from getting confused.
Status: NEW → RESOLVED
Closed: 16 years ago
Depends on: 484429
Resolution: --- → WORKSFORME
Component: Firefox Sync: Backend → Sync
Product: Cloud Services → Firefox
You need to log in before you can comment on or make changes to this bug.