OOM kills python / mysqld in various nova devstack jobs

in all the 16 nova-ceph-multistore jobs that failed in the last 10 days the same test case got killed

$ grep Killed oom-kills.txt | cut -d ':' -f2 | sed 's|controller/logs/syslog.txt|job-output.txt|g' | xargs grep inprogress
/home/gibi/.cache/logsearch/358f5a3fda114764b794323a2f5d2312/job-output.txt:2023-01-17 09:32:24.979704 | controller | {3} tempest.api.compute.admin.test_volume.AttachSCSIVolumeTestJSON.test_attach_scsi_disk_with_config_drive [] ... inprogress
/home/gibi/.cache/logsearch/8587e6a4b6de4edb93de5c064928788e/job-output.txt:2023-01-16 12:00:25.032670 | controller | {2} tempest.api.compute.admin.test_volume.AttachSCSIVolumeTestJSON.test_attach_scsi_disk_with_config_drive [] ... inprogress
/home/gibi/.cache/logsearch/ece0cf2ce71c4a8790a0a36529dd0a8e/job-output.txt:2023-01-14 23:15:05.647826 | controller | {1} tempest.api.compute.admin.test_volume.AttachSCSIVolumeTestJSON.test_attach_scsi_disk_with_config_drive [] ... inprogress
/home/gibi/.cache/logsearch/f5aa5edd4d354c2685fc1f3e13d0ef77/job-output.txt:2023-01-13 23:07:03.726600 | controller | {0} tempest.api.compute.admin.test_volume.AttachSCSIVolumeTestJSON.test_attach_scsi_disk_with_config_drive [] ... inprogress
/home/gibi/.cache/logsearch/1447c6274e924e068578ca260c9ac2a6/job-output.txt:2023-01-13 22:00:29.545457 | controller | {0} tempest.api.compute.admin.test_volume.AttachSCSIVolumeTestJSON.test_attach_scsi_disk_with_config_drive [] ... inprogress
/home/gibi/.cache/logsearch/1bbcaa703b7d42c7a266fde3a6acca65/job-output.txt:2023-01-13 04:13:16.809645 | controller | {2} tempest.api.compute.admin.test_volume.AttachSCSIVolumeTestJSON.test_attach_scsi_disk_with_config_drive [] ... inprogress
/home/gibi/.cache/logsearch/7d9ca42edc5e4bdeb17be8e8045c6468/job-output.txt:2023-01-12 22:32:21.335537 | controller | {3} tempest.api.compute.admin.test_volume.AttachSCSIVolumeTestJSON.test_attach_scsi_disk_with_config_drive [] ... inprogress
/home/gibi/.cache/logsearch/bcb7bcbbbb3b478586906c31c6558b13/job-output.txt:2023-01-12 20:38:12.837475 | controller | {2} tempest.api.compute.admin.test_volume.AttachSCSIVolumeTestJSON.test_attach_scsi_disk_with_config_drive [] ... inprogress
/home/gibi/.cache/logsearch/7572c2bf5e6547c0a1fc6b0f180a2e1f/job-output.txt:2023-01-12 18:17:48.522025 | controller | {0} tempest.api.compute.admin.test_volume.AttachSCSIVolumeTestJSON.test_attach_scsi_disk_with_config_drive [] ... inprogress
/home/gibi/.cache/logsearch/aa5cf699f8d04995b43d009e55a1accd/job-output.txt:2023-01-12 16:48:59.307916 | controller | {1} tempest.api.compute.admin.test_volume.AttachSCSIVolumeTestJSON.test_attach_scsi_disk_with_config_drive [] ... inprogress
/home/gibi/.cache/logsearch/8bc71a0ec0d34373bd25d4f691136084/job-output.txt:2023-01-12 15:49:35.341633 | controller | {0} tempest.api.compute.admin.test_volume.AttachSCSIVolumeTestJSON.test_attach_scsi_disk_with_config_drive [] ... inprogress
/home/gibi/.cache/logsearch/81d7cef2e0b240f89fcfa727304d8e8d/job-output.txt:2023-01-12 15:35:03.978880 | controller | {1} tempest.api.compute.admin.test_volume.AttachSCSIVolumeTestJSON.test_attach_scsi_disk_with_config_drive [] ... inprogress
/home/gibi/.cache/logsearch/c75eb700717b4d3c9942be1385cd4...

I took 6 of these runs and extracted which test cases ran in the killed worker. Then I checked for common test cases and I only found tempest.api.compute.admin.test_volume.AttachSCSIVolumeTestJSON.test_attach_scsi_disk_with_config_drive in the intersection of the test case sets. That is also the one that got killed by OOM.

One idea from Dan to move this to the end of the test case list by renaming it to see if there are a set of test cases triggering OOM not just this one. That would help finding a pattern.

Related fix proposed to branch: master
Review: https://review.opendev.org/c/openstack/nova/+/870924

