Bug 739396 - Snapshot Autoextend stops working after a few resizes
Snapshot Autoextend stops working after a few resizes
Status: CLOSED WORKSFORME
Product: Fedora
Classification: Fedora
Component: lvm2 (Show other bugs)
15
i686 Linux
unspecified Severity unspecified
: ---
: ---
Assigned To: LVM and device-mapper development team
Fedora Extras Quality Assurance
:
Depends On:
Blocks:
  Show dependency treegraph
 
Reported: 2011-09-18 12:13 EDT by Joerg
Modified: 2011-10-19 08:07 EDT (History)
12 users (show)

See Also:
Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of:
Environment:
Last Closed: 2011-10-19 08:07:23 EDT
Type: ---
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: ---
RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---


Attachments (Terms of Use)

  None (edit)
Description Joerg 2011-09-18 12:13:12 EDT
Description of problem:
I have created a snapshot of a logical volume.
Then a start to fill the original logical volume. The Snapshot is resized 3-4 times. After that no further resizing takes place and the snapshot hits 100 %.

Version-Release number of selected component (if applicable):
LVM version:     2.02.84(2) (2011-02-09)
Library version: 1.02.63 (2011-02-09)
Driver version:  4.20.0


How reproducible:
every time

Steps to Reproduce:
1. set 
   snapshot_autoextend_threshold = 90
   snapshot_autoextend_percent = 20
 in lvm.conf
2. create Snap shot
   lvcreate -s -L 5G -n name Logical_VOlume
3. fill logical volume
   use dd
  
Actual results:
after a few resizes the snapshot fills to 100% and stops

Expected results:
resize until volume group is exhausted

Additional info:
the volume group has 420 GB free space.

