[BUG] dm-thin metadata operation failed due to -ENOSPC returned by dm_pool_alloc_data_block() after processing DISCARD bios

[BUG] dm-thin metadata operation failed due to -ENOSPC returned by dm_pool_alloc_data_block() after processing DISCARD bios

[Dennis Yang]

Hi,

Recently we have came across an issue that dm-thin pool will be
switched to READ_ONLY mode because dm_pool_alloc_data_block() returns
-ENOSPC. AFAIK, this should not happen since alloc_data_block() will
check if there is any free space (and commit metadata if it first
reports no free space) before it allocates pool block. In addition,
total virtual space of all thin volumes is smaller than the pool
physical space in my testing environment which makes pool impossible
to run out of space.

This issue could be easily reproduced by the following steps.

1) Create a thin pool and a slightly smaller thin volume
> sudo dmsetup create meta --table "0 40000000 linear /dev/sdf 0"
> sudo dmsetup create data --table "0 10240000 linear /dev/md125 0"
> sudo dd if=/dev/zero of=/dev/mapper/meta bs=1M count=1
> sudo dmsetup create pool --table "0 10240000 thin-pool /dev/mapper/meta /dev/mapper/data 1024 0 2 skip_block_zeroing error_if_no_space"
> sudo dmsetup message pool 0 "create_thin 0"
> sudo dmsetup create thin --table "0 10238976 thin /dev/mapper/pool 0"

2) Make a filesystem and mount it
> sudo mkfs.ext4 -E lazy_itable_init=0,lazy_journal_init=0 /dev/mapper/thin
> sudo mount /dev/mapper/thin /mnt

3) Write a file to mount point until it takes all the space
> sudo dd if=/dev/zero of=/mnt/zero.img bs=1M

4) Remove this file and trim mount point
> sudo rm /mnt/zero.img
> sudo fstrim /mnt

Repeat step 3 and 4 multiple times and the pool will be switched to
READ_ONLY mode and need_checks flag will be set. Kernel message shows
the following messages.
[ 3952.723937] device-mapper: thin: 252:2: metadata operation
'dm_pool_alloc_data_block' failed: error = -28
[ 3952.723940] device-mapper: thin: 252:2: aborting current metadata transaction
[ 3952.725860] device-mapper: thin: 252:2: switching pool to read-only mode

This root cause of this issue is that dm-thin will first remove
mapping and increase corresponding blocks' reference count to prevent
them from being reused before DISCARD bios get processed by the
underlying layers. However. increasing blocks' reference count could
also increase the nr_allocated_this_transaction in struct sm_disk
which makes smd->old_ll.nr_allocated +
smd->nr_allocated_this_transaction bigger than smd->old_ll.nr_blocks.
In this case, alloc_data_block() will never commit metadata to reset
the begin pointer of struct sm_disk, because sm_disk_get_nr_free()
always return an underflow value.

If you need more information, please feel free to let me know.

Regards,
Dennis

Re: [BUG] dm-thin metadata operation failed due to -ENOSPC returned by dm_pool_alloc_data_block() after processing DISCARD bios

[Zdenek Kabelac]

Dne 3.4.2018 v 06:07 Dennis Yang napsal(a):
> Hi,
> 
> Recently we have came across an issue that dm-thin pool will be
> switched to READ_ONLY mode because dm_pool_alloc_data_block() returns
> -ENOSPC. AFAIK, this should not happen since alloc_data_block() will
> check if there is any free space (and commit metadata if it first
> reports no free space) before it allocates pool block. In addition,
> total virtual space of all thin volumes is smaller than the pool
> physical space in my testing environment which makes pool impossible
> to run out of space.
> 


Hi


Which kernel has been used during testing - was this upstream ?
(4.16??)

> This issue could be easily reproduced by the following steps.
> 
> 1) Create a thin pool and a slightly smaller thin volume
>> sudo dmsetup create meta --table "0 40000000 linear /dev/sdf 0"

maximum metadadata size is only ~16G (... 33161216 blocks or so)


>> sudo dmsetup create data --table "0 10240000 linear /dev/md125 0"
>> sudo dd if=/dev/zero of=/dev/mapper/meta bs=1M count=1
>> sudo dmsetup create pool --table "0 10240000 thin-pool /dev/mapper/meta /dev/mapper/data 1024 0 2 skip_block_zeroing error_if_no_space"
>> sudo dmsetup message pool 0 "create_thin 0"
>> sudo dmsetup create thin --table "0 10238976 thin /dev/mapper/pool 0"

I've tried to reproduce with smaller LVs - but haven't managed yet:

