[ kvm-Bugs-2933400 ] virtio-blk io errors / data corruption on raw drives > 1 TB

[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]

 



Bugs item #2933400, was opened at 2010-01-16 15:35
Message generated for change (Comment added) made by masc82
You can respond by visiting: 
https://sourceforge.net/tracker/?func=detail&atid=893831&aid=2933400&group_id=180599

Please note that this message will contain a full copy of the comment thread,
including the initial issue submission, for this request,
not just the latest update.
Category: None
Group: None
Status: Open
Resolution: None
Priority: 9
Private: No
Submitted By: MaSc82 (masc82)
>Assigned to: Nobody/Anonymous (nobody)
Summary: virtio-blk io errors / data corruption on raw drives > 1 TB

Initial Comment:
When attaching raw drives > 1 TB, buffer io errors will most likely occur, filesystems get corrupted. Processes (like mkfs.ext4) might freeze completely when filesystems are created on the guest.

Here's a typical log excerpt when using mkfs.ext4 on a 1.5 TB drive on a Ubuntu 9.10 guest:
(kern.log)
Jan 15 20:40:44 q kernel: [  677.076602] Buffer I/O error on device vde, logical block 366283764
Jan 15 20:40:44 q kernel: [  677.076607] Buffer I/O error on device vde, logical block 366283765
Jan 15 20:40:44 q kernel: [  677.076611] Buffer I/O error on device vde, logical block 366283766
Jan 15 20:40:44 q kernel: [  677.076616] Buffer I/O error on device vde, logical block 366283767
Jan 15 20:40:44 q kernel: [  677.076621] Buffer I/O error on device vde, logical block 366283768
Jan 15 20:40:44 q kernel: [  677.076626] Buffer I/O error on device vde, logical block 366283769
(messages)
Jan 15 20:40:44 q kernel: [  677.076534] lost page write due to I/O error on vde
Jan 15 20:40:44 q kernel: [  677.076541] lost page write due to I/O error on vde
Jan 15 20:40:44 q kernel: [  677.076546] lost page write due to I/O error on vde
Jan 15 20:40:44 q kernel: [  677.076599] lost page write due to I/O error on vde
Jan 15 20:40:44 q kernel: [  677.076604] lost page write due to I/O error on vde
Jan 15 20:40:44 q kernel: [  677.076609] lost page write due to I/O error on vde
Jan 15 20:40:44 q kernel: [  677.076613] lost page write due to I/O error on vde
Jan 15 20:40:44 q kernel: [  677.076618] lost page write due to I/O error on vde
Jan 15 20:40:44 q kernel: [  677.076623] lost page write due to I/O error on vde
Jan 15 20:40:44 q kernel: [  677.076628] lost page write due to I/O error on vde
Jan 15 20:45:55 q Backgrounding to notify hosts...
(The following entries will repeat infinitely, mkfs.ext4 will not exit and cannot be killed)
Jan 15 20:49:27 q kernel: [ 1200.520096] mkfs.ext4     D 0000000000000000     0  1839   1709 0x00000000
Jan 15 20:49:27 q kernel: [ 1200.520101]  ffff88004e157cb8 0000000000000082 ffff88004e157c58 0000000000015880
Jan 15 20:49:27 q kernel: [ 1200.520115]  ffff88004ef6c7c0 0000000000015880 0000000000015880 0000000000015880
Jan 15 20:49:27 q kernel: [ 1200.520118]  0000000000015880 ffff88004ef6c7c0 0000000000015880 0000000000015880
Jan 15 20:49:27 q kernel: [ 1200.520123] Call Trace:
Jan 15 20:49:27 q kernel: [ 1200.520157]  [<ffffffff810da0f0>] ? sync_page+0x0/0x50
Jan 15 20:49:27 q kernel: [ 1200.520178]  [<ffffffff815255f8>] io_schedule+0x28/0x40
Jan 15 20:49:27 q kernel: [ 1200.520182]  [<ffffffff810da12d>] sync_page+0x3d/0x50
Jan 15 20:49:27 q kernel: [ 1200.520185]  [<ffffffff81525b17>] __wait_on_bit+0x57/0x80
Jan 15 20:49:27 q kernel: [ 1200.520192]  [<ffffffff810da29e>] wait_on_page_bit+0x6e/0x80
Jan 15 20:49:27 q kernel: [ 1200.520205]  [<ffffffff81078650>] ? wake_bit_function+0x0/0x40
Jan 15 20:49:27 q kernel: [ 1200.520210]  [<ffffffff810e44e0>] ? pagevec_lookup_tag+0x20/0x30
Jan 15 20:49:27 q kernel: [ 1200.520213]  [<ffffffff810da745>] wait_on_page_writeback_range+0xf5/0x190
Jan 15 20:49:27 q kernel: [ 1200.520217]  [<ffffffff810da807>] filemap_fdatawait+0x27/0x30
Jan 15 20:49:27 q kernel: [ 1200.520220]  [<ffffffff810dacb4>] filemap_write_and_wait+0x44/0x50
Jan 15 20:49:27 q kernel: [ 1200.520235]  [<ffffffff8114ba9f>] __sync_blockdev+0x1f/0x40
Jan 15 20:49:27 q kernel: [ 1200.520239]  [<ffffffff8114bace>] sync_blockdev+0xe/0x10
Jan 15 20:49:27 q kernel: [ 1200.520241]  [<ffffffff8114baea>] block_fsync+0x1a/0x20
Jan 15 20:49:27 q kernel: [ 1200.520249]  [<ffffffff81142f26>] vfs_fsync+0x86/0xf0
Jan 15 20:49:27 q kernel: [ 1200.520252]  [<ffffffff81142fc9>] do_fsync+0x39/0x60
Jan 15 20:49:27 q kernel: [ 1200.520255]  [<ffffffff8114301b>] sys_fsync+0xb/0x10
Jan 15 20:49:27 q kernel: [ 1200.520271]  [<ffffffff81011fc2>] system_call_fastpath+0x16/0x1b

