VirtualBox

Ticket #8085 (closed defect: fixed)

Opened 3 years ago

Last modified 10 months ago

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

Reported by: yrro Owned by:
Priority: minor Component: other
Version: VirtualBox 3.2.12 Keywords:
Cc: Guest type: Linux
Host type: Windows

Description (last modified by frank) (diff)

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.

Attachments

leela-2011-01-11-10-17-57.log Download (50.5 KB) - added by yrro 3 years ago.
IIRC, this happened around the 45-hour mark

Change History

comment:1 Changed 3 years ago by yrro

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

comment:2 Changed 3 years ago by frank

  • Description modified (diff)

comment:3 Changed 3 years ago by aeichner

Please attach a log of the VM.

Changed 3 years ago by yrro

IIRC, this happened around the 45-hour mark

comment:4 Changed 3 years ago by frank

Log attached, Alexander, please have a look.

comment:5 Changed 3 years ago by 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.

comment:6 Changed 10 months ago by yrro

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

comment:7 Changed 10 months ago by frank

  • Status changed from new to closed
  • Resolution set to fixed
  • Description modified (diff)

Thank you for the information!

Note: See TracTickets for help on using tickets.

www.oracle.com
ContactPrivacy policyTerms of Use