lists.openwall.net   lists  /  announce  owl-users  owl-dev  john-users  john-dev  passwdqc-users  yescrypt  popa3d-users  /  oss-security  kernel-hardening  musl  sabotage  tlsify  passwords  /  crypt-dev  xvendor  /  Bugtraq  Full-Disclosure  linux-kernel  linux-netdev  linux-ext4  linux-hardening  linux-cve-announce  PHC 
Open Source and information security mailing list archives
 
Hash Suite: Windows password security audit tool. GUI, reports in PDF.
[<prev] [next>] [<thread-prev] [thread-next>] [day] [month] [year] [list]
Message-ID: <64b7899f-d84d-93de-f9c5-49538bd080d0@i2se.com>
Date:   Sat, 6 Aug 2022 11:50:28 +0200
From:   Stefan Wahren <stefan.wahren@...e.com>
To:     Jan Kara <jack@...e.cz>
Cc:     linux-ext4@...r.kernel.org, Ojaswin Mujoo <ojaswin@...ux.ibm.com>,
        Harshad Shirwadkar <harshadshirwadkar@...il.com>,
        Theodore Ts'o <tytso@....edu>,
        Ritesh Harjani <riteshh@...ux.ibm.com>,
        linux-fsdevel@...r.kernel.org,
        Linux Kernel Mailing List <linux-kernel@...r.kernel.org>,
        Geetika.Moolchandani1@....com, regressions@...ts.linux.dev,
        Florian Fainelli <f.fainelli@...il.com>
Subject: Re: [Regression] ext4: changes to mb_optimize_scan cause issues on
 Raspberry Pi

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@...ux.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@...00100   4 Edge      vc4 hdmi hpd connected
   54:          0          0          0          0 
interrupt-controller@...00100   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

Powered by blists - more mailing lists