test_x86_64_hotplug_cpu.py times out frequently in CI

test_x86_64_hotplug_cpu.py times out frequently in CI

[Stefan Hajnoczi]

Hi Thomas,
test_x86_64_hotplug_cpu.py times out frequently in CI runs. Here is an example:
https://gitlab.com/qemu-project/qemu/-/jobs/8777540230#L1151

The detailed test logs are here:
https://gitlab.com/qemu-project/qemu/-/jobs/8777540230/artifacts/browse/build/tests/functional/x86_64/test_x86_64_hotplug_cpu.HotPlugCPU.test_hotplug/

I looked at this failure with Dan and Peter on IRC. It was pointed out
that the final command assumes that device_del takes effect
immediately. The console log shows that the CPU was still visible to
the guest when the final command executed.

Could be a bug in QEMU, the test, or both?

2025-01-06 15:45:29,308: :/#
2025-01-06 15:45:29,313: cd /sys/devices/system/cpu/cpu0
2025-01-06 15:45:29,315: :/sys/devices/system/cpu/cpu0#
2025-01-06 15:45:29,320: cd /sys/devices/system/cpu/cpu1
2025-01-06 15:45:29,322: sh: cd: /sys/devices/system/cpu/cpu1: No such
file or directory
2025-01-06 15:45:29,325:
2025-01-06 15:45:29,330: :/sys/devices/system/cpu/cpu0# [    7.337146]
CPU1 has been hot-added
2025-01-06 15:45:29,330:
2025-01-06 15:45:29,335: cd /sys/devices/system/cpu/cpu1
2025-01-06 15:45:29,337: :/sys/devices/system/cpu/cpu1#
2025-01-06 15:45:29,342: cd /sys/devices/system/cpu/cpu1

Thanks,
Stefan

Re: test_x86_64_hotplug_cpu.py times out frequently in CI

[Peter Maydell]

On Mon, 6 Jan 2025 at 16:45, Stefan Hajnoczi <stefanha@gmail.com> wrote:
>
> Hi Thomas,
> test_x86_64_hotplug_cpu.py times out frequently in CI runs. Here is an example:
> https://gitlab.com/qemu-project/qemu/-/jobs/8777540230#L1151
>
> The detailed test logs are here:
> https://gitlab.com/qemu-project/qemu/-/jobs/8777540230/artifacts/browse/build/tests/functional/x86_64/test_x86_64_hotplug_cpu.HotPlugCPU.test_hotplug/
>
> I looked at this failure with Dan and Peter on IRC. It was pointed out
> that the final command assumes that device_del takes effect
> immediately. The console log shows that the CPU was still visible to
> the guest when the final command executed.
>
> Could be a bug in QEMU, the test, or both?
>
> 2025-01-06 15:45:29,308: :/#
> 2025-01-06 15:45:29,313: cd /sys/devices/system/cpu/cpu0
> 2025-01-06 15:45:29,315: :/sys/devices/system/cpu/cpu0#
> 2025-01-06 15:45:29,320: cd /sys/devices/system/cpu/cpu1
> 2025-01-06 15:45:29,322: sh: cd: /sys/devices/system/cpu/cpu1: No such
> file or directory
> 2025-01-06 15:45:29,325:
> 2025-01-06 15:45:29,330: :/sys/devices/system/cpu/cpu0# [    7.337146]
> CPU1 has been hot-added
> 2025-01-06 15:45:29,330:
> 2025-01-06 15:45:29,335: cd /sys/devices/system/cpu/cpu1
> 2025-01-06 15:45:29,337: :/sys/devices/system/cpu/cpu1#
> 2025-01-06 15:45:29,342: cd /sys/devices/system/cpu/cpu1

Though the fact that there is no final shell prompt after
the last 'cd' command is perhaps evidence against this being
a simple race where the guest execution of the "cd" command
beat the guest handling of the hot-unplug event.

-- PMM

Re: test_x86_64_hotplug_cpu.py times out frequently in CI

[Thomas Huth]

On 06/01/2025 17.49, Peter Maydell wrote:
> On Mon, 6 Jan 2025 at 16:45, Stefan Hajnoczi <stefanha@gmail.com> wrote:
>>
>> Hi Thomas,
>> test_x86_64_hotplug_cpu.py times out frequently in CI runs. Here is an example:
>> https://gitlab.com/qemu-project/qemu/-/jobs/8777540230#L1151
>>
>> The detailed test logs are here:
>> https://gitlab.com/qemu-project/qemu/-/jobs/8777540230/artifacts/browse/build/tests/functional/x86_64/test_x86_64_hotplug_cpu.HotPlugCPU.test_hotplug/
>>
>> I looked at this failure with Dan and Peter on IRC. It was pointed out
>> that the final command assumes that device_del takes effect
>> immediately. The console log shows that the CPU was still visible to
>> the guest when the final command executed.
>>
>> Could be a bug in QEMU, the test, or both?
>>
>> 2025-01-06 15:45:29,308: :/#
>> 2025-01-06 15:45:29,313: cd /sys/devices/system/cpu/cpu0
>> 2025-01-06 15:45:29,315: :/sys/devices/system/cpu/cpu0#
>> 2025-01-06 15:45:29,320: cd /sys/devices/system/cpu/cpu1
>> 2025-01-06 15:45:29,322: sh: cd: /sys/devices/system/cpu/cpu1: No such
>> file or directory
>> 2025-01-06 15:45:29,325:
>> 2025-01-06 15:45:29,330: :/sys/devices/system/cpu/cpu0# [    7.337146]
>> CPU1 has been hot-added
>> 2025-01-06 15:45:29,330:
>> 2025-01-06 15:45:29,335: cd /sys/devices/system/cpu/cpu1
>> 2025-01-06 15:45:29,337: :/sys/devices/system/cpu/cpu1#
>> 2025-01-06 15:45:29,342: cd /sys/devices/system/cpu/cpu1
> 
> Though the fact that there is no final shell prompt after
> the last 'cd' command is perhaps evidence against this being
> a simple race where the guest execution of the "cd" command
> beat the guest handling of the hot-unplug event.

Yes, sounds like a race ... I'll try to come up with a patch to fix it.

  Thomas