[Regression] ext4: changes to mb_optimize_scan cause issues on Raspberry Pi

[Regression] ext4: changes to mb_optimize_scan cause issues on Raspberry Pi

[Stefan Wahren]

Hi,

i noticed that since Linux 5.18 (Linux 5.19-rc6 is still affected) i'm 
unable to run "rpi-update" without massive performance regression on my 
Raspberry Pi 4 (multi_v7_defconfig + CONFIG_ARM_LPAE). Using Linux 5.17 
this tool successfully downloads the latest firmware (> 100 MB) on my 
development micro SD card (Kingston 16 GB Industrial) with a ext4 
filesystem within ~ 1 min. The same scenario on Linux 5.18 shows the 
following symptoms:

- download takes endlessly much time and leads to an abort by userspace 
in most cases because of the poor performance
- massive system load during download even after download has been 
aborted (heartbeat LED goes wild)
- whole system becomes nearly unresponsive
- system load goes back to normal after > 10 min
- dmesg doesn't show anything suspicious

I was able to bisect this issue:

ff042f4a9b050895a42cae893cc01fa2ca81b95c good
4b0986a3613c92f4ec1bdc7f60ec66fea135991f bad
25fd2d41b505d0640bdfe67aa77c549de2d3c18a bad
b4bc93bd76d4da32600795cd323c971f00a2e788 bad
3fe2f7446f1e029b220f7f650df6d138f91651f2 bad
b080cee72ef355669cbc52ff55dc513d37433600 good
ad9c6ee642a61adae93dfa35582b5af16dc5173a good
9b03992f0c88baef524842e411fbdc147780dd5d bad
aab4ed5816acc0af8cce2680880419cd64982b1d good
14705fda8f6273501930dfe1d679ad4bec209f52 good
5c93e8ecd5bd3bfdee013b6da0850357eb6ca4d8 good
8cb5a30372ef5cf2b1d258fce1711d80f834740a bad
077d0c2c78df6f7260cdd015a991327efa44d8ad bad
cc5095747edfb054ca2068d01af20be3fcc3634f good
27b38686a3bb601db48901dbc4e2fc5d77ffa2c1 good

commit 077d0c2c78df6f7260cdd015a991327efa44d8ad
Author: Ojaswin Mujoo <ojaswin@linux.ibm.com>
Date:   Tue Mar 8 15:22:01 2022 +0530

ext4: make mb_optimize_scan performance mount option work with extents

If i revert this commit with Linux 5.19-rc6 the performance regression 
disappears.

Please ask if you need more information.

Regards

Re: [Regression] ext4: changes to mb_optimize_scan cause issues on Raspberry Pi #forregzbot

[Thorsten Leemhuis]

[TLDR: I'm adding below regression report to the list of tracked
regressions; all text from me you find below is based on a few templates
paragraphs you might have encountered already already in similar form.]

TWIMC: this mail is primarily send for documentation purposes and for
regzbot, my Linux kernel regression tracking bot. These mails usually
contain '#forregzbot' in the subject, to make them easy to spot and filter.

On 18.07.22 15:29, Stefan Wahren wrote:

> i noticed that since Linux 5.18 (Linux 5.19-rc6 is still affected) i'm
> unable to run "rpi-update" without massive performance regression on my
> Raspberry Pi 4 (multi_v7_defconfig + CONFIG_ARM_LPAE). Using Linux 5.17
> this tool successfully downloads the latest firmware (> 100 MB) on my
> development micro SD card (Kingston 16 GB Industrial) with a ext4
> filesystem within ~ 1 min. The same scenario on Linux 5.18 shows the
> following symptoms:
> 
> - download takes endlessly much time and leads to an abort by userspace
> in most cases because of the poor performance
> - massive system load during download even after download has been
> aborted (heartbeat LED goes wild)
> - whole system becomes nearly unresponsive
> - system load goes back to normal after > 10 min
> - dmesg doesn't show anything suspicious
> 
> I was able to bisect this issue:
> 
> commit 077d0c2c78df6f7260cdd015a991327efa44d8ad
> Author: Ojaswin Mujoo <ojaswin@linux.ibm.com>
> Date:   Tue Mar 8 15:22:01 2022 +0530
> 
> ext4: make mb_optimize_scan performance mount option work with extents
> 
> If i revert this commit with Linux 5.19-rc6 the performance regression
> disappears.
> 
> Please ask if you need more information.

Hi, this is your Linux kernel regression tracker. Thanks for the report.
To be sure below issue doesn't fall through the cracks unnoticed, I'm
adding it to regzbot, my Linux kernel regression tracking bot:

#regzbot ^introduced 077d0c2c78df6f7260cdd015a991327efa44d8ad
#regzbot title ext4: changes to mb_optimize_scan cause issues on
Raspberry Pi
#regzbot ignore-activity

This isn't a regression? This issue or a fix for it are already
discussed somewhere else? It was fixed already? You want to clarify when
the regression started to happen? Or point out I got the title or
something else totally wrong? Then just reply -- ideally with also
telling regzbot about it, as explained here:
https://linux-regtracking.leemhuis.info/tracked-regression/

Reminder for developers: When fixing the issue, add 'Link:' tags
pointing to the report (the mail this one replies to), as explained for
in the Linux kernel's documentation; above webpage explains why this is
important for tracked regressions.