In the run https://zuul.opendev.org/t/openstack/build/a52064f718904b33a7b7136bf63a1458/logs the test test_attach_scsi_disk_with_config_drive was moved to the end of the execution and it still triggered an OOM during the test execution.

OOM happened at
Jan 18 15:55:13 np0032779705 kernel: Out of memory: Killed process 127344 (python) total-vm:5232640kB, anon-rss:4173792kB, file-rss:5404kB, shmem-rss:0kB, UID:1002 pgtables:8964kB oom_score_adj:0

dstat shows that there is a sudden increase in memory starting at 15:55:02:

Jan 18 15:55:00.704919 np0032779705 dstat.sh[85428]: 18-01 15:55:00| 28 12 59 1 0|6225M 142M 256M 990M| 569M 569M| 171M 21M|1453 458 |9600 10k|1.65 2.42 4.12|2.0 0 25|40.0 5343 |2297M 1998M| 31 494 0 132 8

Jan 18 15:55:01.702533 np0032779705 dstat.sh[85428]: 18-01 15:55:01| 14 0 85 0 1|6224M 143M 256M 991M| 79k 79k| 265k 148k|17.0 10.0 |2051 4493 |1.65 2.42 4.12|1.0 0 0| 0 0 |2297M 1998M| 31 492 0 101 10

Jan 18 15:55:02.703908 np0032779705 dstat.sh[85428]: 18-01 15:55:02| 14 2 84 0 0|6339M 118M 256M 902M| 39k 39k| 492k 15M|19.0 592 |4253 6209 |1.65 2.42 4.12|1.0 0 0|4.00 2178 |2306M 1989M| 31 492 0 101 10

Jan 18 15:55:03.704748 np0032779705 dstat.sh[85428]: 18-01 15:55:03| 10 11 79 0 0|6965M 128M 227M 300M|3700 3700 | 480k 91M|39.0 1237 |9253 5032 |1.68 2.41 4.11|3.0 0 1.0|2.00 23.0k|2399M 1896M| 31 492 0 95 10

Jan 18 15:55:04.712489 np0032779705 dstat.sh[85428]: 18-01 15:55:04| 10 14 74 1 0|7437M 125M 21M 55M| 34k 34k|6923k 203M| 371 1489 | 16k 7296 |1.68 2.41 4.11|3.0 0 5.0|30.8 50.8k|2605M 1690M| 31 492 0 95 10

Jan 18 15:55:05.711668 np0032779705 dstat.sh[85428]: 18-01 15:55:05| 10 19 67 4 0|7488M 103M 2560k 49M|1318 1318 | 50M 513M|1645 2102 | 12k 9149 |1.68 2.41 4.11|4.0 0 6.0| 623 131k|3139M 1156M| 31 492 0 90 10

Jan 18 15:55:06.702850 np0032779705 dstat.sh[85428]: 18-01 15:55:06| 12 17 54 16 0|7415M 126M 6088k 95M| 97k 97k| 100M 258M|4687 6623 | 21k 23k|1.68 2.41 4.11|1.0 2.0 434|10.2k 64.3k|3371M 924M| 31 492 0 91 10

Jan 18 15:55:07.705732 np0032779705 dstat.sh[85428]: 18-01 15:55:07| 5 9 75 10 0|7427M 120M 5272k 90M|7606 7606 | 65M 153M|3704 3302 | 15k 13k|1.68 2.41 4.11|4.0 0 2.0|13.4k 39.3k|3489M 806M| 31 492 0 90 10

Jan 18 15:55:08.703123 np0032779705 dstat.sh[85428]: 18-01 15:55:08| 5 10 76 9 0|7434M 121M 4320k 85M| 35k 35k| 60M 193M|3134 6494 | 16k 10k|1.62 2.39 4.09|3.0 0 0|14.2k 48.8k|3641M 654M| 31 492 0 90 10

Jan 18 15:55:09.704144 np0032779705 dstat.sh[85428]: 18-01 15:55:09| 8 12 56 24 0|7434M 122M 4120k 83M| 46k 46k| 116M 197M|13.6k 6780 | 30k 37k|1.62 2.39 4.09|4.0 1.0 0|27.9k 50.6k|3762M 533M| 31 492 0 90 10

Jan 18 15:55:10.701265 np0032779705 dstat.sh[85428]: 18-01 15:55:10| 5 10 75 9 1|7442M 122M 3784k 76M| 33k 33k| 63M 199M|3784 4171 | 16k 13k|1.62 2.39 4.09|1.0 1.0 1.0|15.7k 50.8k|3920M 375M| 31 492 0 90 10

Jan 18 15:55:11.702276 np0032779705 dstat.sh[85428]: 18-01 15:55:11| 5 10...

The suspected code part is called from our test here:
The https://github.com/openstack/tempest/blob/6fa213cc0fcab744b46109e5f07cb58b0df4a314/tempest/api/compute/admin/test_volume.py#L84

FWIW, I created another change that was running this test *earlier*, and it worked :

