Track how long various parts of sync take

RESOLVED FIXED in 0.7

Status

()

P1
normal
RESOLVED FIXED
9 years ago
26 days ago

People

(Reporter: Mardak, Assigned: Mardak)

Tracking

(Blocks: 1 bug)

unspecified
Points:
---
Dependency tree / graph

Firefox Tracking Flags

(Not tracked)

Details

(Assignee)

Description

9 years ago
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.
(Assignee)

Comment 1

9 years ago
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.
(Assignee)

Comment 2

9 years ago
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.
Assignee: nobody → edilee
Status: NEW → RESOLVED
Last Resolved: 9 years ago
Resolution: --- → FIXED
Target Milestone: --- → 0.7
(Assignee)

Updated

9 years ago
Blocks: 514601
(Assignee)

Comment 3

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

Updated

9 years ago
Priority: -- → P1
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.