In my case I was switching to virtio at one point, but the behaviour didn't show until there was > 1 TB data on the filesystem. very dangerous.

Tested using 2 different SATA controllers, 1.5 TB lvm/mdraid, single 1.5 TB drive and 2 TB lvm/mdraid.
The behaviour does not occur with if=scsi or if=ide.

#2914397 might be related: https://sourceforge.net/tracker/?func=detail&aid=2914397&group_id=180599&atid=893831
This blog post might also relate: http://www.neuhalfen.name/2009/08/05/OpenSolaris_KVM_and_large_IDE_drives/

CPU: Intel Xeon E5430
KVM: qemu-kvm-0.12.1.2
Kernel:  2.6.32.2, x86_64
Guest OS: Verified to occur on guests Ubuntu Linux 9.10 (64-bit) and Gentoo Linux (64-bit)
Commandline (atm using ide instead of virtio for large drives as a workaround):  qemu-system-x86_64 -S -M pc-0.11 -enable-kvm -m 1500 -smp 2 -name q -uuid 4684a449-0294-6a87-24a0-1f6d7c6e3eba -chardev socket,id=monitor,path=/var/lib/libvirt/qemu/q.monitor,server,nowait -monitor chardev:monitor -boot c -drive cache=writeback,file=/dev/media1/q,if=virtio,index=0,boot=on -drive cache=writeback,file=/dev/media1/q_storage1,if=virtio,index=1 -drive cache=writeback,file=/dev/media2/q_storage2,if=ide,index=0 -drive cache=writeback,file=/dev/media3/q_storage3,if=virtio,index=2 -drive cache=writeback,file=/dev/media4/q_storage4,if=ide,index=1 -drive cache=writeback,file=/dev/media5/q_storage5,if=ide,index=2 -net nic,macaddr=52:54:00:12:34:59,vlan=0,model=virtio,name=virtio.0 -net tap,fd=18,vlan=0,name=tap.0 -serial none -parallel none -usb -usbdevice tablet -vnc 0.0.0.0:2 -k de -vga cirrus

----------------------------------------------------------------------

>Comment By: MaSc82 (masc82)
Date: 2010-04-04 16:26

