Last Comment Bug 806087 - Firefox Sync uses all of my memory and doesn't succeed
: Firefox Sync uses all of my memory and doesn't succeed
Status: RESOLVED FIXED
[MemShrink]
: regression
Product: Cloud Services
Classification: Client Software
Component: Firefox Sync: Backend (show other bugs)
: unspecified
: x86_64 All
: -- normal (vote)
: ---
Assigned To: [PTO to Dec5] Bill McCloskey (:billm)
:
:
Mentors:
Depends on: 806460
Blocks: 778993
  Show dependency treegraph
 
Reported: 2012-10-27 07:18 PDT by B.J. Herbison
Modified: 2013-01-21 09:38 PST (History)
6 users (show)
See Also:
Crash Signature:
(edit)
QA Whiteboard:
Iteration: ---
Points: ---
fixed
fixed
fixed


Attachments
Excerpt from experiment one (265.71 KB, text/plain)
2012-10-27 07:18 PDT, B.J. Herbison
no flags Details
Verbose about:memory from experiment two. (137.01 KB, text/plain)
2012-10-27 07:19 PDT, B.J. Herbison
no flags Details

Description B.J. Herbison 2012-10-27 07:18:51 PDT
Created attachment 675840 [details]
Excerpt from experiment one

I have a sync account (connected to bj@herbison.com) I use to synchronize profiles for Firefox and Nightly builds. Starting yesterday (26 October 2012) my system started hanging. Investigating, it was Nightly hanging with Sync using up to 3 GiB of memory on my 4 GiB system.

I don't know if this behavior is related to a change in Nightly, but I didn't notice it on the morning of 26 October, so the change would have been in the 26 October nightly. Updating to the 27 October Nightly still showed the huge memory use for sync.

Experiment one from this morning:
 o Start nightly.
 o After a short time, memory use increased to 3+GiB.
 o Wait half an hour.
 o Memory use decreased to around 200MiB,
 o In preferences, request a sync.
 o Memory use increased to 3+GiB.

Experiment two from this morning:
 o Create a new profile and run the 27 October 2012 Nightly.
 o Memory use stabilized to around 50MiB.
 o Set up Sync on Nightly, pairing with my Firefox profile.
 o Memory use increased to 3+GiB, increasing and decreasing by large amounts over time.

I will attach an excerpt from verbose about:memory for experiment one and a complete verbose about:memory from one point during experiment two.
Comment 1 B.J. Herbison 2012-10-27 07:19:47 PDT
Created attachment 675841 [details]
Verbose about:memory from experiment two.
Comment 2 B.J. Herbison 2012-10-27 11:17:18 PDT
I get the same 3GB memory usage (going against the same sync profile) from a Win64 Nightly build on Windows XP.
Comment 3 Richard Newman [:rnewman] 2012-10-27 11:36:39 PDT
Can you get a memory dump from the latest Nightly that does not exhibit the problem? (That is, regressionwindow-wanted.)

Last time this happened, it was due to cross-compartment changes.

This should help:

http://ftp.mozilla.org/pub/mozilla.org/firefox/nightly/2012/10/

Thanks!
Comment 4 Gregory Szorc [:gps] 2012-10-27 11:38:30 PDT
Two things are troubling:

1) You appear have really large record payloads. These records should not be more than a few hundred kilobytes. about:memory is reporting them in the 4MB range.

2) Record payload strings appear to not be garbage collected, causing memory bloat.

We should figure out which engines the records are associated with and work our way back from there.