vg-LV1: 0 102384 thin 253:4 1
vg-pool: 0 102400 linear 253:4 0
vg-pool-tpool: 0 102400 thin-pool 253:2 253:3 128 0 2 skip_block_zeroing 
error_if_no_space
vg-pool_tdata: 0 102400 linear 253:0 10240
vg-pool_tmeta: 0 8192 linear 253:1 2048


Regards

Zdenek

Re: [BUG] dm-thin metadata operation failed due to -ENOSPC returned by dm_pool_alloc_data_block() after processing DISCARD bios

[Zdenek Kabelac]

Dne 3.4.2018 v 11:31 Zdenek Kabelac napsal(a):
> Dne 3.4.2018 v 06:07 Dennis Yang napsal(a):
>> Hi,
>>
>> Recently we have came across an issue that dm-thin pool will be
>> switched to READ_ONLY mode because dm_pool_alloc_data_block() returns
>> -ENOSPC. AFAIK, this should not happen since alloc_data_block() will
>> check if there is any free space (and commit metadata if it first
>> reports no free space) before it allocates pool block. In addition,
>> total virtual space of all thin volumes is smaller than the pool
>> physical space in my testing environment which makes pool impossible
>> to run out of space.
>>
> 
> 
> Hi
> 
> 
> Which kernel has been used during testing - was this upstream ?
> (4.16??)
> 

Ahh - wrongly applied fstrim - yep reproducible even on this smaller data set.

I'll open BZ case for this.


Regards


Zdenek

Re: [BUG] dm-thin metadata operation failed due to -ENOSPC returned by dm_pool_alloc_data_block() after processing DISCARD bios

[Zdenek Kabelac]

Dne 3.4.2018 v 06:07 Dennis Yang napsal(a):
> Hi,
> 
> Recently we have came across an issue that dm-thin pool will be
> switched to READ_ONLY mode because dm_pool_alloc_data_block() returns
> -ENOSPC. AFAIK, this should not happen since alloc_data_block() will
> check if there is any free space (and commit metadata if it first
> reports no free space) before it allocates pool block. In addition,
> total virtual space of all thin volumes is smaller than the pool
> physical space in my testing environment which makes pool impossible
> to run out of space.
> 
> This issue could be easily reproduced by the following steps.
> 
> 1) Create a thin pool and a slightly smaller thin volume
>> sudo dmsetup create meta --table "0 40000000 linear /dev/sdf 0"
>> sudo dmsetup create data --table "0 10240000 linear /dev/md125 0"
>> sudo dd if=/dev/zero of=/dev/mapper/meta bs=1M count=1
>> sudo dmsetup create pool --table "0 10240000 thin-pool /dev/mapper/meta /dev/mapper/data 1024 0 2 skip_block_zeroing error_if_no_space"
>> sudo dmsetup message pool 0 "create_thin 0"
>> sudo dmsetup create thin --table "0 10238976 thin /dev/mapper/pool 0"
> 
> 2) Make a filesystem and mount it
>> sudo mkfs.ext4 -E lazy_itable_init=0,lazy_journal_init=0 /dev/mapper/thin
>> sudo mount /dev/mapper/thin /mnt
> 
> 3) Write a file to mount point until it takes all the space
>> sudo dd if=/dev/zero of=/mnt/zero.img bs=1M
> 
> 4) Remove this file and trim mount point
>> sudo rm /mnt/zero.img
>> sudo fstrim /mnt
> 
> Repeat step 3 and 4 multiple times and the pool will be switched to
> READ_ONLY mode and need_checks flag will be set. Kernel message shows
> the following messages.
> [ 3952.723937] device-mapper: thin: 252:2: metadata operation
> 'dm_pool_alloc_data_block' failed: error = -28
> [ 3952.723940] device-mapper: thin: 252:2: aborting current metadata transaction
> [ 3952.725860] device-mapper: thin: 252:2: switching pool to read-only mode
> 
> This root cause of this issue is that dm-thin will first remove
> mapping and increase corresponding blocks' reference count to prevent
> them from being reused before DISCARD bios get processed by the
> underlying layers. However. increasing blocks' reference count could
> also increase the nr_allocated_this_transaction in struct sm_disk
> which makes smd->old_ll.nr_allocated +
> smd->nr_allocated_this_transaction bigger than smd->old_ll.nr_blocks.
> In this case, alloc_data_block() will never commit metadata to reset
> the begin pointer of struct sm_disk, because sm_disk_get_nr_free()
> always return an underflow value.
> 
> If you need more information, please feel free to let me know.

Hi

Just forgotten to mention - tracked through this BZ:

https://bugzilla.redhat.com/1563697

Regards

Zdenek

Re: dm-thin metadata operation failed due to -ENOSPC returned by dm_pool_alloc_data_block() after processing DISCARD bios

[Mike Snitzer]

