Earlier  
Later
New Search
Posted Nick Remark
#openstack-nova - 2019-05-16
19:58:49 sean-k-mooney so i was not sure if the osc command would actully hit the db or the compute node
19:59:26 imacdonn_ yeah, def does ... that stack trace resulted from 'openstack console url show ...'
20:00:43 sean-k-mooney its kind of strange
20:00:54 sean-k-mooney we can see the hearbeat_tick printed
20:01:05 imacdonn_ yeah, but only once
20:01:13 imacdonn_ it should be period from that point on
20:01:17 imacdonn_ periodic
20:01:25 sean-k-mooney no its there several times
20:01:37 sean-k-mooney look at line 140 to 153
20:01:39 imacdonn_ for the same thread?
20:01:58 imacdonn_ in any case, in the non-patched case, it's continuous .. in the patched case, it goes quiet
20:03:14 imacdonn_ those are all within the same second
20:04:24 imacdonn_ I *may* have just found what's different about my env vs. others and devstack
20:07:58 sean-k-mooney have you adjusted any of the messaging timeouts?
20:09:19 imacdonn no, but in my uwsgi config, had "threads = 8" ... I've removed that now, and it seems that the reconnect is working
20:10:09 sean-k-mooney this is the osa one https://opendev.org/openstack/openstack-ansible-os_nova/src/branch/master/templates/nova-uwsgi.ini.j2
20:10:34 imacdonn I'm thinking (loosely) that maybe in the threads=X case, the thread making the RPC call has fired before the thread handling heartbeats has noticed the connection failure and reestablished
20:10:48 sean-k-mooney which defaults to 1
20:11:23 imacdonn yeah. devstack doesn't set it at all
20:11:33 imacdonn I was thinking to figure out what uwsgi does by default .. guessing 1
20:11:41 imacdonn I was *trying....
20:11:52 sean-k-mooney im lookig fot atht too now :)
20:20:04 efried sean-k-mooney: thanks for reviewing.
20:21:49 sean-k-mooney imacdonn: finally https://github.com/unbit/uwsgi/blob/3149df02ed443131c54ea6afb29fcbb0ed4d1139/core/init.c#L96 it default to 1
20:22:13 sean-k-mooney imacdonn: the default is not in the docs
20:23:12 imacdonn hah, thanks
20:23:27 sean-k-mooney for c code uwsgi is actully not to hard to read but finding stuff is a pain
20:24:30 sean-k-mooney imacdonn: so i think we know why vexhost are fine
20:24:47 sean-k-mooney osa expecitly sets it to 1
20:25:11 imacdonn yeah, I think so ... the reconnect seems to be consistently working since I've changed that
20:26:14 imacdonn so now I wonder if I'm giving anything up by doing that, in terms of performance .... haven't really found any good guidance on processes/threads sizing for these things
20:26:49 sean-k-mooney well osa is running with 64 processes and 1 thread per process i think
20:27:03 sean-k-mooney sorry a max of 16 processes
20:27:12 sean-k-mooney each with 1 thread
20:29:09 dansmith is this threads per worker process?
20:29:36 dansmith if so, it could be that multiple threads per worker try to share a single connection pool,
20:29:37 sean-k-mooney yes i belive so
20:29:48 dansmith but maybe one of them gets responsibility for the eventlet heartbeat thread,m
20:30:07 dansmith so if that thread isn't the first scheduled after a period of inactivity, then heartbeat isn't run, we try to use the connection and are stuck?
20:30:11 dansmith something like that?
20:30:27 imacdonn yes, "something like that" is what it feels like
20:30:46 sean-k-mooney well im not sure if we have process=2 thread=2 if that wil result in 2 or 4 python interperters
20:31:05 sean-k-mooney e.g. are teh treads os threads or python threads
20:31:07 melwitt so heartbeat threads is the one that reconnects things if detected to not be open
20:31:08 dansmith I think that would mean two interpreters, two threads each
20:31:13 melwitt *thread
20:31:37 dansmith melwitt: no,
20:31:38 sean-k-mooney right so the gil would mean that only one of the two thread woudl actully be running in each python interperter
20:32:01 dansmith I think any of them would do it, but running or not running the heartbeat but definitely running the other threads is where I can see it getting wonky
20:32:14 sean-k-mooney so maybe it is staving the heart beat thread as you suggest
20:34:50 melwitt I guess I'm confused. so far, I thought the heart beat thread doesn't affect anything other than to log a message saying "connection reset" if it's been idle > 60s. how does its starvation prevent reconnection?
20:36:37 dansmith no, I think the heartbeat thread is just the first thin scheduled after a period of inactivity, so it's the first thing that hits the dead connection
20:36:41 imacdonn I don't think reconnection is being prevented .. you can see it happen in the log at http://paste.openstack.org/show/751486/ ... but I tihnk it might matter *when* it happens
20:37:35 imacdonn (line 227 in the log shows reconnected)
20:38:28 melwitt oh yeah, I see. so why MessagingTimeout? sorry, I just don't get this
20:39:00 imacdonn maybe the RPC request got sent to a dead connection, somehow??
20:39:04 sean-k-mooney the "best" respocne in https://www.reddit.com/r/Python/comments/4s40ge/understanding_uwsgi_threads_processes_and_gil/ seam to gel with how i tought this would be working
20:40:06 sean-k-mooney if we are initalising the connection pool as a module vaiable we are sharing it between the threads and all the therads are being run sequtually under the gil
20:40:47 sean-k-mooney so with threads=8 you had 8 instance of the api all sharing the same connection pool
20:43:58 sean-k-mooney there is a follow futher down where there is a code wakthorugh which explaing the init flow
20:50:52 artom efried, you added me to that review but I think you'll get through them before I get a chance to even start
20:51:04 artom We're all putting out CI fires with our upcoming release
20:51:09 artom (Maybe I shouldn't say that in public?)
20:51:35 efried artom: no worries, I noticed you were on the one above it, which is the important one, but that one's getting a -1 from me in a few minutes here, so you got time :)
20:52:12 artom https://photos.app.goo.gl/fRQoJpE5WnqYeP6E8 was my desk not long ago. Yes, I needed both those drinks to get through the bugs
20:53:30 artom ... and I need to go pick kids up
20:53:33 artom o/
20:54:42 sean-k-mooney dansmith: imacdonn so i think this is the issue https://github.com/openstack/nova/blob/760fc2de32057817bafc0a1512a735dab1c7c68a/nova/rpc.py#L69
20:55:10 sean-k-mooney we intial the transport as a module level vaiable so that is shared across all wsgi ap instace in the same process
20:55:43 sean-k-mooney that end up calling https://github.com/openstack/oslo.messaging/blob/40c25c2bde6d2f5a756e7169060b7ce389caf174/oslo_messaging/transport.py#L192
20:55:52 dansmith sean-k-mooney: well, that's the global thing that does the connectioning to rabbit, yeah
20:56:17 sean-k-mooney which calls the diver manger to construt RabitmqDriver instance which has a connection pool internally
20:56:23 dansmith yup
20:56:30 sean-k-mooney so the connection pool become global too
20:56:35 dansmith right
20:57:09 dansmith sean-k-mooney: this is only part of the equation by the way
20:57:13 sean-k-mooney and sicne we have muleple python threads and the gil limits there exectuion we could starge the heartbeat
20:57:32 dansmith sean-k-mooney: because I think that TRANSPORT is what we use for initializing a connection which we would use if we were going to start a server and listen
20:57:58 dansmith sean-k-mooney: but connections to the *cell* rpc brokers happens in nova.context, because we connect per cell once we read that out
20:58:19 dansmith sean-k-mooney: it's effectively the same situaton though, I imagine they both suffer from the same behavior
20:59:18 sean-k-mooney riping out those gloabls would proably be a pain
20:59:40 dansmith sean-k-mooney: https://github.com/openstack/nova/blob/760fc2de32057817bafc0a1512a735dab1c7c68a/nova/context.py#L376
20:59:56 dansmith sean-k-mooney: having implemented multi-cell tests, I can assure you it is
21:00:24 dansmith but also, it's the thing that avoids us having to build that stuff up a hundred times, even for a single request where we make a couple rpc calls
21:00:41 sean-k-mooney and yep we are storing the connection in a module level CELL_CACHE
21:00:47 dansmith right
21:00:49 sean-k-mooney so yep ist the same issue
21:01:11 melwitt reconnect
21:01:11 melwitt so if the heartbeat thread gets starved, then connections get closed down, and then if reconnect in another thread races with an API request coming in and the API request hits before the reconnect, it will get the MessagingTimeout? I'm looking through the oslo.messaging code and from what I can tell, the reconnect is done on-the-fly when a message is attempted to be sent, so I don't understand how a different thread is doing the
21:02:02 cmart Hello -- can someone help me understand the process by which ephemeral disks get a filesystem label? It's usually `ephemeral0` but I have an instance created today which has `ephemeral0_160_40`
21:02:16 melwitt but if that were true that oslo.messaging automatically tries to reconnect, then the API request shouldn't fail, it would try to reconnect. so, nevermind, I don't know what I'm talking about
21:02:50 sean-k-mooney melwitt: well thats praobly the proble it like is not auto recoonectin on making a request
21:03:06 sean-k-mooney we poroubl have preiodic task or something that is doing th reconnection
21:03:12 sean-k-mooney that is jsut a guess
21:03:25 sean-k-mooney i havent look at this that closely in the past
21:03:42 melwitt yeah. I just can't tell what triggers a reconnect. in https://github.com/openstack/oslo.messaging/blob/40c25c2bde6d2f5a756e7169060b7ce389caf174/oslo_messaging/_drivers/amqpdriver.py I see a bunch of stuff where "recoverable error" will try to reconnect
21:04:12 sean-k-mooney are we using the amqp driver or the rabbitmq one
21:04:16 melwitt sorry, wrong link https://github.com/openstack/oslo.messaging/blob/9.5.0/oslo_messaging/_drivers/impl_rabbit.py
21:04:50 melwitt that other link was me trying to find where/how it raises MessagingTimeout
21:05:54 sean-k-mooney hum i wonder if setting https://github.com/openstack/oslo.messaging/blob/9.5.0/oslo_messaging/_drivers/impl_rabbit.py#L145-L149 to 0 would help?

Earlier   Later