Message:
Christoph Hellwig's virtio-large-iovecs patch which fixed #2941282
(http://sourceforge.net/tracker/?func=detail&aid=2941282&group_id=180599&atid=893831)
also improves things here.
Buffer IO errors seem to be gone, but corruption on large disks remains.
mkfs.ext4 on 1.5 TB disk was ok, but soon after starting rsync:

Apr  4 15:49:30 q kernel: [  975.863441] EXT4-fs error (device vdd):
ext4_add_entry: bad entry in directory #86376462: directory entry across
blocks - offset=0, inode=1025, rec_len=66576, name_len=0
Apr  4 15:50:03 q kernel: [ 1008.142949] EXT4-fs error (device vdd):
ext4_mb_generate_buddy: EXT4-fs: group 10545: 0 blocks in bitmap, 32766 in
gd
Apr  4 15:50:32 q kernel: [ 1037.631463] hrtimer: interrupt too slow,
forcing clock min delta to 71999847 ns
Apr  4 15:50:54 q kernel: [ 1059.334332] EXT4-fs error (device vdd):
ext4_add_entry: bad entry in directory #86376463: directory entry across
blocks - offset=0, inode=1025, rec_len=66576, name_len=0
Apr  4 15:52:46 q kernel: [ 1171.534545] EXT4-fs error (device vdd):
ext4_add_entry: bad entry in directory #86376463: directory entry across
blocks - offset=0, inode=1025, rec_len=66576, name_len=0
Apr  4 15:53:02 q kernel: [ 1187.393262] EXT4-fs error (device vdd):
ext4_add_entry: bad entry in directory #86376464: rec_len is smaller than
minimal - offset=0, inode=1241866, rec_len=8, name_len=0
Apr  4 15:53:02 q kernel: [ 1187.393559] EXT4-fs error (device vdd):
ext4_delete_entry: bad entry in directory #86376464: rec_len is smaller
than minimal - offset=0, inode=1241866, rec_len=8, name_len=0
Apr  4 15:53:02 q kernel: [ 1187.393759] EXT4-fs error (device vdd):
ext4_add_entry: bad entry in directory #86376464: rec_len is smaller than
minimal - offset=0, inode=1241866, rec_len=8, name_len=0

aborting rsync and running fsck.ext4:

root@q:/var/log# fsck -nf /dev/vdd
fsck from util-linux-ng 2.16
e2fsck 1.41.9 (22-Aug-2009)
Pass 1: Checking inodes, blocks, and sizes
Inode 86376705 has an invalid extent node (blk 1902592, lblk 0)
Clear? no
Inode 86376705, i_blocks is 4193888, should be 0.  Fix? no
Inode 86376707 has an invalid extent node (blk 2455552, lblk 0)
Clear? no
Inode 86376707, i_blocks is 1432952, should be 0.  Fix? no
Running additional passes to resolve blocks claimed by more than one
inode...
Pass 1B: Rescanning for multiply-claimed blocks
Multiply-claimed block(s) in inode 86376492: 345538560 345538561
Multiply-claimed block(s) in inode 86376691: 345538560 345538561
Error while iterating over blocks in inode 86376705 (pass1b): Corrupt
extent header
Error while iterating over blocks in inode 86376707 (pass1b): Corrupt
extent header
Pass 1C: Scanning directories for inodes with multiply-claimed blocks
Pass 1D: Reconciling multiply-claimed blocks
(There are 2 inodes containing multiply-claimed blocks.)
File ... (inode #86376492, mod time Wed Feb 17 15:37:40 2010) 
  has 2 multiply-claimed block(s), shared with 1 file(s):
	... (inode #86376691, mod time Sat Jul 11 18:16:10 2009)
Clone multiply-claimed blocks? no
Delete file? no
File ... (inode #86376691, mod time Sat Jul 11 18:16:10 2009) 
  has 2 multiply-claimed block(s), shared with 1 file(s):
	... (inode #86376492, mod time Wed Feb 17 15:37:40 2010)
Clone multiply-claimed blocks? no
Delete file? no
Pass 2: Checking directory structure
Missing '.' in directory inode 86376462.
Fix? no
Invalid inode number for '.' in directory inode 86376462.
Fix? no
Directory entry for '.' in ... (86376462) is big.
Split? no
Directory inode 86376463, block 0, offset 0: directory corrupted
Salvage? no
e2fsck: aborted

The same test using 400 GB disk didn't show any errors.

----------------------------------------------------------------------

Comment By: Jason  (jyellick)
Date: 2010-03-30 07:47

Message:
I too am experiencing this bug.  My disks are not very large, they are
mostly less than 10G, with a few as large as 150G.  I see the error occur
most during periods of heavy IO like system updates causing the filesystem
to remount read only with some data loss.

Host:
Arch Linux
kernel 2.6.33.1 (also observered in 2.6.32)
qemu 0.12.3
drbd replicating vm images

Guest
Arch Linux
kernel 2.6.33.1 (also observed in 2.6.32)
rootfs is ext4 on devicemapper LUKS partition
disk size is less than 10GiB

// Guest kernel log

Mar 20 09:06:57 jhdhr kernel: end_request: I/O error, dev vda, sector
9270528
Mar 20 09:06:57 jhdhr kernel: end_request: I/O error, dev vda, sector
9270536
Mar 20 09:06:57 jhdhr kernel: end_request: I/O error, dev vda, sector
9271520
Mar 20 09:06:57 jhdhr kernel: end_request: I/O error, dev vda, sector
9272488
Mar 20 09:07:04 jhdhr kernel: JBD2: Detected IO errors while flushing file
data on dm-0-8
Mar 20 09:07:09 jhdhr kernel: end_request: I/O error, dev vda, sector
9277384
Mar 20 09:07:09 jhdhr kernel: quiet_error: 2640 callbacks suppressed
Mar 20 09:07:09 jhdhr kernel: Buffer I/O error on device dm-0, logical
block 1159168
Mar 20 09:07:09 jhdhr kernel: lost page write due to I/O error on dm-0
Mar 20 09:07:09 jhdhr kernel: Buffer I/O error on device dm-0, logical
block 1159169
Mar 20 09:07:09 jhdhr kernel: lost page write due to I/O error on dm-0
Mar 20 09:07:09 jhdhr kernel: Buffer I/O error on device dm-0, logical
block 1159170
Mar 20 09:07:09 jhdhr kernel: lost page write due to I/O error on dm-0
Mar 20 09:07:09 jhdhr kernel: Buffer I/O error on device dm-0, logical
block 1159171
Mar 20 09:07:09 jhdhr kernel: lost page write due to I/O error on dm-0
Mar 20 09:07:11 jhdhr kernel: Buffer I/O error on device dm-0, logical
block 1159172
Mar 20 09:07:11 jhdhr kernel: lost page write due to I/O error on dm-0
Mar 20 09:07:11 jhdhr kernel: Buffer I/O error on device dm-0, logical
block 1159173
Mar 20 09:07:11 jhdhr kernel: lost page write due to I/O error on dm-0
Mar 20 09:07:11 jhdhr kernel: Buffer I/O error on device dm-0, logical
block 1159174
Mar 20 09:07:11 jhdhr kernel: lost page write due to I/O error on dm-0
Mar 20 09:07:11 jhdhr kernel: Buffer I/O error on device dm-0, logical
block 1159175
Mar 20 09:07:11 jhdhr kernel: lost page write due to I/O error on dm-0
Mar 20 09:07:11 jhdhr kernel: Buffer I/O error on device dm-0, logical
block 1159176
Mar 20 09:07:11 jhdhr kernel: lost page write due to I/O error on dm-0
Mar 20 09:07:11 jhdhr kernel: Buffer I/O error on device dm-0, logical
block 1159177
Mar 20 09:07:11 jhdhr kernel: lost page write due to I/O error on dm-0
Mar 20 09:07:11 jhdhr kernel: end_request: I/O error, dev vda, sector
9278392
Mar 20 09:07:11 jhdhr kernel: end_request: I/O error, dev vda, sector
9279264
Mar 20 09:07:11 jhdhr kernel: end_request: I/O error, dev vda, sector
9280272
Mar 20 09:07:11 jhdhr kernel: end_request: I/O error, dev vda, sector
9281280
Mar 20 09:07:11 jhdhr kernel: end_request: I/O error, dev vda, sector
9282288
...
// the above blocks of Buffer I/o and lost page, and end_request alternate
for a fair portion of the log
...
// Ultimiately ending in the following
JBD2: Detected IO errors while flushing file data on dm-0-8
Aborting journal on device dm-0-8.
EXT4-fs error (device dm-0): ext4_journal_start_sb: 
EXT4-fs error (device dm-0): ext4_journal_start_sb: Detected aborted
journal
EXT4-fs (dm-0): Remounting filesystem read-only
Detected aborted journal

// The following is actually from a 2.6.32 dump I had, I have not
reproduced this in 2.6.33.1, but thought I would post it for completeness

Mar 30 00:26:13 jhdhr kernel: end_request: I/O error, dev vda, sector
10000
Mar 30 00:26:15 jhdhr kernel: JBD2: Detected IO errors while flushing file
data on dm-0-8
Mar 30 00:26:42 jhdhr kernel: ------------[ cut here ]------------
Mar 30 00:26:42 jhdhr kernel: WARNING: at fs/buffer.c:1159
mark_buffer_dirty+0x74/0x90()
Mar 30 00:26:42 jhdhr kernel: Hardware name: Bochs
Mar 30 00:26:42 jhdhr kernel: Modules linked in: ext4 mbcache jbd2 crc16
cryptd aes_x86_64 aes_generic xts gf128mul dm_crypt dm_mod sr_mod cdrom
floppy ata_piix ata_generic pata_acpi libata scsi_mod virtio_balloon
virtio_blk virtio_net virtio_rng virtio_console virtio_pci virtio_ring
virtio
Mar 30 00:26:42 jhdhr kernel: Pid: 639, comm: jbd2/dm-0-8 Not tainted
2.6.32-ARCH #1
Mar 30 00:26:42 jhdhr kernel: Call Trace:
Mar 30 00:26:42 jhdhr kernel: [<ffffffff81057b63>] ?
warn_slowpath_common+0x73/0xb0
Mar 30 00:26:42 jhdhr kernel: [<ffffffff8113cda4>] ?
mark_buffer_dirty+0x74/0x90
Mar 30 00:26:42 jhdhr kernel: [<ffffffffa013b399>] ?
__jbd2_journal_unfile_buffer+0x9/0x20 [jbd2]
Mar 30 00:26:42 jhdhr kernel: [<ffffffffa013eb7b>] ?
jbd2_journal_commit_transaction+0xcbb/0x1500 [jbd2]
Mar 30 00:26:42 jhdhr kernel: [<ffffffffa0146911>] ? kjournald2+0xb1/0x210
[jbd2]
Mar 30 00:26:42 jhdhr kernel: [<ffffffff810760b0>] ?
autoremove_wake_function+0x0/0x30
Mar 30 00:26:42 jhdhr kernel: [<ffffffffa0146860>] ? kjournald2+0x0/0x210
[jbd2]
Mar 30 00:26:42 jhdhr kernel: [<ffffffffa0146860>] ? kjournald2+0x0/0x210
[jbd2]
Mar 30 00:26:42 jhdhr kernel: [<ffffffff81075cee>] ? kthread+0x8e/0xa0
Mar 30 00:26:42 jhdhr kernel: [<ffffffff8101311a>] ? child_rip+0xa/0x20
Mar 30 00:26:42 jhdhr kernel: [<ffffffff81075c60>] ? kthread+0x0/0xa0
Mar 30 00:26:42 jhdhr kernel: [<ffffffff81013110>] ? child_rip+0x0/0x20
Mar 30 00:26:42 jhdhr kernel: ---[ end trace 015f5ef643c6f770 ]---

// After the above error in 2.6.32 I see these slightly different ext4
messages

JBD2: Detected IO errors while flushing file data on dm-0-8
Aborting journal on device dm-0-8.
EXT4-fs error (device dm-0) in ext4_reserve_inode_write: Journal has
aborted
EXT4-fs (dm-0): delayed block allocation failed for inode 16756 at logical
offset 0 with max blocks 1 with error -30

This should not happen!!  Data will be lost
EXT4-fs error (device dm-0) in ext4_da_writepages: Journal has aborted
EXT4-fs error (device dm-0): ext4_journal_start_sb: Detected aborted
journal
EXT4-fs (dm-0): Remounting filesystem read-only
EXT4-fs (dm-0): ext4_da_writepages: jbd2_start: 323 pages, ino 16756; err
-30

----------------------------------------------------------------------

Comment By: MaSc82 (masc82)
Date: 2010-03-06 12:24

Message:
repeating the test with mkfs.ext4, it now fails as well. seems I've just
been lucky before.

[   86.803074] end_request: I/O error, dev vdd, sector 2930245608
[   86.803084] __ratelimit: 3 callbacks suppressed
[   86.803090] Buffer I/O error on device vdd, logical block 366280701
[   86.803092] lost page write due to I/O error on vdd
[  480.380107] INFO: task mkfs.ext4:2470 blocked for more than 120
seconds.
[  480.380112] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables
this message.
[  480.380115] mkfs.ext4     D 0000000000000000     0  2470   2457
0x00000000
[  480.380120]  ffff88003fd85cb8 0000000000000082 ffff88003fd85cb8
0000000000015880
[  480.380135]  ffff880042c61a60 0000000000015880 0000000000015880
0000000000015880
[  480.380138]  0000000000015880 ffff880042c61a60 0000000000015880
0000000000015880
[  480.380142] Call Trace:
[  480.380188]  [<ffffffff810da020>] ? sync_page+0x0/0x50
[  480.380210]  [<ffffffff81528978>] io_schedule+0x28/0x40
[  480.380213]  [<ffffffff810da05d>] sync_page+0x3d/0x50
[  480.380217]  [<ffffffff81528e97>] __wait_on_bit+0x57/0x80
[  480.380220]  [<ffffffff810da1ce>] wait_on_page_bit+0x6e/0x80
[  480.380240]  [<ffffffff81078540>] ? wake_bit_function+0x0/0x40
[  480.380247]  [<ffffffff810e4490>] ? pagevec_lookup_tag+0x20/0x30
[  480.380251]  [<ffffffff810da675>]
wait_on_page_writeback_range+0xf5/0x190
[  480.380254]  [<ffffffff810da737>] filemap_fdatawait+0x27/0x30
[  480.380257]  [<ffffffff810dabe4>] filemap_write_and_wait+0x44/0x50
[  480.380273]  [<ffffffff8114bd0f>] __sync_blockdev+0x1f/0x40
[  480.380276]  [<ffffffff8114bd3e>] sync_blockdev+0xe/0x10
[  480.380279]  [<ffffffff8114bd5a>] block_fsync+0x1a/0x20
[  480.380287]  [<ffffffff81143196>] vfs_fsync+0x86/0xf0
[  480.380290]  [<ffffffff81143239>] do_fsync+0x39/0x60
[  480.380293]  [<ffffffff8114328b>] sys_fsync+0xb/0x10
[  480.380306]  [<ffffffff81012002>] system_call_fastpath+0x16/0x1b


----------------------------------------------------------------------

Comment By: MaSc82 (masc82)
Date: 2010-03-06 12:13

Message:
I would be very surprised if ext4 would still have these kind of severe
bugs, corrupting fs when it's full, after having stable release since 1,5
years.

Just tried to repeat the test with ext3, failing already at mkfs.ext3:

[  507.436112] end_request: I/O error, dev vdd, sector 2930245504
[  507.436119] __ratelimit: 3 callbacks suppressed
[  507.436125] Buffer I/O error on device vdd, logical block 366280688
[  507.436127] lost page write due to I/O error on vdd
[  507.436679] end_request: I/O error, dev vdd, sector 2930245568
[  507.436682] Buffer I/O error on device vdd, logical block 366280696
[  507.436683] lost page write due to I/O error on vdd
[  507.436687] Buffer I/O error on device vdd, logical block 366280697
[  507.436689] lost page write due to I/O error on vdd
[  507.436692] Buffer I/O error on device vdd, logical block 366280698
[  507.436693] lost page write due to I/O error on vdd
[  507.436696] Buffer I/O error on device vdd, logical block 366280699
[  507.436697] lost page write due to I/O error on vdd
[  507.436700] Buffer I/O error on device vdd, logical block 366280700
[  507.436702] lost page write due to I/O error on vdd
[  507.436704] Buffer I/O error on device vdd, logical block 366280701
[  507.436706] lost page write due to I/O error on vdd
[  507.436708] Buffer I/O error on device vdd, logical block 366280702
[  507.436710] lost page write due to I/O error on vdd
[  507.436712] Buffer I/O error on device vdd, logical block 366280703
[  507.436714] lost page write due to I/O error on vdd
[  720.380113] INFO: task mkfs.ext3:2645 blocked for more than 120
seconds.
[  720.380118] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables
this message.
[  720.380121] mkfs.ext3     D 0000000000000000     0  2645   2458
0x00000004
[  720.380126]  ffff88001259b9a8 0000000000000046 0000000000001000
0000000000015880
[  720.380141]  ffff88003862c7c0 0000000000015880 0000000000015880
0000000000015880
[  720.380145]  0000000000015880 ffff88003862c7c0 0000000000015880
0000000000015880
[  720.380149] Call Trace:
[  720.380194]  [<ffffffff810da020>] ? sync_page+0x0/0x50
[  720.380216]  [<ffffffff81528978>] io_schedule+0x28/0x40
[  720.380219]  [<ffffffff810da05d>] sync_page+0x3d/0x50
[  720.380223]  [<ffffffff81528e97>] __wait_on_bit+0x57/0x80
[  720.380226]  [<ffffffff810da1ce>] wait_on_page_bit+0x6e/0x80
[  720.380239]  [<ffffffff81078540>] ? wake_bit_function+0x0/0x40
[  720.380247]  [<ffffffff810e4490>] ? pagevec_lookup_tag+0x20/0x30
[  720.380250]  [<ffffffff810da675>]
wait_on_page_writeback_range+0xf5/0x190
[  720.380254]  [<ffffffff810da737>] filemap_fdatawait+0x27/0x30
[  720.380263]  [<ffffffff810dabe4>] filemap_write_and_wait+0x44/0x50
[  720.380279]  [<ffffffff8114bd0f>] __sync_blockdev+0x1f/0x40
[  720.380283]  [<ffffffff8114bd3e>] sync_blockdev+0xe/0x10
[  720.380286]  [<ffffffff8114be08>] __blkdev_put+0xa8/0x1a0
[  720.380289]  [<ffffffff811505fb>] ? fsnotify+0xfb/0x140
[  720.380292]  [<ffffffff8114bf0b>] blkdev_put+0xb/0x10
[  720.380295]  [<ffffffff8114bf3e>] blkdev_close+0x2e/0x50
[  720.380304]  [<ffffffff811204ba>] __fput+0xda/0x1f0
[  720.380307]  [<ffffffff811205ed>] fput+0x1d/0x30
[  720.380315]  [<ffffffff8111c6f8>] filp_close+0x58/0x90
[  720.380329]  [<ffffffff810603a7>] put_files_struct+0x77/0xe0
[  720.380333]  [<ffffffff8106045f>] exit_files+0x4f/0x60
[  720.380339]  [<ffffffff810627eb>] do_exit+0x14b/0x360
[  720.380343]  [<ffffffff810dc394>] ?
generic_file_aio_write_nolock+0x44/0xb0
[  720.380346]  [<ffffffff81062a49>] do_group_exit+0x49/0xc0
[  720.380350]  [<ffffffff8106f3ab>] get_signal_to_deliver+0x1bb/0x3b0
[  720.380364]  [<ffffffff810119c0>] do_signal+0x70/0x1c0
[  720.380383]  [<ffffffff812f5ef8>] ? tty_write+0x228/0x290
[  720.380386]  [<ffffffff81011b5f>] do_notify_resume+0x4f/0x60
[  720.380390]  [<ffffffff8111f66c>] ? sys_write+0x4c/0x80
[  720.380393]  [<ffffffff810120fb>] sysret_signal+0x7e/0xcf
[  720.380397] INFO: task blkid:2650 blocked for more than 120 seconds.
[  720.380399] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables
this message.
[  720.380401] blkid         D 0000000000000000     0  2650      1
0x00000000
[  720.380405]  ffff8800082bfc28 0000000000000082 ffff88005842f720
0000000000015880
[  720.380409]  ffff88004b5bde70 0000000000015880 0000000000015880
0000000000015880
[  720.380412]  0000000000015880 ffff88004b5bde70 0000000000015880
0000000000015880
[  720.380416] Call Trace:
[  720.380420]  [<ffffffff815294f7>] __mutex_lock_slowpath+0xd7/0x160
[  720.380423]  [<ffffffff8114c890>] ? blkdev_open+0x0/0xc0
[  720.380426]  [<ffffffff81528f6e>] mutex_lock+0x1e/0x40
[  720.380429]  [<ffffffff8114c518>] __blkdev_get+0x38/0x3a0
[  720.380432]  [<ffffffff8114c890>] ? blkdev_open+0x0/0xc0
[  720.380435]  [<ffffffff8114c88b>] blkdev_get+0xb/0x10
[  720.380438]  [<ffffffff8114c8fc>] blkdev_open+0x6c/0xc0
[  720.380441]  [<ffffffff8111cad6>] __dentry_open+0xe6/0x2e0
[  720.380444]  [<ffffffff8111cdd7>] nameidata_to_filp+0x57/0x70
[  720.380452]  [<ffffffff8112c42a>] do_filp_open+0x2ca/0xac0
[  720.380459]  [<ffffffff810f3f49>] ? __do_fault+0x419/0x4e0
[  720.380470]  [<ffffffff81036419>] ? default_spin_lock_flags+0x9/0x10
[  720.380474]  [<ffffffff81136da2>] ? alloc_fd+0x102/0x150
[  720.380477]  [<ffffffff8111c8a4>] do_sys_open+0x64/0x160
[  720.380480]  [<ffffffff8111c9cb>] sys_open+0x1b/0x20
[  720.380483]  [<ffffffff81012002>] system_call_fastpath+0x16/0x1b


----------------------------------------------------------------------

Comment By: Michael Tokarev (mjtsf)
Date: 2010-03-06 11:32

Message:
I too see similar behavour here when switching from 0.11 to 0.12.  In my
case the filesystems are not large (a few dozens of gigs, 128Gb max).  I
have error_behavour=remount-ro on all my ext* filesystems, and quite
regularly I see one or another filesystem gets remounted read-only, which
accomplished with quite some noize in dmesg like the above --
 Buffer I/O error on device vdX, logical block ZZZZ
and also "lost write on vdX".  I don't see the traces as above - these
looks like bugs in ext4 code somewhere.
Other than that (I/O error on increasingly-numbered blocks) there's
nothing interesting anywhere, that's why I didn't report it so far: the
errors are quite random and difficult to hit, but I can't gather any useful
info - neither on host nor on guest nor from kvm itself.  Remounting the
filesystem after noticing it is again read-only and it works again, till
another incindent.

----------------------------------------------------------------------

Comment By: MaSc82 (masc82)
Date: 2010-03-06 10:11

Message:
in 0.12.3 behaviour has been significantly improved, but seems it's not
fixed.

Tested with a 1.5 TB virtio raw drive, I created ext4 fs directly on the
drive and rsynced data from a larger source to fill up the drive
completely.
Until the drive became full, everything looked good, no more buffer i/o
errors or lost page writes as they were happening in 0.12.2.

I was expecting rsync to abort at one point when disk became full, but it
surprisingly continued quite a while, although df -h was already indicating
there was no space left. 

Following messages began to show up in kernel.log.

[45517.836999] EXT4-fs error (device vdd): ext4_lookup: deleted inode
referenced: 1310728
[45517.847357] EXT4-fs error (device vdd): ext4_lookup: deleted inode
referenced: 1310730
[45517.848044] EXT4-fs error (device vdd): ext4_lookup: deleted inode
referenced: 1310731
[45517.853757] EXT4-fs error (device vdd): ext4_lookup: deleted inode
referenced: 1310733
[45517.864262] EXT4-fs error (device vdd): ext4_lookup: deleted inode
referenced: 1310734
[45517.935073] EXT4-fs error (device vdd): ext4_lookup: deleted inode
referenced: 1310736
[45518.364535] EXT4-fs error (device vdd): ext4_lookup: deleted inode
referenced: 1441857
[45958.938625] EXT4-fs error (device vdd): ext4_lookup: deleted inode
referenced: 1441857
[45959.559208] EXT4-fs error (device vdd): ext4_lookup: deleted inode
referenced: 1310736
[45959.562137] EXT4-fs error (device vdd): ext4_lookup: deleted inode
referenced: 1310734
[45959.564764] EXT4-fs error (device vdd): ext4_lookup: deleted inode
referenced: 1310733
[45959.568446] EXT4-fs error (device vdd): ext4_lookup: deleted inode
referenced: 1310731
[45959.570541] EXT4-fs error (device vdd): ext4_lookup: deleted inode
referenced: 1310730
[45959.580392] EXT4-fs error (device vdd): ext4_lookup: deleted inode
referenced: 1310728
[46393.982995] EXT4-fs error (device vdd): ext4_mb_generate_buddy:
EXT4-fs: group 8465: 28690 blocks in bitmap, 2047 in gd
[46799.823463] EXT4-fs error (device vdd): ext4_lookup: deleted inode
referenced: 1441857
[46800.532939] EXT4-fs error (device vdd): ext4_lookup: deleted inode
referenced: 1310736
[46800.543741] EXT4-fs error (device vdd): ext4_lookup: deleted inode
referenced: 1310734
[46800.547021] EXT4-fs error (device vdd): ext4_lookup: deleted inode
referenced: 1310733
[46800.548173] EXT4-fs error (device vdd): ext4_lookup: deleted inode
referenced: 1310731
[46800.549303] EXT4-fs error (device vdd): ext4_lookup: deleted inode
referenced: 1310730
[46800.561472] EXT4-fs error (device vdd): ext4_lookup: deleted inode
referenced: 1310728
[47518.779879] EXT4-fs error (device vdd): ext4_mb_generate_buddy:
EXT4-fs: group 8689: 28368 blocks in bitmap, 0 in gd
[47686.658580] EXT4-fs error (device vdd): ext4_mb_generate_buddy:
EXT4-fs: group 10822: 27802 blocks in bitmap, 1596 in gd
[47689.313508] EXT4-fs error (device vdd): ext4_mb_generate_buddy:
EXT4-fs: group 9212: 16198 blocks in bitmap, 1158 in gd
[47697.030338] EXT4-fs error (device vdd): ext4_mb_generate_buddy:
EXT4-fs: group 9473: 28686 blocks in bitmap, 1021 in gd
[47726.639706] EXT4-fs error (device vdd): ext4_mb_generate_buddy:
EXT4-fs: group 6825: 2047 blocks in bitmap, 1023 in gd
[47782.529462] EXT4-fs error (device vdd): ext4_mb_generate_buddy:
EXT4-fs: group 252: 358 blocks in bitmap, 102 in gd
[47782.929821] EXT4-fs error (device vdd): ext4_mb_generate_buddy:
EXT4-fs: group 378: 778 blocks in bitmap, 266 in gd
[47782.929945] EXT4-fs error (device vdd): ext4_mb_generate_buddy:
EXT4-fs: group 382: 1023 blocks in bitmap, 511 in gd
[47783.073044] EXT4-fs error (device vdd): ext4_mb_generate_buddy:
EXT4-fs: group 583: 683 blocks in bitmap, 171 in gd
[47786.626901] EXT4-fs error (device vdd): ext4_mb_complex_scan_group: 18
free blocks as per group info. But got 82 blocks
[47788.300039] EXT4-fs error (device vdd): ext4_mb_complex_scan_group: 18
free blocks as per group info. But got 82 blocks
[47788.307045] EXT4-fs error (device vdd): ext4_mb_complex_scan_group: 18
free blocks as per group info. But got 82 blocks
[47790.176599] EXT4-fs error (device vdd): ext4_mb_complex_scan_group: 18
free blocks as per group info. But got 82 blocks

When rsync finally aborted (reporting no space left on device), the
filesystem was corrupt and had to be repaired with fsck.ext4, which
detected multiply-claimed blocks especially within most recently written
files.

----------------------------------------------------------------------

Comment By: Sebastian (grisia)
Date: 2010-01-30 15:03

Message:
Same behavior here.... 

Using QEMU-KVM version 0.11.1 error dosn't appears.

Host (Gentoo):
	Vanilla Kernel Sources 2.6.32.7
	QEMU-KVM 0.12.2
	Guest image is a LVM2 partition (~30Gb)
	Guest is using virtio-blk

Guest (Gentoo):
	Vanilla Kernel Sources 2.6.32.7
	Filesystem is Ext4

Log after copying lot of files:

Jan 30 14:06:02 jboss kernel: [   40.177314] end_request: I/O error, dev
vdd, sector 33555759

Jan 30 14:06:02 jboss kernel: [   40.177314] Buffer I/O error on device
vdd1, logical block 4194462

Jan 30 14:06:02 jboss kernel: [   40.177314] lost page write due to I/O
error on vdd1

...snip...
Jan 30 14:06:02 jboss kernel: [   40.177314] Buffer I/O error on device
vdd1, logical block 4194471

Jan 30 14:06:02 jboss kernel: [   40.177314] lost page write due to I/O
error on vdd1

Jan 30 14:06:02 jboss kernel: [   40.177314] end_request: I/O error, dev
vdd, sector 33556767

Jan 30 14:06:02 jboss kernel: [   40.177314] end_request: I/O error, dev
vdd, sector 37748799

Jan 30 14:06:02 jboss kernel: [   40.177314] end_request: I/O error, dev
vdd, sector 37749055

Jan 30 14:06:02 jboss kernel: [   40.177314] end_request: I/O error, dev
vdd, sector 41943103

Jan 30 14:06:02 jboss kernel: [   40.177314] end_request: I/O error, dev
vdd, sector 41943231

...snip...
Jan 30 14:06:02 jboss kernel: [   40.535373] end_request: I/O error, dev
vdd, sector 58734687

Jan 30 14:06:02 jboss kernel: [   40.535421] end_request: I/O error, dev
vdd, sector 58735695

Jan 30 14:06:02 jboss kernel: [   40.535476] JBD: recovery failed

Jan 30 14:06:02 jboss kernel: [   40.535478] EXT4-fs (vdd1): error loading
journal

Jan 30 14:06:26 jboss kernel: [   63.811349] EXT4-fs (vdd1): mounted
filesystem with ordered data mode

Jan 30 14:06:32 jboss kernel: [   70.131957] EXT4-fs (vdc5): mounted
filesystem with ordered data mode

Jan 30 14:06:48 jboss kernel: [   85.852773] JBD: barrier-based sync
failed on vdd1-8 - disabling barriers

Jan 30 14:07:08 jboss kernel: [  106.391820] end_request: I/O error, dev
vdd, sector 21283503

Jan 30 14:07:08 jboss kernel: [  106.391823] __ratelimit: 12124 callbacks
suppressed

Jan 30 14:07:08 jboss kernel: [  106.391826] Buffer I/O error on device
vdd1, logical block 2660430

Jan 30 14:07:08 jboss kernel: [  106.391828] lost page write due to I/O
error on vdd1

Jan 30 14:07:08 jboss kernel: [  106.391830] Buffer I/O error on device
vdd1, logical block 2660431

Jan 30 14:07:08 jboss kernel: [  106.391832] lost page write due to I/O
error on vdd1

Jan 30 14:07:08 jboss kernel: [  106.391834] Buffer I/O error on device
vdd1, logical block 2660432

Jan 30 14:07:08 jboss kernel: [  106.391835] lost page write due to I/O
error on vdd1

...snip...
Jan 30 14:07:19 jboss kernel: [  116.855081] end_request: I/O error, dev
vdd, sector 38055999

Jan 30 14:07:19 jboss kernel: [  116.855146] end_request: I/O error, dev
vdd, sector 38056983

Jan 30 14:07:19 jboss kernel: [  116.855207] end_request: I/O error, dev
vdd, sector 38057935

Jan 30 14:07:19 jboss kernel: [  116.855271] end_request: I/O error, dev
vdd, sector 38058935

Jan 30 14:07:19 jboss kernel: [  116.855339] end_request: I/O error, dev
vdd, sector 38059943

Jan 30 14:07:19 jboss kernel: [  116.855418] end_request: I/O error, dev
vdd, sector 38060951

Jan 30 14:07:19 jboss kernel: [  117.064320] JBD2: Detected IO errors
while flushing file data on vdd1-8

Jan 30 14:07:19 jboss kernel: [  117.064591] Aborting journal on device
vdd1-8.

Jan 30 14:07:19 jboss kernel: [  117.064663] EXT4-fs error (device vdd1)
in ext4_reserve_inode_write: Journal has aborted

Jan 30 14:07:19 jboss kernel: [  117.064921] EXT4-fs error (device vdd1)
in ext4_dirty_inode: Journal has aborted

Jan 30 14:07:19 jboss kernel: [  117.065410] EXT4-fs error (device vdd1):
ext4_journal_start_sb: Detected aborted journal

Jan 30 14:07:19 jboss kernel: [  117.065413] EXT4-fs (vdd1): Remounting
filesystem read-only

qemu -M pc -cpu host -name kvm.jboss -uuid
50259a3c-d6de-4c6c-811d-753f2df9658a -smp 1 -drive
file=/dev/lg_virtual_machines/jboss,format=host_device,if=virtio,index=0,boot=on,cache=writeback
-drive
file=/dev/lg_virtual_machines_ext/jboss_swap,format=host_device,if=virtio,index=1,cache=writeback
-drive
file=/dev/lg_virtual_machines/yacy,format=host_device,if=virtio,index=2
-drive
file=/dev/lg_virtual_machines_ext/yacy_backup,format=host_device,if=virtio,index=3
-net vde,vlan=0,name=jboss,sock=/var/run/vde2/vde_dmz -net
nic,vlan=0,macaddr=54:52:02:77:5a:04,model=virtio,name=ifdmzjboss -k de -m
256 -parallel none -serial none -boot c -daemonize -vga std -nographic
-balloon virtio -enable-kvm -pidfile /var/run/qemu/kvm.jboss.pid -vnc
unix:/var/lib/qemu/vnc_displays/kvm.jboss.socket -monitor
unix:/var/lib/qemu/monitors/kvm.jboss.socket,server,nowait


----------------------------------------------------------------------

Comment By: Avi Kivity (avik)
Date: 2010-01-17 10:38

Message:
1 TB = 2^40 B = 2^31 sectors.  Overflow?

----------------------------------------------------------------------

Comment By: MaSc82 (masc82)
Date: 2010-01-16 15:59

Message:
updated to prio9, since ppl moving from scsi/ide to virtio with existing
filesystems will at one point experience corruption and data loss.

----------------------------------------------------------------------

You can respond by visiting: 
https://sourceforge.net/tracker/?func=detail&atid=893831&aid=2933400&group_id=180599
--
To unsubscribe from this list: send the line "unsubscribe kvm" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at  http://vger.kernel.org/majordomo-info.html

[Index of Archives]     [KVM ARM]     [KVM ia64]     [KVM ppc]     [Virtualization Tools]     [Spice Development]     [Libvirt]     [Libvirt Users]     [Linux USB Devel]     [Linux Audio Users]     [Yosemite Questions]     [Linux Kernel]     [Linux SCSI]     [XFree86]
  Powered by Linux