Ciao, Thorsten (wearing his 'the Linux kernel's regression tracker' hat)

P.S.: As the Linux kernel's regression tracker I deal with a lot of
reports and sometimes miss something important when writing mails like
this. If that's the case here, don't hesitate to tell me in a public
reply, it's in everyone's interest to set the public record straight.

Re: [Regression] ext4: changes to mb_optimize_scan cause issues on Raspberry Pi

[Stefan Wahren]

Am 18.07.22 um 15:29 schrieb Stefan Wahren:
> Hi,
>
> i noticed that since Linux 5.18 (Linux 5.19-rc6 is still affected) i'm 
> unable to run "rpi-update" without massive performance regression on 
> my Raspberry Pi 4 (multi_v7_defconfig + CONFIG_ARM_LPAE). Using Linux 
> 5.17 this tool successfully downloads the latest firmware (> 100 MB) 
> on my development micro SD card (Kingston 16 GB Industrial) with a 
> ext4 filesystem within ~ 1 min. The same scenario on Linux 5.18 shows 
> the following symptoms:
>
FWIW, here some information about the affected ext4 partition:

fc stats:
0 commits
0 ineligible
0 numblks
0us avg_commit_time
Ineligible reasons:
"Extended attributes changed":    0
"Cross rename":    0
"Journal flag changed":    0
"Insufficient memory":    0
"Swap boot":    0
"Resize":    0
"Dir renamed":    0
"Falloc range op":    0
"Data journalling":    0

options:
rw
bsddf
nogrpid
block_validity
dioread_nolock
nodiscard
delalloc
nowarn_on_error
nojournal_checksum
barrier
auto_da_alloc
user_xattr
noquota
resuid=0
resgid=0
errors=continue
commit=5
min_batch_time=0
max_batch_time=15000
stripe=0
data=ordered
inode_readahead_blks=32
init_itable=10
max_dir_size_kb=0

tune2fs 1.44.5 (15-Dec-2018)
Filesystem volume name:   rootfs
Last mounted on:          /
Filesystem UUID:          3857a514-b0f4-49ce-8430-34762068bb6f
Filesystem magic number:  0xEF53
Filesystem revision #:    1 (dynamic)
Filesystem features:      has_journal ext_attr resize_inode dir_index 
filetype needs_recovery extent flex_bg sparse_super large_file dir_nlink 
extra_isize
Filesystem flags:         unsigned_directory_hash
Default mount options:    user_xattr acl
Filesystem state:         clean
Errors behavior:          Continue
Filesystem OS type:       Linux
Inode count:              927360
Block count:              3755008
Reserved block count:     158603
Free blocks:              1770208
Free inodes:              731074
First block:              0
Block size:               4096
Fragment size:            4096
Reserved GDT blocks:      220
Blocks per group:         32768
Fragments per group:      32768
Inodes per group:         8064
Inode blocks per group:   504
Flex block group size:    16
Filesystem created:       Fri Mar  5 00:10:14 2021
Last mount time:          Sun Jul 24 22:47:19 2022
Last write time:          Sun Jul 24 22:47:18 2022
Mount count:              4
Maximum mount count:      -1
Last checked:             Tue Jul 19 09:16:29 2022
Check interval:           0 (<none>)
Lifetime writes:          25 GB
Reserved blocks uid:      0 (user root)
Reserved blocks gid:      0 (group root)
First inode:              11
Inode size:              256
Required extra isize:     32
Desired extra isize:      32
Journal inode:            8
Default directory hash:   half_md4
Directory Hash Seed:      4f95e9ae-24e1-4c7f-bb32-f4a9c41649a7
Journal backup:           inode blocks

Re: [Regression] ext4: changes to mb_optimize_scan cause issues on Raspberry Pi

[Ojaswin Mujoo]

On Mon, Jul 18, 2022 at 03:29:47PM +0200, Stefan Wahren wrote:
> Hi,
> 
> i noticed that since Linux 5.18 (Linux 5.19-rc6 is still affected) i'm
> unable to run "rpi-update" without massive performance regression on my
> Raspberry Pi 4 (multi_v7_defconfig + CONFIG_ARM_LPAE). Using Linux 5.17 this
> tool successfully downloads the latest firmware (> 100 MB) on my development
> micro SD card (Kingston 16 GB Industrial) with a ext4 filesystem within ~ 1
> min. The same scenario on Linux 5.18 shows the following symptoms:
> 
> - download takes endlessly much time and leads to an abort by userspace in
> most cases because of the poor performance
> - massive system load during download even after download has been aborted
> (heartbeat LED goes wild)
> - whole system becomes nearly unresponsive
> - system load goes back to normal after > 10 min
> - dmesg doesn't show anything suspicious
> 
> I was able to bisect this issue:
> 
> ff042f4a9b050895a42cae893cc01fa2ca81b95c good
> 4b0986a3613c92f4ec1bdc7f60ec66fea135991f bad
> 25fd2d41b505d0640bdfe67aa77c549de2d3c18a bad
> b4bc93bd76d4da32600795cd323c971f00a2e788 bad
> 3fe2f7446f1e029b220f7f650df6d138f91651f2 bad
> b080cee72ef355669cbc52ff55dc513d37433600 good
> ad9c6ee642a61adae93dfa35582b5af16dc5173a good
> 9b03992f0c88baef524842e411fbdc147780dd5d bad
> aab4ed5816acc0af8cce2680880419cd64982b1d good
> 14705fda8f6273501930dfe1d679ad4bec209f52 good
> 5c93e8ecd5bd3bfdee013b6da0850357eb6ca4d8 good
> 8cb5a30372ef5cf2b1d258fce1711d80f834740a bad
> 077d0c2c78df6f7260cdd015a991327efa44d8ad bad
> cc5095747edfb054ca2068d01af20be3fcc3634f good
> 27b38686a3bb601db48901dbc4e2fc5d77ffa2c1 good
> 
> commit 077d0c2c78df6f7260cdd015a991327efa44d8ad
> Author: Ojaswin Mujoo <ojaswin@linux.ibm.com>
> Date:   Tue Mar 8 15:22:01 2022 +0530
> 
> ext4: make mb_optimize_scan performance mount option work with extents
> 
> If i revert this commit with Linux 5.19-rc6 the performance regression
> disappears.
> 
> Please ask if you need more information.

Hi Stefan, 

Apologies, I had missed this email initially. So this particular patch
simply changed a typo in an if condition which was preventing the
mb_optimize_scan option to be enabled correctly (This feature was
introduced in the following commit [1]). I think with the
mb_optimize_scan now working, it is somehow causing the firmware
download/update to take a longer time. 

I'll try to investigate this and get back with my findings.

Regard,
Ojaswin

[1] 
	commit 196e402adf2e4cd66f101923409f1970ec5f1af3
	From: Harshad Shirwadkar <harshadshirwadkar@gmail.com>
	Date: Thu, 1 Apr 2021 10:21:27 -0700
	
	ext4: improve cr 0 / cr 1 group scanning

> 
> Regards
> 

Re: [Regression] ext4: changes to mb_optimize_scan cause issues on Raspberry Pi

[Stefan Wahren]

Hi Ojaswin,

Am 25.07.22 um 17:07 schrieb Ojaswin Mujoo:
> On Mon, Jul 18, 2022 at 03:29:47PM +0200, Stefan Wahren wrote:
>> Hi,
>>
>> i noticed that since Linux 5.18 (Linux 5.19-rc6 is still affected) i'm
>> unable to run "rpi-update" without massive performance regression on my
>> Raspberry Pi 4 (multi_v7_defconfig + CONFIG_ARM_LPAE). Using Linux 5.17 this
>> tool successfully downloads the latest firmware (> 100 MB) on my development
>> micro SD card (Kingston 16 GB Industrial) with a ext4 filesystem within ~ 1
>> min. The same scenario on Linux 5.18 shows the following symptoms:
>>
>> - download takes endlessly much time and leads to an abort by userspace in
>> most cases because of the poor performance
>> - massive system load during download even after download has been aborted
>> (heartbeat LED goes wild)
>> - whole system becomes nearly unresponsive
>> - system load goes back to normal after > 10 min
>> - dmesg doesn't show anything suspicious
>>
>> I was able to bisect this issue:
>>
>> ff042f4a9b050895a42cae893cc01fa2ca81b95c good
>> 4b0986a3613c92f4ec1bdc7f60ec66fea135991f bad
>> 25fd2d41b505d0640bdfe67aa77c549de2d3c18a bad
>> b4bc93bd76d4da32600795cd323c971f00a2e788 bad
>> 3fe2f7446f1e029b220f7f650df6d138f91651f2 bad
>> b080cee72ef355669cbc52ff55dc513d37433600 good
>> ad9c6ee642a61adae93dfa35582b5af16dc5173a good
>> 9b03992f0c88baef524842e411fbdc147780dd5d bad
>> aab4ed5816acc0af8cce2680880419cd64982b1d good
>> 14705fda8f6273501930dfe1d679ad4bec209f52 good
>> 5c93e8ecd5bd3bfdee013b6da0850357eb6ca4d8 good
>> 8cb5a30372ef5cf2b1d258fce1711d80f834740a bad
>> 077d0c2c78df6f7260cdd015a991327efa44d8ad bad
>> cc5095747edfb054ca2068d01af20be3fcc3634f good
>> 27b38686a3bb601db48901dbc4e2fc5d77ffa2c1 good
>>
>> commit 077d0c2c78df6f7260cdd015a991327efa44d8ad
>> Author: Ojaswin Mujoo <ojaswin@linux.ibm.com>
>> Date:   Tue Mar 8 15:22:01 2022 +0530
>>
>> ext4: make mb_optimize_scan performance mount option work with extents
>>
>> If i revert this commit with Linux 5.19-rc6 the performance regression
>> disappears.
>>
>> Please ask if you need more information.
> Hi Stefan,
>
> Apologies, I had missed this email initially. So this particular patch
> simply changed a typo in an if condition which was preventing the
> mb_optimize_scan option to be enabled correctly (This feature was
> introduced in the following commit [1]). I think with the
> mb_optimize_scan now working, it is somehow causing the firmware
> download/update to take a longer time.
>
> I'll try to investigate this and get back with my findings.

thanks. I wasn't able to reproduce this heavy load symptoms with every 
SD card. Maybe this depends on the write performance of the SD card to 
trigger the situation (used command to measure write performance: dd 
if=/dev/zero of=/boot/test bs=1M count=30 oflag=dsync,direct ).

I tested a Kingston consumer 32 GB which had nearly constant write 
performance of 13 MB/s and didn't had the heavy load symptoms. The 
firmware update was done in a few seconds, so hard to say that at least 
the performance regression is reproducible.

I also tested 2x Kingston industrial 16 GB which had a floating write 
performance between 5 and 10 MB/s (wear leveling?) and both had the 
heavy load symptoms.

All SD cards has been detected as ultra high speed DDR50 by the emmc2 
interface.

Best regards

>
> Regard,
> Ojaswin
>
> [1]
> 	commit 196e402adf2e4cd66f101923409f1970ec5f1af3
> 	From: Harshad Shirwadkar <harshadshirwadkar@gmail.com>
> 	Date: Thu, 1 Apr 2021 10:21:27 -0700
> 	
> 	ext4: improve cr 0 / cr 1 group scanning
>
>> Regards
>>

Re: [Regression] ext4: changes to mb_optimize_scan cause issues on Raspberry Pi

[Ojaswin Mujoo]

On Mon, Jul 25, 2022 at 09:09:32PM +0200, Stefan Wahren wrote:
> Hi Ojaswin,
> 
> Am 25.07.22 um 17:07 schrieb Ojaswin Mujoo:
> > On Mon, Jul 18, 2022 at 03:29:47PM +0200, Stefan Wahren wrote:
> > > Hi,
> > > 
> > > i noticed that since Linux 5.18 (Linux 5.19-rc6 is still affected) i'm
> > > unable to run "rpi-update" without massive performance regression on my
> > > Raspberry Pi 4 (multi_v7_defconfig + CONFIG_ARM_LPAE). Using Linux 5.17 this
> > > tool successfully downloads the latest firmware (> 100 MB) on my development
> > > micro SD card (Kingston 16 GB Industrial) with a ext4 filesystem within ~ 1
> > > min. The same scenario on Linux 5.18 shows the following symptoms:
> > > 
> > > - download takes endlessly much time and leads to an abort by userspace in
> > > most cases because of the poor performance
> > > - massive system load during download even after download has been aborted
> > > (heartbeat LED goes wild)
> > > - whole system becomes nearly unresponsive
> > > - system load goes back to normal after > 10 min
> > > - dmesg doesn't show anything suspicious
> > > 
> > > I was able to bisect this issue:
> > > 
> > > ff042f4a9b050895a42cae893cc01fa2ca81b95c good
> > > 4b0986a3613c92f4ec1bdc7f60ec66fea135991f bad
> > > 25fd2d41b505d0640bdfe67aa77c549de2d3c18a bad
> > > b4bc93bd76d4da32600795cd323c971f00a2e788 bad
> > > 3fe2f7446f1e029b220f7f650df6d138f91651f2 bad
> > > b080cee72ef355669cbc52ff55dc513d37433600 good
> > > ad9c6ee642a61adae93dfa35582b5af16dc5173a good
> > > 9b03992f0c88baef524842e411fbdc147780dd5d bad
> > > aab4ed5816acc0af8cce2680880419cd64982b1d good
> > > 14705fda8f6273501930dfe1d679ad4bec209f52 good
> > > 5c93e8ecd5bd3bfdee013b6da0850357eb6ca4d8 good
> > > 8cb5a30372ef5cf2b1d258fce1711d80f834740a bad
> > > 077d0c2c78df6f7260cdd015a991327efa44d8ad bad
> > > cc5095747edfb054ca2068d01af20be3fcc3634f good
> > > 27b38686a3bb601db48901dbc4e2fc5d77ffa2c1 good
> > > 
> > > commit 077d0c2c78df6f7260cdd015a991327efa44d8ad
> > > Author: Ojaswin Mujoo <ojaswin@linux.ibm.com>
> > > Date:   Tue Mar 8 15:22:01 2022 +0530
> > > 
> > > ext4: make mb_optimize_scan performance mount option work with extents
> > > 
> > > If i revert this commit with Linux 5.19-rc6 the performance regression
> > > disappears.
> > > 
> > > Please ask if you need more information.
> > Hi Stefan,
> > 
> > Apologies, I had missed this email initially. So this particular patch
> > simply changed a typo in an if condition which was preventing the
> > mb_optimize_scan option to be enabled correctly (This feature was
> > introduced in the following commit [1]). I think with the
> > mb_optimize_scan now working, it is somehow causing the firmware
> > download/update to take a longer time.
> > 
> > I'll try to investigate this and get back with my findings.
> 
> thanks. I wasn't able to reproduce this heavy load symptoms with every SD
> card. Maybe this depends on the write performance of the SD card to trigger
> the situation (used command to measure write performance: dd if=/dev/zero
> of=/boot/test bs=1M count=30 oflag=dsync,direct ).
> 
> I tested a Kingston consumer 32 GB which had nearly constant write
> performance of 13 MB/s and didn't had the heavy load symptoms. The firmware
> update was done in a few seconds, so hard to say that at least the
> performance regression is reproducible.
> 
> I also tested 2x Kingston industrial 16 GB which had a floating write
> performance between 5 and 10 MB/s (wear leveling?) and both had the heavy
> load symptoms.
> 
> All SD cards has been detected as ultra high speed DDR50 by the emmc2
> interface.
> 
> Best regards
> 
> > 
> > Regard,
> > Ojaswin
> > 
> > [1]
> > 	commit 196e402adf2e4cd66f101923409f1970ec5f1af3
> > 	From: Harshad Shirwadkar <harshadshirwadkar@gmail.com>
> > 	Date: Thu, 1 Apr 2021 10:21:27 -0700
> > 	
> > 	ext4: improve cr 0 / cr 1 group scanning
> > 
> > > Regards
> > > 

Thanks for the info Stefan, I'm still trying to reproduce the issue but
it's slightly challenging since I don't have my RPi handy at the moment. 

In the meantime, would you please try out the mb_optmize_scan=0 command
line options to see if that helps bypass the issue. This will help
confirm if the issue lies in mb_optmize_scan itself or if its something
else.

You can perhaps mount the root file system with this option using
the following kernel command line argument

rootflags="mb_optimize_scan=0"

You can also confirm if mb_optimize_scan was turned off by checking the
first line in output of:

cat /proc/fs/ext4/<dev>/mb_structs_summary

Regards,
Ojaswin

Re: [Regression] ext4: changes to mb_optimize_scan cause issues on Raspberry Pi

[Stefan Wahren]

Hi Ojaswin,

Am 26.07.22 um 08:43 schrieb Ojaswin Mujoo:
> On Mon, Jul 25, 2022 at 09:09:32PM +0200, Stefan Wahren wrote:
>> Hi Ojaswin,
>>
>> Am 25.07.22 um 17:07 schrieb Ojaswin Mujoo:
>>> On Mon, Jul 18, 2022 at 03:29:47PM +0200, Stefan Wahren wrote:
>>>> Hi,
>>>>
>>>> i noticed that since Linux 5.18 (Linux 5.19-rc6 is still affected) i'm
>>>> unable to run "rpi-update" without massive performance regression on my
>>>> Raspberry Pi 4 (multi_v7_defconfig + CONFIG_ARM_LPAE). Using Linux 5.17 this
>>>> tool successfully downloads the latest firmware (> 100 MB) on my development
>>>> micro SD card (Kingston 16 GB Industrial) with a ext4 filesystem within ~ 1
>>>> min. The same scenario on Linux 5.18 shows the following symptoms:
>>>>
>>>> - download takes endlessly much time and leads to an abort by userspace in
>>>> most cases because of the poor performance
>>>> - massive system load during download even after download has been aborted
>>>> (heartbeat LED goes wild)
>>>> - whole system becomes nearly unresponsive
>>>> - system load goes back to normal after > 10 min
>>>> - dmesg doesn't show anything suspicious
>>>>
>>>> I was able to bisect this issue:
>>>>
>>>> ff042f4a9b050895a42cae893cc01fa2ca81b95c good
>>>> 4b0986a3613c92f4ec1bdc7f60ec66fea135991f bad
>>>> 25fd2d41b505d0640bdfe67aa77c549de2d3c18a bad
>>>> b4bc93bd76d4da32600795cd323c971f00a2e788 bad
>>>> 3fe2f7446f1e029b220f7f650df6d138f91651f2 bad
>>>> b080cee72ef355669cbc52ff55dc513d37433600 good
>>>> ad9c6ee642a61adae93dfa35582b5af16dc5173a good
>>>> 9b03992f0c88baef524842e411fbdc147780dd5d bad
>>>> aab4ed5816acc0af8cce2680880419cd64982b1d good
>>>> 14705fda8f6273501930dfe1d679ad4bec209f52 good
>>>> 5c93e8ecd5bd3bfdee013b6da0850357eb6ca4d8 good
>>>> 8cb5a30372ef5cf2b1d258fce1711d80f834740a bad
>>>> 077d0c2c78df6f7260cdd015a991327efa44d8ad bad
>>>> cc5095747edfb054ca2068d01af20be3fcc3634f good
>>>> 27b38686a3bb601db48901dbc4e2fc5d77ffa2c1 good
>>>>
>>>> commit 077d0c2c78df6f7260cdd015a991327efa44d8ad
>>>> Author: Ojaswin Mujoo <ojaswin@linux.ibm.com>
>>>> Date:   Tue Mar 8 15:22:01 2022 +0530
>>>>
>>>> ext4: make mb_optimize_scan performance mount option work with extents
>>>>
>>>> If i revert this commit with Linux 5.19-rc6 the performance regression
>>>> disappears.
>>>>
>>>> Please ask if you need more information.
>>> Hi Stefan,
>>>
>>> Apologies, I had missed this email initially. So this particular patch
>>> simply changed a typo in an if condition which was preventing the
>>> mb_optimize_scan option to be enabled correctly (This feature was
>>> introduced in the following commit [1]). I think with the
>>> mb_optimize_scan now working, it is somehow causing the firmware
>>> download/update to take a longer time.
>>>
>>> I'll try to investigate this and get back with my findings.
>> thanks. I wasn't able to reproduce this heavy load symptoms with every SD
>> card. Maybe this depends on the write performance of the SD card to trigger
>> the situation (used command to measure write performance: dd if=/dev/zero
>> of=/boot/test bs=1M count=30 oflag=dsync,direct ).
>>
>> I tested a Kingston consumer 32 GB which had nearly constant write
>> performance of 13 MB/s and didn't had the heavy load symptoms. The firmware
>> update was done in a few seconds, so hard to say that at least the
>> performance regression is reproducible.
>>
>> I also tested 2x Kingston industrial 16 GB which had a floating write
>> performance between 5 and 10 MB/s (wear leveling?) and both had the heavy
>> load symptoms.
>>
>> All SD cards has been detected as ultra high speed DDR50 by the emmc2
>> interface.
>>
>> Best regards
>>
>>> Regard,
>>> Ojaswin
>>>
>>> [1]
>>> 	commit 196e402adf2e4cd66f101923409f1970ec5f1af3
>>> 	From: Harshad Shirwadkar <harshadshirwadkar@gmail.com>
>>> 	Date: Thu, 1 Apr 2021 10:21:27 -0700
>>> 	
>>> 	ext4: improve cr 0 / cr 1 group scanning
>>>
>>>> Regards
>>>>
> Thanks for the info Stefan, I'm still trying to reproduce the issue but
> it's slightly challenging since I don't have my RPi handy at the moment.
>
> In the meantime, would you please try out the mb_optmize_scan=0 command
> line options to see if that helps bypass the issue. This will help
> confirm if the issue lies in mb_optmize_scan itself or if its something
> else.
>
I run the firmware update 5 times with mb_optimize_scan=0 on my 
Raspberry Pi 4 and the industrial SD card and everytime the update worked.
>
> Regards,
> Ojaswin

Re: [Regression] ext4: changes to mb_optimize_scan cause issues on Raspberry Pi

[Thorsten Leemhuis]

On 26.07.22 17:54, Stefan Wahren wrote:
> Hi Ojaswin,
> 
> Am 26.07.22 um 08:43 schrieb Ojaswin Mujoo:
>> On Mon, Jul 25, 2022 at 09:09:32PM +0200, Stefan Wahren wrote:
>>> Hi Ojaswin,
>>>
>>> Am 25.07.22 um 17:07 schrieb Ojaswin Mujoo:
>>>> On Mon, Jul 18, 2022 at 03:29:47PM +0200, Stefan Wahren wrote:
>>>>> Hi,
>>>>>
>>>>> i noticed that since Linux 5.18 (Linux 5.19-rc6 is still affected) i'm
>>>>> unable to run "rpi-update" without massive performance regression
>>>>> on my
>>>>> Raspberry Pi 4 (multi_v7_defconfig + CONFIG_ARM_LPAE). Using Linux
>>>>> 5.17 this
>>>>> tool successfully downloads the latest firmware (> 100 MB) on my
>>>>> development
>>>>> micro SD card (Kingston 16 GB Industrial) with a ext4 filesystem
>>>>> within ~ 1
>>>>> min. The same scenario on Linux 5.18 shows the following symptoms:
>>>>>
>>>>> - download takes endlessly much time and leads to an abort by
>>>>> userspace in
>>>>> most cases because of the poor performance
>>>>> - massive system load during download even after download has been
>>>>> aborted
>>>>> (heartbeat LED goes wild)
>>>>> - whole system becomes nearly unresponsive
>>>>> - system load goes back to normal after > 10 min
>>>>> - dmesg doesn't show anything suspicious
>>>>>
>>>>> I was able to bisect this issue:
>>>>>
>>>>> ff042f4a9b050895a42cae893cc01fa2ca81b95c good
>>>>> 4b0986a3613c92f4ec1bdc7f60ec66fea135991f bad
>>>>> 25fd2d41b505d0640bdfe67aa77c549de2d3c18a bad
>>>>> b4bc93bd76d4da32600795cd323c971f00a2e788 bad
>>>>> 3fe2f7446f1e029b220f7f650df6d138f91651f2 bad
>>>>> b080cee72ef355669cbc52ff55dc513d37433600 good
>>>>> ad9c6ee642a61adae93dfa35582b5af16dc5173a good
>>>>> 9b03992f0c88baef524842e411fbdc147780dd5d bad
>>>>> aab4ed5816acc0af8cce2680880419cd64982b1d good
>>>>> 14705fda8f6273501930dfe1d679ad4bec209f52 good
>>>>> 5c93e8ecd5bd3bfdee013b6da0850357eb6ca4d8 good
>>>>> 8cb5a30372ef5cf2b1d258fce1711d80f834740a bad
>>>>> 077d0c2c78df6f7260cdd015a991327efa44d8ad bad
>>>>> cc5095747edfb054ca2068d01af20be3fcc3634f good
>>>>> 27b38686a3bb601db48901dbc4e2fc5d77ffa2c1 good
>>>>>
>>>>> commit 077d0c2c78df6f7260cdd015a991327efa44d8ad
>>>>> Author: Ojaswin Mujoo <ojaswin@linux.ibm.com>
>>>>> Date:   Tue Mar 8 15:22:01 2022 +0530
>>>>>
>>>>> ext4: make mb_optimize_scan performance mount option work with extents
>>>>>
>>>>> If i revert this commit with Linux 5.19-rc6 the performance regression
>>>>> disappears.
>>>>>
>>>>> Please ask if you need more information.
>>>> Hi Stefan,
>>>>
>>>> Apologies, I had missed this email initially. So this particular patch
>>>> simply changed a typo in an if condition which was preventing the
>>>> mb_optimize_scan option to be enabled correctly (This feature was
>>>> introduced in the following commit [1]). I think with the
>>>> mb_optimize_scan now working, it is somehow causing the firmware
>>>> download/update to take a longer time.
>>>>
>>>> I'll try to investigate this and get back with my findings.
>>> thanks. I wasn't able to reproduce this heavy load symptoms with
>>> every SD
>>> card. Maybe this depends on the write performance of the SD card to
>>> trigger
>>> the situation (used command to measure write performance: dd
>>> if=/dev/zero
>>> of=/boot/test bs=1M count=30 oflag=dsync,direct ).
>>>
>>> I tested a Kingston consumer 32 GB which had nearly constant write
>>> performance of 13 MB/s and didn't had the heavy load symptoms. The
>>> firmware
>>> update was done in a few seconds, so hard to say that at least the
>>> performance regression is reproducible.
>>>
>>> I also tested 2x Kingston industrial 16 GB which had a floating write
>>> performance between 5 and 10 MB/s (wear leveling?) and both had the
>>> heavy
>>> load symptoms.
>>>
>>> All SD cards has been detected as ultra high speed DDR50 by the emmc2
>>> interface.
>>>
>>> Best regards
>>>
>>>> Regard,
>>>> Ojaswin
>>>>
>>>> [1]
>>>>     commit 196e402adf2e4cd66f101923409f1970ec5f1af3
>>>>     From: Harshad Shirwadkar <harshadshirwadkar@gmail.com>
>>>>     Date: Thu, 1 Apr 2021 10:21:27 -0700
>>>>     
>>>>     ext4: improve cr 0 / cr 1 group scanning
>>>>
>>>>> Regards
>>>>>
>> Thanks for the info Stefan, I'm still trying to reproduce the issue but
>> it's slightly challenging since I don't have my RPi handy at the moment.
>>
>> In the meantime, would you please try out the mb_optmize_scan=0 command
>> line options to see if that helps bypass the issue. This will help
>> confirm if the issue lies in mb_optmize_scan itself or if its something
>> else.
>>
> I run the firmware update 5 times with mb_optimize_scan=0 on my
> Raspberry Pi 4 and the industrial SD card and everytime the update worked.
>>

[CCing Jan]

FYI, Jan yesterday reported benchmark regresses that might or might not
be related Stefan's regression on the Raspberry Pi:
https://lore.kernel.org/all/20220727105123.ckwrhbilzrxqpt24@quack3/

Ciao, Thorsten (wearing his 'the Linux kernel's regression tracker' hat)

P.S.: As the Linux kernel's regression tracker I deal with a lot of
reports and sometimes miss something important when writing mails like
this. If that's the case here, don't hesitate to tell me in a public
reply, it's in everyone's interest to set the public record straight.

#regzbot monitor
https://lore.kernel.org/all/20220727105123.ckwrhbilzrxqpt24@quack3/

Re: [Regression] ext4: changes to mb_optimize_scan cause issues on Raspberry Pi

[Jan Kara]

Hello!

On Mon 18-07-22 15:29:47, Stefan Wahren wrote:
> i noticed that since Linux 5.18 (Linux 5.19-rc6 is still affected) i'm
> unable to run "rpi-update" without massive performance regression on my
> Raspberry Pi 4 (multi_v7_defconfig + CONFIG_ARM_LPAE). Using Linux 5.17 this
> tool successfully downloads the latest firmware (> 100 MB) on my development
> micro SD card (Kingston 16 GB Industrial) with a ext4 filesystem within ~ 1
> min. The same scenario on Linux 5.18 shows the following symptoms:

Thanks for report and the bisection!
 
> - download takes endlessly much time and leads to an abort by userspace in
> most cases because of the poor performance
> - massive system load during download even after download has been aborted
> (heartbeat LED goes wild)

OK, is it that the CPU is busy or are we waiting on the storage card?
Observing top(1) for a while should be enough to get the idea.  (sorry, I'm
not very familiar with RPi so I'm not sure what heartbeat LED shows).

> - whole system becomes nearly unresponsive
> - system load goes back to normal after > 10 min

So what likely happens is that the downloaded data is in the pagecache and
what is causing the stuckage is that we are writing it back to the SD card
that somehow is much less efficient with mb_optimize_scan=1 for your setup.
Even if you stop the download, we still have dirty data in the page cache
which we need to write out so that is the reason why the system takes so
long to return back to normal.

> - dmesg doesn't show anything suspicious
> 
> I was able to bisect this issue:
> 
> ff042f4a9b050895a42cae893cc01fa2ca81b95c good
> 4b0986a3613c92f4ec1bdc7f60ec66fea135991f bad
> 25fd2d41b505d0640bdfe67aa77c549de2d3c18a bad
> b4bc93bd76d4da32600795cd323c971f00a2e788 bad
> 3fe2f7446f1e029b220f7f650df6d138f91651f2 bad
> b080cee72ef355669cbc52ff55dc513d37433600 good
> ad9c6ee642a61adae93dfa35582b5af16dc5173a good
> 9b03992f0c88baef524842e411fbdc147780dd5d bad
> aab4ed5816acc0af8cce2680880419cd64982b1d good
> 14705fda8f6273501930dfe1d679ad4bec209f52 good
> 5c93e8ecd5bd3bfdee013b6da0850357eb6ca4d8 good
> 8cb5a30372ef5cf2b1d258fce1711d80f834740a bad
> 077d0c2c78df6f7260cdd015a991327efa44d8ad bad
> cc5095747edfb054ca2068d01af20be3fcc3634f good
> 27b38686a3bb601db48901dbc4e2fc5d77ffa2c1 good
> 
> commit 077d0c2c78df6f7260cdd015a991327efa44d8ad
> Author: Ojaswin Mujoo <ojaswin@linux.ibm.com>
> Date:   Tue Mar 8 15:22:01 2022 +0530
> 
> ext4: make mb_optimize_scan performance mount option work with extents
> 
> If i revert this commit with Linux 5.19-rc6 the performance regression
> disappears.
> 
> Please ask if you need more information.

Can you run "iostat -x 1" while the download is running so that we can see
roughly how the IO pattern looks?

Also can get filesystem metadata image of your card like:
  e2image -r <fs-device> - | gzip >/tmp/ext4-image.gz

and put it somewhere for download? The image will contain only fs metadata,
not data so it should be relatively small and we won't have access to your
secrets ;). With the image we'd be able to see how the free space looks
like and whether it perhaps does not trigger some pathological behavior.

My current suspicion is that because the new allocator strategy spreads
allocations over more block groups, we end up with more open erase blocks
on the SD card which forces the firmware to do more garbage collection and
RMW of erase blocks and write performance tanks...

Thanks.
								Honza

-- 
Jan Kara <jack@suse.com>
SUSE Labs, CR

Re: [Regression] ext4: changes to mb_optimize_scan cause issues on Raspberry Pi

[Stefan Wahren]

Hi Jan,

Am 28.07.22 um 12:00 schrieb Jan Kara:
> Hello!
> Can you run "iostat -x 1" while the download is running so that we can see
> roughly how the IO pattern looks?
>
> Also can get filesystem metadata image of your card like:
>    e2image -r <fs-device> - | gzip >/tmp/ext4-image.gz
>
> and put it somewhere for download? The image will contain only fs metadata,
> not data so it should be relatively small and we won't have access to your
> secrets ;). With the image we'd be able to see how the free space looks
> like and whether it perhaps does not trigger some pathological behavior.
>
> My current suspicion is that because the new allocator strategy spreads
> allocations over more block groups, we end up with more open erase blocks
> on the SD card which forces the firmware to do more garbage collection and
> RMW of erase blocks and write performance tanks...
>
> Thanks.
thanks for your feedback. Unfortunately i'm busy the next days, so it 
will take some time to provide this.
> 								Honza
>

Re: [Regression] ext4: changes to mb_optimize_scan cause issues on Raspberry Pi

[Stefan Wahren]

Hi Jan,

Am 28.07.22 um 12:00 schrieb Jan Kara:
>
> Also can get filesystem metadata image of your card like:
>    e2image -r <fs-device> - | gzip >/tmp/ext4-image.gz
>
> and put it somewhere for download? The image will contain only fs metadata,
> not data so it should be relatively small and we won't have access to your
> secrets ;). With the image we'd be able to see how the free space looks
> like and whether it perhaps does not trigger some pathological behavior.
i've problems with this. If i try store uncompressed the metadata of the 
second SD card partition (/dev/sdb2 = rootfs) the generated image file 
is nearly big as the whole partition. In compressed state it's 25 MB. Is 
this expected?

