| Posted | Nick | Remark | |
|---|---|---|---|
| #openstack-nova - 2019-05-16 | |||
| 19:17:47 | melwitt | this is get_vnc_console https://github.com/openstack/nova/blob/master/nova/compute/api.py#L3876 | |
| 19:17:53 | sean-k-mooney | that is what called form here https://github.com/openstack/nova/blob/master/nova/api/openstack/compute/consoles.py#L48 | |
| 19:18:37 | sean-k-mooney | oh ok so that one does a downcall to the compute cool | |
| 19:18:41 | melwitt | I think that's the xen thing that no one except old rax cluster uses | |
| 19:19:05 | dansmith | this is one reason I suggested using a different call | |
| 19:19:14 | dansmith | because console has all manner of stuff wrapped up in it | |
| 19:19:25 | dansmith | I think pause/unpause is a call right? use that | |
| 19:19:33 | dansmith | or just boot/delete | |
| 19:19:43 | imacdonn | looking at my py2 devstack, it seems the connection reset is observed at a difference place | |
| 19:19:47 | sean-k-mooney | ya or the server diagnostics | |
| 19:19:50 | dansmith | well, boot isn't a call from the apiI guess, so pause | |
| 19:19:53 | dansmith | sean-k-mooney: or that | |
| 19:20:51 | sean-k-mooney | ... of cose they are only in the nova client... | |
| 19:20:53 | melwitt | imacdonn: in my py2 devstack, I see the connection reset in nova-api log (for get_vnc_console) | |
| 19:22:06 | sean-k-mooney | nova diagnostics <server> is definetly a down call to the compute but nova get-vnc-console should be too | |
| 19:43:05 | sean-k-mooney | efried: just finsihed reviewing https://review.opendev.org/#/q/topic:bug/1809095+(status:open+OR+status:merged) | |
| 19:43:41 | sean-k-mooney | efried: im provisionly +1 on both i have one question on the second patch but its and edgecase | |
| 19:55:16 | imacdonn_ | sean-k-mooney: vnc console does rpc .. you can see it in the trace at http://paste.openstack.org/show/751486/ | |
| 19:55:31 | imacdonn_ | (the trace for the RPC timeout) | |
| 19:56:10 | sean-k-mooney | those call to the compute node? ya | |
| 19:56:33 | imacdonn_ | yes | |
| 19:56:36 | sean-k-mooney | but it was not clear what api enpoint osc was calling for openstack console url show | |
| 19:57:10 | sean-k-mooney | if you are using the nova clintes get-vnc-console that was defietly downcalling | |
| 19:57:36 | sean-k-mooney | osc is doing some magic to figure out what console type the vm is uesing | |
| 19:57:49 | sean-k-mooney | as it has a singel command that works for all console types | |
| 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 | |