| Posted | Nick | Remark | |
|---|---|---|---|
| #openstack-nova - 2022-04-28 | |||
| 18:01:08 | opendevreview | Balazs Gibizer proposed openstack/nova stable/ussuri: Reproduce bug 1953359 https://review.opendev.org/c/openstack/nova/+/822047 | |
| 18:01:09 | opendevreview | Balazs Gibizer proposed openstack/nova stable/ussuri: Extend the reproducer for 1953359 and 1952915 https://review.opendev.org/c/openstack/nova/+/822048 | |
| 18:01:10 | opendevreview | Balazs Gibizer proposed openstack/nova stable/ussuri: [rt] Apply migration context for incoming migrations https://review.opendev.org/c/openstack/nova/+/822050 | |
| 18:17:25 | opendevreview | Elod Illes proposed openstack/nova stable/yoga: [CI] Install dependencies for docs target https://review.opendev.org/c/openstack/nova/+/839809 | |
| 18:22:21 | opendevreview | Elod Illes proposed openstack/nova stable/xena: [CI] Install dependencies for docs target https://review.opendev.org/c/openstack/nova/+/839810 | |
| 18:23:42 | opendevreview | Elod Illes proposed openstack/nova stable/wallaby: [CI] Install dependencies for docs target https://review.opendev.org/c/openstack/nova/+/839811 | |
| 18:25:32 | opendevreview | Elod Illes proposed openstack/nova stable/victoria: [CI] Install dependencies for docs target https://review.opendev.org/c/openstack/nova/+/839812 | |
| 18:26:42 | opendevreview | Elod Illes proposed openstack/nova stable/ussuri: [CI] Install dependencies for docs target https://review.opendev.org/c/openstack/nova/+/839813 | |
| 19:06:43 | melwitt | dansmith: yoga fix for docs job is ready https://review.opendev.org/c/openstack/nova/+/839809 | |
| 19:07:19 | dansmith | melwitt: I'm going to go out on a limb and say it'd be okay for you to slam those mofos in :) | |
| 19:07:40 | dansmith | you know, IMHO :D | |
| 19:08:06 | sean-k-mooney | i certenly would not object | |
| 19:11:15 | melwitt | haha ok | |
| 21:37:26 | opendevreview | Dan Smith proposed openstack/nova master: DNM: Run against performance.json patch https://review.opendev.org/c/openstack/nova/+/838934 | |
| 22:11:42 | dansmith | clarkb: around? | |
| 22:15:17 | clarkb | dansmith: hi | |
| 22:15:44 | dansmith | not even a full devstack run and 57k queries to the keystone db.. seems high, no? | |
| 22:16:16 | clarkb | dansmith: that does seem high. But openstackclient does have to get a new token for everything since there is no token caching | |
| 22:16:18 | clarkb | perhaps related to that? | |
| 22:16:30 | dansmith | still, 57k | |
| 22:16:39 | dansmith | also, they're almost all select | |
| 22:16:47 | dansmith | don't we have to insert when we create a token? | |
| 22:16:51 | clarkb | yes I think so | |
| 22:17:24 | dansmith | https://termbin.com/s2xj | |
| 22:17:26 | clarkb | I wonder if we need to instrument keystoen directly to try and identify that? | |
| 22:17:44 | dansmith | I think I'd like to know, cause that seems like some n^2 stuff to me | |
| 22:17:46 | clarkb | all of the other services look pretty reasonable | |
| 22:17:51 | dansmith | yes | |
| 22:17:56 | dansmith | neutron is pretty high, | |
| 22:18:14 | dansmith | and I see the number climb pretty fast when it's creating our network and subnet, which seems weird, | |
| 22:18:22 | dansmith | but it's still not 57k-level concerning | |
| 22:18:44 | clarkb | the token issuance would've been my first guess but I agree that those should be writes not reads | |
| 22:18:50 | dansmith | I would think | |
| 22:18:53 | clarkb | and even then we don't do 57k osc commands | |
| 22:18:55 | clarkb | like maybe 1k | |
| 22:18:57 | dansmith | right | |
| 22:19:30 | clarkb | I guess every other api request wiht a keystone token may have to validate with keystone? | |
| 22:19:44 | clarkb | but napkin math adding everything else together there doens't come close to 57k | |
| 22:20:13 | dansmith | yes, I expect validates to turn into selects, but still seems crazy high | |
| 22:20:47 | dansmith | 113 inserts, so maybe say 100 of those are tokens | |
| 22:21:09 | dansmith | that is 570 validates for each one | |
| 22:21:30 | dansmith | I guess catalog lookups maybe | |
| 22:21:48 | dansmith | but still, production systems must be getting _hammered) | |
| 22:21:58 | clarkb | it definitely seems like identifying the source of those and either reducingthem or making them more performant would be a worthwhile exercise | |
| 22:22:53 | dansmith | yeah curious to see if the keystone people think that's crazy or not | |
| 22:24:44 | dansmith | clarkb: check this: https://zuul.opendev.org/t/openstack/build/f31b8439b6dc47a19f9c99bbe3653d74/log/controller/logs/devstacklog.txt#20158 | |
| 22:24:49 | dansmith | 82k by the end of the devstack run | |
| 22:25:10 | dansmith | no wonder my 100k limit was rolling over on a full tempest run | |
| 22:25:27 | clarkb | wow and that is before tempest runs | |
| 22:26:11 | dansmith | yeah | |
| 22:27:32 | dansmith | like maybe some ORM usage is causing a bunch of lookups each time we pull a token or something | |
| 22:27:45 | dansmith | like 20 queries to pull the catalog entries or something | |
| 22:28:29 | dansmith | dmendiza[m]: I dunno what tz you're in, but are you around? | |
| 22:28:45 | clarkb | dansmith: if you want we can hold a node then you can check the count and check it again 5 minute slater and see if background tasks have a big impact. You can also do things like catalog list and check the delta etc | |
| 22:29:01 | clarkb | though I seem to recall you are good about running local devstack too | |
| 22:29:02 | dansmith | clarkb: it repros locally just fine, but thanks :) | |
| 22:29:06 | dansmith | yeah | |
| 22:30:18 | dansmith | my local run crashed in the middle, which is why I only got to 57k apparently | |
| 22:31:50 | dansmith | it might be cool to have a way to run tempest single-threaded and capture the after-before numbers for each test to see which operations inflate numbers like these | |
| 23:12:00 | dansmith | clarkb: one test into tempest locally and keystone selects increase by 2500 | |
| 23:14:53 | clarkb | dansmith: once you track this down every database behind openstack will owe you beers :) | |
| 23:15:31 | dansmith | I'm just surprised, this might be common knowledge, I dunno | |
| 23:15:44 | dansmith | and I'm just telling you because, I dunno, I need a buddy to be surprised with | |
| 23:17:26 | clarkb | I mean I'm surprised too | |
| 23:17:38 | clarkb | that seems pretty excessive to do a lgocial unit of work in an openstack cloud | |
| 23:17:39 | sean-k-mooney[m] | we are using fernet tokens now instead of uuid tokens right? | |
| 23:18:18 | dansmith | sean-k-mooney[m]: are we? I thought that meant we didn't have to actually store them in order to validate | |
| 23:18:42 | dansmith | provider = fernet | |
| 23:18:48 | sean-k-mooney[m] | so i tought we made the switch by default a while ago | |
| 23:18:55 | dansmith | yep ^ | |
| 23:20:07 | sean-k-mooney[m] | have you tried deploying just keystone and then makeing a singel token issue request to see what that results in from a db point of view | |
| 23:20:49 | dansmith | no, I'm just watching the numbers during runs and was surprised.. wasn't looking for anything, was just like "this number has too many zeroes" | |
| 23:21:03 | clarkb | even then why do fernet tokens make you think thousnads of db queries per logical cloud action? | |
| 23:21:34 | dansmith | neutron queries are super high too, | |
| 23:21:53 | dansmith | I'm running tempest mostly doing compute tests right now and neutron and keystone are both ~25k selects | |
| 23:22:04 | dansmith | and nova-api is ~2500 for reference | |
| 23:22:28 | sean-k-mooney[m] | clarkb they done i was wonderign if we were sitll using uuid tokens by mistake or something like that | |
| 23:22:52 | dansmith | sean-k-mooney[m]: ah, good thought then.. but config mentions fernet, so I assume.. | |
| 23:24:53 | sean-k-mooney[m] | im kind of surpiseed how low placement its in those results | |
| 23:25:21 | sean-k-mooney[m] | for a service that is basicaly a restapi bolted on top a db it does not do much in the db during that run | |
| 23:25:53 | dansmith | sean-k-mooney[m]: that is before a tempest run, so not much for placement to have done yet | |
| 23:26:29 | sean-k-mooney[m] | i assume that keystone is somewhat inflated as presumable devstack is not caching the tokens so every osc call is a new token ectra | |
| 23:26:50 | dansmith | it is, but still, how can it be 80k? | |
| 23:27:31 | sean-k-mooney[m] | it might be interseting to just add a count of osc calls to devstack but ya its very high | |
| 23:28:37 | dansmith | so in my ongoing tempest run, we're testing compute, nova-api has made 3700 select calls, keystone has made 42k so far | |
| 23:28:47 | dansmith | and tempest doesn't get a token for every operation, AFAIK | |
| 23:29:03 | dansmith | (neutron has made 47k btw) | |
| 23:37:21 | sean-k-mooney[m] | that is nuts considering that neutron with ovn which moves some of the state to the ovn db | |
| 23:37:38 | dansmith | ...and considering we're not testing neutron yet, just using it through nova | |
| 23:37:38 | sean-k-mooney[m] | granted ovn is mainly ment to reduce rpc load not db load | |
| 23:37:59 | dansmith | I'm up to 52k for keystone, 80k for neutron | |
| 23:38:00 | sean-k-mooney[m] | there are quite a few warning in the keystone log | |
| 23:38:05 | sean-k-mooney[m] | https://zuul.opendev.org/t/openstack/build/f31b8439b6dc47a19f9c99bbe3653d74/log/controller/logs/screen-keystone.txt?severity=3 | |
| 23:38:07 | dansmith | 6k for nova-api | |
| 23:38:25 | sean-k-mooney[m] | looks the initalial account creation | |
| 23:39:09 | sean-k-mooney[m] | but not sure why the default domain and roles cant be found | |
| 23:39:21 | dansmith | before bootstrap is run maybe? | |
| 23:40:07 | sean-k-mooney[m] | maybe but i would have expected us to bring up keystone pretty early in devstack | |
| 23:40:30 | dansmith | it's mid-early | |
| 23:40:40 | dansmith | or, early-mod | |