https://storage.gra.cloud.ovh.net/v1/AUTH_dcaab5e32b234d56b626f72581e3644c/zuul_opendev_logs_362/870924/2/check/nova-ceph-multistore/3626391/testr_results.html

That being said, this test tooked more than 181secs so I created a new revision for knowing how it takes for creating the cached image and how large this cached image is using the memory :

https://review.opendev.org/c/openstack/tempest/+/870913/2/tempest/api/compute/admin/test_aaa_volume.py#90

Still waiting the results but here I think we need to modify this test to maybe not caching this way if we can, or maybe to be run differently.

Related fix proposed to branch: master
Review: https://review.opendev.org/c/openstack/tempest/+/870974

Glance default cirros image increased on November from 16MB to 1GB. Shouldn't be in theory a problem but since this test is blindly copying the full image data into memory, it's becoming a very greedy run.

This test necessarly needs to be refactored so that only metadata is copied in memory or if data has to be compared, this has necessarly has to be done by chunks.

Related fix proposed to branch: master
Review: https://review.opendev.org/c/openstack/tempest/+/871000

Reviewed: https://review.opendev.org/c/openstack/tempest/+/870974
Committed: https://opendev.org/openstack/tempest/commit/a6b7e334cf27eddacb9ec28fb728dbfa30e4a8c6
Submitter: "Zuul (22348)"
Branch: master

commit a6b7e334cf27eddacb9ec28fb728dbfa30e4a8c6
Author: Balazs Gibizer <email address hidden>
Date: Wed Jan 18 17:43:01 2023 +0100

    Skip test_attach_scsi_disk_with_config_drive

    This test causes excessive memory usage in the test executor as it
    downloads glance image data in memory. This currently causes OOM issues
    in the gate so the test case is skipped until the image data copying is
    made smarter.

    Related-Bug: #2002951
    Change-Id: I0bfac0310fdd6ef44a633d40422cfcfdfc85a426

I'm moving this to Confirmed as we agreed in this patch that this is an issue [1]. We should close this once the test_attach_scsi_disk_with_config_drive is unskipped.

[1] https://opendev.org/openstack/tempest/commit/a6b7e334cf27eddacb9ec28fb728dbfa30e4a8c6

Putting to high as the test is not skipped thanks to https://review.opendev.org/c/openstack/tempest/+/870974

Proposal to fix the rootcause (downloading the entire image in memory) is under review https://review.opendev.org/c/openstack/tempest/+/871000

Reviewed: https://review.opendev.org/c/openstack/tempest/+/871000
Committed: https://opendev.org/openstack/tempest/commit/2c192f46db1b253fe312f6539bfda4735bd07e15
Submitter: "Zuul (22348)"
Branch: master

commit 2c192f46db1b253fe312f6539bfda4735bd07e15
Author: Dan Smith <email address hidden>
Date: Wed Jan 18 11:22:34 2023 -0800

    Chunked GET request support

    In one test, we are downloading the entire image (into memory) and
    re-uploading it. That works when the image is 16MiB but not when it
    is 1GiB. This adds support to the internal http client for chunked
    downloads (similar to upload), makes the image client able to take
    that flag, and finally makes the offending test do a chunked upload/
    download streaming operation.

    Note this un-skips the test, effectively reverting a6b7e334c
    because the test should no longer consume large amounts of memory.

    Related-Bug: #2002951
    Change-Id: I31e537538a1862e71091aa470da3b8e9c799bf15

Moving the Nova status of the bug to Fix Released as https://review.opendev.org/c/openstack/tempest/+/871000 fixed the root cause for the failing nova jobs.

I'm moving this to "Fix Released" as the bug was fixed in https://review.opendev.org/c/openstack/tempest/+/871000. I checked the test_attach_scsi_disk_with_config_drive test and in the last 7 days, the test failed 8 times. None failure out of these 8 failures was relevant to this bug [1].

[1] https://opensearch.logs.openstack.org/_dashboards/app/dashboards?security_tenant=global/view/a2282980-4327-11ed-8b28-cdde0c7cf02f?_g=(filters:!(),refreshInterval:(pause:!t,value:0),time:(from:now-7d,to:now))&_a=(description:'',filters:!(),fullScreenMode:!f,options:(hidePanelTitles:!f,useMargins:!t),query:(language:kuery,query:'test_name.keyword:%22tempest.api.compute.admin.test_volume.AttachSCSIVolumeTestJSON.test_attach_scsi_disk_with_config_drive%22%20and%20test_status.keyword:%22fail%22'),timeRestore:!f,title:'Subunit%20-%20Test%20Results',viewMode:view)

Change abandoned by "Ghanshyam <email address hidden>" on branch: master
Review: https://review.opendev.org/c/openstack/tempest/+/870913
Reason: no activity for long time, feel free to restore it if needed

Change abandoned by "Stephen Finucane <email address hidden>" on branch: master
Review: https://review.opendev.org/c/openstack/nova/+/870924