Bug 659301

Have you checked the image with qemu-img check?

qemu-img check:
                     .
                     .
                     .
Leaked cluster 32761 refcount=1 reference=0
Leaked cluster 32762 refcount=1 reference=0
Leaked cluster 32763 refcount=1 reference=0
Leaked cluster 32764 refcount=1 reference=0
Leaked cluster 32765 refcount=1 reference=0
Leaked cluster 32766 refcount=1 reference=0
Leaked cluster 32767 refcount=1 reference=0

16545 leaked clusters were found on the image.
This means waste of disk space, but no harm to data.

16k clusters means about 1 GB worth of leaked clusters. Wow. That alone is bad enough (did you have lots of I/O errors on your storage backend?), but it doesn't explain disk usage up to 200 GB and more.

The huge disk is a direct result of repeated enospace events: for each one, vdsm extend the LV by 1Gb. The question reduces to why qemu generates (so many) enospace events, event after the LV is far larger than the qcow2 virtual size.

Moran, how easy it to reproduce it? Is it only a function of the storage?
Is there a slight chance for accessing the image by 2 VMs at once?

Please attach gdb to the qemu-kvm instance and set a breakpoint on bdrv_mon_event. The next time an ENOSPC occurs the breakpoint will trigger. Please provide the backtrace from there.

Also, if you have a VM in this state and I may log into your machine to debug this, please contact me.

Also, just to be sure: If many ENOSPC events are triggered at the same time (the log snippet posted above seems to show this case), VDSM will collapse them and increase the image size only once, right? qemu emits the event once for every request that was in flight and failed.

