Earlier  
Later
New Search
Posted Nick Remark
#openstack-nova - 2017-06-05
15:46:17 mriedem mordred: also, i'm not sure why this would have regressed in the last few days, i don't see anything related to changing the startup order in devstack
15:46:39 mordred mriedem: it might just have always been a race and something else caused something else to be slow so it just started showing up
15:47:09 cfriesen_ mriedem: mordred: in our environment the users are generally very tightly couple to the admins, so we expose all the sched failure logs directly to the user
15:47:13 mordred mriedem: or, actually,it could have always been here, but now something is improved so we get all the way to tests before the self-healing
15:47:32 mordred cfriesen_: yah - I have admin on almost none of my clouds :)
15:47:50 mordred so I'm usually the annoying voice of "how do I learn this as a non-admin"
15:48:57 mriedem looking at the placement logs it takes quite a while for it to be ready it looks like
15:49:01 mriedem http://logs.openstack.org/95/468095/2/gate/gate-shade-functional/3f5d8dc/logs/screen-placement-api.txt.gz
15:50:06 mriedem the first request i see it process is this:
15:50:07 mriedem Jun 02 12:46:58.883989 ubuntu-xenial-osic-cloud1-s3500-9104911 devstack@placement-api.service[22675]: DEBUG nova.api.openstack.placement.requestlog [None req-6e9651be-51e5-40e6-a887-bd72120060a0 service placement] Starting request: 10.39.244.211 "GET /placement/resource_providers?resources=MEMORY_MB%3A256%2CVCPU%3A1" {{(pid=22678) __call__ /opt/stack/new/nova/nova/api/openstack/placement/requestlog.py:38}}
15:50:31 mriedem which is the one during scheduling
15:50:38 mriedem so....placement isn't up when the compute service is trying to check in
15:50:41 mriedem wtf
15:51:00 mriedem takes >1 minute to startup placement-api
15:51:17 mriedem i don't know if that's systemd / uwsgi shenanigans or what
15:51:24 mriedem cdent: ^ any ideas?
15:51:36 cdent mriedem: sorry on intense hangout
15:51:44 cdent will catch up soonish
15:52:58 mriedem cdent: just tell them we're going to start doing noop claims everywhere
15:52:59 mriedem problem solved
15:54:41 mriedem sdague: maybe your spidey sense can detect something ^?
15:55:39 mriedem looks like we start placement here http://logs.openstack.org/95/468095/2/gate/gate-shade-functional/3f5d8dc/logs/devstacklog.txt.gz#_2017-06-02_12_45_42_061
15:55:47 mriedem 2017-06-02 12:45:42.061 | Waiting for placement-api to start...
15:56:41 mriedem which is *after* we started n-cpu
15:56:45 mriedem derp
15:56:56 jaypipes alex_xu: https://review.openstack.org/#/c/469578
15:57:15 sdague mriedem: it's only 4 seconds for start
15:57:30 mriedem http://logs.openstack.org/95/468095/2/gate/gate-shade-functional/3f5d8dc/logs/devstacklog.txt.gz#_2017-06-02_12_45_10_006
15:58:08 mriedem so we start placement-api 32 seconds after we start nova-compute,
15:58:22 mriedem nova-compute starts up and tries to register the compute node with placement but gets a 503 b/c placement isn't up yet,
15:58:33 mriedem meanwhile, the compute host is mapped to the cell and tests start,
15:59:00 mriedem test tries to create a server, scheduler asks placement for a resource provider (compute node) for the server, there are 0 because none are registered, and the server create fails,
15:59:18 mriedem 15 seconds later, n-cpu registers the compute node with placement during it's periodic task to update avialable resources (1 minute cron)
15:59:21 openstackgerrit Jay Pipes proposed openstack/nova master: placement project_id, user_id in PUT /allocations https://review.openstack.org/469634
15:59:21 openstackgerrit Jay Pipes proposed openstack/nova master: placement: Add GET /usages to placement API https://review.openstack.org/469635
15:59:22 openstackgerrit Jay Pipes proposed openstack/nova master: placement: use separate tables for projects/users https://review.openstack.org/470645
15:59:22 mriedem mordred: ^
16:01:02 mriedem cdent: edleafe: jaypipes: dansmith: can someone summarize whatever changes are coming out of the hangout you just had in the dev ML please?
16:01:10 dansmith mriedem: jay is on it
16:01:15 jaypipes mriedem: yes.
16:01:21 jaypipes mriedem: I will. etherpad being worked.
16:01:26 mriedem ok thanks
16:01:47 sdague mriedem: yeh, our order is super bonkers
16:01:49 sdague we should fix that
16:01:56 cdent mriedem: the devstack problem, appears to be that fundamentally placement starts after nova in stack.sh
16:02:06 mriedem cdent: yeah
16:02:07 sdague I actually have no idea why placement comes after nova, that's just silly
16:02:21 sdague someone propose the ordering patch, and I'll fast approve
16:02:27 mriedem i think it's because nova.sh sets up the config or something?
16:02:36 mriedem might be circular dep
16:02:39 cdent we can start later though
16:02:45 sdague mriedem: the config stage is a lot earlier
16:02:47 cdent we can config after but start before
16:02:49 sdague and should be done
16:02:50 cdent I'll push somehting
16:02:55 cdent one sec
16:02:57 sdague yeh
16:03:21 cdent is there a bug to related to in the commit?
16:03:34 mriedem cdent: https://bugs.launchpad.net/devstack/+bug/1695634
16:03:34 openstack Launchpad bug 1695634 in devstack "Something weird just broke in creating servers" [Undecided,New]
16:07:10 cdent sdague, mriedem : https://review.openstack.org/471042
16:07:16 cdent i started before neutron and cinder too
16:10:40 mriedem cdent: question inline
16:12:58 cdent mriedem: answer inline
16:18:22 mriedem ok i'd just remove the comment
16:18:24 mriedem the note i mean
16:18:27 mriedem the comment is fine, the note is confusing
16:18:32 cdent k
16:19:03 cdent done
16:19:20 mriedem thanks
16:28:21 mordred cdent, mriedem: woot! thank you!
16:29:13 mordred I'm glad this turned out to be potentially an actual issue and not just a random testing weird
16:29:21 cdent was a good spot
16:29:41 cdent that the problem hasn't come up sooner is odd
16:29:49 cdent you must be doing something faster than other things are
16:30:05 mordred yah. it's still interesting why it only started showing up friday
16:30:29 cdent did reverting that change you reverted make any difference?
16:30:32 mriedem i don't see anything in devstack or nova around friday that would cause the start time issue
16:30:35 mordred cdent: we have a very low overhead to start running tests and our tests are all pretty quick - so I think we're a really good race from end-of-devstack to "and now stuff is running"
16:31:32 mordred mriedem: onlything I can think of is that something about the fix for the stacktrace maybe also caused something to not issue an extra registration sync
16:31:57 mriedem my patch stopped doing the pointless update_instance_info rpc cast from n-cpu to n-sch
16:31:59 mordred so maybe there was an accidental retry happening that the stacktrace fix removed?
16:31:59 cdent periodic job timing?
16:32:00 mriedem sending an empty list
16:32:38 mriedem the periodic kicks in ~1 minute after init_host on the compute
16:33:11 mriedem if update_instance_info were an rpc call that would make sense why things were slower during n-cpu startup, but it's a cast
16:33:17 cdent If I remember right, init_host calls all the same stuff that the periodic does/
16:33:33 jaypipes edleafe, dansmith, cdent, alex_xu: https://etherpad.openstack.org/p/placement-allocations-straw-man
16:33:57 mriedem cdent: the pre_start_hook calls update_available_resource
16:34:06 mriedem which calls the RT to create the ComputeNode record and do some things yeah
16:34:19 mriedem that's different from the update_instance_info stuff cast to the scheduler
16:34:24 cdent thanks jaypipes, I'm going home, will look from there, where the lack of people ought to allow proper attention
16:34:29 mriedem ^ is all about server group affinity/anti-affinity filters
16:34:30 jaypipes kk
16:35:13 dansmith jaypipes: can I reset colors on that so we can see only deltas from this?
16:35:21 cdent dansmith++
16:35:22 jaypipes dansmith: go for it.
16:35:25 cfriesen_ there are so many races around server group affinity/antiaffinity it's not even funny
16:37:36 cfriesen_ jaypipes: is it possible to have floating point values for resources?
16:37:45 cfriesen_ or is it integer only?

Earlier   Later