| Posted | Nick | Remark | |
|---|---|---|---|
| #openstack-nova - 2019-08-06 | |||
| 13:41:15 | mriedem | cdent: i think the "older computes" comment is from when edleafe wrote this https://review.opendev.org/#/c/160511/ back in kilo :) | |
| 13:49:03 | mriedem | cdent: but yeah i suppose we have to hit that method to get the host mapping at least once per host to determine which cell the host is in so we know where to pull the instances from (which cell db), so in your test with 25 fake computes the profiler shows that method was called 25 times | |
| 13:49:04 | cdent | mriedem: the patch prior to my last one there shows how to do profiling in an eventlet situation, in case you want to try it elsewhere | |
| 13:49:30 | mriedem | yup i saw, thanks. that would be useful with something like this god awful mess https://review.opendev.org/#/c/674422/ | |
| 13:49:34 | cdent | (I tried to do 100 fake computes and my compute explored) | |
| 13:50:04 | cdent | exploded even | |
| 13:50:05 | mriedem | i don't think i've been able to go over 30 fake computes in a devstack with 8GB RAM and 8 VCPU | |
| 13:50:13 | mriedem | and 1 API_WORKER per service | |
| 13:50:59 | cdent | I think I could probably make 50, I'm pretty smooth at 25 with 16GB,16vcpu | |
| 13:51:23 | mriedem | you know, i'd give a scratch n sniff sticker if someone threw up a small doc about how to do profiling like this in nova somewhere in https://docs.openstack.org/nova/latest/contributor/#testing | |
| 13:51:44 | cdent | I think I could do that, but it would really depend on the smell | |
| 13:52:13 | efried | gibi, melwitt: Y'all okay if I continue working on the series at https://review.opendev.org/#/c/524306/ ? | |
| 13:54:07 | gibi | efried: it is OK for me. I can keep reviewing the patches. | |
| 13:54:16 | efried | gibi: I'd be fixing the func failures, either in your poison patch or by slotting another one underneath. And melwitt I'd be addressing gibi's comment on the bottom by removing that fixture. | |
| 13:54:41 | efried | gibi: You think the ComputeDriver.get_available_resource signature change is worth doing? | |
| 13:56:22 | gibi | efried: I need a refresh why we started this series in the first place. What is wrong with generating a new context. I got involved into it due to the testing impact of it | |
| 13:56:53 | dustinc | efried: good point thanks | |
| 13:57:13 | efried | gibi: I'm not completely sure why the series was *started*, but I can tell you why I got involved. | |
| 13:58:10 | gibi | efried: I'm going to dig into the past to see the reason.. | |
| 13:58:14 | efried | gibi: The global_request_id we're logging is coming from whatever RequestContext is in oslo.context's thread local store, which is *not* the same context we're using to pass the X-Openstack-Request-Id header around to other services like Placement. | |
| 13:58:33 | efried | which means that, without additional hacking, we can't actually follow the request from e.g. n-cpu to placement | |
| 13:58:38 | efried | which was the whole point of global_request_id in the first place. | |
| 13:58:50 | gibi | efried: thanks, that seems to be a worthy cause | |
| 13:59:00 | efried | So I've been trying to track down how that whole mechanism works and how we can get it so you can actually grep logs for a request ID and see the flow of an operation. | |
| 13:59:36 | efried | gibi: My latest attempt actually diverged from that series a little bit: https://review.opendev.org/#/c/674138/ | |
| 13:59:41 | gibi | is there any alternative to passing the context to the ComputeDriver.get_available_resource ? | |
| 14:00:42 | efried | To avoid having that one libvirt method call get_admin_context? Yes, melwitt and I talked about storing the context on, like, the compute manager object and accessing it from the virt driver via the virtapi. | |
| 14:00:55 | efried | Questionable which is a worse hack, really. | |
| 14:01:13 | gibi | I see | |
| 14:01:13 | efried | Having it as a param to get_available_resource seems appropriate from a zoomed-out perspective | |
| 14:01:18 | efried | but it's a fairly intrusive change as you can see. | |
| 14:01:26 | efried | but | |
| 14:01:27 | gibi | yepp | |
| 14:01:42 | efried | that's assuming we need to be putting restrictions on get[_admin]_context like this at all. | |
| 14:02:02 | efried | which, if we're doing that more carefully, we might not need to bother with | |
| 14:02:40 | mriedem | cdent: typically root beer and grape are all i offer | |
| 14:03:14 | efried | gibi: https://review.opendev.org/#/c/674138/ operates on the theory that get[_admin]_context should be able to be used wherever, and should (still) not overwrite the thread local store, as long as we're careful about where we *do* overwrite, and as long as we set global_request_id properly/carefully in the right places. | |
| 14:04:07 | efried | so what I did was essentially make overwrite=False the default, and then made sure we're always setting a global_request_id in whatever RequestContext we're using. | |
| 14:04:09 | gibi | efried: I think I like your current ^^ approach than the restriction of get[_admin]_context | |
| 14:04:52 | efried | I need to go poke through the logs and see whether/how it worked. Like, see if a live migration operation gets logged properly throughout all the hosts. | |
| 14:05:28 | efried | btw, on that note, the nova-live-migration job seems to produce only one n-cpu log. Is it the consolidated log from both "nodes"? | |
| 14:05:34 | gibi | I feel there are smaller amount of places where we need to generate new global_request_id than the number of places we call for a new context | |
| 14:05:40 | efried | ++ | |
| 14:06:34 | gibi | efried: there is a subnode-2 folder in the logs | |
| 14:06:43 | gibi | with another n-cpu logs | |
| 14:06:47 | efried | ah! | |
| 14:06:51 | efried | Thanks | |
| 14:07:26 | gibi | so in summary If your approach works then I'm OK to abbandon the old series | |
| 14:09:21 | efried | gibi: I'm sure there's still more to do. This is not a simple thing. | |
| 14:09:57 | efried | glancing at the n-api log, my initial thought is that the global_request_id is being persisted too long. | |
| 14:10:12 | efried | I think what we probably want to do is change it any time we get a new incoming API request. | |
| 14:11:00 | efried | As yet, I have no idea where in the code would be a good place to do that... | |
| 14:15:36 | gibi | efried: does this in connection with the fact that periodic tasks also needs a context / global_request_id but they are not triggered by a specific API request? | |
| 14:19:55 | efried | gibi: Yup, that's an issue as well. | |
| 14:20:19 | efried | I'm not sure whether periodics ought to have one global_request_id forever, or if they should get a new one every time they trigger. | |
| 14:21:01 | efried | but I'm *pretty* sure they shouldn't share a global_request_id with any actual operations from an API request | |
| 14:23:24 | cdent | efried: new one each job would be most useful when grepping (or otherwise searching) | |
| 14:23:42 | efried | cdent: "job", are you talking about periodics or API requests? | |
| 14:23:48 | cdent | periodics | |
| 14:24:25 | efried | Okay. Meanwhile cdent I could probably use your wsgi skills here... | |
| 14:24:44 | efried | can you help me find where nova does that middleware thing with the request_id? | |
| 14:24:55 | cdent | yeah, one sec | |
| 14:26:09 | efried | actually, I don't think that's what I want. | |
| 14:26:14 | efried | Cause that part is working | |
| 14:26:43 | efried | problem right now is, that req ID is persisting way too long in the API thread. | |
| 14:26:55 | cdent | efried: nova/api/compute_req_id.py has a subclass of oslo_middleware.request_id.RequestId | |
| 14:27:14 | efried | Yeah, that's setting the header inbound & outbound, which is working. | |
| 14:27:22 | efried | sorry, inbound only | |
| 14:27:25 | cdent | efried: is it possible that tempest is _sending_ it | |
| 14:28:52 | efried | cdent: looks like not. | |
| 14:29:00 | efried | which is actually fine for now | |
| 14:29:13 | cdent | efried: i haven't got enough context loaded in at the moment | |
| 14:29:25 | efried | actually if tempest *were* sending it, I wouldn't be seeing the behavior I'm seeing | |
| 14:29:36 | efried | cdent: So what I'm looking for is this: | |
| 14:29:45 | efried | Presumably the API server sits there waiting for requests | |
| 14:29:56 | efried | when a request comes in, it... spawns? reuses? a thread to handle it | |
| 14:30:21 | efried | Whatever RequestContext that thread gets needs to get a fresh global_request_id | |
| 14:30:31 | efried | early as possible | |
| 14:30:59 | efried | so - I need to grab hold of the code that spins off that thread | |
| 14:31:39 | efried | (btw, ^ is for API requests obvi. Periodics will be a separate thing entirely.) | |
| 14:33:01 | mriedem | https://github.com/openstack/nova/blob/master/nova/api/openstack/auth.py#L57 is what creates the RequestContext in the compute API | |
| 14:35:21 | efried | mriedem: yup https://review.opendev.org/#/c/674138/4/nova/api/openstack/auth.py | |
| 14:35:41 | efried | So that's working now | |
| 14:35:57 | efried | the thing I'm trying to tackle now is, I want each API request to get a new global_request_id. | |
| 14:36:16 | efried | because right now it's getting reused for multiple operations | |
| 14:36:33 | efried | Actually, cdent, I think perhaps that compute_req_id might be the place to do it. | |
| 14:36:59 | efried | The superclass is pulling in a request ID from headers if available... but what I can do is *set* a new one if there wasn't one in the header. | |
| 14:43:20 | openstackgerrit | Eric Fried proposed openstack/nova master: WIP: Always set a global_request_id in RequestContext https://review.opendev.org/674138 | |
| 14:43:22 | openstackgerrit | Eric Fried proposed openstack/nova master: WIP: Correct global_request_id sent to Placement https://review.opendev.org/674129 | |
| 14:43:36 | efried | cdent, mriedem: let's see how that shakes out ^ | |
| 14:46:23 | openstackgerrit | Matt Riedemann proposed openstack/nova master: Replace non-nova server fault message https://review.opendev.org/674821 | |
| 14:46:34 | mriedem | dansmith: ^ | |
| 14:46:47 | fungi | i'm watching these go up too, thanks mriedem! | |
| 14:47:07 | dansmith | mriedem: ack | |
| 14:55:47 | cdent | sorry efried was drawn away into another converation | |
| 14:56:07 | cdent | I had thought that the existing one was supposed to set a new one | |
| 14:56:08 | cdent | (if not present) | |
| 14:58:16 | efried | cdent: If you look at the parent impl, it doesn't. | |
| 14:58:46 | efried | Previous PS of my change did it further down, but too late, and sucked up whatever was in thread local already if one wasn't set. | |
| 14:59:22 | efried | It's possibly the guts of my ensure_global_id never gets hit now, which would possibly be a good thing. | |