1438675 - Sync is slow with buffer engine

Status: RESOLVED DUPLICATE of bug 1435588

(Firefox :: Sync, defect, P2)

Description

[Kanchan Kumari QA]

Case #1:
1. Create a fresh Fx profile
2. Sync with Fx account which has ~1500 bookmarks

Observed: Sync finishes up in 1.15 minutes.

Case #2:
1. Create a fresh Fx profile
2. Go to about:config and flip services.sync.engine.bookmarks.buffer pref to true
3. Sync with same Fx account from case #1 

Observed: Sync takes 3:30 minutes to finish syncing all bookmarks.

Comment 1

[Lina Butler [:lina]]

Thanks, Kanchan! Could you please upload the logs from that sync? I have 3500 bookmarks, and a sync takes about 40s (30s to download and stashing in the mirror; 10s to merge). 3m30s is definitely excessive, especially for a much smaller profile.

Comment 2

[Kanchan Kumari QA]

Attachment: success-sync-1518724406736.txt

This is same Fx account which I used in bug 1437153.

Comment 3

[Kanchan Kumari QA]

Attachment: success-sync-1518724407608.txt

This one got logged at the same time (a second after the above log)

Comment 4

[Mark Hammond [:markh] [:mhammond]]

Thanks Kanchan - would it be possible for you to set the preference "services.sync.log.logger.engine.bookmarks" to "Trace" (or use about:sync to set engine logging to Trace) and re-create the issue and upload the new logs which appear?

Comment 5

[Lina Butler [:lina]]

Thanks, Kanchan, these logs are pretty helpful already! Good news...from the first log (attachment 8951471 [details]), the merge itself appears to only take just over a second:

> 1518724401908 Sync.Engine.Bookmarks.Mirror  DEBUG Building remote tree from mirror
> 1518724402916 Sync.Engine.Bookmarks.Mirror  DEBUG Recalculating frecencies for new URLs

Inserting the records into the mirror appears to take the bulk of the time, which is bug 1435588:

> 1518724200176 Sync.Collection DEBUG GET success 200 https://sync-572-us-west-2.sync.services.mozilla.com/1.5/89057808/storage/bookmarks?full=1&sort=index&limit=1000
> 1518724401896 Sync.Engine.Bookmarks INFO  Records: 1427 applied, 1427 successfully, 0 failed to apply, 0 newly failed to apply, 0 reconciled.

The no-op merge in the second sync (attachment 8951472 [details]) takes 132ms, which is even better:

> 1518724407036 Sync.Engine.Bookmarks.Mirror  DEBUG Building remote tree from mirror
> 1518724407168 Sync.Engine.Bookmarks.Mirror  DEBUG Recalculating frecencies for new URLs

However...

