964804 - Jobs not being scheduled

Status: RESOLVED FIXED

(Infrastructure & Operations Graveyard :: CIDuty, task)

Description

[Ed Morley [:emorley]]

Tests are not being scheduled once builds are complete.
Philor reports this happened ~10 hrs ago too.

All trees closed.

Comment 1

[Ed Morley [:emorley]]

philor: https://tbpl.mozilla.org/?showall=1&tree=B2g-Inbound&onlyunstarred=1
philor: where's the orange?
philor: yeah, G is permaorange, Gi is over 50% red, so... where's the orange?
philor: 04:36 push got its linux desktop coalesced to a 04:51 push? 04:51 push got no tests scheduled at all?
philor: that looks like either totally busted scheduling, or, a reconfig that made all my dreams come true, not sure which
...
philor: edmorley|sheriffduty: the former, you should close every tree, we haven't scheduled tests on builds that finished 40 minutes ago
philor: and judging by my experience last night when I noticed it and started screaming one minute before it unstuck, closing should be enough to unstick it
edmorley|sheriffduty: philor: was there a bug for last night, or should I file new? (I didn't seen anything in the bugmail)
philor: edmorley|sheriffduty: nope, I started screaming "urgent:" precisely one minute before it unstuck :)

Comment 2

[Chris AtLee [:catlee]]

Looking at https://secure.pub.build.mozilla.org/buildapi/self-serve/try/rev/4a4d24c24588

The change was pushed at 07:15:57. Buildbot picked up the change at 07:16:27:
2014-01-28 07:16:27-0800 [HTTPPageGetter,client] adding change, who [e-mail], 1 files, rev=4a4d24c24588827cc045b49ed35a0d4f8155d144, branch=try, repository=, comments try: -b do -p linux,macosx64,win32,android,emulator -u mochitests,reftest -t none, category None, project

submittime for these builds isn't much later, until 07:32:06, where we see a few entries like this:
2014-01-28 07:32:05-0800 [-] b2g_try-b2g: propfunc returned {'builduid': '742a333baa8a498798ec59f68bd97bc5'}

which matches the builduid in the request here https://secure.pub.build.mozilla.org/buildapi/self-serve/try/build/36050468

Comment 3

[Ed Morley [:emorley]]

Trees reopened; leaving open for further investigation :-)


philor: is there any way that nagios can watch the scheduler?
catlee: philor: to notice when it's stuck?
philor: or is there no way to see a scheduling backlog except by being the scheduler that has a 45 minute backlog right now?
philor: like the 30 minute backlog it had last night
philor: and the one that I now wonder if we have every single night, right before we schedule all the things at once and cause the nightly closures
catlee: philor: I'll take a peek

