disk i/o locks up execution of guest for a long time

[Sam Morris]

Occasionally, when I save a file in vim in my guest (Debian running Linux 2.6.32), the VM will lock up for ~20 seconds while the disk I/O is performed. After that time, everything continues executing normally.

When this happens, the following kernel messages are logged -- see comment 1.

There is nothing in the VirtualBox log for the VM.

Please note, this is not a duplicate of #7858; in this bug, the guest returns after the delay, during which disk I/O is indicated in the disk activity status indicator; in the other bug, the guest never responds, and the indicator is not lit.

[Sam Morris]

Oh, damn trac for using WikiFormatting by default! :)

Here are the log messages in plain:

Jan 15 16:31:14 leela kernel: [135567.816259] ata1.00: exception Emask 0x0 SAct 0x3 SErr 0x0 action 0x6 frozen
Jan 15 16:31:14 leela kernel: [135567.816267] ata1.00: failed command: READ FPDMA QUEUED
Jan 15 16:31:14 leela kernel: [135567.816276] ata1.00: cmd 60/08:00:3f:09:40/01:00:04:00:00/40 tag 0 ncq 135168 in
Jan 15 16:31:14 leela kernel: [135567.816278]          res 40/00:01:00:00:00/00:00:00:00:00/00 Emask 0x4 (timeout)
Jan 15 16:31:14 leela kernel: [135567.816283] ata1.00: status: { DRDY }
Jan 15 16:31:14 leela kernel: [135567.816287] ata1.00: failed command: WRITE FPDMA QUEUED
Jan 15 16:31:14 leela kernel: [135567.816295] ata1.00: cmd 61/08:08:bf:a5:d8/00:00:06:00:00/40 tag 1 ncq 4096 out
Jan 15 16:31:14 leela kernel: [135567.816297]          res 40/00:00:00:00:00/00:00:00:00:00/00 Emask 0x4 (timeout)
Jan 15 16:31:14 leela kernel: [135567.816302] ata1.00: status: { DRDY }
Jan 15 16:31:14 leela kernel: [135567.816322] ata1: hard resetting link
Jan 15 16:31:14 leela kernel: [135568.136438] ata1: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
Jan 15 16:31:19 leela kernel: [135573.136315] ata1.00: qc timeout (cmd 0xec)
Jan 15 16:31:19 leela kernel: [135573.136394] ata1.00: failed to IDENTIFY (I/O error, err_mask=0x4)
Jan 15 16:31:19 leela kernel: [135573.136398] ata1.00: revalidation failed (errno=-5)
Jan 15 16:31:19 leela kernel: [135573.136417] ata1: hard resetting link
Jan 15 16:31:19 leela kernel: [135573.456530] ata1: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
Jan 15 16:31:29 leela kernel: [135583.456327] ata1.00: qc timeout (cmd 0xec)
Jan 15 16:31:29 leela kernel: [135583.456420] ata1.00: failed to IDENTIFY (I/O error, err_mask=0x4)
Jan 15 16:31:29 leela kernel: [135583.456425] ata1.00: revalidation failed (errno=-5)
Jan 15 16:31:29 leela kernel: [135583.456442] ata1: limiting SATA link speed to 1.5 Gbps
Jan 15 16:31:29 leela kernel: [135583.456459] ata1: hard resetting link
Jan 15 16:31:30 leela kernel: [135583.776535] ata1: SATA link up 1.5 Gbps (SStatus 113 SControl 310)
Jan 15 16:31:30 leela kernel: [135583.777532] ata1.00: configured for UDMA/133
Jan 15 16:31:30 leela kernel: [135583.777539] ata1.00: device reported invalid CHS sector 0
Jan 15 16:31:30 leela kernel: [135583.777543] ata1.00: device reported invalid CHS sector 0
Jan 15 16:31:30 leela kernel: [135583.777559] sd 0:0:0:0: [sda] Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE
Jan 15 16:31:30 leela kernel: [135583.777564] sd 0:0:0:0: [sda] Sense Key : Aborted Command [current] [descriptor]
Jan 15 16:31:30 leela kernel: [135583.777570] Descriptor sense data with sense descriptors (in hex):
Jan 15 16:31:30 leela kernel: [135583.777573]         72 0b 00 00 00 00 00 0c 00 0a 80 00 00 00 00 00 
Jan 15 16:31:30 leela kernel: [135583.777582]         00 00 00 00 
Jan 15 16:31:30 leela kernel: [135583.777587] sd 0:0:0:0: [sda] Add. Sense: No additional sense information
Jan 15 16:31:30 leela kernel: [135583.777592] sd 0:0:0:0: [sda] CDB: Read(10): 28 00 04 40 09 3f 00 01 08 00
Jan 15 16:31:30 leela kernel: [135583.777602] end_request: I/O error, dev sda, sector 71305535
Jan 15 16:31:30 leela kernel: [135583.777623] ata1: EH complete

[aeichner]

Please attach a log of the VM.

[Sam Morris]

IIRC, this happened around the 45-hour mark

[Frank Mehnert]

Log attached, Alexander, please have a look.

[aeichner]

The log doesn't contain further information which could help to isolate the problem. It shows that the VM was successfully suspended/resumed after the hang occurred. This means the controller successfully processed all I/O requests and raised an interrupt to notify the guest. Could be some kind race condition but it is not some kind of SMP setup (where we have other reports for and lowering the CPU count helps there) and async I/O is not used either.

[Sam Morris]

Hi there, I've not seen this bug for a long time, so feel free to close.

[Frank Mehnert]

Thank you for the information!