> 1518724401906 Sync.Engine.Bookmarks.Mirror  DEBUG Temporarily reparenting remote items with missing parents to unfiled: ["5P465nQUklQM","I0jhsFJqvzII","ivfvHZMSYPW2","n3T41vK9e_PE","qmNxg--Hb1zp","uXp6rBUSbkJ4","yjpoiUnbjjpa","yrLlLi8EPiBN","-51PufmeSb4R","0jXPVCRmsaGY","1AekcHYEkDK0","1erGzOnwBLs0","3Drsq5BMRJTh","4XsrSzR4vFZB","4w2WyAt4JW5T","6Pw6WmVM0IAA","6VRqh92Z3sU6","6nLg2IJP6mXG","7obJIZ1UfWtr","8-ct2S994iVj","8Nnl7kcdzDZf","9ldaJhZ8SdIU","9xq-WvuU33Or","Ac8NdjSzQb94","B6SiTVutQSor","BREF3qTgZgr4","Ct42lBCqLukD","D8zOJ8AZ63sA","DNrjeS_bZ0yK","EWf_JAUV7_rs","F05MlSgr7Ngk","FPpZrIliNNk6","FXevUr_EwkEb","G2LvegTwEM8D","GPZjIvNxuh1_","IFyXjJiQmXFG","Icj8LCANXtpx","JP3DME5l8ny5","JSaoWZpbwNRV","JsbMxhI3gWkz","KyUiAF0Z4_Ba","L1dO-XqNwYsc","M4atQeqvuX-F","M8HCzHA-OZhR","MgSO5Pys18Pj","N909YwiTzPL9","NmncUgTq0t5G","OFEkMCi_FsxQ","ORDfRO9H6nAG","PZuGAJXFSYrx","QQ_3o188rb-V","RqNMuYOQl0CX","SLjfWxYHMSHs","SSmqyfNatZIx","TK9ZsJ-LCkPZ","V9kvXhR3MAMo","W-ZwraTLFxkX","WDK8uOVzVMIl","WRqaMopUyaQW","X2ky8ZGKE8Mf","Y2rF1hD36Pre","YoZAua9g9Jox","ZRfZmXO75Ewn","_Ej_-ml7xe6c","_KVS1NuA2EwQ","aTUSSc97Dvgx","c6U36n4-11NN","cBs3ZSwd5DyB","cK3_-U1OC3hh","chUlhtT6aCyS","d01bQttGZy1D","dLvJyF669U0m","dl9qBOQrz2wW","duqMdcfsJDKC","eQnwblZknusK","fSUdmUahDC36","fTM91kWbTaLr","fvFbT7M7mnVd","gQArX6TWXgcU","gXBXOzlleV2m","gtKp-k7ZFiTO","h4TSmeZUlrj0","hS-x_DEGZHBl","hZAypUV1h4ew","hrq8URFs1SNc","iDp37unPa5vg","iO7fCyPFhPAW","k_2J4dAiZ7IC","lWXji34n8gTf","lY9PzFcJz10W","m9q5aIebXL3D","n_PFwlZMXHq1","njtJThmnDRZG","nsXSMVBPWQdt","o0SaE0yjowpk","oERpT4g4w8gN","oyAdYT-_eo_4","pTS2o5PKyfZN","pwt8Rwpn39LL","q7RL3SSp2S5w","qN1WO2eRESP-","qXIruSRApkWk","qh1eBCqYGHLq","qktrG0z5Bi8r","rHi72m-zk59b","rKWSYTyoaD33","rhekJKwYf32p","s1UqNnq29DvD","sHDpt99Lsic6","sOTPVp_WTqQh","skXkKHTvITYQ","tRuD0F6gZ237","uXoS7JMWB1rn","v2nbE19iBfxL","v6XTba33uppN","vZnyovBffSBb","wBp-8aOoVNrd","wDLUWUcuXn-2","wUnxeb5XVb0d","x-6vwPVjHW9g","x2GUDKMG0WYZ","xGpqHqvP1ryZ","xIb7_o2WT_FO","yTsP_g26hN14","ycLzza0q_MMa","zZmPUUKQNRve","nBylpKZjgdSX"]

This is a problem. Any chance you can cross-reference those GUIDs with the client and server trees in About Sync? Which device did they come from, and did you change them at all on any devices?

Comment 6

[Kanchan Kumari QA]

Attachment: logs.zip

