It would be nice to get some concrete numbers for how much faster (or slower!) we've got as a result of: * Simplified crypto -- fewer HTTP requests, no PKI - affects initial keygen, initial sync, and each first sync * Engine improvements * Places, async queries, other underlying changes. Need some timed runs against a local test server, ideally with simulated latency. Extra points for isolating changes, rather than testing 4.0b7 vs. 4.0b9pre! I'll be getting around to this once the bug list has been cut down some.

I set up Sync to pull down my own profile, which has a large history. Note that this isn't a complete analysis versus older versions; just a quick test run to get an idea of things, and to answer Bug 608156. Summary times from the sync log: 2011-01-11 11:36:15 Engine.Bookmarks DEBUG Total (ms): sync 3803, processIncoming 3556, uploadOutgoing 218, syncStartup 15, syncFinish 1, createRecord 31, findDupe 37, resetLastSync 1, isEqual 28, reconcile 219, syncCleanup 0, resetClient 1 2011-01-11 11:38:50 Engine.History DEBUG Total (ms): sync 141823, processIncoming 140723, uploadOutgoing 0, syncStartup 7, syncFinish 733, findDupe 8762, resetLastSync 1, deleteId 6, handleDupe 71, reconcile 22137, syncCleanup 0, resetClient 1 2011-01-11 11:39:00 Engine.Passwords DEBUG Total (ms): sync 9743, processIncoming 9629, uploadOutgoing 0, syncStartup 27, syncFinish 86, findDupe 880, resetLastSync 4, reconcile 1343, syncCleanup 1, resetClient 4 2011-01-11 11:39:01 Engine.Prefs DEBUG Total (ms): sync 805, processIncoming 348, uploadOutgoing 452, syncStartup 3, syncFinish 0, reconcile 0, resetLastSync 0, createRecord 26, syncCleanup 0, resetClient 0 2011-01-11 11:39:01 Engine.Tabs DEBUG Total (ms): sync 750, processIncoming 601, uploadOutgoing 143, syncStartup 6, syncFinish 0, resetClient 2, resetLastSync 1, createRecord 14, findDupe 0, reconcile 2, syncCleanup 0 2011-01-11 11:39:01 Service.Main INFO Sync completed successfully in 171.88 secs. Notable results from Instruments (attached): of that 170 seconds: * 2.3 was spent running AsyncExecuteStatement in a separate thread * 17 seconds was spent in nsNavHistory::AddVisit; 2.4 in SetPageTitle * Raw crypto was a small amount of the total time; only 15 seconds of the total run at some point passed through libnss3.dylib. Most of that time was spent in an endless tower of JS invocations -- one example has a js::Invoke taking 7.3 seconds, at the bottom of which is about 400msec of nsCryptoHMAC. Preliminary recommendation: * There's no point running crypto on a different thread. It's a bunch of tiny operations. * Crypto wins will come from avoiding redundant work -- there are tons of base64 translation, array allocation and copying, deallocation, GCing, and key lookup around every crypto event. * One big saving would come from optimizing history storage, perhaps by batching. Are there any specific questions that anybody would like answered from this sample run?

10MB trace: http://people.mozilla.com/~rnewman/traces/bug624485.tar.bz2 Instruments run of a 170-second sync in 2011-01-10 Minefield build.

(In reply to comment #1) > * 17 seconds was spent in nsNavHistory::AddVisit; 2.4 in SetPageTitle > * One big saving would come from optimizing history storage, perhaps by > batching. Sync should be using the history batching API, which will batch the SQL-level activity. Can anyone confirm that it is or is not? Also, some changes are in progress for an improved API that pushes the SQL writes off the main thread, which might help here. It'd be great to get this same analysis done when that work is ready to test.

(In reply to comment #3) > (In reply to comment #1) > > * 17 seconds was spent in nsNavHistory::AddVisit; 2.4 in SetPageTitle > > > * One big saving would come from optimizing history storage, perhaps by > > batching. > > Sync should be using the history batching API, which will batch the SQL-level > activity. Can anyone confirm that it is or is not? It is. We wrap our history and bookmarks syncing in a nsINavFoobarService::runInBatchMode call where Foobar = Bookmarks or History, respectively. > Also, some changes are in progress for an improved API that pushes the SQL > writes off the main thread, which might help here. It'd be great to get this > same analysis done when that work is ready to test. Yep. We have bug 606353 filed for using the new async history API that sdwilsh is adding to Places.

(In reply to comment #3) > Sync should be using the history batching API, which will batch the SQL-level > activity. Can anyone confirm that it is or is not? I should clarify: my comments were from looking at the profile, not the code :D My batching comment was aimed a level up from SQL -- a user with a big history like me (even though I trimmed it down) spends *a lot* of time in history sync, and perhaps (I don't know -- haven't read the code) combining the 17,000 calls to AddVisit could help. From the profile: Out of 17,415 calls to AddVisit, I see 7,664 calls to InternalAddVisit, and within that 6,331 calls to storage::Statement::Execute. Those might be inaccurate due to sampling, but it looks like SQL activity is approximately 3:1 batched. > Also, some changes are in progress for an improved API that pushes the SQL > writes off the main thread, which might help here. It'd be great to get this > same analysis done when that work is ready to test. That should be a wall-clock improvement, yes. I'll keep the profile around to reproduce.