681900 - TBPL is using a lot of CPU with usebuildbot=1

Status: RESOLVED FIXED

(Tree Management Graveyard :: TBPL, defect)

Description

[Mounir Lamouri (:mounir)]

I've been trying to use http://tbpl.allizom.org with usebuildbot=1 for all my TBPL tabs (2 to 3 tabs open 24/7) since a few days and Firefox was hardly usable with sometimes a low script dialog popping in the TBPL tabs. I was reloading the tabs regularly to make sure it wasn't due to a high amount of data being used.

CCing Mike who told me suffer from the same issue and thinks it might come from push with a lot of commits.

FWIW, I just move back my tabs to tbpl.mozilla.org/ without usebuildbot=1 and things seem back to normal.

Comment 1

[Randell Jesup [:jesup] (needinfo me)]

I was seeing 20-sec pauses (on a Xeon-1280!) due to allizom with usebuildbot=1, and getting the dialog.  I killed the app-tab and opened a new regular one a while later; the problem seems to have either gone away or gotten much better. 

Before I killed it I grabbed a short jprof profile of one of the freezes (starting when I noticed echo failing, stopping when I saw my typing appear).

I'll attach it.

Comment 2

[Randell Jesup [:jesup] (needinfo me)]

Attachment: jprof of a few seconds of the "hang" due to allizom

Comment 3

[Markus Stange [:mstange]]

Do you remember how many pushes were visible?

Comment 4

[Arpad Borsos [:Swatinem]]

A firebug profile, also with an overview of the network tab would be good. We do one request per revision so that may be one of the problem sources.
Do those hangs occur every 2 minutes (the tbpl refresh interval)? How big is the compartment? Maybe GC pauses are another problem source.

Comment 5

[Randell Jesup [:jesup] (needinfo me)]

No idea on number of pushes.  The tab had been open for a day or two.