Re: [Regression] ext4: changes to mb_optimize_scan cause issues on Raspberry Pi

[Stefan Wahren]

Hi,

Am 31.07.22 um 22:42 schrieb Stefan Wahren:
> Hi Jan,
>
> Am 28.07.22 um 12:00 schrieb Jan Kara:
>>
>> Also can get filesystem metadata image of your card like:
>>    e2image -r <fs-device> - | gzip >/tmp/ext4-image.gz
>>
>> and put it somewhere for download? The image will contain only fs 
>> metadata,
>> not data so it should be relatively small and we won't have access to 
>> your
>> secrets ;). With the image we'd be able to see how the free space looks
>> like and whether it perhaps does not trigger some pathological behavior.
> i've problems with this. If i try store uncompressed the metadata of 
> the second SD card partition (/dev/sdb2 = rootfs) the generated image 
> file is nearly big as the whole partition. In compressed state it's 25 
> MB. Is this expected?

This performance regression is also reproducible with 5.19 kernel 
(arm64, defconfig) and 64-bit Raspberry Pi OS. Unfortunately the problem 
with metadata generation is the same, the generated uncompressed file is 
15 GB.

Re: [Regression] ext4: changes to mb_optimize_scan cause issues on Raspberry Pi

[Stefan Wahren]

