Bug 739396

Summary: Snapshot Autoextend stops working after a few resizes
Product: [Fedora] Fedora Reporter: Joerg <joerg>
Component: lvm2Assignee: LVM and device-mapper development team <lvm-team>
Status: CLOSED WORKSFORME QA Contact: Fedora Extras Quality Assurance <extras-qa>
Severity: unspecified Docs Contact:
Priority: unspecified    
Version: 15CC: agk, bmarzins, bmr, dwysocha, heinzm, jonathan, lvm-team, mbroz, msnitzer, prajnoha, prockai, zkabelac
Target Milestone: ---   
Target Release: ---   
Hardware: i686   
OS: Linux   
Whiteboard:
Fixed In Version: Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2011-10-19 12:07:23 UTC Type: ---
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:

Description Joerg 2011-09-18 16:13:12 UTC 
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 15:04:41 UTC 
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 12:07:23 UTC 
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.