For starters, what's the value of services.sync.registerEngines from about:config? If that is listed as "User Set" and there are any entries not in {Bookmarks,Form,History,Password,Prefs,Tab,Addons}, please go to the Sync prefs pane and temporarily disable things not in that set, restart Nightly, and let us know a) what you disabled and b) if that has any effect.
Comment 5 B.J. Herbison 2012-10-27 19:02:44 PDT
(In reply to Richard Newman [:rnewman] from comment #3)
> Can you get a memory dump from the latest Nightly that does not exhibit the
> problem? (That is, regressionwindow-wanted.)
> 
> Last time this happened, it was due to cross-compartment changes.

The problem is more complicated than I hoped. I tried versions of Nightly as far back as 21 October 2012. Each version I tried (with a clean profile) started taking all of my memory when I tried to sync with my current sync profile.

However, this obviously hasn't been happening daily since last Sunday--I would have noticed everything getting slow as I started swapping (as I did last night and today). So something changed with the Sync server or with my sync profile sometime Friday.

However, there is a problem with Nightly. I created a new Firefox 16.0.2 profile and enabled Sync and that version of Firefox is able to connect to the Sync account with maximum memory use of less than 1/4 GiB.

I'll try some older Nightly versions tomorrow.

(In reply to Gregory Szorc [:gps] from comment #4)
> Two things are troubling:
> 
> 2) Record payload strings appear to not be garbage collected, causing memory
> bloat.

In some of my experiment I would see the memory use drop by gigabytes and then grow again. It seemed that some garbage collection was happening, but more records were being created at a fast rate.
 
> We should figure out which engines the records are associated with and work
> our way back from there.
> 
> For starters, what's the value of services.sync.registerEngines from
> about:config?

The value of services.sync.registerEngines is set to the default.
Comment 6 timbugzilla 2012-10-27 19:19:27 PDT
I've been having this problem for at least 2 weeks. I found that disabling bookmarks syncing (I had ~2000 at the time) stopped the errors/memory exhaustion.

Today I reduced my bookmarks to ~ 1000 and manually synced them across machines (using a json backup file). Now syncing is fine (tested by adding a new and different bookmark to each machine).
Comment 7 B.J. Herbison 2012-10-28 05:07:30 PDT
I have just under 1000 bookmarks. The only two items I was syncing were bookmarks and history. I tried history alone and the sync failed, bookmarks alone and the sync succeeded.
Comment 8 B.J. Herbison 2012-10-28 14:16:13 PDT
In the tests in my last comment, I created separate profiles to sync bookmarks and history. After that I turned off history sync for my main profile, synced successfully, turned on history sync as well, and now sync works with both history and bookmarks for that profile.

I still have a profile I created earlier for testing that syncs both bookmarks and history, that profile uses huge amounts of memory for synchronization. It takes less than ten seconds to use up 3GiB of memory. (It's amazing what you can do with a fast processor.)

I tried old Nightly builds of Firefox: the 31 July build syncs without problems, and the 1 August version chews up memory.  (That version can take up to 30 seconds to eat up my memory. There's been a performance improvement since 1 August.)

Good:
https://ftp.mozilla.org/pub/mozilla.org/firefox/nightly/2012/07/2012-07-31-mozilla-inbound-debug/
firefox-17.0a1.en-US.debug-linux-x86_64.tar.bz2

Bad:
https://ftp.mozilla.org/pub/mozilla.org/firefox/nightly/2012/08/2012-08-01-mozilla-inbound-debug/
firefox-17.0a1.en-US.debug-linux-x86_64.tar.bz2

I will save the profile and I would be glad to run other versions of Firefox against the profile.
Comment 9 Richard Newman [:rnewman] 2012-10-28 15:38:39 PDT
(In reply to B.J. Herbison from comment #8)

> I tried old Nightly builds of Firefox: the 31 July build syncs without
> problems, and the 1 August version chews up memory.  (That version can take
> up to 30 seconds to eat up my memory. There's been a performance improvement
> since 1 August.)

Bug 767209 landed in that time, which seems to adjust GC timing behavior.

billm: Sync generates *a lot* of garbage, as it pulls down several megabytes of strings, does lots of JSON parsing and crypto, builds a lot of objects, and performs tens of thousands of function calls, all as fast as the machine can manage. Could Bug 767209 (or Bug 778993, for that matter) cause enough delay in GC that memory consumption could spike?




For posterity, a full list of changes that I think could have an effect here (manually pruned from `hg log -d "2012-07-30 to 2012-08-01"`):

changeset:   106612:e544775ed3a7
user:        Jan de Mooij <jdemooij@mozilla.com>
date:        Wed Aug 01 09:30:39 2012 +0200
summary:     Bug 779093 - Fix --disable-methodjit orange. r=dvander

changeset:   106611:a73cf1325796
user:        Sean Stangl <sstangl@mozilla.com>
date:        Tue Jul 31 22:44:22 2012 -0700
summary:     Bug 772892 - Follow-up: hack around regalloc misassignation. no_r

changeset:   106605:b46621aba6fd
user:        David Anderson <danderson@mozilla.com>
date:        Mon Jul 30 17:19:10 2012 -0700
summary:     Add JM inline cache for calling into Ion (bug 775818, r=jandem,pierron).

changeset:   101058:f6ebe752f7cd
user:        Bill McCloskey <wmccloskey@mozilla.com>
date:        Tue Jul 31 18:39:39 2012 -0700
summary:     Bug 767209 - Consider changing GC slice time, or making it dynamic (r=terrence,smaug)

changeset:   101057:c894763d1bbc
user:        Bill McCloskey <wmccloskey@mozilla.com>
date:        Tue Jul 31 18:33:29 2012 -0700
summary:     Bug 778993 - Separate runtime's gcMallocBytes from compartment's gcMallocBytes Bug 778993 - Separate runtime's gcMallocBytes from compartment's gcMallocBytes (r=gwagner)
Comment 10 Richard Newman [:rnewman] 2012-10-28 16:03:15 PDT
(In reply to B.J. Herbison from comment #5)

> The problem is more complicated than I hoped. I tried versions of Nightly as
> far back as 21 October 2012. Each version I tried (with a clean profile)
> started taking all of my memory when I tried to sync with my current sync
> profile.
> 
> However, this obviously hasn't been happening daily since last Sunday--I
> would have noticed everything getting slow as I started swapping (as I did
> last night and today). So something changed with the Sync server or with my
> sync profile sometime Friday.

Note that a sync against a new profile is very different to an incremental sync against an existing profile. In the former, we download everything on the server; in the latter, only the things that have changed.


(In reply to B.J. Herbison from comment #8)

> I still have a profile I created earlier for testing that syncs both
> bookmarks and history, that profile uses huge amounts of memory for
> synchronization. It takes less than ten seconds to use up 3GiB of memory.
> (It's amazing what you can do with a fast processor.)

I would be very interested to see logs for this.

Offline (most easily by editing the profile's prefs.js without Firefox running), set:

user_pref("services.sync.log.appender.file.logOnSuccess", true);
user_pref("services.sync.log.logger.engine.bookmarks", "Trace");
user_pref("services.sync.log.logger.engine.history", "Trace");
user_pref("services.sync.log.logger.network.resources", "Trace");

Then launch the profile, let it sync, and — assuming it doesn't crash — grab all of the logs from about:sync-log that were written during the sync. They'll contain sensitive information (your bookmarks and history), so don't post them here -- send them to me if you're willing.
Comment 11 Richard Newman [:rnewman] 2012-10-29 11:16:09 PDT
From logs: the bookmarks failure is inserting a query record. In fact, that fails for a bunch of queries. Filed Bug 806460.

Otherwise, there's nothing here that looks particularly bad, other than spending nearly five minutes downloading and applying records. There's a lot of history, but sync finishes fine. Nothing has changed in Sync that would make that generate more garbage than usual…
Comment 12 [PTO to Dec5] Bill McCloskey (:billm) 2012-10-29 17:23:30 PDT
I was able to reproduce this. It's fixed by backing out bug 778993. I guess I'll have to back it out and figure out a different approach.
Comment 13 B.J. Herbison 2012-10-29 17:42:40 PDT
(In reply to Bill McCloskey (:billm) from comment #12)
> I was able to reproduce this. It's fixed by backing out bug 778993. I guess
> I'll have to back it out and figure out a different approach.

Is it reasonable to back that patch out of Firefox 17 before it get shipped? The performance issues I've seen would make many people walk away from Firefox (if they happen to get hit by it).
Comment 14 Richard Newman [:rnewman] 2012-10-29 17:44:02 PDT
(In reply to B.J. Herbison from comment #13)

> Is it reasonable to back that patch out of Firefox 17 before it get shipped?
> The performance issues I've seen would make many people walk away from
> Firefox (if they happen to get hit by it).

It also seems to cause crashes, even on heavyweight machines, if Sync's trace logging is enabled -- it seems to act as a significant multiplier for rapid chrome memory allocation.
Comment 15 [PTO to Dec5] Bill McCloskey (:billm) 2012-10-29 17:53:19 PDT
Yes, I backed out the patch in bug 806644 and I'm asking for approval to land on aurora and beta. So, most likely, this will be fixed for FF17.
Comment 16 Ryan VanderMeulen [:RyanVM] 2012-10-30 08:05:25 PDT
Backout cset:
https://hg.mozilla.org/mozilla-central/rev/cb997ba8433b

Note You need to log in before you can comment on or make changes to this bug.