Sep 18 15:24:58 server lvm[1268]: Monitoring snapshot VG50-iscsi1_201109181524
Sep 18 15:24:59 server lvm[1268]: Monitoring snapshot VG50-iscsi1_win7back_201109181524
Sep 18 16:18:29 server lvm[1268]: Extension of snapshot VG50/iscsi1_win7back_201109181524 finished successfully.
Sep 18 16:20:19 server lvm[1268]: Extension of snapshot VG50/iscsi1_win7back_201109181524 finished successfully.
Sep 18 16:22:29 server lvm[1268]: Extension of snapshot VG50/iscsi1_win7back_201109181524 finished successfully.
Sep 18 16:23:49 server lvm[1268]: Extension of snapshot VG50/iscsi1_win7back_201109181524 finished successfully.
Sep 18 16:27:59 server lvm[1268]: Extension of snapshot VG50/iscsi1_win7back_201109181524 finished successfully.
Sep 18 16:29:49 server lvm[1268]: Extension of snapshot VG50/iscsi1_win7back_201109181524 finished successfully.
Sep 18 16:31:09 server lvm[1268]: Snapshot VG50-iscsi1_win7back_201109181524 is now 80% full.
Sep 18 16:31:09 server lvm[1268]: Extension of snapshot VG50/iscsi1_win7back_201109181524 finished successfully.
Sep 18 16:32:39 server lvm[1268]: Snapshot VG50-iscsi1_win7back_201109181524 is now 85% full.
Sep 18 16:32:39 server lvm[1268]: Extension of snapshot VG50/iscsi1_win7back_201109181524 finished successfully.
Sep 18 16:33:49 server lvm[1268]: Snapshot VG50-iscsi1_win7back_201109181524 is now 90% full.
Sep 18 16:33:49 server lvm[1268]: Extending logical volume iscsi1_win7back_201109181524 to 6.00 GiB
Sep 18 16:33:57 server lvm[1268]: Another thread is handling an event. Waiting...
Sep 18 16:33:58 server lvm[1268]: Another thread is handling an event. Waiting...
Sep 18 16:34:21 server lvm[1268]: Monitoring snapshot VG50-iscsi1_win7back_201109181524
Sep 18 16:34:21 server lvm[1268]: Logical volume iscsi1_win7back_201109181524 successfully resized
Sep 18 16:34:22 server lvm[1268]: Extension of snapshot VG50/iscsi1_win7back_201109181524 finished successfully.
Sep 18 16:34:24 server lvm[1268]: No longer monitoring snapshot VG50-iscsi1_win7back_201109181524
Sep 18 16:34:31 server lvm[1268]: Extension of snapshot VG50/iscsi1_win7back_201109181524 finished successfully.
Sep 18 16:35:31 server lvm[1268]: Snapshot VG50-iscsi1_win7back_201109181524 is now 80% full.
Sep 18 16:35:31 server lvm[1268]: Extension of snapshot VG50/iscsi1_win7back_201109181524 finished successfully.
Sep 18 16:37:31 server lvm[1268]: Snapshot VG50-iscsi1_win7back_201109181524 is now 87% full.
Sep 18 16:37:31 server lvm[1268]: Extension of snapshot VG50/iscsi1_win7back_201109181524 finished successfully.
Sep 18 16:39:11 server lvm[1268]: Snapshot VG50-iscsi1_win7back_201109181524 is now 90% full.
Sep 18 16:39:11 server lvm[1268]: Extending logical volume iscsi1_win7back_201109181524 to 7.20 GiB
Sep 18 16:39:17 server lvm[1268]: Another thread is handling an event. Waiting...
Sep 18 16:39:18 server lvm[1268]: Another thread is handling an event. Waiting...
Sep 18 16:42:49 server lvm[1268]: Monitoring snapshot VG50-iscsi1_win7back_201109181524
Sep 18 16:42:50 server lvm[1268]: Logical volume iscsi1_win7back_201109181524 successfully resized
Sep 18 16:42:50 server lvm[1268]: Extension of snapshot VG50/iscsi1_win7back_201109181524 finished successfully.
Sep 18 16:42:51 server lvm[1268]: No longer monitoring snapshot VG50-iscsi1_win7back_201109181524
Sep 18 16:42:59 server lvm[1268]: dm_task_run failed, errno = 22, Invalid argument
Sep 18 16:43:09 server lvm[1268]: Snapshot VG50-iscsi1_win7back_201109181524 is now 82% full.
Sep 18 16:43:09 server lvm[1268]: Extension of snapshot VG50/iscsi1_win7back_201109181524 finished successfully.
Sep 18 16:44:59 server lvm[1268]: Snapshot VG50-iscsi1_win7back_201109181524 is now 85% full.
Sep 18 16:44:59 server lvm[1268]: Extension of snapshot VG50/iscsi1_win7back_201109181524 finished successfully.
Sep 18 16:47:39 server lvm[1268]: Snapshot VG50-iscsi1_win7back_201109181524 is now 90% full.
Sep 18 16:47:39 server lvm[1268]: Extending logical volume iscsi1_win7back_201109181524 to 8.64 GiB
Sep 18 16:47:47 server lvm[1268]: Another thread is handling an event. Waiting...
Sep 18 16:47:48 server lvm[1268]: Another thread is handling an event. Waiting...
Sep 18 16:48:47 server lvm[1268]: Monitoring snapshot VG50-iscsi1_win7back_201109181524
Sep 18 16:48:47 server lvm[1268]: Logical volume iscsi1_win7back_201109181524 successfully resized
Sep 18 16:48:47 server lvm[1268]: Extension of snapshot VG50/iscsi1_win7back_201109181524 finished successfully.
Sep 18 16:48:49 server lvm[1268]: No longer monitoring snapshot VG50-iscsi1_win7back_201109181524
Sep 18 16:48:57 server lvm[1268]: Extension of snapshot VG50/iscsi1_win7back_201109181524 finished successfully.
Sep 18 16:51:17 server lvm[1268]: Snapshot VG50-iscsi1_win7back_201109181524 is now 80% full.
Sep 18 16:51:17 server lvm[1268]: Extension of snapshot VG50/iscsi1_win7back_201109181524 finished successfully.
Sep 18 16:51:27 server lvm[1268]: Another thread is handling an event. Waiting...
Sep 18 16:53:27 server lvm[1268]: Another thread is handling an event. Waiting...
Sep 18 16:55:07 server lvm[1268]: Snapshot VG50-iscsi1_win7back_201109181524 is now 85% full.
Sep 18 16:55:07 server lvm[1268]: Extension of snapshot VG50/iscsi1_win7back_201109181524 finished successfully.
Sep 18 16:55:27 server lvm[1268]: Another thread is handling an event. Waiting...
Sep 18 16:55:47 server lvm[1268]: Another thread is handling an event. Waiting...
Sep 18 16:57:27 server lvm[1268]: Snapshot VG50-iscsi1_win7back_201109181524 is now 90% full.
Sep 18 16:57:27 server lvm[1268]: Extending logical volume iscsi1_win7back_201109181524 to 10.36 GiB
Sep 18 16:57:28 server lvm[1268]: Another thread is handling an event. Waiting...
Sep 18 16:57:37 server lvm[1268]: Another thread is handling an event. Waiting...
Sep 18 16:58:39 server lvm[1268]: Monitoring snapshot VG50-iscsi1_win7back_201109181524
Sep 18 16:58:40 server lvm[1268]: Logical volume iscsi1_win7back_201109181524 successfully resized
Sep 18 16:58:40 server lvm[1268]: Extension of snapshot VG50/iscsi1_win7back_201109181524 finished successfully.
Sep 18 16:58:42 server lvm[1268]: No longer monitoring snapshot VG50-iscsi1_win7back_201109181524
Sep 18 16:58:49 server lvm[1268]: dm_task_run failed, errno = 22, Invalid argument
Sep 18 16:58:59 server lvm[1268]: Extension of snapshot VG50/iscsi1_win7back_201109181524 finished successfully.
Sep 18 17:00:49 server lvm[1268]: Snapshot VG50-iscsi1_win7back_201109181524 is now 80% full.
Sep 18 17:00:49 server lvm[1268]: Extension of snapshot VG50/iscsi1_win7back_201109181524 finished successfully.
Sep 18 17:03:59 server lvm[1268]: Snapshot VG50-iscsi1_win7back_201109181524 is now 85% full.
Sep 18 17:03:59 server lvm[1268]: Extension of snapshot VG50/iscsi1_win7back_201109181524 finished successfully.
Sep 18 17:06:39 server lvm[1268]: Snapshot VG50-iscsi1_win7back_201109181524 is now 90% full.
Sep 18 17:06:39 server lvm[1268]: Extending logical volume iscsi1_win7back_201109181524 to 12.43 GiB
Sep 18 17:06:47 server lvm[1268]: Another thread is handling an event. Waiting...
Sep 18 17:06:48 server lvm[1268]: Another thread is handling an event. Waiting...
Sep 18 17:07:11 server lvm[1268]: Monitoring snapshot VG50-iscsi1_win7back_201109181524
Sep 18 17:07:11 server lvm[1268]: Logical volume iscsi1_win7back_201109181524 successfully resized
Sep 18 17:07:11 server lvm[1268]: Extension of snapshot VG50/iscsi1_win7back_201109181524 finished successfully.
Sep 18 17:07:13 server lvm[1268]: No longer monitoring snapshot VG50-iscsi1_win7back_201109181524
Sep 18 17:07:21 server lvm[1268]: Extension of snapshot VG50/iscsi1_win7back_201109181524 finished successfully.
Sep 18 17:10:51 server lvm[1268]: Snapshot VG50-iscsi1_win7back_201109181524 is now 80% full.
Sep 18 17:10:51 server lvm[1268]: Extension of snapshot VG50/iscsi1_win7back_201109181524 finished successfully.
Sep 18 17:23:33 server lvm[1268]: Trying to umount invalid snapshot VG50-iscsi1_win7back_201109181524...
Comment 1 Zdenek Kabelac 2011-10-18 11:04:41 EDT
Couldn't be here the issue, that your 'dd' command fills blocks too fast and dmeventd is not responsive enough to grow so quickly. 

Could you try to use lower value for threshold - i.e. 80% or 70% ?
Comment 2 Joerg 2011-10-19 08:07:23 EDT
Hi I checked with 70 %.

Now it seems that this is working.

So maybe the issue is that 90 % is not a good threshold value.

Thank you.

Note You need to log in before you can comment on or make changes to this bug.