On Tue, Apr 03 2018 at 12:07am -0400,
Dennis Yang <dennisyang@qnap.com> wrote:

> Hi,
> 
> Recently we have came across an issue that dm-thin pool will be
> switched to READ_ONLY mode because dm_pool_alloc_data_block() returns
> -ENOSPC. AFAIK, this should not happen since alloc_data_block() will
> check if there is any free space (and commit metadata if it first
> reports no free space) before it allocates pool block. In addition,
> total virtual space of all thin volumes is smaller than the pool
> physical space in my testing environment which makes pool impossible
> to run out of space.
> 
> This issue could be easily reproduced by the following steps.
> 
> 1) Create a thin pool and a slightly smaller thin volume
> > sudo dmsetup create meta --table "0 40000000 linear /dev/sdf 0"
> > sudo dmsetup create data --table "0 10240000 linear /dev/md125 0"
> > sudo dd if=/dev/zero of=/dev/mapper/meta bs=1M count=1
> > sudo dmsetup create pool --table "0 10240000 thin-pool /dev/mapper/meta /dev/mapper/data 1024 0 2 skip_block_zeroing error_if_no_space"
> > sudo dmsetup message pool 0 "create_thin 0"
> > sudo dmsetup create thin --table "0 10238976 thin /dev/mapper/pool 0"
> 
> 2) Make a filesystem and mount it
> > sudo mkfs.ext4 -E lazy_itable_init=0,lazy_journal_init=0 /dev/mapper/thin
> > sudo mount /dev/mapper/thin /mnt
> 
> 3) Write a file to mount point until it takes all the space
> > sudo dd if=/dev/zero of=/mnt/zero.img bs=1M
> 
> 4) Remove this file and trim mount point
> > sudo rm /mnt/zero.img
> > sudo fstrim /mnt
> 
> Repeat step 3 and 4 multiple times and the pool will be switched to
> READ_ONLY mode and need_checks flag will be set. Kernel message shows
> the following messages.
> [ 3952.723937] device-mapper: thin: 252:2: metadata operation
> 'dm_pool_alloc_data_block' failed: error = -28
> [ 3952.723940] device-mapper: thin: 252:2: aborting current metadata transaction
> [ 3952.725860] device-mapper: thin: 252:2: switching pool to read-only mode
> 
> This root cause of this issue is that dm-thin will first remove
> mapping and increase corresponding blocks' reference count to prevent
> them from being reused before DISCARD bios get processed by the
> underlying layers. However. increasing blocks' reference count could
> also increase the nr_allocated_this_transaction in struct sm_disk
> which makes smd->old_ll.nr_allocated +
> smd->nr_allocated_this_transaction bigger than smd->old_ll.nr_blocks.
> In this case, alloc_data_block() will never commit metadata to reset
> the begin pointer of struct sm_disk, because sm_disk_get_nr_free()
> always return an underflow value.
> 
> If you need more information, please feel free to let me know.

FYI, I just staged the following fix:
https://git.kernel.org/pub/scm/linux/kernel/git/device-mapper/linux-dm.git/commit/?h=dm-4.18&id=2b21877316f3a517554c1b34e6b32f4d1ad10493

Re: dm-thin metadata operation failed due to -ENOSPC returned by dm_pool_alloc_data_block() after processing DISCARD bios

[Mike Snitzer]

On Tue, Jun 26 2018 at  4:01pm -0400,
Mike Snitzer <snitzer@redhat.com> wrote:

> On Tue, Apr 03 2018 at 12:07am -0400,
> Dennis Yang <dennisyang@qnap.com> wrote:
> 
> > Hi,
> > 
> > Recently we have came across an issue that dm-thin pool will be
> > switched to READ_ONLY mode because dm_pool_alloc_data_block() returns
> > -ENOSPC. AFAIK, this should not happen since alloc_data_block() will
> > check if there is any free space (and commit metadata if it first
> > reports no free space) before it allocates pool block. In addition,
> > total virtual space of all thin volumes is smaller than the pool
> > physical space in my testing environment which makes pool impossible
> > to run out of space.
> > 
> > This issue could be easily reproduced by the following steps.
> > 
> > 1) Create a thin pool and a slightly smaller thin volume
> > > sudo dmsetup create meta --table "0 40000000 linear /dev/sdf 0"
> > > sudo dmsetup create data --table "0 10240000 linear /dev/md125 0"
> > > sudo dd if=/dev/zero of=/dev/mapper/meta bs=1M count=1
> > > sudo dmsetup create pool --table "0 10240000 thin-pool /dev/mapper/meta /dev/mapper/data 1024 0 2 skip_block_zeroing error_if_no_space"
> > > sudo dmsetup message pool 0 "create_thin 0"
> > > sudo dmsetup create thin --table "0 10238976 thin /dev/mapper/pool 0"
> > 
> > 2) Make a filesystem and mount it
> > > sudo mkfs.ext4 -E lazy_itable_init=0,lazy_journal_init=0 /dev/mapper/thin
> > > sudo mount /dev/mapper/thin /mnt
> > 
> > 3) Write a file to mount point until it takes all the space
> > > sudo dd if=/dev/zero of=/mnt/zero.img bs=1M
> > 
> > 4) Remove this file and trim mount point
> > > sudo rm /mnt/zero.img
> > > sudo fstrim /mnt
> > 
> > Repeat step 3 and 4 multiple times and the pool will be switched to
> > READ_ONLY mode and need_checks flag will be set. Kernel message shows
> > the following messages.
> > [ 3952.723937] device-mapper: thin: 252:2: metadata operation
> > 'dm_pool_alloc_data_block' failed: error = -28
> > [ 3952.723940] device-mapper: thin: 252:2: aborting current metadata transaction
> > [ 3952.725860] device-mapper: thin: 252:2: switching pool to read-only mode
> > 
> > This root cause of this issue is that dm-thin will first remove
> > mapping and increase corresponding blocks' reference count to prevent
> > them from being reused before DISCARD bios get processed by the
> > underlying layers. However. increasing blocks' reference count could
> > also increase the nr_allocated_this_transaction in struct sm_disk
> > which makes smd->old_ll.nr_allocated +
> > smd->nr_allocated_this_transaction bigger than smd->old_ll.nr_blocks.
> > In this case, alloc_data_block() will never commit metadata to reset
> > the begin pointer of struct sm_disk, because sm_disk_get_nr_free()
> > always return an underflow value.
> > 
> > If you need more information, please feel free to let me know.
> 
> FYI, I just staged the following fix:
> https://git.kernel.org/pub/scm/linux/kernel/git/device-mapper/linux-dm.git/commit/?h=dm-4.18&id=2b21877316f3a517554c1b34e6b32f4d1ad10493

(following output is with a debugging patch to print process_discard_bio
extents)

Using the test in the report, with the referenced patch applied, without
waiting for fstrim to complete:

[  734.449585] device-mapper: thin: process_discard_bio: begin=0 end=319
[  734.474426] XFS (dm-6): Mounting V5 Filesystem
[  734.481787] XFS (dm-6): Ending clean mount
[  734.577167] device-mapper: thin: process_discard_bio: begin=50 end=319
[  734.587850] device-mapper: thin: 253:4: switching pool to out-of-data-space (queue IO) mode
[  736.484991] device-mapper: thin: 253:4: switching pool to write mode
[  737.586929] device-mapper: thin: process_discard_bio: begin=50 end=319
[  737.597587] device-mapper: thin: 253:4: switching pool to out-of-data-space (queue IO) mode
[  739.560326] device-mapper: thin: 253:4: switching pool to write mode
[  740.651914] device-mapper: thin: process_discard_bio: begin=50 end=319
[  740.662223] device-mapper: thin: 253:4: switching pool to out-of-data-space (queue IO) mode
[  742.628723] device-mapper: thin: 253:4: switching pool to write mode
[  743.727873] device-mapper: thin: process_discard_bio: begin=50 end=319
[  743.738578] device-mapper: thin: 253:4: switching pool to out-of-data-space (queue IO) mode
[  745.700557] device-mapper: thin: 253:4: switching pool to write mode
[  746.799316] device-mapper: thin: process_discard_bio: begin=50 end=319
[  746.809928] device-mapper: thin: 253:4: switching pool to out-of-data-space (queue IO) mode
[  748.772334] device-mapper: thin: 253:4: switching pool to write mode
[  749.876049] device-mapper: thin: process_discard_bio: begin=50 end=319
[  749.916739] XFS (dm-6): Unmounting Filesystem

with sleep after fstrim:

[ 1462.939299] device-mapper: thin: process_discard_bio: begin=0 end=319
[ 1462.968260] XFS (dm-6): Mounting V5 Filesystem
[ 1462.976490] XFS (dm-6): Ending clean mount
[ 1463.074625] device-mapper: thin: process_discard_bio: begin=50 end=319
[ 1468.177317] device-mapper: thin: process_discard_bio: begin=50 end=319
[ 1473.271058] device-mapper: thin: process_discard_bio: begin=50 end=319
[ 1478.364355] device-mapper: thin: process_discard_bio: begin=50 end=319
[ 1483.456330] device-mapper: thin: process_discard_bio: begin=50 end=319
[ 1488.553290] device-mapper: thin: process_discard_bio: begin=50 end=319
[ 1493.593228] XFS (dm-6): Unmounting Filesystem