Every 2 minutes is quite possible, though I didn't measure it - I was busy with other things.  GC is unlikely; process size didn't explode, and 20 sec for GC... It could have been causing repeated GC's though so fast the UI didn't get to run for 20s.  Others were reporting similar problems (frequent comments in #developers).

Comment 6

[Marco Bonardo [:mak]]

Fwiw, I have the same exact problem with tinderbox mode on allizom, when there is a large number of ongoing changesets I get long pauses with 1-2 seconds hangs in the browser UI. My CPU is "almost" as fast as jesup's (i7 2600), should't be that bad.

Comment 7

[Marco Bonardo [:mak]]

note that I usually have 3 tbpl app-tabs open and if there is no high number of pushes ongoing I don't see any slowdown.

Comment 8

[Randell Jesup [:jesup] (needinfo me)]

It's doing it again now, and it does roughly appear to be every 2 minutes - 10 seconds of 100% use of one core; UI frozen

Comment 10

[Randell Jesup [:jesup] (needinfo me)]

about:memory 

│  ├────192,510,822 B (06.17%) -- compartment(http://tbpl.allizom.org/?usebuildbot=1)
│  │    ├───92,119,040 B (02.95%) -- gc-heap
│  │    │   ├──53,547,024 B (01.72%) -- objects
│  │    │   ├──24,981,952 B (00.80%) -- strings
│  │    │   ├───9,616,136 B (00.31%) -- arena-unused
│  │    │   ├───2,015,104 B (00.06%) -- shapes
│  │    │   ├───1,239,144 B (00.04%) -- arena-padding
│  │    │   └─────719,680 B (00.02%) -- arena-headers
│  │    ├───61,155,064 B (01.96%) -- string-chars
│  │    ├───31,025,624 B (00.99%) -- object-slots
│  │    ├────3,215,360 B (00.10%) -- mjit-code
│  │    ├────2,645,074 B (00.08%) -- scripts
│  │    ├────1,356,088 B (00.04%) -- property-tables
│  │    ├──────434,408 B (00.01%) -- tjit-data
│  │    │      ├──148,000 B (00.00%) -- allocators-reserve
│  │    │      ├──147,648 B (00.00%) -- trace-monitor
│  │    │      └──138,760 B (00.00%) -- allocators-main
│  │    ├──────429,092 B (00.01%) -- mjit-data
│  │    └──────131,072 B (00.00%) -- tjit-code

Comment 11

[Randell Jesup [:jesup] (needinfo me)]

Attachment: Extended jprof (taken over 3 pauses)

This is a composite jprof across the one I captured last night and two more this morning; each around 5ish seconds long.

Comment 12

[Randell Jesup [:jesup] (needinfo me)]

1/2 hour later; may (*) have leaked/grown around 8mb

│  ├────200,506,903 B (06.22%) -- compartment(http://tbpl.allizom.org/?usebuildbot=1)
│  │    ├───94,957,568 B (02.94%) -- gc-heap
│  │    │   ├──55,761,968 B (01.73%) -- objects
│  │    │   ├──26,018,496 B (00.81%) -- strings
│  │    │   ├───9,082,824 B (00.28%) -- arena-unused
│  │    │   ├───2,067,008 B (00.06%) -- shapes
│  │    │   ├───1,285,416 B (00.04%) -- arena-padding
│  │    │   └─────741,856 B (00.02%) -- arena-headers
│  │    ├───63,884,288 B (01.98%) -- string-chars
│  │    ├───32,378,968 B (01.00%) -- object-slots
│  │    ├────4,067,328 B (00.13%) -- mjit-code
│  │    ├────2,645,307 B (00.08%) -- scripts
│  │    ├────1,386,480 B (00.04%) -- property-tables
│  │    ├──────677,932 B (00.02%) -- mjit-data
│  │    ├──────377,960 B (00.01%) -- tjit-data
│  │    │      ├──148,000 B (00.00%) -- allocators-reserve
│  │    │      ├──147,648 B (00.00%) -- trace-monitor
│  │    │      └───82,312 B (00.00%) -- allocators-main
│  │    └──────131,072 B (00.00%) -- tjit-code

Comment 13

[Arpad Borsos [:Swatinem]]

Well we really do have a lot of objects around, so the high memory usage is kind of expected...
A firebug profile would be really useful for the hangs (probably js), I cant extract anything from the jprof.

Comment 14

[Mounir Lamouri (:mounir)]

Are they more data stored and computation done when using buildbot?

Comment 15

[Matt Brubeck (:mbrubeck)]

Well, during times when tinderbox is lagged by several hours, the usebuildbot view will often have many more results visible...

Comment 16

[Mounir Lamouri (:mounir)]

I never had any major issue with TBPL performance before and using buildbot really kills my machine (which is damn fast!). Are they so many missing results?

Comment 17

[Arpad Borsos [:Swatinem]]

It should be less, in theory. Need to take a deeper look what is going on there.

Comment 18

[Markus Stange [:mstange]]

In continuous updates, the Tinderbox backends only requests new builds since the last refresh. The Buildbot backend re-requests all builds for all pushes.
getRevisionBuilds.php could use a "since" parameter.

Comment 19

[Randell Jesup [:jesup] (needinfo me)]

I'm going to stop worrying about this and assume whomever is responsible for tbpl.allizom can reproduce it at will.   Final mem measurement after several more hours:

│  ├────250,869,000 B (07.36%) -- compartment(http://tbpl.allizom.org/?usebuildbot=1)
│  │    ├──114,454,528 B (03.36%) -- gc-heap
│  │    │  ├───69,120,400 B (02.03%) -- objects
│  │    │  ├───31,808,736 B (00.93%) -- strings
│  │    │  ├────8,157,024 B (00.24%) -- arena-unused
│  │    │  ├────2,907,328 B (00.09%) -- shapes
│  │    │  ├────1,566,864 B (00.05%) -- arena-padding
│  │    │  └──────894,176 B (00.03%) -- arena-headers
│  │    ├───79,064,440 B (02.32%) -- string-chars
│  │    ├───40,145,296 B (01.18%) -- object-slots
│  │    ├────9,183,232 B (00.27%) -- mjit-code
│  │    ├────3,991,744 B (00.12%) -- scripts
│  │    ├────1,988,520 B (00.06%) -- property-tables
│  │    ├────1,395,120 B (00.04%) -- mjit-data
│  │    ├──────515,048 B (00.02%) -- tjit-data
│  │    │      ├──219,400 B (00.01%) -- allocators-main
│  │    │      ├──148,000 B (00.00%) -- allocators-reserve
│  │    │      └──147,648 B (00.00%) -- trace-monitor
│  │    └──────131,072 B (00.00%) -- tjit-code

Comment 20

[Arpad Borsos [:Swatinem]]

Wow, 250M is really unacceptably much.
Starting a fresh tbpl uses 8M, having it run for 2-3 hours bloats that up to 16M, minimizing memory does not help there, so we are definitely leaking something.

Object.keys(Controller._data._finishedResultsWithPush).length <- this is the number of runs we are tracking.
That is something like 1300 for a freshly started tbpl and 1600 for the one that has been running some time. So not a really big growth. Why does our heap grow twice as large?

We seem to create a lot of fragmentation to the js heap:
92.71 MB (24.25%) -- gc-heap-chunk-dirty-unused

So this may as well be related to gc pauses. How do I measure those?

We have a lot of circular refs from runs->pushes->runs->... and so on.

We have a lot of redundant strings (note the high strings and string-chars measurement in the compartment) for the various log urls. Making those getters would cut down on the memory usage a bit. Markus?

Comment 21

[Arpad Borsos [:Swatinem]]

Just a few more quick observations (need to create bugs for those):
- The bugcache saves the whole json that the bz api returns. Only cache those properties that we actually need
- pushes.patches.tags is a jquery-enhanced array. Make that a flat js array.

Comment 22

[Arpad Borsos [:Swatinem]]

Now thats interesting. Using Chromiums profiler, i got the following information:

_afterLoadedHiddenBuildersCallback is the number one on the memory profile, so I suspect we are leaking those.

From the profile, the innerHTML setter called from UserInterface__refreshPushResultsInPushNode is on the highest position. Haven’t I once made sure that we only regenerate the DOM when we have actual changes? Seems that optimization broke.

BuildbotDBUser__createMachineResults with new MachineResult() is also quite high.

Comment 23

[Arpad Borsos [:Swatinem]]

Attachment: probable fix

Chasing down that _afterLoadedHiddenBuildersCallback leak:
When we were calling that callback, we never cleared it. So the next time we call _afterHiddenBuildersHaveLoaded we save it in oldCallback and the chain gets larger every single call.

Hopefully this is it.

Comment 24

[Arpad Borsos [:Swatinem]]

pushed: http://hg.mozilla.org/users/mstange_themasta.com/tinderboxpushlog/rev/2d54516addff
lets get this deployed and tested.

Comment 25

[Phil Ringnalda (:philor)]

Deployed to tbpl.m.o by way of bug 683241, but since I never really saw this, I can't say whether or not that fixed it.

Comment 26

[Arpad Borsos [:Swatinem]]

(In reply to Phil Ringnalda (:philor) from comment #25)
> Deployed to tbpl.m.o by way of bug 683241, but since I never really saw
> this, I can't say whether or not that fixed it.

Why isnt anyone of the tbpl contributors ccd to this ominous bug 683241?

Comment 27

[Robert Helmer [:rhelmer]]

(In reply to Arpad Borsos (Swatinem) from comment #26)
> (In reply to Phil Ringnalda (:philor) from comment #25)
> > Deployed to tbpl.m.o by way of bug 683241, but since I never really saw
> > this, I can't say whether or not that fixed it.
> 
> Why isnt anyone of the tbpl contributors ccd to this ominous bug 683241?

Fixed (not sure it needs to be private anyway but can work that out tomorrow).

Bug 683241 was just about setting up the staging environment, I think bug 669000 is supposed to be for tracking the production push anyway. It just took less time than expected so IT got prod done early :)

Comment 28

[Arpad Borsos [:Swatinem]]

Thanks for CCing.

@jesup: Is this fix working for you?

Comment 29

[Randell Jesup [:jesup] (needinfo me)]

I'd say no.  Perhaps the leak is slower, but yesterday (after running for hours) the compartment use was ~45MB.  Now:

│  ├────161,822,191 B (04.55%) -- compartment(http://tbpl.allizom.org/?usebuildbot=1)
│  │    ├───73,129,984 B (02.05%) -- gc-heap
│  │    │   ├──46,428,864 B (01.30%) -- objects
│  │    │   ├──21,191,328 B (00.60%) -- strings
│  │    │   ├───2,678,904 B (00.08%) -- arena-unused
│  │    │   ├───1,211,136 B (00.03%) -- shapes
│  │    │   ├───1,048,424 B (00.03%) -- arena-padding
│  │    │   └─────571,328 B (00.02%) -- arena-headers
│  │    ├───54,391,152 B (01.53%) -- string-chars
│  │    ├───27,949,296 B (00.79%) -- object-slots
│  │    ├────2,953,216 B (00.08%) -- mjit-code
│  │    ├────1,373,919 B (00.04%) -- scripts
│  │    ├──────745,952 B (00.02%) -- property-tables
│  │    ├──────692,648 B (00.02%) -- mjit-data
│  │    ├──────454,952 B (00.01%) -- tjit-data
│  │    │      ├──172,224 B (00.00%) -- trace-monitor
│  │    │      ├──148,000 B (00.00%) -- allocators-reserve
│  │    │      └──134,728 B (00.00%) -- allocators-main
│  │    └──────131,072 B (00.00%) -- tjit-code

Comment 30

[Arpad Borsos [:Swatinem]]

Thats for the memory usage, I haven´t tackled that yet. Do you still see the periodic hang?

Comment 31

[Randell Jesup [:jesup] (needinfo me)]

I haven't noticed the hang, but I'll keep an eye out.

Comment 32

[Robert Helmer [:rhelmer]]

(In reply to Randell Jesup [:jesup] from comment #29)
> I'd say no.  Perhaps the leak is slower, but yesterday (after running for
> hours) the compartment use was ~45MB.  Now:
> 
> │  ├────161,822,191 B (04.55%) --
> compartment(http://tbpl.allizom.org/?usebuildbot=1)
> │  │    ├───73,129,984 B (02.05%) -- gc-heap
> │  │    │   ├──46,428,864 B (01.30%) -- objects
> │  │    │   ├──21,191,328 B (00.60%) -- strings
> │  │    │   ├───2,678,904 B (00.08%) -- arena-unused
> │  │    │   ├───1,211,136 B (00.03%) -- shapes
> │  │    │   ├───1,048,424 B (00.03%) -- arena-padding
> │  │    │   └─────571,328 B (00.02%) -- arena-headers
> │  │    ├───54,391,152 B (01.53%) -- string-chars
> │  │    ├───27,949,296 B (00.79%) -- object-slots
> │  │    ├────2,953,216 B (00.08%) -- mjit-code
> │  │    ├────1,373,919 B (00.04%) -- scripts
> │  │    ├──────745,952 B (00.02%) -- property-tables
> │  │    ├──────692,648 B (00.02%) -- mjit-data
> │  │    ├──────454,952 B (00.01%) -- tjit-data
> │  │    │      ├──172,224 B (00.00%) -- trace-monitor
> │  │    │      ├──148,000 B (00.00%) -- allocators-reserve
> │  │    │      └──134,728 B (00.00%) -- allocators-main
> │  │    └──────131,072 B (00.00%) -- tjit-code

Could you try on tbpl.mozilla.org?usebuildbot=1 

tbpl.allizom.org is still the old stage server (in transition because it's depended upon as pseudo-production by some people), and it looks like it has not had an "hg pull" in a while (see bug 682586).

We should probably have a way to tell via the web what rev tbpl is on.. I'll file a separate bug for that if there isn't one already.

Comment 33

[Robert Helmer [:rhelmer]]

Just to clarify:

tbpl.mozilla.org is currently on 22f844d0e37a
tbpl.allizom.org is currently on 052258e7b517

According to http://hg.mozilla.org/users/mstange_themasta.com/tinderboxpushlog/ tbpl.allizom doesn't include the patch from this bug.

We'll get this straightened out ASAP, so stage will always be at or ahead of prod.

Comment 34

[Arpad Borsos [:Swatinem]]

I would say this (the recursion) is fixed. Please reopen if you still see this.