739396 – Snapshot Autoextend stops working after a few resizes

Bug 739396 - Snapshot Autoextend stops working after a few resizes

Summary: Snapshot Autoextend stops working after a few resizes

Keywords:
Status:	CLOSED WORKSFORME
Alias:	None
Product:	Fedora
Classification:	Fedora
Component:	lvm2
Sub Component:
Version:	15
Hardware:	i686
OS:	Linux
Priority:	unspecified
Severity:	unspecified
Target Milestone:	---
Assignee:	LVM and device-mapper development team
QA Contact:	Fedora Extras Quality Assurance
Docs Contact:
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+	depends on / blocked

Reported:	2011-09-18 16:13 UTC by Joerg
Modified:	2011-10-19 12:07 UTC (History)
CC List:	12 users (show)
Fixed In Version:
Doc Type:	Bug Fix
Doc Text:
Clone Of:
Environment:
Last Closed:	2011-10-19 12:07:23 UTC
Type:	---
Embargoed:
Dependent Products:

Attachments	(Terms of Use)

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.

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