Hi,

Am 06.08.22 um 17:23 schrieb Stefan Wahren:
> Hi,
>
> Am 31.07.22 um 22:42 schrieb Stefan Wahren:
>> Hi Jan,
>>
>> Am 28.07.22 um 12:00 schrieb Jan Kara:
>>>
>>> Also can get filesystem metadata image of your card like:
>>>    e2image -r <fs-device> - | gzip >/tmp/ext4-image.gz
>>>
>>> and put it somewhere for download? The image will contain only fs 
>>> metadata,
>>> not data so it should be relatively small and we won't have access 
>>> to your
>>> secrets ;). With the image we'd be able to see how the free space looks
>>> like and whether it perhaps does not trigger some pathological 
>>> behavior.
>> i've problems with this. If i try store uncompressed the metadata of 
>> the second SD card partition (/dev/sdb2 = rootfs) the generated image 
>> file is nearly big as the whole partition. In compressed state it's 
>> 25 MB. Is this expected?
>
> This performance regression is also reproducible with 5.19 kernel 
> (arm64, defconfig) and 64-bit Raspberry Pi OS. Unfortunately the 
> problem with metadata generation is the same, the generated 
> uncompressed file is 15 GB.
>
recently i upgraded my build machine (Intel Core i7-1260P) which now 
runs Ubuntu 22.04 including a recent 5.15 kernel. On my build machine if 
i try to install my build kernel modules on the mentioned Industrial 
Kingston SD card 16 GB (SDCIT) and call "sync" immediately, the process 
will takes very long with recent LTS kernel (~ 5 minutes) and trigger a 
hung task warning:

[ 1692.880208] INFO: task sync:22272 blocked for more than 120 seconds.
[ 1692.880222]       Not tainted 5.15.0-46-generic #49-Ubuntu
[ 1692.880225] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" 
disables this message.
[ 1692.880228] task:sync            state:D stack:    0 pid:22272 ppid:  
5238 flags:0x00004002
[ 1692.880237] Call Trace:
[ 1692.880240]  <TASK>
[ 1692.880246]  __schedule+0x23d/0x590
[ 1692.880257]  schedule+0x4e/0xc0
[ 1692.880261]  wb_wait_for_completion+0x59/0x90
[ 1692.880269]  ? wait_woken+0x70/0x70
[ 1692.880275]  sync_inodes_sb+0xbe/0x100
[ 1692.880282]  sync_inodes_one_sb+0x19/0x20
[ 1692.880288]  iterate_supers+0xab/0x110
[ 1692.880294]  ? __x64_sys_tee+0xe0/0xe0
[ 1692.880300]  ksys_sync+0x42/0xa0
[ 1692.880304]  __do_sys_sync+0xe/0x20
[ 1692.880307]  do_syscall_64+0x59/0xc0
[ 1692.880312]  ? do_user_addr_fault+0x1e7/0x670
[ 1692.880319]  ? syscall_exit_to_user_mode+0x27/0x50
[ 1692.880324]  ? exit_to_user_mode_prepare+0x37/0xb0
[ 1692.880331]  ? irqentry_exit_to_user_mode+0x9/0x20
[ 1692.880336]  ? irqentry_exit+0x1d/0x30
[ 1692.880340]  ? exc_page_fault+0x89/0x170
[ 1692.880345]  entry_SYSCALL_64_after_hwframe+0x61/0xcb
[ 1692.880353] RIP: 0033:0x7fcbda436abb
[ 1692.880358] RSP: 002b:00007ffc94923968 EFLAGS: 00000246 ORIG_RAX: 
00000000000000a2
[ 1692.880363] RAX: ffffffffffffffda RBX: 00007ffc94923b48 RCX: 
00007fcbda436abb
[ 1692.880366] RDX: 00007fcbda53c101 RSI: 00007ffc94923b48 RDI: 
00007fcbda4f4e29
[ 1692.880369] RBP: 0000000000000001 R08: 0000000000000001 R09: 
0000000000000000
[ 1692.880371] R10: 000055ca76fb4340 R11: 0000000000000246 R12: 
000055ca752c3bc0
[ 1692.880373] R13: 000055ca752c119f R14: 00007fcbda53442c R15: 
000055ca752c1034
[ 1692.880379]  </TASK>

Interestingly if i switch to the older ubuntu kernel version 5.15.25 
(which shouldn't have "ext4: make mb_optimize_scan performance mount 
option work with extents" applied) the write process is much faster (~ 1 
minute) and i never saw the hung task.

Btw i setup a repo [1] to collect information about this issue. The 
first file adds a kernel log in regression case. The kernel was 5.19-rc6 
with multi_v7_defconfig and ARM_LPAE & EXT4_DEBUG enabled.

rpi-update was started before (backup & clean). The actual download 
started at 11:11:29 and is aborted at 11:14:18.

HTH

[1] - https://github.com/lategoodbye/mb_optimize_scan_regress
[2] - 
https://github.com/lategoodbye/mb_optimize_scan_regress/commit/6ff14dd4026d8607290b2727f5a2c3522567fb21

Re: [Regression] ext4: changes to mb_optimize_scan cause issues on Raspberry Pi

[Jan Kara]

Hi Stefan,

Back from vacation...

On Sun 31-07-22 22:42:56, Stefan Wahren wrote:
> Hi Jan,
> 
> Am 28.07.22 um 12:00 schrieb Jan Kara:
> > 
> > Also can get filesystem metadata image of your card like:
> >    e2image -r <fs-device> - | gzip >/tmp/ext4-image.gz
> > 
> > and put it somewhere for download? The image will contain only fs metadata,
> > not data so it should be relatively small and we won't have access to your
> > secrets ;). With the image we'd be able to see how the free space looks
> > like and whether it perhaps does not trigger some pathological behavior.
> i've problems with this. If i try store uncompressed the metadata of the
> second SD card partition (/dev/sdb2 = rootfs) the generated image file is
> nearly big as the whole partition. In compressed state it's 25 MB. Is this
> expected?

Yes, that is expected. The resulting file is a sparse file that contains
only metadata blocks that is the reason why it compresses so well but looks
big.

								Honza

-- 
Jan Kara <jack@suse.com>
SUSE Labs, CR

Re: [Regression] ext4: changes to mb_optimize_scan cause issues on Raspberry Pi

[Stefan Wahren]

Hi Jan,

Am 15.08.22 um 12:34 schrieb Jan Kara:
> Hi Stefan,
>
> Back from vacation...
>
> On Sun 31-07-22 22:42:56, Stefan Wahren wrote:
>> Hi Jan,
>>
>> Am 28.07.22 um 12:00 schrieb Jan Kara:
>>> Also can get filesystem metadata image of your card like:
>>>     e2image -r <fs-device> - | gzip >/tmp/ext4-image.gz
>>>
>>> and put it somewhere for download? The image will contain only fs metadata,
>>> not data so it should be relatively small and we won't have access to your
>>> secrets ;). With the image we'd be able to see how the free space looks
>>> like and whether it perhaps does not trigger some pathological behavior.
>> i've problems with this. If i try store uncompressed the metadata of the
>> second SD card partition (/dev/sdb2 = rootfs) the generated image file is
>> nearly big as the whole partition. In compressed state it's 25 MB. Is this
>> expected?
> Yes, that is expected. The resulting file is a sparse file that contains
> only metadata blocks that is the reason why it compresses so well but looks
> big.

i've added here:

https://github.com/lategoodbye/mb_optimize_scan_regress/blob/main/Kingston_SDCIT_rootfs_metadata.gz

>
> 								Honza
>

Re: [Regression] ext4: changes to mb_optimize_scan cause issues on Raspberry Pi

[Stefan Wahren]

Hi Jan,

+add Florian

