514600 - Track how long various parts of sync take

Status: RESOLVED FIXED

(Firefox :: Sync, defect, P1)

Description

[Ed Lee :Mardak]

We can instrument the functions on the sync engine object and show the total times in the log.

Right now I'm seeing some values like these.. at 8pm:

2009-09-03 20:03:16	Engine.Clients       INFO	Total (ms): processIncoming 64, sync 66, syncFinish 0, syncStartup 1, uploadOutgoing 1
2009-09-03 20:03:16	Engine.Bookmarks     INFO	Total (ms): processIncoming 68, sync 71, syncFinish 0, syncStartup 1, uploadOutgoing 1
2009-09-03 20:03:16	Engine.Forms         INFO	Total (ms): processIncoming 69, sync 110, syncFinish 35, syncStartup 4, uploadOutgoing 1
2009-09-03 20:03:16	Engine.History       INFO	Total (ms): processIncoming 67, sync 108, syncFinish 39, syncStartup 1, uploadOutgoing 1
2009-09-03 20:03:16	Engine.Passwords     INFO	Total (ms): processIncoming 104, sync 106, syncFinish 0, syncStartup 0, uploadOutgoing 1
2009-09-03 20:03:17	Engine.Prefs         INFO	Total (ms): processIncoming 79, sync 82, syncFinish 0, syncStartup 0, uploadOutgoing 12009-09-03 20:03:17	Engine.Tabs          INFO	Total (ms): createRecord 4, processIncoming 56, sync 112, syncFinish 0, syncStartup 0, uploadOutgoing 56

These are all getting 0 records from the server, so processIncoming is "latency + 0 results" and that's ~70ms. Form and History send a DELETE in syncFinish, and those take ~40ms.

Comment 1

[Ed Lee :Mardak]

http://hg.mozilla.org/labs/weave/rev/47bb48ec036d
Instrument all functions that are part of the sync engine (except some constructors, etc.) and generate statistics (min/max/sum/num/avg) for processing. For now with the default appender, implement toString to report just the total time.

Comment 2

[Ed Lee :Mardak]

With bug 514323 (using info/collections) instead of GETting for each collection..

2009-09-03 20:17:53	Engine.Clients       INFO	Total (ms): processIncoming 0, sync 2, syncFinish 0, syncStartup 1, uploadOutgoing 1
2009-09-03 20:17:53	Engine.Bookmarks     INFO	Total (ms): processIncoming 0, sync 3, syncFinish 0, syncStartup 0, uploadOutgoing 1
2009-09-03 20:17:54	Engine.Forms         INFO	Total (ms): processIncoming 1, sync 73, syncFinish 66, syncStartup 5, uploadOutgoing 1
2009-09-03 20:17:54	Engine.History       INFO	Total (ms): processIncoming 0, sync 66, syncFinish 64, syncStartup 1, uploadOutgoing 1
2009-09-03 20:17:54	Engine.Passwords     INFO	Total (ms): processIncoming 0, sync 2, syncFinish 0, syncStartup 1, uploadOutgoing 1
2009-09-03 20:17:54	Engine.Prefs         INFO	Total (ms): processIncoming 0, sync 2, syncFinish 0, syncStartup 1, uploadOutgoing 1
2009-09-03 20:17:54	Engine.Tabs          INFO	Total (ms): createRecord 3, processIncoming 0, sync 77, syncFinish 0, syncStartup 1, uploadOutgoing 76

Total sync times for no activity (up/down) end up around ~3ms. ! That's over 20 times faster !!! ;) ;) ;)

I'll file a bug to be smarter about sending DELETEs.

Comment 3

[Ed Lee :Mardak]

FYI, about an 1.5-2 hours ago, processIncoming was taking ~250ms to download 0 results. (before bug 514323)