| Posted | Nick | Remark | |
|---|---|---|---|
| #openstack-nova - 2023-01-18 | |||
| 14:21:31 | sean-k-mooney | https://eventlet.net/doc/modules/greenpool.html#eventlet.greenpool.GreenPool.waitall | |
| 14:22:08 | gibi | we are not pooling our eventlets | |
| 14:23:00 | gibi | and as you noted the greenthread.kill assumes we have access to the greented to kill | |
| 14:23:23 | sean-k-mooney | well we do have a greenthread pool but its provide by oslo | |
| 14:23:38 | sean-k-mooney | i was just looking at the docs to see if we have a way to list the greenthreads | |
| 14:23:45 | gibi | when we call spawn or spawn_n we are not using the greenlet from the pool | |
| 14:24:04 | sean-k-mooney | ya but i think there is a default pool that is used | |
| 14:24:10 | sean-k-mooney | i could be wrong | |
| 14:24:51 | gibi | at least I haven't came accross it when originally fixed part of this problem | |
| 14:25:18 | sean-k-mooney | i guess if there is one it does not say https://eventlet.net/doc/basic_usage.html#eventlet.spawn | |
| 14:25:40 | sean-k-mooney | is there any reason not to jsut have one gloabl pool | |
| 14:26:39 | sean-k-mooney | gibi: i was thinking of https://docs.openstack.org/nova/latest/configuration/config.html#DEFAULT.executor_thread_pool_size by the way | |
| 14:26:46 | sean-k-mooney | Size of executor thread pool when executor is threading or eventlet. | |
| 14:28:34 | gibi | as far as I see that is only used by oslo_messaging creating rpc message handler threads / eventlets. but nova uses spawn and spawn_n directly outside of oslo messaging | |
| 14:28:55 | gibi | we can try to pool them but I'm not sure both spawn and spawn_n can be pooled in the same way | |
| 14:29:05 | gibi | as they are not creating the same entity | |
| 14:29:24 | sean-k-mooney | there are spawn and spawn_n function on the pools | |
| 14:29:32 | sean-k-mooney | we might need a speerate on form the rpc one | |
| 14:29:39 | sean-k-mooney | or want a seperate one | |
| 14:29:48 | sean-k-mooney | but i think form an api point of view it shoudl be fine | |
| 14:30:07 | sean-k-mooney | https://eventlet.net/doc/modules/greenpool.html#eventlet.greenpool.GreenPool.spawn and https://eventlet.net/doc/modules/greenpool.html#eventlet.greenpool.GreenPool.spawn_n | |
| 14:30:44 | sean-k-mooney | hopefully we could just update it here https://github.com/openstack/nova/blob/master/nova/utils.py#L635-L684 | |
| 14:31:12 | sean-k-mooney | so create a module level pool and use that then in the test call waitall on the base testcase cleanup | |
| 14:32:34 | sean-k-mooney | https://github.com/openstack/nova/blob/master/nova/test.py#L150 we currently done tha a cleanup function but in setup we can also jsut add | |
| 14:32:55 | sean-k-mooney | self.addCleanup(utils.greenpool.waitall) | |
| 14:35:26 | gibi | I can try to set up a way to reproduce the issue more frequently locally and try to see if the pooling might solve it or not | |
| 14:40:36 | bauzas | sorry, was at the hairdresser | |
| 14:48:57 | opendevreview | Balazs Gibizer proposed openstack/nova master: DNM: Test OOM killed test https://review.opendev.org/c/openstack/nova/+/870950 | |
| 14:54:00 | gibi | bauzas: one result from your OOM trial is that I noticed that test in question takes a realitvely long time even if it passes tempest.api.compute.admin.test_aaa_volume.AttachSCSIVolumeTestJSON.test_attach_scsi_disk_with_config_drive [181.818420s] | |
| 14:54:27 | bauzas | gibi: yup, I've seen it | |
| 14:54:56 | bauzas | maybe we should introspect the memory size of the cached image | |
| 15:20:41 | bauzas | gibi: fwiw, since the UT ran successfully in the DNM patch, I looked at n-api log and I found we called it | |
| 15:20:53 | bauzas | gibi: while on https://834de1be955e9175dba1-6977f7378e5264bdb9ba9d1465839752.ssl.cf1.rackcdn.com/869900/6/gate/nova-ceph-multistore/f5aa5ed/controller/logs/screen-n-api.txt we were not calling it | |
| 15:21:16 | bauzas | so, I think the test was killed during the first glance call | |
| 15:22:01 | bauzas | https://github.com/openstack/tempest/blob/master/tempest/api/compute/admin/test_volume.py#L84-L89 | |
| 15:49:44 | dansmith | I'm stacking a ceph devstack right now | |
| 15:49:59 | dansmith | so when it's done I could try running just that test and see if it behaves properly in isolation | |
| 15:55:58 | opendevreview | Sylvain Bauza proposed openstack/nova master: DNM: Testing the killed test https://review.opendev.org/c/openstack/nova/+/870924 | |
| 16:21:53 | gibi | bauzas, dansmith: https://bugs.launchpad.net/nova/+bug/2002951/comments/5 based on dstat and the tempest log I'm pretty sure that loading the image data is using up the memory | |
| 16:22:38 | bauzas | gibi: I added a few lines | |
| 16:22:48 | dansmith | gibi: oh is show_image() eating the whole image? | |
| 16:22:56 | bauzas | https://review.opendev.org/c/openstack/tempest/+/870913/2/tempest/api/compute/admin/test_aaa_volume.py | |
| 16:23:05 | dansmith | like response.content instead of response.iter_content ? | |
| 16:23:12 | bauzas | dansmith: I asked for the image cache size in my next revision | |
| 16:23:27 | bauzas | gibi: that was my guess | |
| 16:23:35 | bauzas | hence the new rev I created $ | |
| 16:23:57 | dansmith | if so I guess that's my bad for making the image size large, although that is exactly why I did it :) | |
| 16:25:06 | dansmith | oh, I see, | |
| 16:25:10 | gibi | dansmith: I don't see any iter_content involved | |
| 16:25:14 | dansmith | it's actually downloading and re-uploading the image? | |
| 16:25:18 | gibi | yepp | |
| 16:25:28 | gibi | and doing it in memory | |
| 16:25:31 | dansmith | riight, okay | |
| 16:25:47 | dansmith | so yeah that'll have to turn into a chunked loop | |
| 16:26:06 | dansmith | I can take a look at that if you want, but we might want to just disable that test for the moment | |
| 16:26:25 | bauzas | dansmith: as you see they copy in memory the whole image | |
| 16:26:27 | gibi | bauzas: if I'm right L90 in your modification wont return https://review.opendev.org/c/openstack/tempest/+/870913/2/tempest/api/compute/admin/test_aaa_volume.py#90 | |
| 16:26:59 | bauzas | gibi: hmm? | |
| 16:27:05 | bauzas | https://docs.openstack.org/oslo.utils/ocata/examples/timeutils.html#using-a-stopwatch-as-a-context-manager | |
| 16:27:08 | gibi | bauzas: OMM will kill the process in the midle | |
| 16:27:19 | gibi | OOM | |
| 16:27:28 | bauzas | gibi: no, the test is run before | |
| 16:27:33 | dansmith | this also means anyone using tempest with a real image (like for verification) will be eating a ton of data | |
| 16:27:37 | bauzas | that's still using aaa | |
| 16:27:48 | gibi | calling _create_image_with_custom_property will trigger the OOM | |
| 16:28:03 | bauzas | gibi: it wasn't the case in the first revision | |
| 16:28:20 | bauzas | we waited for 180secs but eventually we didn't got a kill | |
| 16:28:59 | gibi | hm, maybe at that run the image fit into memory | |
| 16:29:28 | bauzas | https://storage.gra.cloud.ovh.net/v1/AUTH_dcaab5e32b234d56b626f72581e3644c/zuul_opendev_logs_362/870924/2/check/nova-ceph-multistore/3626391/testr_results.html | |
| 16:29:50 | bauzas | gibi: yeah, because the test is called firstly | |
| 16:29:59 | gibi | anyhow dansmith if you look into fixing it then I will propose to disable this test in tempest with a @skip decorator as it is probably dangerous to run in any job | |
| 16:30:07 | dansmith | yeah, do it | |
| 16:30:10 | gibi | ack | |
| 16:30:18 | gibi | bauzas: ahh yeah, that helps to fit | |
| 16:30:28 | dansmith | I'm still stacking, had to start over because horizon seems broken :/ | |
| 16:30:39 | dansmith | 2023 is off to a *great* start | |
| 16:31:08 | bauzas | gibi: that said, I wonder why this test was fine since like 10 months before | |
| 16:31:13 | gibi | my local tox -e functional-py310 env produces strange failures (>1000 failed test on master) so yeah it is *great* :D | |
| 16:31:27 | dansmith | bauzas: I recently increased the size of the image used on the ceph job from 16MB to 1G | |
| 16:31:32 | dansmith | but that was in like november or so | |
| 16:31:39 | dansmith | so I'm pretty surprised we've been holding on this long | |
| 16:31:54 | dansmith | probably because that memory never gets touched again and just gets swapped out | |
| 16:32:56 | sean-k-mooney | the gate was pretty ok after you went on pto in the start od december | |
| 16:33:06 | sean-k-mooney | so i dont think its related to using the 1G image | |
| 16:33:09 | dansmith | sean-k-mooney: I'm happy to leave if that's what helps | |
| 16:33:30 | dansmith | sean-k-mooney: this job crashing with OOM seems clearly related as the job eats the 1g image and ... swells to 1g before it goes boom | |
| 16:33:45 | dansmith | s/job/test worker/ | |
| 16:33:52 | sean-k-mooney | ok do we know why its only happening now or did we get lucky beofre | |
| 16:34:02 | gibi | maybe something else grown in memory usage recently a bit and pushing the overall worker VM over the line | |
| 16:34:27 | gibi | sean-k-mooney: as bauzas shown if your run this test earlier in the job then it still passes | |
| 16:34:32 | dansmith | sean-k-mooney: read the scrollback :) | |
| 16:34:35 | sean-k-mooney | ya well ok we could revert back to 512 mb and see if it grows by 512mb | |
| 16:34:46 | sean-k-mooney | i was just starting too ya | |
| 16:34:47 | dansmith | sean-k-mooney: gibi identified a test that reads the whole image into memory | |
| 16:34:58 | sean-k-mooney | oh ok | |
| 16:34:58 | bauzas | gibi: dansmith: added Tempest and glance to the bug report | |
| 16:35:10 | sean-k-mooney | so fix that test or revert i assume fix the test to not do that | |
| 16:35:21 | sean-k-mooney | or exilcitly use a small image in that test | |
| 16:35:28 | bauzas | sean-k-mooney: I have a change that will tell us how much memory it takes https://review.opendev.org/c/openstack/tempest/+/870913/2/tempest/api/compute/admin/test_aaa_volume.py#90 | |
| 16:35:37 | dansmith | no, the test is old there's nothing to revert | |