Am 28.07.22 um 12:00 schrieb Jan Kara:
> Hello!
>
> On Mon 18-07-22 15:29:47, Stefan Wahren wrote:
>> i noticed that since Linux 5.18 (Linux 5.19-rc6 is still affected) i'm
>> unable to run "rpi-update" without massive performance regression on my
>> Raspberry Pi 4 (multi_v7_defconfig + CONFIG_ARM_LPAE). Using Linux 5.17 this
>> tool successfully downloads the latest firmware (> 100 MB) on my development
>> micro SD card (Kingston 16 GB Industrial) with a ext4 filesystem within ~ 1
>> min. The same scenario on Linux 5.18 shows the following symptoms:
> Thanks for report and the bisection!
>   
>> - download takes endlessly much time and leads to an abort by userspace in
>> most cases because of the poor performance
>> - massive system load during download even after download has been aborted
>> (heartbeat LED goes wild)
> OK, is it that the CPU is busy or are we waiting on the storage card?
> Observing top(1) for a while should be enough to get the idea.  (sorry, I'm
> not very familiar with RPi so I'm not sure what heartbeat LED shows).

My description wasn't precise. I mean the green ACT LED, which uses the 
LED heartbeat trigger:

"This allows LEDs to be controlled by a CPU load average. The flash 
frequency is a hyperbolic function of the 1-minute load average."

I'm not sure if it's CPU or IO driven load, here the top output in bad case:

top - 08:44:17 up 43 min,  2 users,  load average: 5,02, 5,45, 5,17
Tasks: 142 total,   1 running, 141 sleeping,   0 stopped,   0 zombie
%Cpu(s):  0,4 us,  0,4 sy,  0,0 ni, 49,0 id, 50,2 wa,  0,0 hi, 0,0 si,  
0,0 st
MiB Mem :   7941,7 total,   4563,1 free,    312,7 used,   3066,0 buff/cache
MiB Swap:    100,0 total,    100,0 free,      0,0 used.   7359,6 avail Mem

   PID USER      PR  NI    VIRT    RES    SHR S  %CPU  %MEM TIME+ COMMAND
   879 pi        20   0  237712  50880  38824 S   1,6   0,6 0:07.69 
lxterminal
   539 root      20   0  203424  46356  25228 S   1,3   0,6 0:08.66 Xorg
  1046 pi        20   0   10296   2936   2556 R   1,3   0,0 0:03.13 top
   680 pi        20   0   83820  22172  17648 S   0,7   0,3 0:01.22 pcmanfm
    11 root      20   0       0      0      0 I   0,3   0,0 0:01.13 
rcu_sched
   234 root       0 -20       0      0      0 I   0,3   0,0 0:00.20 
kworker/u+
     1 root      20   0   33200   8580   6468 S   0,0   0,1 0:14.17 systemd
     2 root      20   0       0      0      0 S   0,0   0,0 0:00.02 
kthreadd
     3 root       0 -20       0      0      0 I   0,0   0,0 0:00.00 rcu_gp
     4 root       0 -20       0      0      0 I   0,0   0,0 0:00.00 
rcu_par_gp
     8 root       0 -20       0      0      0 I   0,0   0,0 0:00.00 
mm_percpu+
     9 root      20   0       0      0      0 I   0,0   0,0 0:00.00 
rcu_tasks+
    10 root      20   0       0      0      0 S   0,0   0,0 0:03.77 
ksoftirqd+
    12 root      rt   0       0      0      0 S   0,0   0,0 0:00.01 
migration+
    14 root      20   0       0      0      0 S   0,0   0,0 0:00.00 cpuhp/0
    15 root      20   0       0      0      0 S   0,0   0,0 0:00.00 cpuhp/1
    16 root      rt   0       0      0      0 S   0,0   0,0 0:00.01 
migration+

>
>> - whole system becomes nearly unresponsive
>> - system load goes back to normal after > 10 min
> So what likely happens is that the downloaded data is in the pagecache and
> what is causing the stuckage is that we are writing it back to the SD card
> that somehow is much less efficient with mb_optimize_scan=1 for your setup.
> Even if you stop the download, we still have dirty data in the page cache
> which we need to write out so that is the reason why the system takes so
> long to return back to normal.
>
>> - dmesg doesn't show anything suspicious
>>
>> I was able to bisect this issue:
>>
>> ff042f4a9b050895a42cae893cc01fa2ca81b95c good
>> 4b0986a3613c92f4ec1bdc7f60ec66fea135991f bad
>> 25fd2d41b505d0640bdfe67aa77c549de2d3c18a bad
>> b4bc93bd76d4da32600795cd323c971f00a2e788 bad
>> 3fe2f7446f1e029b220f7f650df6d138f91651f2 bad
>> b080cee72ef355669cbc52ff55dc513d37433600 good
>> ad9c6ee642a61adae93dfa35582b5af16dc5173a good
>> 9b03992f0c88baef524842e411fbdc147780dd5d bad
>> aab4ed5816acc0af8cce2680880419cd64982b1d good
>> 14705fda8f6273501930dfe1d679ad4bec209f52 good
>> 5c93e8ecd5bd3bfdee013b6da0850357eb6ca4d8 good
>> 8cb5a30372ef5cf2b1d258fce1711d80f834740a bad
>> 077d0c2c78df6f7260cdd015a991327efa44d8ad bad
>> cc5095747edfb054ca2068d01af20be3fcc3634f good
>> 27b38686a3bb601db48901dbc4e2fc5d77ffa2c1 good
>>
>> commit 077d0c2c78df6f7260cdd015a991327efa44d8ad
>> Author: Ojaswin Mujoo <ojaswin@linux.ibm.com>
>> Date:   Tue Mar 8 15:22:01 2022 +0530
>>
>> ext4: make mb_optimize_scan performance mount option work with extents
>>
>> If i revert this commit with Linux 5.19-rc6 the performance regression
>> disappears.
>>
>> Please ask if you need more information.
> Can you run "iostat -x 1" while the download is running so that we can see
> roughly how the IO pattern looks?
>
Here the output during download:

Device            r/s     w/s     rkB/s     wkB/s   rrqm/s wrqm/s  
%rrqm  %wrqm r_await w_await aqu-sz rareq-sz wareq-sz svctm  %util
mmcblk1          0,00    2,00      0,00     36,00     0,00 0,00   0,00   
0,00    0,00 23189,50  46,38     0,00    18,00 500,00 100,00

avg-cpu:  %user   %nice %system %iowait  %steal   %idle
            0,25    0,00    0,00   49,62    0,00   50,13

Device            r/s     w/s     rkB/s     wkB/s   rrqm/s wrqm/s  
%rrqm  %wrqm r_await w_await aqu-sz rareq-sz wareq-sz svctm  %util
mmcblk1          0,00    2,00      0,00     76,00     0,00 0,00   0,00   
0,00    0,00 46208,50  92,42     0,00    38,00 500,00 100,00

avg-cpu:  %user   %nice %system %iowait  %steal   %idle
            0,25    0,00    0,00   49,62    0,00   50,13

Device            r/s     w/s     rkB/s     wkB/s   rrqm/s wrqm/s  
%rrqm  %wrqm r_await w_await aqu-sz rareq-sz wareq-sz svctm  %util
mmcblk1          0,00    3,00      0,00     76,00     0,00 0,00   0,00   
0,00    0,00 48521,67 145,56     0,00    25,33 333,33 100,00

avg-cpu:  %user   %nice %system %iowait  %steal   %idle
            0,25    0,00    0,00   49,62    0,00   50,13

Device            r/s     w/s     rkB/s     wkB/s   rrqm/s wrqm/s  
%rrqm  %wrqm r_await w_await aqu-sz rareq-sz wareq-sz svctm  %util
mmcblk1          0,00    1,00      0,00     32,00     0,00 0,00   0,00   
0,00    0,00 57416,00  57,42     0,00    32,00 1000,00 100,00

avg-cpu:  %user   %nice %system %iowait  %steal   %idle
            0,25    0,00    0,00   49,75    0,00   50,00

Device            r/s     w/s     rkB/s     wkB/s   rrqm/s wrqm/s  
%rrqm  %wrqm r_await w_await aqu-sz rareq-sz wareq-sz svctm  %util
mmcblk1          0,00    3,00      0,00    112,00     0,00 0,00   0,00   
0,00    0,00 49107,67 147,32     0,00    37,33 333,33 100,00

avg-cpu:  %user   %nice %system %iowait  %steal   %idle
            0,25    0,00    0,00   49,62    0,00   50,13

Device            r/s     w/s     rkB/s     wkB/s   rrqm/s wrqm/s  
%rrqm  %wrqm r_await w_await aqu-sz rareq-sz wareq-sz svctm  %util
mmcblk1          0,00    1,00      0,00     12,00     0,00 0,00   0,00   
0,00    0,00 59402,00  59,40     0,00    12,00 1000,00 100,00

avg-cpu:  %user   %nice %system %iowait  %steal   %idle
            0,25    0,00    0,00   49,62    0,00   50,13

Device            r/s     w/s     rkB/s     wkB/s   rrqm/s wrqm/s  
%rrqm  %wrqm r_await w_await aqu-sz rareq-sz wareq-sz svctm  %util
mmcblk1          0,00    3,00      0,00    148,00     0,00 0,00   0,00   
0,00    0,00 51140,33 153,42     0,00    49,33 333,33 100,00

avg-cpu:  %user   %nice %system %iowait  %steal   %idle
            0,25    0,00    0,00   49,62    0,00   50,13

Device            r/s     w/s     rkB/s     wkB/s   rrqm/s wrqm/s  
%rrqm  %wrqm r_await w_await aqu-sz rareq-sz wareq-sz svctm  %util
mmcblk1          0,00    3,00      0,00     68,00     0,00 0,00   0,00   
0,00    0,00 53751,00 161,25     0,00    22,67 333,33 100,00

avg-cpu:  %user   %nice %system %iowait  %steal   %idle
            0,25    0,00    0,00   49,62    0,00   50,13

Device            r/s     w/s     rkB/s     wkB/s   rrqm/s wrqm/s  
%rrqm  %wrqm r_await w_await aqu-sz rareq-sz wareq-sz svctm  %util
mmcblk1          0,00    2,00      0,00     32,00     0,00 0,00   0,00   
0,00    0,00 53363,50 106,73     0,00    16,00 500,00 100,00

avg-cpu:  %user   %nice %system %iowait  %steal   %idle
            0,25    0,00    0,00   49,62    0,00   50,13

Device            r/s     w/s     rkB/s     wkB/s   rrqm/s wrqm/s  
%rrqm  %wrqm r_await w_await aqu-sz rareq-sz wareq-sz svctm  %util
mmcblk1          0,00    2,00      0,00     24,00     0,00 0,00   0,00   
0,00    0,00 39266,00  78,53     0,00    12,00 500,00 100,00

avg-cpu:  %user   %nice %system %iowait  %steal   %idle
            0,25    0,00    0,00   49,75    0,00   50,00

Device            r/s     w/s     rkB/s     wkB/s   rrqm/s wrqm/s  
%rrqm  %wrqm r_await w_await aqu-sz rareq-sz wareq-sz svctm  %util
mmcblk1          0,00    2,00      0,00     80,00     0,00 0,00   0,00   
0,00    0,00 40135,00  80,27     0,00    40,00 500,00 100,00

avg-cpu:  %user   %nice %system %iowait  %steal   %idle
            0,25    0,00    0,00   49,62    0,00   50,13

Device            r/s     w/s     rkB/s     wkB/s   rrqm/s wrqm/s  
%rrqm  %wrqm r_await w_await aqu-sz rareq-sz wareq-sz svctm  %util
mmcblk1          0,00    5,00      0,00    184,00     0,00 0,00   0,00   
0,00    0,00 51459,80 257,30     0,00    36,80 200,00 100,00

avg-cpu:  %user   %nice %system %iowait  %steal   %idle
            0,25    0,00    0,00   49,62    0,00   50,13

Device            r/s     w/s     rkB/s     wkB/s   rrqm/s wrqm/s  
%rrqm  %wrqm r_await w_await aqu-sz rareq-sz wareq-sz svctm  %util
mmcblk1          0,00    2,00      0,00     56,00     0,00 0,00   0,00   
0,00    0,00 52412,50 104,83     0,00    28,00 500,00 100,00

avg-cpu:  %user   %nice %system %iowait  %steal   %idle
            0,25    0,00    0,00   49,62    0,00   50,13

Device            r/s     w/s     rkB/s     wkB/s   rrqm/s wrqm/s  
%rrqm  %wrqm r_await w_await aqu-sz rareq-sz wareq-sz svctm  %util
mmcblk1          0,00    3,00      0,00     80,00     0,00 0,00   0,00   
0,00    0,00 56386,00 169,16     0,00    26,67 333,33 100,00

avg-cpu:  %user   %nice %system %iowait  %steal   %idle
            0,25    0,00    0,00   49,62    0,00   50,13

Device            r/s     w/s     rkB/s     wkB/s   rrqm/s wrqm/s  
%rrqm  %wrqm r_await w_await aqu-sz rareq-sz wareq-sz svctm  %util
mmcblk1          0,00    5,00      0,00     84,00     0,00 0,00   0,00   
0,00    0,00 53314,20 266,57     0,00    16,80 200,00 100,00

avg-cpu:  %user   %nice %system %iowait  %steal   %idle
            0,50    0,00    0,00   49,50    0,00   50,00

Device            r/s     w/s     rkB/s     wkB/s   rrqm/s wrqm/s  
%rrqm  %wrqm r_await w_await aqu-sz rareq-sz wareq-sz svctm  %util
mmcblk1          0,00    4,00      0,00     76,00     0,00 0,00   0,00   
0,00    0,00 58021,00 232,08     0,00    19,00 250,00 100,00

avg-cpu:  %user   %nice %system %iowait  %steal   %idle
            0,25    0,00    0,25   49,50    0,00   50,00

Device            r/s     w/s     rkB/s     wkB/s   rrqm/s wrqm/s  
%rrqm  %wrqm r_await w_await aqu-sz rareq-sz wareq-sz svctm  %util
mmcblk1          0,00    4,00      0,00     72,00     0,00 0,00   0,00   
0,00    0,00 62048,50 248,19     0,00    18,00 250,00 100,00

avg-cpu:  %user   %nice %system %iowait  %steal   %idle
            0,25    0,00    0,00   49,62    0,00   50,13

Device            r/s     w/s     rkB/s     wkB/s   rrqm/s wrqm/s  
%rrqm  %wrqm r_await w_await aqu-sz rareq-sz wareq-sz svctm  %util
mmcblk1          0,00    2,00      0,00    116,00     0,00 0,00   0,00   
0,00    0,00 69769,00 139,54     0,00    58,00 500,00 100,00

avg-cpu:  %user   %nice %system %iowait  %steal   %idle
            6,47    0,00    2,49   59,20    0,00   31,84

Device            r/s     w/s     rkB/s     wkB/s   rrqm/s wrqm/s  
%rrqm  %wrqm r_await w_await aqu-sz rareq-sz wareq-sz svctm  %util
mmcblk1          1,00    4,00    132,00    624,00    32,00 243,00  
96,97  98,38  530,00 30246,50 121,52   132,00   156,00 178,00  89,00

avg-cpu:  %user   %nice %system %iowait  %steal   %idle
            0,00    0,00    0,00   49,87    0,00   50,13

Device            r/s     w/s     rkB/s     wkB/s   rrqm/s wrqm/s  
%rrqm  %wrqm r_await w_await aqu-sz rareq-sz wareq-sz svctm  %util
mmcblk1          0,00    2,00      0,00    296,00     0,00 0,00   0,00   
0,00    0,00 1358,50   2,72     0,00   148,00 500,00 100,00

avg-cpu:  %user   %nice %system %iowait  %steal   %idle
            0,25    0,00    0,00   49,75    0,00   50,00

Device            r/s     w/s     rkB/s     wkB/s   rrqm/s wrqm/s  
%rrqm  %wrqm r_await w_await aqu-sz rareq-sz wareq-sz svctm  %util
mmcblk1          0,00    3,00      0,00    124,00     0,00 1,00   0,00  
25,00    0,00 2043,67   6,13     0,00    41,33 333,33 100,00

avg-cpu:  %user   %nice %system %iowait  %steal   %idle
            0,25    0,00    0,25   49,37    0,00   50,13

Device            r/s     w/s     rkB/s     wkB/s   rrqm/s wrqm/s  
%rrqm  %wrqm r_await w_await aqu-sz rareq-sz wareq-sz svctm  %util
mmcblk1          0,00    6,00      0,00    412,00     0,00 0,00   0,00   
0,00    0,00 3315,17  19,89     0,00    68,67 166,67 100,00

avg-cpu:  %user   %nice %system %iowait  %steal   %idle
            0,51    0,00    0,00   48,47    0,00   51,02

Device            r/s     w/s     rkB/s     wkB/s   rrqm/s wrqm/s  
%rrqm  %wrqm r_await w_await aqu-sz rareq-sz wareq-sz svctm  %util
mmcblk1          0,00    1,00      0,00     56,00     0,00 0,00   0,00   
0,00    0,00 4249,00   4,25     0,00    56,00 1000,00 100,00

avg-cpu:  %user   %nice %system %iowait  %steal   %idle
            0,50    0,00    0,75   48,87    0,00   49,87

Device            r/s     w/s     rkB/s     wkB/s   rrqm/s wrqm/s  
%rrqm  %wrqm r_await w_await aqu-sz rareq-sz wareq-sz svctm  %util
mmcblk1          0,00    2,00      0,00    248,00     0,00 0,00   0,00   
0,00    0,00 5190,50  10,38     0,00   124,00 500,00 100,00

avg-cpu:  %user   %nice %system %iowait  %steal   %idle
            0,75    0,00    0,00   49,38    0,00   49,88

Device            r/s     w/s     rkB/s     wkB/s   rrqm/s wrqm/s  
%rrqm  %wrqm r_await w_await aqu-sz rareq-sz wareq-sz svctm  %util
mmcblk1          0,00    1,00      0,00     24,00     0,00 0,00   0,00   
0,00    0,00 6017,00   6,02     0,00    24,00 1000,00 100,00


Additionally i tried to compare the interrupt count between good and bad 
case. I booted the RPi 4, run rpi-update and dumped /proc/interrupts 
after 60 sec. In bad case the progress stuck somewhere in the half (not 
really deterministic) and in good it's finished or almost. Here is the diff:

--- intr_bad.log    2022-08-06 11:12:23.445661581 +0200
+++ intr_good.log    2022-08-06 11:27:32.104188861 +0200
@@ -1,19 +1,19 @@
             CPU0       CPU1       CPU2       CPU3
   25:          1          0          0          0     GICv2  99 
Level     timer
   26:          0          0          0          0     GICv2  29 
Level     arch_timer
- 27:       4551       3011       3326       2569     GICv2  30 
Level     arch_timer
+ 27:       4532       3367       3381       3439     GICv2  30 
Level     arch_timer
   35:          0          0          0          0     GICv2 175 
Level     PCIe PME
   36:        345          0          0          0     GICv2 112 
Level     DMA IRQ
   37:          0          0          0          0     GICv2 114 
Level     DMA IRQ
   43:         10          0          0          0     GICv2 125 
Level     ttyS1
   44:          0          0          0          0     GICv2 149 
Level     fe205000.i2c, fe804000.i2c
- 45:      34529          0          0          0     GICv2 158 
Level     mmc0, mmc1
- 46:        853          0          0          0     GICv2  65 
Level     fe00b880.mailbox
+ 45:      36427          0          0          0     GICv2 158 
Level     mmc0, mmc1
+ 46:        941          0          0          0     GICv2  65 
Level     fe00b880.mailbox
   47:       6864          0          0          0     GICv2 153 
Level     uart-pl011
   48:          0          0          0          0     GICv2 105 
Level     fe980000.usb, fe980000.usb
- 49:        925          0          0          0  BRCM STB PCIe MSI 
524288 Edge      xhci_hcd
- 50:      46821          0          0          0     GICv2 189 
Level     eth0
- 51:      15199          0          0          0     GICv2 190 
Level     eth0
+ 49:        836          0          0          0  BRCM STB PCIe MSI 
524288 Edge      xhci_hcd
+ 50:      86424          0          0          0     GICv2 189 
Level     eth0
+ 51:      23329          0          0          0     GICv2 190 
Level     eth0
   52:          0          0          0          0     GICv2 129 
Level     vc4 hvs
   53:          0          0          0          0 
interrupt-controller@7ef00100   4 Edge      vc4 hdmi hpd connected
   54:          0          0          0          0 
interrupt-controller@7ef00100   5 Edge      vc4 hdmi hpd disconnected
@@ -22,12 +22,12 @@
   57:          0          0          0          0     GICv2 107 
Level     fe004000.txp
   58:          0          0          0          0     GICv2 141 
Level     vc4 crtc
   59:          0          0          0          0     GICv2 142 
Level     vc4 crtc, vc4 crtc
- 60:         10          0          0          0     GICv2 133 
Level     vc4 crtc
+ 60:         11          0          0          0     GICv2 133 
Level     vc4 crtc
  IPI0:          0          0          0          0  CPU wakeup interrupts
  IPI1:          0          0          0          0  Timer broadcast 
interrupts
-IPI2:        216        252        218        269  Rescheduling interrupts
-IPI3:      16955      16920      16352      16607  Function call interrupts
+IPI2:        265        264        229        248  Rescheduling interrupts
+IPI3:       9865      37517      13414      24022  Function call interrupts
  IPI4:          0          0          0          0  CPU stop interrupts
-IPI5:        826        190        290        204  IRQ work interrupts
+IPI5:        532        245        238        210  IRQ work interrupts
  IPI6:          0          0          0          0  completion interrupts
  Err:          0

Re: [Regression] ext4: changes to mb_optimize_scan cause issues on Raspberry Pi

[Jan Kara]

Hi Stefan!

On Sat 06-08-22 11:50:28, Stefan Wahren wrote:
> Am 28.07.22 um 12:00 schrieb Jan Kara:
> > Hello!
> > 
> > On Mon 18-07-22 15:29:47, Stefan Wahren wrote:
> > > i noticed that since Linux 5.18 (Linux 5.19-rc6 is still affected) i'm
> > > unable to run "rpi-update" without massive performance regression on my
> > > Raspberry Pi 4 (multi_v7_defconfig + CONFIG_ARM_LPAE). Using Linux 5.17 this
> > > tool successfully downloads the latest firmware (> 100 MB) on my development
> > > micro SD card (Kingston 16 GB Industrial) with a ext4 filesystem within ~ 1
> > > min. The same scenario on Linux 5.18 shows the following symptoms:
> > Thanks for report and the bisection!
> > > - download takes endlessly much time and leads to an abort by userspace in
> > > most cases because of the poor performance
> > > - massive system load during download even after download has been aborted
> > > (heartbeat LED goes wild)
> > OK, is it that the CPU is busy or are we waiting on the storage card?
> > Observing top(1) for a while should be enough to get the idea.  (sorry, I'm
> > not very familiar with RPi so I'm not sure what heartbeat LED shows).
> 
> My description wasn't precise. I mean the green ACT LED, which uses the LED
> heartbeat trigger:
> 
> "This allows LEDs to be controlled by a CPU load average. The flash
> frequency is a hyperbolic function of the 1-minute load average."
> 
> I'm not sure if it's CPU or IO driven load, here the top output in bad case:
> 
> top - 08:44:17 up 43 min,  2 users,  load average: 5,02, 5,45, 5,17
> Tasks: 142 total,   1 running, 141 sleeping,   0 stopped,   0 zombie
> %Cpu(s):  0,4 us,  0,4 sy,  0,0 ni, 49,0 id, 50,2 wa,  0,0 hi, 0,0 si,  0,0
> st
> MiB Mem :   7941,7 total,   4563,1 free,    312,7 used,   3066,0 buff/cache
> MiB Swap:    100,0 total,    100,0 free,      0,0 used.   7359,6 avail Mem

OK, there's plenty of memory available, CPUs are mostly idle, the load is
likely created by tasks waiting for IO (which also contribute to load
despite not consuming CPU). Not much surprising here.

> > Can you run "iostat -x 1" while the download is running so that we can see
> > roughly how the IO pattern looks?
> > 
> Here the output during download:
> 
> Device            r/s     w/s     rkB/s     wkB/s   rrqm/s wrqm/s  %rrqm 
> %wrqm r_await w_await aqu-sz rareq-sz wareq-sz svctm  %util
> mmcblk1          0,00    2,00      0,00     36,00     0,00 0,00   0,00  
> 0,00    0,00 23189,50  46,38     0,00    18,00 500,00 100,00
> 
> avg-cpu:  %user   %nice %system %iowait  %steal   %idle
>            0,25    0,00    0,00   49,62    0,00   50,13
> 
> Device            r/s     w/s     rkB/s     wkB/s   rrqm/s wrqm/s  %rrqm 
> %wrqm r_await w_await aqu-sz rareq-sz wareq-sz svctm  %util
> mmcblk1          0,00    2,00      0,00     76,00     0,00 0,00   0,00  
> 0,00    0,00 46208,50  92,42     0,00    38,00 500,00 100,00
> 
> avg-cpu:  %user   %nice %system %iowait  %steal   %idle
>            0,25    0,00    0,00   49,62    0,00   50,13
> 
> Device            r/s     w/s     rkB/s     wkB/s   rrqm/s wrqm/s  %rrqm 
> %wrqm r_await w_await aqu-sz rareq-sz wareq-sz svctm  %util
> mmcblk1          0,00    3,00      0,00     76,00     0,00 0,00   0,00  
> 0,00    0,00 48521,67 145,56     0,00    25,33 333,33 100,00
> 
> avg-cpu:  %user   %nice %system %iowait  %steal   %idle
>            0,25    0,00    0,00   49,62    0,00   50,13

So this is interesting. We can see the card is 100% busy. The IO submitted
to the card is formed by small requests - 18-38 KB per request - and each
request takes 0.3-0.5s to complete. So the resulting throughput is horrible
- only tens of KB/s. Also we can see there are many IOs queued for the
device in parallel (aqu-sz columnt). This does not look like load I would
expect to be generated by download of a large file from the web.

You have mentioned in previous emails that with dd(1) you can do couple
MB/s writing to this card which is far more than these tens of KB/s. So the
file download must be doing something which really destroys the IO pattern
(and with mb_optimize_scan=0 ext4 happened to be better dealing with it and
generating better IO pattern). Can you perhaps strace the process doing the
download (or perhaps strace -f the whole rpi-update process) so that we can
see how does the load generated on the filesystem look like? Thanks!

								Honza
-- 
Jan Kara <jack@suse.com>
SUSE Labs, CR

Re: [Regression] ext4: changes to mb_optimize_scan cause issues on Raspberry Pi

[Stefan Wahren]

Hi Jan,

Am 16.08.22 um 11:34 schrieb Jan Kara:
> Hi Stefan!
>
> On Sat 06-08-22 11:50:28, Stefan Wahren wrote:
>> Am 28.07.22 um 12:00 schrieb Jan Kara:
>>> Hello!
>>>
>>> On Mon 18-07-22 15:29:47, Stefan Wahren wrote:
>>>> i noticed that since Linux 5.18 (Linux 5.19-rc6 is still affected) i'm
>>>> unable to run "rpi-update" without massive performance regression on my
>>>> Raspberry Pi 4 (multi_v7_defconfig + CONFIG_ARM_LPAE). Using Linux 5.17 this
>>>> tool successfully downloads the latest firmware (> 100 MB) on my development
>>>> micro SD card (Kingston 16 GB Industrial) with a ext4 filesystem within ~ 1
>>>> min. The same scenario on Linux 5.18 shows the following symptoms:
>>> Thanks for report and the bisection!
>>>> - download takes endlessly much time and leads to an abort by userspace in
>>>> most cases because of the poor performance
>>>> - massive system load during download even after download has been aborted
>>>> (heartbeat LED goes wild)
>>> OK, is it that the CPU is busy or are we waiting on the storage card?
>>> Observing top(1) for a while should be enough to get the idea.  (sorry, I'm
>>> not very familiar with RPi so I'm not sure what heartbeat LED shows).
>> My description wasn't precise. I mean the green ACT LED, which uses the LED
>> heartbeat trigger:
>>
>> "This allows LEDs to be controlled by a CPU load average. The flash
>> frequency is a hyperbolic function of the 1-minute load average."
>>
>> I'm not sure if it's CPU or IO driven load, here the top output in bad case:
>>
>> top - 08:44:17 up 43 min,  2 users,  load average: 5,02, 5,45, 5,17
>> Tasks: 142 total,   1 running, 141 sleeping,   0 stopped,   0 zombie
>> %Cpu(s):  0,4 us,  0,4 sy,  0,0 ni, 49,0 id, 50,2 wa,  0,0 hi, 0,0 si,  0,0
>> st
>> MiB Mem :   7941,7 total,   4563,1 free,    312,7 used,   3066,0 buff/cache
>> MiB Swap:    100,0 total,    100,0 free,      0,0 used.   7359,6 avail Mem
> OK, there's plenty of memory available, CPUs are mostly idle, the load is
> likely created by tasks waiting for IO (which also contribute to load
> despite not consuming CPU). Not much surprising here.
>
>>> Can you run "iostat -x 1" while the download is running so that we can see
>>> roughly how the IO pattern looks?
>>>
>> Here the output during download:
>>
>> Device            r/s     w/s     rkB/s     wkB/s   rrqm/s wrqm/s  %rrqm
>> %wrqm r_await w_await aqu-sz rareq-sz wareq-sz svctm  %util
>> mmcblk1          0,00    2,00      0,00     36,00     0,00 0,00   0,00
>> 0,00    0,00 23189,50  46,38     0,00    18,00 500,00 100,00
>>
>> avg-cpu:  %user   %nice %system %iowait  %steal   %idle
>>             0,25    0,00    0,00   49,62    0,00   50,13
>>
>> Device            r/s     w/s     rkB/s     wkB/s   rrqm/s wrqm/s  %rrqm
>> %wrqm r_await w_await aqu-sz rareq-sz wareq-sz svctm  %util
>> mmcblk1          0,00    2,00      0,00     76,00     0,00 0,00   0,00
>> 0,00    0,00 46208,50  92,42     0,00    38,00 500,00 100,00
>>
>> avg-cpu:  %user   %nice %system %iowait  %steal   %idle
>>             0,25    0,00    0,00   49,62    0,00   50,13
>>
>> Device            r/s     w/s     rkB/s     wkB/s   rrqm/s wrqm/s  %rrqm
>> %wrqm r_await w_await aqu-sz rareq-sz wareq-sz svctm  %util
>> mmcblk1          0,00    3,00      0,00     76,00     0,00 0,00   0,00
>> 0,00    0,00 48521,67 145,56     0,00    25,33 333,33 100,00
>>
>> avg-cpu:  %user   %nice %system %iowait  %steal   %idle
>>             0,25    0,00    0,00   49,62    0,00   50,13
> So this is interesting. We can see the card is 100% busy. The IO submitted
> to the card is formed by small requests - 18-38 KB per request - and each
> request takes 0.3-0.5s to complete. So the resulting throughput is horrible
> - only tens of KB/s. Also we can see there are many IOs queued for the
> device in parallel (aqu-sz columnt). This does not look like load I would
> expect to be generated by download of a large file from the web.
>
> You have mentioned in previous emails that with dd(1) you can do couple
> MB/s writing to this card which is far more than these tens of KB/s. So the
> file download must be doing something which really destroys the IO pattern
> (and with mb_optimize_scan=0 ext4 happened to be better dealing with it and
> generating better IO pattern). Can you perhaps strace the process doing the
> download (or perhaps strace -f the whole rpi-update process) so that we can
> see how does the load generated on the filesystem look like? Thanks!

i can do that. But may be the sources of rpi-update is more helpful?

https://github.com/raspberrypi/rpi-update/blob/master/rpi-update

>
> 								Honza

Re: [Regression] ext4: changes to mb_optimize_scan cause issues on Raspberry Pi

[Stefan Wahren]

Hi Jan,

Am 16.08.22 um 11:34 schrieb Jan Kara:
> Hi Stefan!
> So this is interesting. We can see the card is 100% busy. The IO submitted
> to the card is formed by small requests - 18-38 KB per request - and each
> request takes 0.3-0.5s to complete. So the resulting throughput is horrible
> - only tens of KB/s. Also we can see there are many IOs queued for the
> device in parallel (aqu-sz columnt). This does not look like load I would
> expect to be generated by download of a large file from the web.
>
> You have mentioned in previous emails that with dd(1) you can do couple
> MB/s writing to this card which is far more than these tens of KB/s. So the
> file download must be doing something which really destroys the IO pattern
> (and with mb_optimize_scan=0 ext4 happened to be better dealing with it and
> generating better IO pattern). Can you perhaps strace the process doing the
> download (or perhaps strace -f the whole rpi-update process) so that we can
> see how does the load generated on the filesystem look like? Thanks!

i didn't create the strace yet, but i looked at the source of 
rpi-update. At the end the download phase is a curl call to download a 
tar archive and pipe it directly to tar.

You can find the content list of the tar file here:

https://raw.githubusercontent.com/lategoodbye/mb_optimize_scan_regress/main/rpi-firmware-tar-content-list.txt

Best regards

>
> 								Honza

Re: [Regression] ext4: changes to mb_optimize_scan cause issues on Raspberry Pi

[Ojaswin Mujoo]

On Tue, Aug 16, 2022 at 10:45:48PM +0200, Stefan Wahren wrote:
> Hi Jan,
> 
> Am 16.08.22 um 11:34 schrieb Jan Kara:
> > Hi Stefan!
> > So this is interesting. We can see the card is 100% busy. The IO submitted
> > to the card is formed by small requests - 18-38 KB per request - and each
> > request takes 0.3-0.5s to complete. So the resulting throughput is horrible
> > - only tens of KB/s. Also we can see there are many IOs queued for the
> > device in parallel (aqu-sz columnt). This does not look like load I would
> > expect to be generated by download of a large file from the web.
> > 
> > You have mentioned in previous emails that with dd(1) you can do couple
> > MB/s writing to this card which is far more than these tens of KB/s. So the
> > file download must be doing something which really destroys the IO pattern
> > (and with mb_optimize_scan=0 ext4 happened to be better dealing with it and
> > generating better IO pattern). Can you perhaps strace the process doing the
> > download (or perhaps strace -f the whole rpi-update process) so that we can
> > see how does the load generated on the filesystem look like? Thanks!
> 
> i didn't create the strace yet, but i looked at the source of rpi-update. At
> the end the download phase is a curl call to download a tar archive and pipe
> it directly to tar.
> 
> You can find the content list of the tar file here:
> 
> https://raw.githubusercontent.com/lategoodbye/mb_optimize_scan_regress/main/rpi-firmware-tar-content-list.txt
> 
> Best regards
> 
> > 
> > 								Honza
Hi Jan and Stefan,

I did some analysis of this on my Raspberry Pi 3B+. Not sure of the root
cause yet but here is what I observed:

1. So I noticed that the download itself is not causing any issues in my
case, but the download with a pipe to tar is what causes the degradation.
With the pipe to tar, mb_optimize_scan=1 takes around 7mins whereas
mb_optimize_scan=0 takes 1 min

2. I tried to replicate this performance degradation by running untar
on an x86 machine but I not able to get the degradation. It is
reproducible pretty consistently on my Raspberry Pi though (w/ an 8GB
memory card).

3. I did analyse the resulting mb_optimize_scan=0 vs mb_optmize_scan=1
filesystem and seems like the allocated blocks are more spread out in
mb_optmize_scan=1 case but not yet sure if that is the issue.

Will update here if I notice anything else.

Regards,
Ojaswin

Re: [Regression] ext4: changes to mb_optimize_scan cause issues on Raspberry Pi

[Jan Kara]

Hi Stefan!

On Tue 16-08-22 22:45:48, Stefan Wahren wrote:
> Am 16.08.22 um 11:34 schrieb Jan Kara:
> > Hi Stefan!
> > So this is interesting. We can see the card is 100% busy. The IO submitted
> > to the card is formed by small requests - 18-38 KB per request - and each
> > request takes 0.3-0.5s to complete. So the resulting throughput is horrible
> > - only tens of KB/s. Also we can see there are many IOs queued for the
> > device in parallel (aqu-sz columnt). This does not look like load I would
> > expect to be generated by download of a large file from the web.
> > 
> > You have mentioned in previous emails that with dd(1) you can do couple
> > MB/s writing to this card which is far more than these tens of KB/s. So the
> > file download must be doing something which really destroys the IO pattern
> > (and with mb_optimize_scan=0 ext4 happened to be better dealing with it and
> > generating better IO pattern). Can you perhaps strace the process doing the
> > download (or perhaps strace -f the whole rpi-update process) so that we can
> > see how does the load generated on the filesystem look like? Thanks!
> 
> i didn't create the strace yet, but i looked at the source of rpi-update. At
> the end the download phase is a curl call to download a tar archive and pipe
> it directly to tar.
> 
> You can find the content list of the tar file here:
> 
> https://raw.githubusercontent.com/lategoodbye/mb_optimize_scan_regress/main/rpi-firmware-tar-content-list.txt

Thanks for the details! This is indeed even better. Looking at the tar
archive I can see it consists of a lot of small files big part of them
is even below 10k. So this very much matches the workload I was examining
with reaim where I saw regression (although only ~8%) even on normal
rotating drive on x86 machine. In that case I have pretty much confirmed
that the problem is due to mb_optimize_scan=1 spreading small allocated
files more which is likely also harmful for the SD card because it requires
touching more erase blocks.

Thanks for help with debugging this, I will implement some of the
heuristics we discussed with other ext4 developers to avoid this behavior
and will send you patch for testing.

								Honza
-- 
Jan Kara <jack@suse.com>
SUSE Labs, CR