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