| Posted | Nick | Remark | |
|---|---|---|---|
| #openstack-nova - 2021-05-24 | |||
| 16:52:22 | melwitt | dansmith: sorry, I guess I'm confused. I thought you were pointing out that making it configurable in nova would result in still having things be green threads | |
| 16:53:07 | dansmith | melwitt: I'm saying that if you were to ask for native threading in oslo.messaging, but you were monkeypatching python's thread library, then you're going to get greenthreads from your "native" o.msg threading module | |
| 16:53:14 | melwitt | yeah, I'm not sure if anyone else uses eventlet on purpose or if it's only indirectly through oslo.service or oslo.messaging | |
| 16:53:41 | dansmith | glance certainly does use it | |
| 16:53:56 | dansmith | they spawn background threads for import tasks | |
| 16:54:06 | melwitt | dansmith: ah, ok. yeah | |
| 16:54:10 | melwitt | hm, ok | |
| 16:54:13 | dansmith | and they do monkeypatch | |
| 16:54:24 | dansmith | because otherwise it would be kinda pointless | |
| 16:54:46 | dansmith | cinder monkeypatches too | |
| 16:55:20 | dansmith | and they call eventlet operations directly, in a looot of places | |
| 16:55:38 | dansmith | lots of direct threadpool and eventlet.sleep() interaction | |
| 16:55:41 | melwitt | ok, so when I began looking at this, I was assuming that nova does something different than anyone else and that's why we hit the error, but I could not find what that could be | |
| 16:55:43 | dansmith | so I think they're intentionally using eventlet | |
| 16:56:05 | melwitt | meaning, that we are not the only ones using eventlet, yet we're the only ones who hit this | |
| 16:56:46 | dansmith | well, that's what I'm trying to zero in on.. if we're the only ones.. why | |
| 16:57:24 | melwitt | so far, the only thing I can think of is we just having a lot more green threads flying around. either that, or there is something different about the way we do database interactions through sqla | |
| 16:58:21 | melwitt | I couldn't find anything when I looked, but obviously I could have missed something | |
| 17:02:09 | sean-k-mooney | is the reentrent call is happing as part of the rollback | |
| 17:02:37 | sean-k-mooney | i wonder if this could be releated to how we hanedl exction with teh scater gater implemation | |
| 17:03:41 | melwitt | sean-k-mooney: looks like if you don't choose an executor, it will detect whether you're monkey patched and if you are, it will use eventlet executor, else it will use native threading https://github.com/openstack/oslo.messaging/blob/5aa645b38b4c1cf08b00e687eb6c7c4b8a0211fc/oslo_messaging/_utils.py#L70 | |
| 17:04:26 | melwitt | sean-k-mooney: yeah, something dies in the middle of the rollback and then the connection is left in a bad state and then when it's accessed again it raises that error | |
| 17:05:09 | melwitt | sean-k-mooney: that was one of the earliest theories but there are also bug report for this same thing in OSP10 when we didn't have scatter gather | |
| 17:05:15 | sean-k-mooney | welll what i was wondering is dont we have slighly odd exctpion handeling in the scater gater wehere we return the excptions instead of raisign them | |
| 17:05:19 | sean-k-mooney | or am i imagining things | |
| 17:05:20 | melwitt | and I have looked at those traces too | |
| 17:05:26 | sean-k-mooney | never mind then | |
| 17:06:12 | dansmith | melwitt: is it always during a scatter/gather? | |
| 17:06:39 | melwitt | dansmith: no, it happened in OSP10 too when we didn't have scatter/gather | |
| 17:07:21 | melwitt | and I have seen traces where it was raised from a "get quotas" call, from service_update I have seen a lot | |
| 17:07:26 | dansmith | oh right, I read that | |
| 17:07:31 | lyarwood | https://bugs.launchpad.net/nova/+bug/1929446 - This is the issue I was highlighting earlier if anyone has time to help narrow this down a little. | |
| 17:07:32 | openstack | Launchpad bug 1929446 in OpenStack Compute (nova) "check_can_live_migrate_source taking > 60 seconds in CI" [Undecided,New] | |
| 17:07:52 | sean-k-mooney | i am not sure this is evently related | |
| 17:07:58 | sean-k-mooney | it might be | |
| 17:08:08 | sean-k-mooney | but the nova api was not alwasy monky patched | |
| 17:08:22 | melwitt | there was a window when it wasn't | |
| 17:08:35 | sean-k-mooney | if you ran it under uwisgi before scater gatter was added it was not monkey patched | |
| 17:08:44 | melwitt | but it was prior to uwsgi/mod_wsgi being a way to run nova-api | |
| 17:08:45 | sean-k-mooney | the comman line nova-api alwasy was | |
| 17:08:48 | melwitt | right | |
| 17:09:08 | melwitt | *but it was monkey patched | |
| 17:09:18 | sean-k-mooney | no we had a perfiod of time when uwsgi was supported but we did not monkey patch | |
| 17:09:30 | melwitt | I know | |
| 17:09:31 | sean-k-mooney | athough we may not have relased that way downstream | |
| 17:09:40 | melwitt | I'm saying that prior to uwsgi it was always monkey patched | |
| 17:09:51 | sean-k-mooney | ah yes it was | |
| 17:10:20 | sean-k-mooney | osp 10 is what newton i think we just used the nova-api command directly at that point | |
| 17:10:27 | melwitt | but even if we stop monkey patching in nova-api, we will still see this in nova-scheduler and nova-conductor at least | |
| 17:11:00 | sean-k-mooney | is there a cler writeup of how the error happens | |
| 17:11:02 | melwitt | yeah. and in the sosreports I've looked at for 13 it's also the nova-api command in these cases, afaict from the ps output | |
| 17:11:49 | melwitt | sean-k-mooney: yeah but not in the context of openstack. this is a private bug but here https://bugzilla.redhat.com/show_bug.cgi?id=1927994#c45 and the links are https://github.com/PyMySQL/PyMySQL/issues/234 https://github.com/sqlalchemy/sqlalchemy/issues/3258 https://github.com/PyMySQL/PyMySQL/issues/260 | |
| 17:11:49 | sean-k-mooney | i think ooo avoid using apache initally due to concens of memory overhead | |
| 17:11:50 | openstack | melwitt: Error: Error getting bugzilla.redhat.com bug #1927994: NotPermitted | |
| 17:12:28 | sean-k-mooney | ah ok i was looking at the nova bug report and trying to find the repoducer | |
| 17:13:16 | zzzeek | hey just snooping a little bit, I think the main thing nova is doing that nobody else is, is using eventlet monkeypatching *with* mod_wsgi at the same time | |
| 17:13:18 | melwitt | we haven't been able to reproduce it in openstack | |
| 17:13:39 | zzzeek | so that's two frameworks with heavy and opposing opinions on concurrency getting together | |
| 17:13:57 | melwitt | zzzeek: the traces I've been looking at have all been not running under mod_wsgi and also occurred in services (scheduler and conductor) that are not using wsgi in any form | |
| 17:14:08 | zzzeek | ah | |
| 17:14:50 | zzzeek | melwitt: that's odd. pymysql doesnt like if you use eventlet but as long as the scope of a connection is maintained in only one greenlet at a time, this kind of error shouldnt happen. what can happen is if requsts are interrupted and not cleaned up correctly | |
| 17:15:27 | zzzeek | or if cleanup code itself is not able to run correctly due to the monkeypatrching | |
| 17:15:41 | sean-k-mooney | dont we initalise the connection globally and share it between all greentherads | |
| 17:15:49 | melwitt | no we don't | |
| 17:16:24 | melwitt | that's not a "connection" it's a "transaction context manager" which is a factory if I'm remembering terminology zzzeek explained to me last time | |
| 17:16:41 | sean-k-mooney | ah yes that is what i was thinking of | |
| 17:17:00 | sean-k-mooney | the object we recently wraped in teh run once decorator | |
| 17:17:10 | melwitt | and he has confirmed that is the correct way to use it, the threads can share that factory and get new connections from it | |
| 17:17:55 | sean-k-mooney | so when ever we context switch eventlet never guarentes we will resume on the same tread. | |
| 17:18:01 | sean-k-mooney | but normally we have only one | |
| 17:18:02 | melwitt | yeah the configure() of those objects | |
| 17:18:15 | sean-k-mooney | could this be related to the use of pthread for the heartbeat | |
| 17:18:52 | melwitt | which heartbeat? the service heartbeats are eventlet, that I saw | |
| 17:19:15 | sean-k-mooney | the only real pthread i know of in nova are teh oslo.messaging heartbeat and the libvirt one | |
| 17:19:28 | sean-k-mooney | although no that would not make sense fo 10/13 | |
| 17:20:03 | dansmith | at one point we changed the ordering of our imports relative to the monkeypatching to "fix" something | |
| 17:20:14 | melwitt | zzzeek: yeah... dansmith pointed out that glance and cinder use eventlet and monkey patch, but yet we don't see this error from them | |
| 17:20:15 | dansmith | and I think that got backported.. I wonder if that's relevant? | |
| 17:21:00 | sean-k-mooney | melwitt: i was refering to https://github.com/openstack/oslo.messaging/blob/5aa645b38b4c1cf08b00e687eb6c7c4b8a0211fc/oslo_messaging/_drivers/impl_rabbit.py#L90-L100 | |
| 17:21:14 | melwitt | * melwitt looks for link | |
| 17:21:31 | sean-k-mooney | dansmith: mdboots change | |
| 17:21:39 | dansmith | sean-k-mooney: right | |
| 17:21:52 | melwitt | I was just looking at that earlier | |
| 17:21:59 | dansmith | sean-k-mooney: I wonder if that ended up with us getting a combination of real and green threads in a way that is problematic.. | |
| 17:22:13 | sean-k-mooney | https://github.com/openstack/nova/commit/3c5e2b0e9fac985294a949852bb8c83d4ed77e04#diff-c2e5ad6353633e738ba126e0f11ea14ed3f6ea94554deec967586fd2dfcf060d | |
| 17:22:16 | sean-k-mooney | that one | |
| 17:22:35 | melwitt | yeah that's it | |
| 17:22:58 | melwitt | sean-k-mooney: ack thanks (pthread) | |
| 17:23:16 | sean-k-mooney | dansmith: well in principal that should have moved the patching eairler so less likely to get a mix | |
| 17:23:28 | sean-k-mooney | but you are suggestign without it we still could be | |
| 17:23:31 | sean-k-mooney | if we have not backported it | |
| 17:23:34 | dansmith | well, | |
| 17:23:45 | melwitt | yeah, we did not backport it | |
| 17:23:49 | dansmith | I think in wsgi mode that will come in at the point at which we hit it due to importing that api module | |
| 17:24:15 | dansmith | melwitt: oh I thought we did.. maybe that's related to the sudden cessation of reports? :) | |
| 17:24:29 | melwitt | could be, yeah | |
| 17:24:45 | dansmith | melwitt: did you say you didn't see it at all in later releases, or just ... less? | |
| 17:25:07 | sean-k-mooney | this was merged in train | |
| 17:25:18 | melwitt | dansmith: I could not find any mention of it past queens/13 when I bugzilla searched everything under nova and pymysql | |
| 17:25:22 | sean-k-mooney | so if we did not abckprot we shoudl see it up to 15 | |