5.6-rc1, fstrim reports different value 1 minute later

5.6-rc1, fstrim reports different value 1 minute later

[Chris Murphy]

Host: kernel 5.5.3, qemu-kvm, Btrfs, backing file is raw with +C  5.6.
Guest: kernel 5.6.0-rc1, / is Btrfs

Boot and login, and immediately run these commands:

[root@localhost ~]# df -h
/dev/vda4        96G  4.4G   91G   5% /
# fstrim -v /
/: 91 GiB (97633062912 bytes) trimmed

1 minute later

[root@localhost ~]# fstrim -v /
/: 3.5 GiB (3747549184 bytes) trimmed
[root@localhost ~]#

There's no activity happening in this one minute period. Reboot, and
it's reproducible again. 91G trimmed the first time then 3.5G the
second. Seems like new and unusual behavior. No kernel messages at all
in either host or guest.

-- 
Chris Murphy

Re: 5.6-rc1, fstrim reports different value 1 minute later

[Roman Mamedov]

On Wed, 12 Feb 2020 23:08:03 -0700
Chris Murphy <lists@colorremedies.com> wrote:

> Host: kernel 5.5.3, qemu-kvm, Btrfs, backing file is raw with +C  5.6.
> Guest: kernel 5.6.0-rc1, / is Btrfs
> 
> Boot and login, and immediately run these commands:
> 
> [root@localhost ~]# df -h
> /dev/vda4        96G  4.4G   91G   5% /
> # fstrim -v /
> /: 91 GiB (97633062912 bytes) trimmed
> 
> 1 minute later
> 
> [root@localhost ~]# fstrim -v /
> /: 3.5 GiB (3747549184 bytes) trimmed
> [root@localhost ~]#
> 
> There's no activity happening in this one minute period. Reboot, and
> it's reproducible again. 91G trimmed the first time then 3.5G the
> second. Seems like new and unusual behavior. No kernel messages at all
> in either host or guest.

For completeness, what would be returned the 3rd time you trim?

-- 
With respect,
Roman

Re: 5.5-5.6-rc1, fstrim reports different value 1 minute later

[Chris Murphy]

On Wed, Feb 12, 2020 at 11:21 PM Roman Mamedov <rm@romanrm.net> wrote:
>
> On Wed, 12 Feb 2020 23:08:03 -0700
> Chris Murphy <lists@colorremedies.com> wrote:
>
> > Host: kernel 5.5.3, qemu-kvm, Btrfs, backing file is raw with +C  5.6.
> > Guest: kernel 5.6.0-rc1, / is Btrfs
> >
> > Boot and login, and immediately run these commands:
> >
> > [root@localhost ~]# df -h
> > /dev/vda4        96G  4.4G   91G   5% /
> > # fstrim -v /
> > /: 91 GiB (97633062912 bytes) trimmed
> >
> > 1 minute later
> >
> > [root@localhost ~]# fstrim -v /
> > /: 3.5 GiB (3747549184 bytes) trimmed
> > [root@localhost ~]#

Reboot the VM with 5.5.3 and I get very slightly different values but
same behavior.
~]$ sudo -i
[sudo] password for hack:
[root@localhost ~]# fstrim -v /
/: 92.2 GiB (98953457664 bytes) trimmed
[root@localhost ~]# fstrim -v /
/: 3.7 GiB (3950542848 bytes) trimmed
[root@localhost ~]# exit

5 minutes later

$ sudo fstrim -v /
/: 3.4 GiB (3658797056 bytes) trimmed


> For completeness, what would be returned the 3rd time you trim?

I'm not seeing a pattern. Sometimes it's the same. Sometimes it's a
little different like above.

-- 
Chris Murphy

Re: fstrim reports different value 1 minute later

[Chris Murphy]

On Wed, Feb 12, 2020 at 11:21 PM Roman Mamedov <rm@romanrm.net> wrote:
>
> On Wed, 12 Feb 2020 23:08:03 -0700
> Chris Murphy <lists@colorremedies.com> wrote:
>
> > Host: kernel 5.5.3, qemu-kvm, Btrfs, backing file is raw with +C  5.6.
> > Guest: kernel 5.6.0-rc1, / is Btrfs
> >
> > Boot and login, and immediately run these commands:
> >
> > [root@localhost ~]# df -h
> > /dev/vda4        96G  4.4G   91G   5% /
> > # fstrim -v /
> > /: 91 GiB (97633062912 bytes) trimmed
> >
> > 1 minute later
> >
> > [root@localhost ~]# fstrim -v /
> > /: 3.5 GiB (3747549184 bytes) trimmed
> > [root@localhost ~]#

Huh... these are about 10s apart.

# uname -r
5.4.18-200.fc31.x86_64
[root@localhost ~]# fstrim -v /
/: 92 GiB (98746789888 bytes) trimmed
[root@localhost ~]# fstrim -v /
/: 3.6 GiB (3808149504 bytes) trimmed
[root@localhost ~]# fstrim -v /
/: 3.7 GiB (3993657344 bytes) trimmed
[root@localhost ~]# fstrim -v /
/: 3.6 GiB (3812700160 bytes) trimmed
[root@localhost ~]# fstrim -v /
/: 3.6 GiB (3812700160 bytes) trimmed
[root@localhost ~]# fstrim -v /
/: 3.6 GiB (3812700160 bytes) trimmed
[root@localhost ~]# fstrim -v /
/: 3.6 GiB (3812700160 bytes) trimmed
[root@localhost ~]# fstrim -v /
/: 3.6 GiB (3812700160 bytes) trimmed
[root@localhost ~]# fstrim -v /
/: 3.6 GiB (3813261312 bytes) trimmed
[root@localhost ~]#

3-4 minute gap

# fstrim -v /
/: 3.5 GiB (3729862656 bytes) trimmed

OK and on baremetal with 5.5.3.. also 10s delay

# fstrim -v /
/: 82.6 GiB (88663547904 bytes) trimmed
[root@fmac ~]# fstrim -v /
/: 11.3 GiB (12157599744 bytes) trimmed
[root@fmac ~]# fstrim -v /
/: 11.3 GiB (12156633088 bytes) trimmed
[root@fmac ~]#

There's no good use case for multiple fstrim instance this short
apart. I stumbled on it by accident while seeing what the behavior is
of a fallocated file created inside a VM on a sparse raw file used as
the VM's backing "device" - so at first I thought it was related to
that but now it's obviously not related to VM stuff at all.

I have fstrim.timer set to run fstrim.service once per week, and that
reports sane (expected) values each time. But, it also tends to happen
soon after a fresh boot or wake from S3.

-- 
Chris Murphy

Re: fstrim reports different value 1 minute later

[Roman Mamedov]

On Wed, 12 Feb 2020 23:37:26 -0700
Chris Murphy <lists@colorremedies.com> wrote:

> I have fstrim.timer set to run fstrim.service once per week, and that
> reports sane (expected) values each time. But, it also tends to happen
> soon after a fresh boot or wake from S3.

I believe Btrfs now[1] tracks which areas have been trimmed already during the
current mount and does not re-trim them again, like ext4 does since a long
time ago. In case of ext4, for your scenario the first trim would return 91GB,
and the subsequent ones (assuming no FS activity) would trim 0 bytes.

But if the above is indeed the cause, then I'm not sure why it still always
retrims about 3.6 GB or 11 GB for your other machine, even with no writes or
deletions.

[1] https://patchwork.kernel.org/patch/11254859/


-- 
With respect,
Roman