| Posted | Nick | Remark | |
|---|---|---|---|
| #openstack-nova - 2018-06-18 | |||
| 20:57:54 | openstackgerrit | Matt Riedemann proposed openstack/nova master: Clarify placement DB schema migration https://review.openstack.org/576265 | |
| 20:59:53 | SpamapS | So.. question about placement service logs.. | |
| 21:00:00 | SpamapS | They're basically destroying our ELK stack | |
| 21:00:05 | SpamapS | is there any value in logging all of that at INFO? | |
| 21:10:59 | openstackgerrit | Eric Fried proposed openstack/nova-specs master: Spec: Handling Reshaped Provider Trees https://review.openstack.org/572583 | |
| 21:13:16 | openstackgerrit | Eric Fried proposed openstack/nova-specs master: Spec: Handling Reshaped Provider Trees https://review.openstack.org/572583 | |
| 21:13:53 | efried | SpamapS: You can bust the log level down if you like. | |
| 21:14:19 | efried | SpamapS: What kind of logging are you seeing? I haven't looked at one lately. | |
| 21:16:20 | openstackgerrit | Chris Dent proposed openstack/nova master: Isolate placement database config https://review.openstack.org/541435 | |
| 21:16:34 | openstackgerrit | Chris Dent proposed openstack/nova master: Ensure that os-traits sync is attempted only at start of process https://review.openstack.org/553857 | |
| 21:19:26 | openstackgerrit | Dan Smith proposed openstack/nova stable/queens: Add amd-ssbd and amd-no-ssb CPU flags https://review.openstack.org/576270 | |
| 21:25:11 | jroll | efried: random tempest-full run on INFO: http://logs.openstack.org/66/362766/109/gate/tempest-full/52a4e60/controller/logs/screen-placement-api.txt.gz?level=INFO | |
| 21:25:17 | jroll | that is certainly a lot of logs | |
| 21:25:32 | jroll | looks like it's logging each request at INFO | |
| 21:25:44 | efried | jroll: Is that not what it should be doing? | |
| 21:25:56 | efried | It's not logging payloads. | |
| 21:26:02 | efried | That would be DEBUG-worthy. | |
| 21:26:04 | jroll | I don't know, I don't make those decisions :P | |
| 21:26:18 | zcorneli | dansmith: For that test fixup, looks like there's a number of similar issues in the objects/ dir, worth fixing them all? | |
| 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.. | |