(In reply to Mark Hammond [:markh] from comment #4)
> Thanks Kanchan - would it be possible for you to set the preference
> "services.sync.log.logger.engine.bookmarks" to "Trace" (or use about:sync to
> set engine logging to Trace) and re-create the issue and upload the new logs
> which appear?

Please find attached log.

Comment 7

[Kanchan Kumari QA]

> > 1518724401906 Sync.Engine.Bookmarks.Mirror  DEBUG Temporarily reparenting remote items with missing parents to unfiled: ["5P465nQUklQM","I0jhsFJqvzII","ivfvHZMSYPW2","n3T41vK9e_PE","qmNxg--Hb1zp","uXp6rBUSbkJ4","yjpoiUnbjjpa","yrLlLi8EPiBN","-51PufmeSb4R","0jXPVCRmsaGY","1AekcHYEkDK0","1erGzOnwBLs0","3Drsq5BMRJTh","4XsrSzR4vFZB","4w2WyAt4JW5T","6Pw6WmVM0IAA","6VRqh92Z3sU6","6nLg2IJP6mXG","7obJIZ1UfWtr","8-ct2S994iVj","8Nnl7kcdzDZf","9ldaJhZ8SdIU","9xq-WvuU33Or","Ac8NdjSzQb94","B6SiTVutQSor","BREF3qTgZgr4","Ct42lBCqLukD","D8zOJ8AZ63sA","DNrjeS_bZ0yK","EWf_JAUV7_rs","F05MlSgr7Ngk","FPpZrIliNNk6","FXevUr_EwkEb","G2LvegTwEM8D","GPZjIvNxuh1_","IFyXjJiQmXFG","Icj8LCANXtpx","JP3DME5l8ny5","JSaoWZpbwNRV","JsbMxhI3gWkz","KyUiAF0Z4_Ba","L1dO-XqNwYsc","M4atQeqvuX-F","M8HCzHA-OZhR","MgSO5Pys18Pj","N909YwiTzPL9","NmncUgTq0t5G","OFEkMCi_FsxQ","ORDfRO9H6nAG","PZuGAJXFSYrx","QQ_3o188rb-V","RqNMuYOQl0CX","SLjfWxYHMSHs","SSmqyfNatZIx","TK9ZsJ-LCkPZ","V9kvXhR3MAMo","W-ZwraTLFxkX","WDK8uOVzVMIl","WRqaMopUyaQW","X2ky8ZGKE8Mf","Y2rF1hD36Pre","YoZAua9g9Jox","ZRfZmXO75Ewn","_Ej_-ml7xe6c","_KVS1NuA2EwQ","aTUSSc97Dvgx","c6U36n4-11NN","cBs3ZSwd5DyB","cK3_-U1OC3hh","chUlhtT6aCyS","d01bQttGZy1D","dLvJyF669U0m","dl9qBOQrz2wW","duqMdcfsJDKC","eQnwblZknusK","fSUdmUahDC36","fTM91kWbTaLr","fvFbT7M7mnVd","gQArX6TWXgcU","gXBXOzlleV2m","gtKp-k7ZFiTO","h4TSmeZUlrj0","hS-x_DEGZHBl","hZAypUV1h4ew","hrq8URFs1SNc","iDp37unPa5vg","iO7fCyPFhPAW","k_2J4dAiZ7IC","lWXji34n8gTf","lY9PzFcJz10W","m9q5aIebXL3D","n_PFwlZMXHq1","njtJThmnDRZG","nsXSMVBPWQdt","o0SaE0yjowpk","oERpT4g4w8gN","oyAdYT-_eo_4","pTS2o5PKyfZN","pwt8Rwpn39LL","q7RL3SSp2S5w","qN1WO2eRESP-","qXIruSRApkWk","qh1eBCqYGHLq","qktrG0z5Bi8r","rHi72m-zk59b","rKWSYTyoaD33","rhekJKwYf32p","s1UqNnq29DvD","sHDpt99Lsic6","sOTPVp_WTqQh","skXkKHTvITYQ","tRuD0F6gZ237","uXoS7JMWB1rn","v2nbE19iBfxL","v6XTba33uppN","vZnyovBffSBb","wBp-8aOoVNrd","wDLUWUcuXn-2","wUnxeb5XVb0d","x-6vwPVjHW9g","x2GUDKMG0WYZ","xGpqHqvP1ryZ","xIb7_o2WT_FO","yTsP_g26hN14","ycLzza0q_MMa","zZmPUUKQNRve","nBylpKZjgdSX"]
> 
> This is a problem. Any chance you can cross-reference those GUIDs with the
> client and server trees in About Sync? Which device did they come from, and
> did you change them at all on any devices?

These bookmarks were from another browser (Chrome). I imported them on windows and I remember deleting the 'imported from Chrome' folder but somehow these were in records after bug 1437153. I didn't make any changes to these bookmarks on other devices other than deleting bookmark/folder on the same device. I will investigate more on this and let you know my findings.

Comment 8

[Mark Hammond [:markh] [:mhammond]]

I tested with 10k bookmarks and even with trace logging, the engine completed on a new profile in 67s - which seems very fast, and quite a bit faster than in a profile without the buffer enabled. So I think we can say the bug as described was fixed by bug 1435588, and we can track any other weirdness in the other bugs we have on file.