catlee: edmorley|sheriffduty: just tests?
RyanVM: catlee: well, my push to c-c from 6 minutes ago isn't even showing pending builds, so I would guess "everything"
philor: catlee: probably over, ended at 07:48
edmorley|sheriffduty: catlee: other than old cruft, https://secure.pub.build.mozilla.org/buildapi/pending is looking pretty empty
catlee: philor: ok. how about last night?
philor: https://secure.pub.build.mozilla.org/buildapi/self-serve/b2g-inbound/rev/7bc0d1e21cb7 - emulator-debug build finished at 07:25, scheduled tests at 07:48
philor: catlee: both, I think, since my try build taking forever to show up was what first made me start looking
philor: catlee: yeah, both: https://secure.pub.build.mozilla.org/buildapi/self-serve/try/rev/4a4d24c24588 was pushed at 07:15
catlee: philor: so I see tons of pending jobs piling up until around 6:49, when they start to go down again
catlee: it looks like jobs were getting scheduled...
cyborgshadow: catlee: 6:49 what timezone?
catlee: cyborgshadow: PT
cyborgshadow: catlee: so...1 hour 5 minutes ago?
catlee: cyborgshadow: yeah
cyborgshadow: catlee: I have a huge spike at around 6:35 PT - 6:50 PT
cyborgshadow: catlee: but it started pretty precisely around 6:35
catlee: cyborgshadow: spike of what?
cyborgshadow: catlee: db traffic
catlee: philor: so I see the sendchange at 07:24:19
catlee: cyborgshadow: any other spikes you see?
cyborgshadow: catlee: I'm only the database guy. New relic isn't monitoring the buildbot application, so I can see db traffic and queries.
cyborgshadow: catlee: I can try and dig to see what those queries were.
catlee: just wondering if it's happened before
cyborgshadow: catlee: note however though, I'm finding several potential improvements to buildbot today and seeking approval to make them happier.
cyborgshadow: catlee: that I can check.
cyborgshadow: catlee: yes it has. It tends to happen 1 or 2 times a day, but the last 3 days in particular it's been at a high spike all day.
catlee: cyborgshadow: around what times?
catlee: buildapi is really slow right now...
edmorley|sheriffduty: catlee: seems down for retriggers again
bhearsum: catlee: slaverebooter is running, that may be affecting it...
cyborgshadow: catlee: the last 3 days one started around 14:00-16:00 on the 25th. Prior spikes align with that time: 14:00-16:00 they start ramping up. They don't come down until 05:00 usually.
cyborgshadow: catlee: fwiw: after implementing the changes I did a few minutes ago, we're at an alltime low on utilization on the box currently.
cyborgshadow: catlee: but network traffic is up, so it's a positive indication surrounding the changes. (utilization down +network traffic up = change was positive)
dustin: cyborgshadow++ awesome :)
catlee: nice
cyborgshadow: dustin: fwiw: we went from a new entry in the slow query log every 1-2 seconds to now only having 2 in the last 40 minutes.
dustin: awesome!
dustin: we're still slow though :(
dustin: I wish I could tell which bit of buidlapi is causing the slow
dustin: I strongly suspect reporter.py
dustin: but it's possible that memcache's hit rate is lower than redis
dustin: or that the web UI, now that it's on a faster host, is causing more hits
dustin: or that slaverebooter is bludgeoning it
bhearsum: it wouldn't shock me if it's that
bhearsum: slave rebooter runs for just over an hour on a 43 */4 * * * schedule

Comment 4

[Chris AtLee [:catlee]]

Looks like it didn't get around to noticing the changes until this:

2014-01-28 07:21:26-0800 [-] Looking at changes: [<buildbot.changes.changes.Change instance at 0x5a89f38>, <buildbot.changes.changes.Change instance at 0x117d4248>, <buildbot.changes.changes.Change instance at 0x6f32c68>, <buildbot.changes.changes.Change instance at 0x989d3b0>, <buildbot.changes.changes.Change instance at 0xba1d2d8>, <buildbot.changes.changes.Change instance at 0xc3a2128>]
2014-01-28 07:21:26-0800 [-] TryChooser OPTIONS : MESSAGE Namespace(build=['opt', 'debug'], talos=u'none', test=u'mochitests,reftest', user_platforms=set([u'win32', u'android', u'macosx64', u'emulator', u'linux'])) : try: -b do -p linux,macosx64,win32,android,emulator -u mochitests,reftest -t none

Comment 5

[Chris AtLee [:catlee]]

I don't know what else I can do without catching it in action again

Comment 6

[Chris AtLee [:catlee]]

Possibly related, we're seeing bad latency to the db:
 1. 10.26.48.1                                       0.0%    96  253.5 240.2 210.0 278.8  15.1
 2. v-1034.border2.scl3.mozilla.net                  1.1%    96  532.2 482.6 412.3 554.6  29.8
 3. v-1030.fw1.scl3.mozilla.net                      0.0%    95  512.5 481.9 418.7 563.2  30.3
 4. buildbot-rw-vip.db.scl3.mozilla.com              0.0%    95  493.7 486.4 424.6 554.6  28.0

Comment 7

[Ryan VanderMeulen [:RyanVM]]

Trees were closed for this again at 09:24.

Comment 8

[Ryan VanderMeulen [:RyanVM]]

Some trees were reopened at 13:12. In order to avoid a big load spike, the remaining trees were reopened at 15:09.

Comment 9

[Phil Ringnalda (:philor)]

It's gotten bad enough again (really, has been bad enough for the last hour or two, but I'm slow) that I've closed all trees.

Comment 10

[Ryan VanderMeulen [:RyanVM]]

And closed again.

Comment 11

[Hal Wine [:hwine] (use NI)]

releng firewall upgrade and other measures have corrected the ping times that was the root cause.