Test delay-report-ns and delay-stop-ns via HMP qemu-io (break, aio_read, resume) on a null node (with blkdebug).
Signed-off-by: Hanna Czenczek <[email protected]> --- tests/qemu-iotests/tests/io-delay-reporting | 187 ++++++++++++++++++ .../qemu-iotests/tests/io-delay-reporting.out | 90 +++++++++ 2 files changed, 277 insertions(+) create mode 100755 tests/qemu-iotests/tests/io-delay-reporting create mode 100644 tests/qemu-iotests/tests/io-delay-reporting.out diff --git a/tests/qemu-iotests/tests/io-delay-reporting b/tests/qemu-iotests/tests/io-delay-reporting new file mode 100755 index 00000000000..7a51d2c4063 --- /dev/null +++ b/tests/qemu-iotests/tests/io-delay-reporting @@ -0,0 +1,187 @@ +#!/usr/bin/env python3 +# group: rw +# +# Test the I/O delay QMP event. +# +# Copyright (C) 2026 Red Hat, Inc. +# +# SPDX-License-Identifier: GPL-2.0-or-later +# +# Creator/Owner: Hanna Czenczek <[email protected]> + +import asyncio +import iotests +from iotests import filter_qmp_event, log + +DELAY_REPORT_MS = 5000 # ms +DELAY_STOP_MS = 10000 # ms +EPSILON_MS = 50 # ms -- small delta that can safely be added/subtracted +NS_PER_MS = 1000 * 1000 +DELAY_REPORT_NS = DELAY_REPORT_MS * NS_PER_MS +DELAY_STOP_NS = DELAY_STOP_MS * NS_PER_MS + +qtest_clock = 0 # ms + +iotests.script_initialize() + +def vm_qemu_io(qvm, virtio_blk_id, cmd): + log(f'[HMP] qemu-io to {virtio_blk_id}: {cmd}') + command_line=f'qemu-io -d {virtio_blk_id}/virtio-backend "{cmd}"' + log(qvm.qmp('human-monitor-command', command_line=command_line)) + +def advance_clock_to(qvm, clock_ms): + """ + Retain the current absolute clock time so we can step *to* a specific time + via `clock_step`. + """ + + # pylint does not like global much, but this is a test script, and not + # using global would just make this more complicated. + global qtest_clock # pylint: disable=global-statement + msecs = clock_ms - qtest_clock + log(f'[qtest] clock_step {msecs}ms to {clock_ms}ms') + qvm.qtest(f'clock_step {msecs * NS_PER_MS}') + qtest_clock += msecs + +def reset_clock(): + """ + Reset the internal qtest clock to 0; use before launching a new VM. + """ + + global qtest_clock # pylint: disable=global-statement + qtest_clock = 0 + +def await_event(qvm, match): + evt = qvm.event_wait(match, timeout=30.0) + assert evt is not None + return evt + +def assert_no_event(qvm, event_name): + try: + evt = qvm.event_wait(event_name, timeout=0.1) + assert evt is None, f'Unexpected {event_name} event: {evt}' + except asyncio.TimeoutError: + pass + log(f'(No {event_name} event)') + +def run(error): + """ + If @error is False, run both requests normally. + If it is True, inject an error into the second one. + """ + + log('') + log(f'=== Running tests with error={error} ===') + log('') + + reset_clock() + with iotests.VM() as vm: + # Cannot use null-co.latency-ns, as that uses realtime (not qtest time) + # Need to use raw to get the read_aio event working + opts = { + 'driver': 'raw', + 'node-name': 'test-node', + 'file': { + 'driver': 'blkdebug', + 'image': { + 'driver': 'null-co', + }, + }, + } + if error: + opts['file']['inject-error'] = [{ + 'event': 'read_aio', + 'iotype': 'read', + 'sector': str(4096 // 512), + 'once': 'on', + }] + vm.add_blockdev(vm.qmp_to_opts(opts)) + + vm.launch() + + log(f'[QMP] device_add id=vblk delay-report-ns={DELAY_REPORT_NS} ' + f'delay-stop-ns={DELAY_STOP_NS}') + log(vm.qmp('device_add', { + 'driver': 'virtio-blk', + 'id': 'vblk', + 'drive': 'test-node', + 'delay-report-ns': DELAY_REPORT_NS, + 'delay-stop-ns': DELAY_STOP_NS, + })) + + try: + vm_qemu_io(vm, 'vblk', 'break read_aio read_0') + vm_qemu_io(vm, 'vblk', 'aio_read 0k 4k') + vm_qemu_io(vm, 'vblk', 'wait_break read_0') + + vm_qemu_io(vm, 'vblk', 'break read_aio read_1') + vm_qemu_io(vm, 'vblk', 'aio_read 4k 4k') + vm_qemu_io(vm, 'vblk', 'wait_break read_1') + + advance_clock_to(vm, DELAY_REPORT_MS - EPSILON_MS) + + # Assert there is no event before the step + assert_no_event(vm, 'BLOCK_IO_DELAY') + + advance_clock_to(vm, DELAY_REPORT_MS) + + # But now there should be, right on time + events = [await_event(vm, 'BLOCK_IO_DELAY'), + await_event(vm, 'BLOCK_IO_DELAY')] + events.sort(key=lambda event: event['data']['offset']) + for event in events: + log(event, filters=[filter_qmp_event]) + + # Have the read_0 request finish -- advance clock to test the + # correct duration + advance_clock_to(vm, DELAY_REPORT_MS + EPSILON_MS) + vm_qemu_io(vm, 'vblk', 'resume read_0') + log(await_event(vm, 'BLOCK_IO_DONE'), filters=[filter_qmp_event]) + + # Let read_1 hang for longer to trigger a STOP + advance_clock_to(vm, DELAY_STOP_MS) + + # Read the pre-STOP notification + log(await_event(vm, 'BLOCK_IO_DELAY'), filters=[filter_qmp_event]) + + # Then the actual STOP + log(await_event(vm, 'STOP'), filters=[filter_qmp_event]) + log('[QMP] query-status') + log(vm.qmp('query-status')) + + # Have the read_1 request finish + advance_clock_to(vm, DELAY_STOP_MS + EPSILON_MS) + vm_qemu_io(vm, 'vblk', 'resume read_1') + log(await_event(vm, 'BLOCK_IO_DONE'), filters=[filter_qmp_event]) + + log('[QMP] cont') + log(vm.qmp('cont')) + log(await_event(vm, 'RESUME'), filters=[filter_qmp_event]) + log('[QMP] query-status') + log(vm.qmp('query-status')) + except Exception: + # The VM will not be able to quit without these requests finished, + # which (without this block) would make the test hang instead of + # exit if something unexpected goes wrong + vm_qemu_io(vm, 'vblk', 'resume read_0') + vm_qemu_io(vm, 'vblk', 'resume read_1') + raise + + # Test device unplug to verify that stopping the delay tracking timer + # works + log('[QMP] device_del id=vblk') + log(vm.qmp('device_del', id='vblk')) + + # system_reset forces the device unplug to happen + log('[QMP] system_reset') + log(vm.qmp('system_reset')) + + event = vm.event_wait('DEVICE_DELETED', 20.0, + {'data': {'device': 'vblk'}}) + assert event is not None + log(event, filters=[filter_qmp_event]) + + vm.shutdown() + +run(False) +run(True) diff --git a/tests/qemu-iotests/tests/io-delay-reporting.out b/tests/qemu-iotests/tests/io-delay-reporting.out new file mode 100644 index 00000000000..99349d2b124 --- /dev/null +++ b/tests/qemu-iotests/tests/io-delay-reporting.out @@ -0,0 +1,90 @@ + +=== Running tests with error=False === + +[QMP] device_add id=vblk delay-report-ns=5000000000 delay-stop-ns=10000000000 +{"return": {}} +[HMP] qemu-io to vblk: break read_aio read_0 +{"return": ""} +[HMP] qemu-io to vblk: aio_read 0k 4k +{"return": ""} +[HMP] qemu-io to vblk: wait_break read_0 +{"return": ""} +[HMP] qemu-io to vblk: break read_aio read_1 +{"return": ""} +[HMP] qemu-io to vblk: aio_read 4k 4k +{"return": ""} +[HMP] qemu-io to vblk: wait_break read_1 +{"return": ""} +[qtest] clock_step 4950ms to 4950ms +(No BLOCK_IO_DELAY event) +[qtest] clock_step 50ms to 5000ms +{"data": {"action": "report", "bytes": 4096, "latency-ns": 5000000000, "offset": 0, "operation": "read", "qom-path": "/machine/peripheral/vblk/virtio-backend"}, "event": "BLOCK_IO_DELAY", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}} +{"data": {"action": "report", "bytes": 4096, "latency-ns": 5000000000, "offset": 4096, "operation": "read", "qom-path": "/machine/peripheral/vblk/virtio-backend"}, "event": "BLOCK_IO_DELAY", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}} +[qtest] clock_step 50ms to 5050ms +[HMP] qemu-io to vblk: resume read_0 +{"return": ""} +{"data": {"bytes": 4096, "failed": false, "latency-ns": 5050000000, "offset": 0, "operation": "read", "qom-path": "/machine/peripheral/vblk/virtio-backend"}, "event": "BLOCK_IO_DONE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}} +[qtest] clock_step 4950ms to 10000ms +{"data": {"action": "stop", "bytes": 4096, "latency-ns": 10000000000, "offset": 4096, "operation": "read", "qom-path": "/machine/peripheral/vblk/virtio-backend"}, "event": "BLOCK_IO_DELAY", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}} +{"event": "STOP", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}} +[QMP] query-status +{"return": {"running": false, "status": "io-hang"}} +[qtest] clock_step 50ms to 10050ms +[HMP] qemu-io to vblk: resume read_1 +{"return": ""} +{"data": {"bytes": 4096, "failed": false, "latency-ns": 10050000000, "offset": 4096, "operation": "read", "qom-path": "/machine/peripheral/vblk/virtio-backend"}, "event": "BLOCK_IO_DONE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}} +[QMP] cont +{"return": {}} +{"event": "RESUME", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}} +[QMP] query-status +{"return": {"running": true, "status": "running"}} +[QMP] device_del id=vblk +{"return": {}} +[QMP] system_reset +{"return": {}} +{"data": {"device": "vblk", "path": "/machine/peripheral/vblk"}, "event": "DEVICE_DELETED", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}} + +=== Running tests with error=True === + +[QMP] device_add id=vblk delay-report-ns=5000000000 delay-stop-ns=10000000000 +{"return": {}} +[HMP] qemu-io to vblk: break read_aio read_0 +{"return": ""} +[HMP] qemu-io to vblk: aio_read 0k 4k +{"return": ""} +[HMP] qemu-io to vblk: wait_break read_0 +{"return": ""} +[HMP] qemu-io to vblk: break read_aio read_1 +{"return": ""} +[HMP] qemu-io to vblk: aio_read 4k 4k +{"return": ""} +[HMP] qemu-io to vblk: wait_break read_1 +{"return": ""} +[qtest] clock_step 4950ms to 4950ms +(No BLOCK_IO_DELAY event) +[qtest] clock_step 50ms to 5000ms +{"data": {"action": "report", "bytes": 4096, "latency-ns": 5000000000, "offset": 0, "operation": "read", "qom-path": "/machine/peripheral/vblk/virtio-backend"}, "event": "BLOCK_IO_DELAY", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}} +{"data": {"action": "report", "bytes": 4096, "latency-ns": 5000000000, "offset": 4096, "operation": "read", "qom-path": "/machine/peripheral/vblk/virtio-backend"}, "event": "BLOCK_IO_DELAY", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}} +[qtest] clock_step 50ms to 5050ms +[HMP] qemu-io to vblk: resume read_0 +{"return": ""} +{"data": {"bytes": 4096, "failed": false, "latency-ns": 5050000000, "offset": 0, "operation": "read", "qom-path": "/machine/peripheral/vblk/virtio-backend"}, "event": "BLOCK_IO_DONE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}} +[qtest] clock_step 4950ms to 10000ms +{"data": {"action": "stop", "bytes": 4096, "latency-ns": 10000000000, "offset": 4096, "operation": "read", "qom-path": "/machine/peripheral/vblk/virtio-backend"}, "event": "BLOCK_IO_DELAY", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}} +{"event": "STOP", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}} +[QMP] query-status +{"return": {"running": false, "status": "io-hang"}} +[qtest] clock_step 50ms to 10050ms +[HMP] qemu-io to vblk: resume read_1 +{"return": ""} +{"data": {"bytes": 4096, "failed": true, "latency-ns": 10050000000, "offset": 4096, "operation": "read", "qom-path": "/machine/peripheral/vblk/virtio-backend"}, "event": "BLOCK_IO_DONE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}} +[QMP] cont +{"return": {}} +{"event": "RESUME", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}} +[QMP] query-status +{"return": {"running": true, "status": "running"}} +[QMP] device_del id=vblk +{"return": {}} +[QMP] system_reset +{"return": {}} +{"data": {"device": "vblk", "path": "/machine/peripheral/vblk"}, "event": "DEVICE_DELETED", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}} -- 2.55.0
