| Posted | Nick | Remark | |
|---|---|---|---|
| #openstack-nova - 2023-01-18 | |||
| 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 | bauzas | gibi: dansmith: added Tempest and glance to the bug report | |
| 16:34:58 | sean-k-mooney | oh ok | |
| 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 | |
| 16:35:41 | dansmith | we need to fix the test | |
| 16:36:31 | bauzas | dansmith: I think we have now an issue because we call more tests | |
| 16:36:34 | sean-k-mooney | by revert i ment your image change but the test is clearly not writen as we woudl like | |
| 16:36:43 | sean-k-mooney | i.e. it should not break with a bix image | |
| 16:36:50 | sean-k-mooney | *big | |
| 16:36:57 | bauzas | while it was working fine before, now the memory is too large | |
| 16:36:58 | sean-k-mooney | like downstream i know we use rhel images in some cases | |
| 16:37:11 | sean-k-mooney | and those are just under a gig too like 700mb | |
| 16:37:35 | dansmith | the images client in tempest already chunks the upload, it just does it from a fixed size buffer, so it just needs to be smarter | |
| 16:37:37 | bauzas | sean-k-mooney: again, we'll know how much memory creates this test with my new CI job | |
| 16:38:03 | sean-k-mooney | bauzas: just got back to this point in scrolback | |
| 16:38:07 | sean-k-mooney | bauzas: ack | |
| 16:38:22 | dansmith | the large image was specifically to flush out things like this, so I don't think going back to a small image gets us anything useful | |
| 16:38:26 | bauzas | anyway, this is a guess | |
| 16:38:38 | bauzas | nothing was changed in this module since Feb 22 | |
| 16:38:39 | dansmith | if anything, it makes me think we can make it larger as this might have been the OOM limit I was running into with 2G | |
| 16:38:40 | sean-k-mooney | dansmith: i agree | |
| 16:39:03 | bauzas | https://github.com/openstack/tempest/blob/master/tempest/api/compute/admin/test_volume.py | |