Re: [regression] 5.15 kernel triggering 100x more inode evictions

[Thorsten Leemhuis <regressions@leemhuis.info>]

Hi, this is your Linux kernel regression tracker. Top-posting for once,
to make this easily accessible to everyone.

Btrfs maintainers, what's up here? Yes, this regression report was a bit
confusing in the beginning, but Bruno worked on it. And apparently it's
already fixed in 5.16, but still in 5.15. Is this caused by a change
that is to big to backport or something?

Ciao, Thorsten

#regzbot poke

On 04.04.22 07:29, Bruno Damasceno Freire wrote:
> On 28.03.22 13:28, Thorsten Leemhuis wrote:
>> Hi Btrfs developers, this is your Linux kernel regression tracker.
>> Top-posting for once, to make this easily accessible to everyone.
>>
>> Are there any known regressions in 5.15 that cause more inode evictions?
>> There is a user reporting such problems, see the msg quoted below, which
>> is the last from this thread:
>>
>> https://lore.kernel.org/all/MN2PR20MB2512314446801B92562E26B5D2169@MN2PR20MB2512.namprd20.prod.outlook.com/
>>
>> @Bruno: sorry, you report is very hard to follow at least for me. Maybe
>> the btrfs developers have a idea what's wrong here, but if not you
>> likely need to make this easier for all us:
>>
>> Write a really simple testcase and run it on those vanilla kernels that
>> matter, which are in this case: The latest 5.17.y and 5.15.y releases to
>> check if it was already solved -- and if not, on 5.14 and 5.15. Maybe
>> you need to bisect the issue to bring us closer the the root of the
>> problem. But with a bit of luck the btrfs developers might have an idea
>> already.
>>
>> Ciao, Thosten
> 
> Hi Thorsten,
> Thanks for the feedback.
> I tried my best to make it simple this time.
> I hope it is, at least, better than before.
> Grazie, Bruno
> 
> *** Test case about high inode eviction on the 5.15 kernel ***
> 
> This regression was first observed during rpm operations with specific packages that became A LOT slower to update ranging from 4 to 30 minutes [1].
> The symptoms are: high cpu usage, high inode eviction and much slower I/O performance.
> Analyzing the rpm's strace report and making some experiments I could replace the rpm with a script that do 3 thing:
> - rename a file, unlink the renamed file and create a new file.
> 
> This test case is designed to trigger the following regression on the 5.15 kernel:
> * repeated renameat2, unlink and openat system calls reach files with btrfs compression property enable.
> * the combination of these system calls and the btrfs compression property triggers the high inode eviction.
> * the high inode eviction causes to much work for the btrfs directory logging.
> * the overloaded btrfs directory logging causes the slower I/O performance.
> 
> A simplified script is supplied.
> For a more capable script, more information and more test results please refer to my github account [2].
> 
> [1] https://bugzilla.opensuse.org/show_bug.cgi?id=1193549
> [2] https://github.com/bdamascen0/s3e
> 
> Index:
> 1.   Vanilla kernels
> 2.   k5.14.21 x k5.15.32
> 2.1. Detailed test report for compressed files
> 2.2. Comparison results for compressed files
> 2.3. Detailed test report for uncompressed files
> 2.4. Comparison results for uncompressed files
> 2.5. Cpu usage
> 3.   k5.17.1 and k5.16.15
> 3.1. Basic test report
> 4.   Simplified test script
> 
> 
> 1.   Vanilla kernels
> 
> This test case mainly covers the following vanilla kernels [3]: 5.15.32 and 5.14.21.
> The 5.15.32 vanilla kernel produced abnormal results:
> * high cpu usage, high inode eviction and much slower I/O performance for compressed files.
> * double inode eviction and slightly worse I/O performance for uncompressed files.
> The 5.14.21 vanilla kernel produced normal results and is used as a reference.
> The 5.17.1 and 5.16.15 vanilla kernels [4] produced normal results which can be found at the end.
> 
> [3] https://wiki.ubuntu.com/Kernel/MainlineBuilds 
> [4] https://software.opensuse.org/package/kernel-vanilla
> 
> 
> 2.   k5.14.21 x k5.15.32
> 
> 2.1  Detailed test report for compressed files
> 
> ubuntu jammy jellyfish -- kernel 5.14.21 --- vanilla --- (kvm)
> ...updating   50 files on /mnt/inode-ev/zstd: Job took    226 ms @inode_evictions: 51
> ...updating   50 files on /mnt/inode-ev/lzo:  Job took    222 ms @inode_evictions: 51
> ...updating  100 files on /mnt/inode-ev/zstd: Job took    384 ms @inode_evictions: 101
> ...updating  100 files on /mnt/inode-ev/lzo:  Job took    462 ms @inode_evictions: 101
> ...updating  150 files on /mnt/inode-ev/zstd: Job took    493 ms @inode_evictions: 151
> ...updating  150 files on /mnt/inode-ev/lzo:  Job took    554 ms @inode_evictions: 151
> ...updating  200 files on /mnt/inode-ev/zstd: Job took    804 ms @inode_evictions: 201
> ...updating  200 files on /mnt/inode-ev/lzo:  Job took    725 ms @inode_evictions: 201
> ...updating  250 files on /mnt/inode-ev/zstd: Job took    745 ms @inode_evictions: 251
> ...updating  250 files on /mnt/inode-ev/lzo:  Job took    758 ms @inode_evictions: 251
> ...updating 1000 files on /mnt/inode-ev/zstd: Job took   3452 ms @inode_evictions: 1001
> ...updating 1000 files on /mnt/inode-ev/lzo:  Job took   2979 ms @inode_evictions: 1001
> ubuntu jammy jellyfish -- kernel 5.15.32 --- vanilla --- (kvm)
> ...updating   50 files on /mnt/inode-ev/zstd: Job took    420 ms @inode_evictions: 1275
> ...updating   50 files on /mnt/inode-ev/lzo:  Job took    488 ms @inode_evictions: 1275
> ...updating  100 files on /mnt/inode-ev/zstd: Job took   1649 ms @inode_evictions: 5050
> ...updating  100 files on /mnt/inode-ev/lzo:  Job took   1566 ms @inode_evictions: 5050
> ...updating  150 files on /mnt/inode-ev/zstd: Job took   4448 ms @inode_evictions: 11325
> ...updating  150 files on /mnt/inode-ev/lzo:  Job took   4136 ms @inode_evictions: 11325
> ...updating  200 files on /mnt/inode-ev/zstd: Job took   9177 ms @inode_evictions: 20100
> ...updating  200 files on /mnt/inode-ev/lzo:  Job took   9070 ms @inode_evictions: 20100
> ...updating  250 files on /mnt/inode-ev/zstd: Job took  16191 ms @inode_evictions: 31375
> ...updating  250 files on /mnt/inode-ev/lzo:  Job took  16062 ms @inode_evictions: 31375
> ...updating 1000 files on /mnt/inode-ev/zstd: Job took 132865 ms @inode_evictions: 104195
> ...updating 1000 files on /mnt/inode-ev/lzo:  Job took 131979 ms @inode_evictions: 106639
> 
> 2.2. Comparison results for compressed files
> 
> k5.15.32 vanilla (compared to: k5.14.21 vanilla)
> 50   files gives aprox.  1.8 x more time and aprox.  25 x more inode evictions 
> 100  files gives aprox.  3.3 x more time and aprox.  50 x more inode evictions 
> 150  files gives aprox.  7.4 x more time and aprox.  75 x more inode evictions 
> 200  files gives aprox. 11.4 x more time and aprox. 100 x more inode evictions 
> 250  files gives aprox. 21.1 x more time and aprox. 125 x more inode evictions 
> 1000 files gives aprox. 38.4 x more time and aprox. 100 x more inode evictions 
> 
> 2.3  Detailed test report for uncompressed files
> 
> ubuntu jammy jellyfish -- kernel 5.14.21 --- vanilla --- (kvm)
> ...updating   50 files on /mnt/inode-ev/uncompressed: Job took  214 ms @inode_evictions: 51
> ...updating  100 files on /mnt/inode-ev/uncompressed: Job took  402 ms @inode_evictions: 101
> ...updating  150 files on /mnt/inode-ev/uncompressed: Job took  543 ms @inode_evictions: 151
> ...updating  200 files on /mnt/inode-ev/uncompressed: Job took  694 ms @inode_evictions: 201
> ...updating  250 files on /mnt/inode-ev/uncompressed: Job took  835 ms @inode_evictions: 251
> ...updating 1000 files on /mnt/inode-ev/uncompressed: Job took 3162 ms @inode_evictions: 1001
> ubuntu jammy jellyfish -- kernel 5.15.32 --- vanilla --- (kvm)
> ...updating   50 files on /mnt/inode-ev/uncompressed: Job took  269 ms @inode_evictions: 99
> ...updating  100 files on /mnt/inode-ev/uncompressed: Job took  359 ms @inode_evictions: 199
> ...updating  150 files on /mnt/inode-ev/uncompressed: Job took  675 ms @inode_evictions: 299
> ...updating  200 files on /mnt/inode-ev/uncompressed: Job took  752 ms @inode_evictions: 399
> ...updating  250 files on /mnt/inode-ev/uncompressed: Job took 1149 ms @inode_evictions: 499
> ...updating 1000 files on /mnt/inode-ev/uncompressed: Job took 7333 ms @inode_evictions: 1999
> 
> 2.4. Comparison results for uncompressed files
> 
> k5.15.32 vanilla (compared to: k5.14.21 vanilla)
> 50   files gives aprox. 1.2 x more time and aprox. 2 x more inode evictions 
> 100  files gives aprox. 0.8 x more time and aprox. 2 x more inode evictions 
> 150  files gives aprox. 1.2 x more time and aprox. 2 x more inode evictions 
> 200  files gives aprox. 1.0 x more time and aprox. 2 x more inode evictions 
> 250  files gives aprox. 1.3 x more time and aprox. 2 x more inode evictions 
> 1000 files gives aprox. 2.3 x more time and aprox. 2 x more inode evictions 
> 
> 2.5. Cpu usage
> 
> ubuntu jammy jellyfish -- kernel 5.15.32 --- vanilla --- (kvm)
> ...updating 1000 files on /mnt/inode-ev/zstd:         Job took 132691 ms - real 2m12,731s sys 2m 7,134s
> ...updating 1000 files on /mnt/inode-ev/lzo:          Job took 134130 ms - real 2m14,149s sys 2m 8,447s
> ...updating 1000 files on /mnt/inode-ev/uncompressed: Job took   7241 ms - real 0m 7,256s sys 0m 4,732s
> 
> 
> 3    k5.17.1 and k5.16.15
> 
> Just for the record, the 5.16 kernel never reproduced the regression.
> The real life workload to trigger the regression, the rpm package updates, were verified to work fine since 5.16~rc6 [1].
> It was expected that the synthetic workload from the script also produced normal results on the 5.16 and 5.17 kernels.
> 
> [1] https://bugzilla.opensuse.org/show_bug.cgi?id=1193549
> 
> 
> 3.1  Basic test report
> 
> opensuse tumbleweed ----- kernel 5.16.15 --- vanilla --- (kvm)
> ...updating 250 files on /mnt/inode-ev/zstd:         Job took 910 ms @inode_evictions: 250
> ...updating 250 files on /mnt/inode-ev/lzo:          Job took 740 ms @inode_evictions: 250
> ...updating 250 files on /mnt/inode-ev/uncompressed: Job took 717 ms @inode_evictions: 250
> opensuse tumbleweed ----- kernel 5.17.1 ---- vanilla --- (kvm)
> ...updating 250 files on /mnt/inode-ev/zstd:         Job took 701 ms @inode_evictions: 250
> ...updating 250 files on /mnt/inode-ev/lzo:          Job took 695 ms @inode_evictions: 250
> ...updating 250 files on /mnt/inode-ev/uncompressed: Job took 954 ms @inode_evictions: 250
> 
> 
> 4.   Simplified test script
> 
> This simplified script tries to setup, format and mount a ramdisk block device.
> It creates 3 testing folders (zstd, lzo, uncompressed) and set its btrfs compression property.
> For each time the script is executed, 3 tests are done and the bpftrace is started right before each test.
> 
> #!/bin/bash
> # s3e_t3.sh (based on s3e.sh version 4.7)
> # Simple Syscall Signature Emulator (test3)
> # test3: populate + test. test renameat2/openat + unlink syscalls w/ empty files (3x)
> # Copyright (c) 2022 Bruno Damasceno <bdamasceno@hotmail.com.br>
> # Warning: no safety checks
> 
> dir1=zstd
> dir2=lzo
> dir3=uncompressed
> DIR=zzz
> NUM_FILES=250
> DEV=/dev/ram0
> MNT=/mnt/inode-ev
> DIR_1="$MNT/$dir1"
> DIR_2="$MNT/$dir2"
> DIR_3="$MNT/$dir3"
> 
> populate() {
>     DIR=$1
>     echo "...populating 1st generation of files on $DIR:"
>     for ((i = 1; i <= $NUM_FILES; i++)); do
>         echo -n > $DIR/file_$i
>     done
>     }
> 
> run_test() {
>     DIR=$1
>     sync
>     xfs_io -c "fsync" $DIR
>     echo -e "\n...updating $NUM_FILES files on $DIR:"
>     #dumb pause so bpftrace has time to atach its probe
>     sleep 3s
>     start=$(date +%s%N)
>     for ((i = 1; i <= $NUM_FILES; i++)); do
>         mv $DIR/file_$i $DIR/file_$i-RPMDELETE
>         unlink $DIR/file_$i-RPMDELETE
>         echo -n > $DIR/file_$i
>         echo -n "_$i"
>         [ $i != $NUM_FILES ] && echo -ne "\r"
>     done
>     end=$(date +%s%N)
>     dur=$(( (end - start) / 1000000 ))
>     echo -ne "\r"
>     echo "Job took $dur milliseconds"
>     }
> 
> modprobe brd rd_size=128000 max_part=1 rd_nr=1
> mkfs.btrfs --label inode-ev --force $DEV > /dev/null
> mkdir $MNT
> mount $DEV $MNT
> mkdir $MNT/{$dir1,$dir2,$dir3}
> btrfs property set $DIR_1 compression zstd:1
> btrfs property set $DIR_2 compression lzo
> btrfs property set $DIR_3 compression none
> 
> for dir in "$DIR_1" "$DIR_2" "$DIR_3"
>     do
>         populate "$dir"
>         bpftrace -e 'kprobe:btrfs_evict_inode { @inode_evictions = count(); }' & run_test "$dir"
>         pkill bpftrace
>         #dumb pause to wait the bpftrace report
>         sleep 2s
>     done
> 
> umount $MNT
> rm --dir $MNT
> rmmod brd
>