| Posted | Nick | Remark | |
|---|---|---|---|
| #openstack-nova - 2018-06-18 | |||
| 21:26:33 | jroll | efried: in my experience, apache/nginx/whatever does the request logging, and the service only logs whatever else is needed | |
| 21:26:55 | jroll | but clearly someone decided at some point this should happen in placement at info ¯\_(ツ)_/¯ | |
| 21:27:17 | efried | cdent, jaypipes - what are your thoughts on making placement logging less noisy? | |
| 21:27:41 | efried | jroll: I mean, you can always bust the log level down, right? | |
| 21:28:06 | jroll | efried: I assume there are some important things logged at INFO | |
| 21:28:39 | efried | jroll: You mean in general, or here? | |
| 21:28:48 | jroll | both? | |
| 21:28:50 | efried | cause here all I see is just the calls. | |
| 21:29:06 | jroll | well that's the point, signal-to-noise ratio is low | |
| 21:30:12 | jroll | to be clear, I don't (currently) have a problem, just got curious | |
| 21:30:38 | efried | and what I'm saying is, if these lines about which operations are called and how long they took and how many bytes they generated are all considered "noise", you can switch to WARNING and you'll get not those, but you (seemingly) won't lose out on anything else. | |
| 21:30:51 | efried | Ima go look see if there's anything else logged at INFO... | |
| 21:30:59 | jroll | I just checked, heh | |
| 21:31:09 | jroll | curl http://logs.openstack.org/66/362766/109/gate/tempest-full/52a4e60/controller/logs/screen-placement-api.txt.gz\?level\=INFO | grep -v nova.api.openstack.placement.requestlog | grep -v 'switches on core' | grep INFO | |
| 21:31:19 | jroll | gives a single line | |
| 21:31:44 | efried | Yeah, traits db sync and online migration are the only other two things in the code. | |
| 21:31:49 | jroll | so you're right, there isn't really anything other than request logging at INFO | |
| 21:32:07 | efried | (online _data_ migration, that is - nothing to do with migrating instances) | |
| 21:32:13 | jroll | most openstack services log very useful things at INFO, so operators tend to run at INFO | |
| 21:32:21 | SpamapS | "Info: Usually indicates successful service start/stop, versions and such non-error related data. This should include largely positive units of work that are accomplished (such as starting a compute, creating a user, deleting a volume, etc.)" | |
| 21:33:07 | efried | useful is in the eye of the beholder, I suppose. | |
| 21:33:08 | SpamapS | https://specs.openstack.org/openstack/openstack-specs/specs/log-guidelines.html | |
| 21:33:18 | SpamapS | IMO those should be TRACE | |
| 21:33:19 | efried | SpamapS: I don't really see this as violating that precept, personally. | |
| 21:33:36 | SpamapS | They aren't really useful for realtime analysis. | |
| 21:33:45 | efried | No, trace would include all the payloads, generated SQL statements and result sets, etc. | |
| 21:33:47 | SpamapS | They're good for like, tracing through to find out when an aggregate changed to what or was requested as what. | |
| 21:34:08 | SpamapS | but every single compute node is constantly hitting placement | |
| 21:34:39 | efried | Put in the context of the other logs, the info level is useful for letting you figure out which calls happened when and what their result was. | |
| 21:35:19 | efried | Keeping in mind that placement doesn't necessarily see a 4xx as a "failure" or whatever, so something that's an ERROR in n-cpu or n-cond or whatever might just be a vanilla request/response to placement. | |
| 21:35:28 | efried | So we can't condition on status code. | |
| 21:35:55 | efried | Turn it around: if we were to take these lines out of INFO level, the log would be basically empty. | |
| 21:36:17 | SpamapS | Ya, at this point we're just going to dump them from our ELK cluster. | |
| 21:36:28 | SpamapS | They represent ~70% of all logs flowing in. | |
| 21:36:49 | efried | SpamapS: I'm going to say again, if you don't like these INFO messages, change the log level (for placement only) to WARNING. | |
| 21:37:10 | SpamapS | Ya, just wondering why people would think these would be useful enough for INFO. | |
| 21:37:12 | efried | SpamapS: Because I reckon you do want to know if something goes wrong. So you don't just want to blow away the logs. | |
| 21:37:45 | SpamapS | Yeah thats what I meant by dump them.. we'll not send the INFO+placement through to elastic. | |
| 21:38:11 | efried | SpamapS: For ffdc, being able to correlate an ERROR in the nova logs to the corresponding placement calls - that's useful. And INFO-worthy IMO. | |
| 21:38:47 | efried | again because placement has no way to distinguish what's ERROR-worthy from the client's perspective. | |
| 21:39:22 | efried | Also finding it a little hard to believe that the placement log is noisier than the combined compute logs. Keep in mind that there's only one placement service. | |
| 21:39:54 | SpamapS | the computes don't spray as much on INFO | |
| 21:40:06 | SpamapS | unless they're super busy with churn | |
| 21:40:43 | SpamapS | meanwhile they're constantly hammering on placement | |
| 21:40:48 | efried | yup | |
| 21:52:01 | jaypipes | SpamapS, jroll: do you have specific advice on what to down-level from INFO? | |
| 22:07:02 | Sundar | efried: Please ping me when you can | |
| 22:07:17 | efried | Sundar: I'm here. | |
| 22:07:35 | efried | Sundar: I skimmed your responses, but didn't dig deep yet. | |
| 22:08:02 | efried | oh, right, the main issue is "cyborg discovers automatically etc." | |
| 22:08:09 | efried | This is missing the point, I think. | |
| 22:08:40 | efried | When we do `openstack accelerator create` we're not getting a specific device. We're creating an ethereal meta-thingy that basically just has an ID for now. | |
| 22:09:15 | efried | It's not until after placement has done its thang that you can actually (with the help of the plugin) associate that with an actual (possibly-virtual) device. | |
| 22:10:02 | Sundar | efried: Sure, I am saying that Cyborg discovers PCI functions and such, apart from devices per se. So, all the information needed for an attach are already there. | |
| 22:10:17 | efried | Except it's not. | |
| 22:10:44 | Sundar | Could you clarify? What is missing? | |
| 22:10:53 | efried | The main purpose of `openstack accelerator create <config details>` is to give <config details> a handle so we don't have to sling a random dict around all the services. | |
| 22:11:16 | efried | It's the same principle as the port in neutron. You do a `port create` and get a UUID, but it's not associated with anything *real* yet. | |
| 22:11:36 | efried | It's only much later, once you've landed on a real host, that you actually get a port on a NIC with an IP or whatever. | |
| 22:11:42 | efried | Same thing here. | |
| 22:11:44 | Sundar | That can be done from Nova compute -> os-acc, as opposed t doing at the controller between n-sched/placement and Cyborg | |
| 22:12:28 | Sundar | The analogy with Neutron is ok, but do we need to copy it exactly? | |
| 22:12:41 | Sundar | We need to see what makes sense in this context, right? | |
| 22:12:52 | efried | heh, yeah, we should copy it insofar as it makes sense, and no further. | |
| 22:13:28 | Sundar | What goes wrong if we create an attach object when n-cpu calls os-acc? | |
| 22:13:48 | efried | well, what's an "attach object"? | |
| 22:13:58 | efried | But let me answer that anyway | |
| 22:14:13 | jaypipes | efried: it's pretty much the same as a "volume attachment". it's an ephemeral connection_info thing. | |
| 22:14:20 | efried | The problem is that n-cond needed to know things about that accelerator long before we ever get to n-cpu. | |
| 22:14:28 | efried | jaypipes: It was a semi-rhetorical question. | |
| 22:14:34 | jaypipes | efried: yes, I know :) | |
| 22:14:43 | Sundar | It is an object that encapsulates what it takes to attach an accelerator to a VM | |
| 22:14:46 | jaypipes | efried: as mine was a semi-rhetorical answer. | |
| 22:15:03 | jaypipes | efried: it's a non-consumable thing. it's just configuration info. | |
| 22:15:12 | jaypipes | efried: i.e. it isn't a placement concern. | |
| 22:15:20 | efried | Sundar: Example: I want my instance to have a VGPU with 1 display heads and resolution of 1024x768 (ambitious, I know). | |
| 22:15:48 | efried | Sundar: I need a way to have that information passed from the very start of my `server create` request. | |
| 22:16:17 | efried | So when I do `openstack server create --flavor foo --image bar --accelerator <what goes here?>` | |
| 22:16:29 | efried | And the answer could be <random dict of values> | |
| 22:16:33 | efried | but that sucks. | |
| 22:16:38 | jaypipes | efried: like the neutron port profile.. | |
| 22:16:45 | efried | jaypipes: precisely | |
| 22:16:53 | jaypipes | efried: which is used to created the instance pci device request | |
| 22:17:10 | Sundar | I am not an expert on GPUs by a long shot :) but can't you apply traits on your GPU indicating what resolutions it can support, and use those traits in placement to pick a device? | |
| 22:17:12 | efried | So instead we first do `openstack accelerator create --type vgpu --specs display_heads=1,resolution=1024x768`, or similar. | |
| 22:17:41 | Sundar | "--specs display_heads=1,resolution=1024x768`" --> why can't this be a trait? | |
| 22:17:45 | efried | And we get back an "accelerator UUID" Or maybe it's called an "attachment UUID". Whatever term, not important right now. Point is, it's just a handle for that config data. | |
| 22:17:52 | efried | Sundar: It *is*. That's the point. | |
| 22:17:59 | jaypipes | efried: it's >1 trait, to be clear. | |
| 22:18:15 | efried | Sundar: We're not *creating* anything in placement at this point in the game. That was already done by cyborg when you did your discovery and whatnot. | |
| 22:18:49 | efried | So now we got back some $acc_uuid and we can say `openstack server create --flavor foo --image bar --accelerator $acc_uuid` | |
| 22:19:31 | Sundar | efried, jaypipes: Since it is a trait, placement can choose a GPU device in a node on on that basis, and have n-cpu call os-acc to 'configure' the gpu as needed? | |
| 22:19:55 | efried | yes, Sundar, that's exactly what's going to happen. I'm talking through how placement is going to get that information. | |
| 22:19:58 | mriedem | SpamapS: jroll: efried: n-api also logs requests at INFO http://logs.openstack.org/66/362766/109/gate/tempest-full/52a4e60/controller/logs/screen-n-api.txt.gz#_Jun_15_15_26_18_719528 | |
| 22:20:55 | SpamapS | That makes sense. It just doesn't get as many requests. :) | |
| 22:20:56 | efried | Sundar: ...So now when the conductor needs to draw up a placement query for allocation candidates, it asks cyborg (via os-acc?) "hey, give me the details on this accelerator: $acc_uuid". Cyborg returns the AccGPU object, populated with an AccGPUProfile, which in turn is populated with information about display_heads=1 and resolution=1024x768 | |
| 22:21:32 | Sundar | efried: May be I am being dense. The placement knows enough to choose a RP (GPU in a node). What else does it need? The rest can be left to entities in the compute node, right? | |
| 22:21:33 | efried | conductor parlays that into querystring content for GET /allocation_candidates and sends it down to placement. | |
| 22:22:11 | efried | Sundar: Nope, placement knows what it's told. I need to tell it about more than just "I need one VGPU". Otherwise I have to do all my filtering later, which defeats the purpose of having used placement. | |
| 22:22:30 | Sundar | "conductor needs to draw up a placement query for allocation candidates, it asks cyborg (via os-acc?)" This is not needed for selecting a node | |