(In reply to comment #8)

> Also, just to be sure: If many ENOSPC events are triggered at the same time
> (the log snippet posted above seems to show this case), VDSM will collapse them
> and increase the image size only once, right? qemu emits the event once for
> every request that was in flight and failed.

Doh, bug 568098 is still alive, and this one might be a dup. vdsm cannot really collapse multiple events - it processes the first event on sight. If further events arrive after the first was processed, they are addressed as unrelated ones. Maybe the timing of events allows to collapse events in vdsm, but this is reminiscent of solving races with sleep, which is against my religion.

I can reproduce 100%

qemu-kvm-0.12.1.2-2.113.el6_0.3.x86_64
vm2-2.02.72-8.el6_0.2.x86_64
vdsm-4.9-25.el6.x86_64
kernel-2.6.32-71.7.1.el6.x86_64

Using iSCSI storage (enterprise class array - IBM DS3300)

Logs attached from vdsm and libvirt

Created attachment 464892 [details]
VDSM and libvirt logs

What's the size of the vDisk? As you stated it might be that multiple ENOSPACE per IO cause the system to increase the storage way too much (bz568098).

From the above vdsm.log:

libvirtEventLoop::INFO::2010-12-05 16:38:51,966::libvirtvm::860::vds.vmlog.8124aa09-3306-4aaf-b3a5-892dc01e221e::(_onAbnormalStop) abnormal vm stop device virtio-disk0 error enospc
libvirtEventLoop::DEBUG::2010-12-05 16:38:51,966::storage_mailbox::99::Storage.SPM.Messages.Extend::(__init__) new extend msg created: domain: 30d6c222-dba6-4970-a95c-1f270719fd5c, volume: dc2f029b-54ed-47cb-8bec-173f362a4468
libvirtEventLoop::DEBUG::2010-12-05 16:38:51,966::vm::1284::vds.vmlog.8124aa09-3306-4aaf-b3a5-892dc01e221e::(_lvExtend) _lvExtend: hda: apparentsize 15032385536 req 15360

>>>>>>>>>> What's req 15360 mean?

libvirtEventLoop::INFO::2010-12-05 16:38:51,967::libvirtvm::860::vds.vmlog.8124aa09-3306-4aaf-b3a5-892dc01e221e::(_onAbnormalStop) abnormal vm stop device virtio-disk0 error enospc
libvirtEventLoop::DEBUG::2010-12-05 16:38:51,967::storage_mailbox::99::Storage.SPM.Messages.Extend::(__init__) new extend msg created: domain: 30d6c222-dba6-4970-a95c-1f270719fd5c, volume: dc2f029b-54ed-47cb-8bec-173f362a4468
libvirtEventLoop::DEBUG::2010-12-05 16:38:51,968::vm::1284::vds.vmlog.8124aa09-3306-4aaf-b3a5-892dc01e221e::(_lvExtend) _lvExtend: hda: apparentsize 15032385536 req 15360
libvirtEventLoop::INFO::2010-12-05 16:38:51,968::libvirtvm::860::vds.vmlog.8124aa09-3306-4aaf-b3a5-892dc01e221e::(_onAbnormalStop) abnormal vm stop device virtio-disk0 error enospc
libvirtEventLoop::DEBUG::2010-12-05 16:38:51,968::storage_mailbox::99::Storage.SPM.Messages.Extend::(__init__) new extend msg created: domain: 30d6c222-dba6-4970-a95c-1f270719fd5c, volume: dc2f029b-54ed-47cb-8bec-173f362a4468
libvirtEventLoop::DEBUG::2010-12-05 16:38:51,969::vm::1284::vds.vmlog.8124aa09-3306-4aaf-b3a5-892dc01e221e::(_lvExtend) _lvExtend: hda: apparentsize 15032385536 req 15360

req 15360 means a request for extension of the said LV to 15360 MiB.

We're certainly seeing multiple events come in

The vDisk is set to  20gb and starts off at 1GB.
After a minute or so into the install it needs to do the first extend and you see the lv go from 1GB to 2Gb a few seconds later it's 3Gb, then the VM gets paused (see notification in RHEV-M UI) but watching the lv it keeps on growing, even past the 20GB total allocation. I stopped the VM and killed the disk at 31GB (logs attached)

Created attachment 464902 [details]
2nd run - vdsm + libvirt logs. Here we see multiple events coming in

(In reply to comment #9)
> (In reply to comment #8)
> 
> > Also, just to be sure: If many ENOSPC events are triggered at the same time
> > (the log snippet posted above seems to show this case), VDSM will collapse them
> > and increase the image size only once, right? qemu emits the event once for
> > every request that was in flight and failed.
> 
> Doh, bug 568098 is still alive, and this one might be a dup. vdsm cannot really
> collapse multiple events - it processes the first event on sight. If further
> events arrive after the first was processed, they are addressed as unrelated
> ones. Maybe the timing of events allows to collapse events in vdsm, but this is
> reminiscent of solving races with sleep, which is against my religion.

The bug you mentioned has been handled with very low priority as we were told that VDSM does cope with the fact that multiple events are emitted. If this isn't true, I'm not surprised that things break...

Anyway, these events _are_ independent events, so somebody must do the collapsing. It should be very easy to do for VDSM, because as long as it hasn't continued the VM, it definitely knows that it should resize only once. A stopped VM doesn't issue any more requests that could fail.

Anyway, adding Luiz to CC.

Kevin, please explain how vdsm can reliably collapse the events. There is an inherent race between handling the first event (which includes extending LV and continuing qemu) and the reception of further events.

True, but this isn't any different when you try to collapse them in qemu. How do you relate a block error event to a stop event today? What you really get is a number of block error events and one stop event. It should be safe to ignore any block error that isn't followed by a stop (you can double-check by querying the VM state).

But maybe what you really should do is to look at the high watermark even after an ENOSPC and use that to check if the image size needs to be further increased?

Created attachment 467701 [details]
bt

attached is the requested log.

(gdb) bt
#0  bdrv_mon_event (bdrv=0x2aa7490, action=BDRV_ACTION_STOP, error=28, is_read=0) at block.c:1436
#1  0x000000000041dd33 in virtio_blk_handle_rw_error (opaque=0x7f886801c1f0, ret=-28) at /usr/src/debug/qemu-kvm-0.12.1.2/hw/virtio-blk.c:77
#2  virtio_blk_rw_complete (opaque=0x7f886801c1f0, ret=-28) at /usr/src/debug/qemu-kvm-0.12.1.2/hw/virtio-blk.c:93
#3  0x0000000000479ade in multiwrite_user_cb (opaque=0x7f886804bc60, ret=<value optimized out>) at block.c:1907
#4  multiwrite_cb (opaque=0x7f886804bc60, ret=<value optimized out>) at block.c:1926
#5  0x000000000048d13d in qcow_aio_write_cb (opaque=0x7f8870019010, ret=-28) at block/qcow2.c:648
#6  0x000000000047eb68 in posix_aio_process_queue (opaque=0x2aa3300) at posix-aio-compat.c:460
#7  0x000000000047ec68 in posix_aio_read (opaque=0x2aa3300) at posix-aio-compat.c:501
#8  0x000000000040b4af in main_loop_wait (timeout=1000) at /usr/src/debug/qemu-kvm-0.12.1.2/vl.c:4234
#9  0x0000000000428c2a in kvm_main_loop () at /usr/src/debug/qemu-kvm-0.12.1.2/qemu-kvm.c:2133
#10 0x000000000040e5cb in main_loop (argc=<value optimized out>, argv=<value optimized out>, envp=<value optimized out>) at /usr/src/debug/qemu-kvm-0.12.1.2/vl.c:4444
#11 main (argc=<value optimized out>, argv=<value optimized out>, envp=<value optimized out>) at /usr/src/debug/qemu-kvm-0.12.1.2/vl.c:6601

(gdb) frame 5
#5  0x000000000048d13d in qcow_aio_write_cb (opaque=0x7f8870019010, ret=-28) at block/qcow2.c:648
648         acb->common.cb(acb->common.opaque, ret);
(gdb) p *acb
$1 = {common = {pool = 0x8501e0, bs = 0x2aa7490, cb = 0x479a90 <multiwrite_cb>, opaque = 0x7f886804bc60, next = 0x7f887000fb00}, sector_num = 5606528, qiov = 0x7f8868028220, buf = 0x7f88681e5800 "", 
  orig_buf = 0x7f88681df600, remaining_sectors = 511, cur_nr_sectors = 511, cluster_offset = 3178561536, cluster_data = 0x0, hd_aiocb = 0x0, hd_iov = {iov_base = 0x7f88681e5800, iov_len = 261632}, 
  hd_qiov = {iov = 0x7f8870019078, niov = 1, nalloc = -1, size = 261632}, bh = 0x0, l2meta = {offset = 2870542336, cluster_offset = 3178561536, n_start = 0, nb_available = 511, nb_clusters = 4, 
    depends_on = 0x0, dependent_requests = {lh_first = 0x0}, next_in_flight = {le_next = 0x0, le_prev = 0x2aa7ec8}}, next_depend = {le_next = 0x0, le_prev = 0x7f88700a4130}}

(gdb) frame 6
#6  0x000000000047eb68 in posix_aio_process_queue (opaque=0x2aa3300) at posix-aio-compat.c:460
460                     acb->common.cb(acb->common.opaque, ret);
(gdb) p *acb
$3 = {common = {pool = 0x84eea0, bs = 0x2aa8120, cb = 0x48cee0 <qcow_aio_write_cb>, opaque = 0x7f8870019010, next = 0x7f8870028bf0}, aio_fildes = 11, {aio_iov = 0x7f8870019078, 
    aio_ioctl_buf = 0x7f8870019078}, aio_niov = 1, aio_nbytes = 261632, ev_signo = 12, aio_offset = 3178561536, node = {tqe_next = 0x0, tqe_prev = 0x85c240}, aio_type = 2, ret = -28, active = 1, 
  next = 0x7f8870019740, async_context_id = 0}
(gdb)

qcow2 acb:
> l2meta = {offset = 2870542336, cluster_offset = 3178561536, n_start = 0,

file acb:
>     aio_ioctl_buf = 0x7f8870019078}, aio_niov = 1, aio_nbytes = 261632,
> ev_signo = 12, aio_offset = 3178561536

These few values are the interesting ones. The guest was trying to access offset 2870542336 on the virtual hard disk (2.8 GB), and qcow2 translated this into an access at offset 3178561536 in the host LV (3.1 GB). This looks perfectly sane.

This is another strong indication that VDSM tries to increase the size multiple size until it reaches really big sizes, even though qemu only wanted to access something around 3 GB.

Idan, if you see another issue with IDE, please use the bug for reporting it.

Are there more reports of this bug? It seems that all the cases so far the issue is that there was a real ENOSPC that was reported multiple times. In this case, this is solvable through vdsm and arguably not a bug in qemu terms (not worth to open it for discussion).

If there are other cases that are not caused by 'normal' operation please report them, otherwise we'll close the issue.

Nobody seems to have found a case where it's not caused by missing event collapsing, so I'm closing this as a duplicate of the existing request.

*** This bug has been marked as a duplicate of bug 568098 ***