diff mbox series

[1/2] spi: atmel: Do not cancel a transfer upon any signal

Message ID 20231127095842.389631-1-miquel.raynal@bootlin.com
State Accepted
Commit 1ca2761a7734928ffe0678f88789266cf3d05362
Headers show
Series [1/2] spi: atmel: Do not cancel a transfer upon any signal | expand

Commit Message

Miquel Raynal Nov. 27, 2023, 9:58 a.m. UTC
The intended move from wait_for_completion_*() to
wait_for_completion_interruptible_*() was to allow (very) long spi memory
transfers to be stopped upon user request instead of freezing the
machine forever as the timeout value could now be significantly bigger.

However, depending on the user logic, applications can receive many
signals for their own "internal" purpose and have nothing to do with the
requested kernel operations, hence interrupting spi transfers upon any
signal is probably not a wise choice. Instead, let's switch to
wait_for_completion_killable_*() to only catch the "important"
signals. This was likely the intended behavior anyway.

Fixes: e0205d6203c2 ("spi: atmel: Prevent false timeouts on long transfers")
Cc: stable@vger.kernel.org
Reported-by: Ronald Wahl <ronald.wahl@raritan.com>
Signed-off-by: Miquel Raynal <miquel.raynal@bootlin.com>
---
Hello Ronald, this is only compile tested, please let me know if that
fixes your use case or if you still suffer from interrupted transfers.
Thanks!
---
 drivers/spi/spi-atmel.c | 4 ++--
 1 file changed, 2 insertions(+), 2 deletions(-)

Comments

Mark Brown Nov. 27, 2023, 4:48 p.m. UTC | #1
On Mon, 27 Nov 2023 10:58:41 +0100, Miquel Raynal wrote:
> The intended move from wait_for_completion_*() to
> wait_for_completion_interruptible_*() was to allow (very) long spi memory
> transfers to be stopped upon user request instead of freezing the
> machine forever as the timeout value could now be significantly bigger.
> 
> However, depending on the user logic, applications can receive many
> signals for their own "internal" purpose and have nothing to do with the
> requested kernel operations, hence interrupting spi transfers upon any
> signal is probably not a wise choice. Instead, let's switch to
> wait_for_completion_killable_*() to only catch the "important"
> signals. This was likely the intended behavior anyway.
> 
> [...]

Applied to

   https://git.kernel.org/pub/scm/linux/kernel/git/broonie/sound.git for-next

Thanks!

[1/2] spi: atmel: Do not cancel a transfer upon any signal
      commit: 595d2639451d3490c545c644ece726a0410ad39b
[2/2] spi: atmel: Drop unused defines
      commit: 28d8051efae17b6d83544f3c1cf06f6a71677e91

All being well this means that it will be integrated into the linux-next
tree (usually sometime in the next 24 hours) and sent to Linus during
the next merge window (or sooner if it is a bug fix), however if
problems are discovered then the patch may be dropped or reverted.

You may get further e-mails resulting from automated or manual testing
and review of the tree, please engage with people reporting problems and
send followup patches addressing any issues that are reported if needed.

If any updates are required or you are submitting further changes they
should be sent as incremental updates against current git, existing
patches will not be replaced.

Please add any relevant lists and maintainers to the CCs when replying
to this mail.

Thanks,
Mark
Ronald Wahl Nov. 27, 2023, 5:54 p.m. UTC | #2
On 27.11.23 16:10, Ronald Wahl wrote:
> On 27.11.23 10:58, Miquel Raynal wrote:
>> The intended move from wait_for_completion_*() to
>> wait_for_completion_interruptible_*() was to allow (very) long spi memory
>> transfers to be stopped upon user request instead of freezing the
>> machine forever as the timeout value could now be significantly bigger.
>>
>> However, depending on the user logic, applications can receive many
>> signals for their own "internal" purpose and have nothing to do with the
>> requested kernel operations, hence interrupting spi transfers upon any
>> signal is probably not a wise choice. Instead, let's switch to
>> wait_for_completion_killable_*() to only catch the "important"
>> signals. This was likely the intended behavior anyway.
>
> Actually this seems to work. But aborting a process that has a SPI
> transfer running causes ugly messages from kernel. This is somehow
> unexpected:
>
> # dd if=/dev/urandom of=/flashdisk/testfile bs=1024 count=512
> ^C[  380.726760] spi-nor spi0.0: spi transfer canceled
> [  380.731688] spi-nor spi0.0: SPI transfer failed: -512
> [  380.737141] spi_master spi0: failed to transfer one message from queue
> [  380.746495] spi-nor spi0.0: spi transfer canceled
> [  380.751549] spi-nor spi0.0: SPI transfer failed: -512
> [  380.756844] spi_master spi0: failed to transfer one message from queue
>
> JFFS2 also logs an informational message which is less visible but also
> may rise eyebrows:
> [  380.743904] jffs2: Write of 4164 bytes at 0x0016a47c failed. returned
> -512, retlen 68
>
> Killing a process is something to expect in certain cases and it should
> not cause such messages which may create some anxiety that something bad
> had happened. So maybe the "kill" case should be silent (e.g. level
> "debug")
> but without out hiding real errors. But even when hiding the message in the
> SPI framework it may cause additional messages in upper layers like JFFS2.
> I'm not sure whether all of this is a good idea. This is something others
> have to decide.

... and now I just got a crash when unmounting and remounting jffs2:

unmount:
[ 8245.821105] spi-nor spi0.0: spi transfer canceled
[ 8245.826288] spi-nor spi0.0: SPI transfer failed: -512
[ 8245.831508] spi_master spi0: failed to transfer one message from queue
[ 8245.838484] jffs2: Write of 1092 bytes at 0x00181458 failed. returned -512, retlen 68
[ 8245.839786] spi-nor spi0.0: spi transfer canceled
[ 8245.844759] spi-nor spi0.0: SPI transfer failed: -512
[ 8245.850145] spi_master spi0: failed to transfer one message from queue
[ 8245.856909] jffs2: Write of 1092 bytes at 0x0018189c failed. returned -512, retlen 0
[ 8245.856942] jffs2: Not marking the space at 0x0018189c as dirty because the flash driver returned retlen zero

mount:
[ 8831.213456] jffs2: error: (1142) jffs2_link_node_ref: Adding new ref 28bd9da7 at (0x000ad578-0x000ae5bc) not immediately after previous (0x000ad578-0x000ad578)
[ 8831.228212] Internal error: Oops - undefined instruction: 0 [#1] THUMB2
[ 8831.234996] CPU: 0 PID: 1142 Comm: mount Not tainted 6.6.2-sama5 #1
[ 8831.241587] Hardware name: Atmel SAMA5
[ 8831.245478] PC is at jffs2_link_node_ref+0xe/0xe2
[ 8831.250360] LR is at jffs2_link_node_ref+0xb9/0xe2
[ 8831.255473] pc : [<c020969c>]    lr : [<c0209747>]    psr: 00000033
[ 8831.261893] sp : c974dd78  ip : 00000000  fp : c09c6a5c
[ 8831.267428] r10: c1572f18  r9 : 0000e002  r8 : c2849964
[ 8831.272801] r7 : 00001a44  r6 : 000ae5bc  r5 : c14df4a8  r4 : c1620208
[ 8831.279647] r3 : 00000001  r2 : 40000000  r1 : c090ce3c  r0 : 00000093
[ 8831.286340] Flags: nzcv  IRQs on  FIQs on  Mode SVC_32  ISA Thumb  Segment none
[ 8831.293974] Control: 50c53c7d  Table: 21470059  DAC: 00000051
[ 8831.300025] Register r0 information: non-paged memory
[ 8831.305239] Register r1 information: non-slab/vmalloc memory
[ 8831.311220] Register r2 information: non-paged memory
[ 8831.316427] Register r3 information: non-paged memory
[ 8831.321630] Register r4 information: slab kmalloc-2k start c1620000 pointer offset 520 size 2048
[ 8831.330796] Register r5 information: slab jffs2_refblock start c14df3e0 pointer offset 200 size 248
[ 8831.340219] Register r6 information: non-paged memory
[ 8831.345422] Register r7 information: non-paged memory
[ 8831.350784] Register r8 information: slab kmalloc-4k start c2849000 pointer offset 2404 size 4096
[ 8831.360032] Register r9 information: non-paged memory
[ 8831.365243] Register r10 information: slab pde_opener start c1572f18 pointer offset 0 size 24
[ 8831.374137] Register r11 information: non-slab/vmalloc memory
[ 8831.380041] Register r12 information: NULL pointer
[ 8831.385140] Process mount (pid: 1142, stack limit = 0xb9d2bb39)
[ 8831.391215] Stack: (0xc974dd78 to 0xc974e000)
[ 8831.395884] dd60:                                                       000ad578 000ae5bc
[ 8831.404242] dd80: 000ad578 000ad578 c2849dec c2805e00 c1620208 c2849dec 00000000 c021130d
[ 8831.412762] dda0: c1572d50 00000694 0000069c 00000036 00010000 c2937755 00000000 20061985
[ 8831.421280] ddc0: 0000069c 00000000 c2849964 c2805e00 c1620208 c2849964 0000069c 00000008
[ 8831.429799] dde0: 00000000 c2849ff8 c2849000 c020c40b c09c6a5c c974de34 c974de30 00000000
[ 8831.438154] de00: 00000004 0000069c 00001000 c2937bc0 00000208 c1620000 00000000 000a0000
[ 8831.446665] de20: 00000000 00000000 0000000a 00070000 c2849000 00000000 00001000 00000000
[ 8831.455184] de40: 00000000 00000000 00010000 c2805e00 00000000 00000000 00200000 c2937e00
[ 8831.463704] de60: 00000000 00008000 c0975a98 c020e02d c1001300 00000200 c020f3eb 00000dc0
[ 8831.472062] de80: c2937e00 00000000 c020f3eb c2805e00 c156fc80 c29b9400 00200000 c2937e00
[ 8831.480584] dea0: 00000000 c020f42d c29b9400 c156fc80 c09c6a64 c29b9400 c1298c00 c156fc80
[ 8831.489100] dec0: c020f5c9 c02a853d 0000003a 00000000 c156fc80 c020f5c9 c974df58 c02a85ff
[ 8831.497458] dee0: c156fc80 c020f5c9 00000000 c020f5bf c156fc80 c156fc80 00000020 c016fdc3
[ 8831.505976] df00: c156fc80 00000000 c1374780 c0115c75 00000000 00000000 c156fc80 c0182209
[ 8831.514497] df20: c2937e00 c974df58 c2937f80 00000000 c2937e00 c2937f80 00008000 00000000
[ 8831.523015] df40: 0006d71a 00008000 00068991 c0182307 00000000 c015048b c1360d90 c18b3a18
[ 8831.531370] df60: 00001000 c2937f80 c2937e00 00000000 00000015 c0182539 00000000 0006d71a
[ 8831.539881] df80: 0006d725 00000000 0006d70c 0006d71a 00000015 c010023c c1374780 00000015
[ 8831.548399] dfa0: 00068991 c0100041 00000000 0006d70c 0006d70c 0006d71a 0006d725 00008000
[ 8831.556908] dfc0: 00000000 0006d70c 0006d71a 00000015 00008000 00000000 0006d938 00068991
[ 8831.565263] dfe0: b6ea606c beb82b9c 00039818 b6ea607c a0000010 0006d70c 00000000 00000000
[ 8831.573779]  jffs2_link_node_ref from jffs2_sum_scan_sumnode+0x1a5/0x320
[ 8831.580860]  jffs2_sum_scan_sumnode from jffs2_scan_medium+0x2d7/0xab0
[ 8831.587595]  jffs2_scan_medium from jffs2_do_mount_fs+0xeb/0x356
[ 8831.593958]  jffs2_do_mount_fs from jffs2_do_fill_super+0xf7/0x182
[ 8831.600332]  jffs2_do_fill_super from mtd_get_sb+0x61/0x98
[ 8831.606176]  mtd_get_sb from get_tree_mtd+0x4f/0xe8
[ 8831.611241]  get_tree_mtd from vfs_get_tree+0x13/0x7c
[ 8831.616648]  vfs_get_tree from path_mount+0x409/0x4d4
[ 8831.621891]  path_mount from do_mount+0x33/0x40
[ 8831.626593]  do_mount from sys_mount+0xeb/0xfe
[ 8831.631367]  sys_mount from ret_fast_syscall+0x1/0x5c
[ 8831.636591] Exception stack(0xc974dfa8 to 0xc974dff0)
[ 8831.641961] dfa0:                   00000000 0006d70c 0006d70c 0006d71a 0006d725 00008000
[ 8831.650314] dfc0: 00000000 0006d70c 0006d71a 00000015 00008000 00000000 0006d938 00068991
[ 8831.658818] dfe0: b6ea606c beb82b9c 00039818 b6ea607c
[ 8831.664195] Code: 6a63 b085 990a b903 (de02) 6ae5
[ 8831.669135] ---[ end trace 0000000000000000 ]---
[ 8831.673902] Kernel panic - not syncing: Fatal exception

The previous aborted I/Os from a dd may also play a role here but the crash is
clearly a cause of the interrupted transfers. It's a bit odd that it is an
undefined instruction but probably it was a stack overflow.

Looking back in the SPI driver history I see some occasions where interruptible
transfers were changed to non-interruptible transfers because filesystems like
jffs2 used SIGKILL during unmount or maybe other reasons:

775c4c0032c4 "spi: stm32-qspi: remove signal sensitive on completion"
26cfc0dbe43a "spi-zynq-qspi: use wait_for_completion_timeout to make zynq_qspi_exec_mem_op not interruptible"
7f3ac71ac3b0 "spi: davinci: fix spurious i/o error"

Having them in spi-atmel now seems a bit off and even a source of misbehaviour
and even crashes.

- ron
Miquel Raynal Nov. 29, 2023, 8:49 a.m. UTC | #3
Hi Ronald,

+ Richard, my dear jffs2 expert ;)

ronald.wahl@raritan.com wrote on Mon, 27 Nov 2023 18:54:40 +0100:

> On 27.11.23 16:10, Ronald Wahl wrote:
> > On 27.11.23 10:58, Miquel Raynal wrote:  
> >> The intended move from wait_for_completion_*() to
> >> wait_for_completion_interruptible_*() was to allow (very) long spi memor  
> y
> >> transfers to be stopped upon user request instead of freezing the
> >> machine forever as the timeout value could now be significantly bigger.
> >>
> >> However, depending on the user logic, applications can receive many
> >> signals for their own "internal" purpose and have nothing to do with the
> >> requested kernel operations, hence interrupting spi transfers upon any
> >> signal is probably not a wise choice. Instead, let's switch to
> >> wait_for_completion_killable_*() to only catch the "important"
> >> signals. This was likely the intended behavior anyway.  
> >
> > Actually this seems to work. But aborting a process that has a SPI
> > transfer running causes ugly messages from kernel. This is somehow
> > unexpected:
> >
> > # dd if=/dev/urandom of=/flashdisk/testfile bs=1024 count=512
> > ^C[  380.726760] spi-nor spi0.0: spi transfer canceled
> > [  380.731688] spi-nor spi0.0: SPI transfer failed: -512
> > [  380.737141] spi_master spi0: failed to transfer one message from queue
> > [  380.746495] spi-nor spi0.0: spi transfer canceled
> > [  380.751549] spi-nor spi0.0: SPI transfer failed: -512
> > [  380.756844] spi_master spi0: failed to transfer one message from queue
> >
> > JFFS2 also logs an informational message which is less visible but also
> > may rise eyebrows:
> > [  380.743904] jffs2: Write of 4164 bytes at 0x0016a47c failed. retu  
> rned
> > -512, retlen 68
> >
> > Killing a process is something to expect in certain cases and it should
> > not cause such messages which may create some anxiety that something bad
> > had happened. So maybe the "kill" case should be silent (e.g. level
> > "debug")
> > but without out hiding real errors. But even when hiding the message in t  
> he
> > SPI framework it may cause additional messages in upper layers like JFFS2  
> .
> > I'm not sure whether all of this is a good idea. This is something others
> > have to decide.  
> 
> ... and now I just got a crash when unmounting and remounting jffs2:
> 
> unmount:
> [ 8245.821105] spi-nor spi0.0: spi transfer canceled
> [ 8245.826288] spi-nor spi0.0: SPI transfer failed: -512
> [ 8245.831508] spi_master spi0: failed to transfer one message from queue
> [ 8245.838484] jffs2: Write of 1092 bytes at 0x00181458 failed. returned -5
> 12, retlen 68
> [ 8245.839786] spi-nor spi0.0: spi transfer canceled
> [ 8245.844759] spi-nor spi0.0: SPI transfer failed: -512
> [ 8245.850145] spi_master spi0: failed to transfer one message from queue
> [ 8245.856909] jffs2: Write of 1092 bytes at 0x0018189c failed. returned -5
> 12, retlen 0
> [ 8245.856942] jffs2: Not marking the space at 0x0018189c as dirty because the flash driver returned retlen zero
> 
> mount:
> [ 8831.213456] jffs2: error: (1142) jffs2_link_node_ref: Adding new ref 28b
> d9da7 at (0x000ad578-0x000ae5bc) not immediately after previous (0x000ad578
> -0x000ad578)
> [ 8831.228212] Internal error: Oops - undefined instruction: 0 [#1] THUMB2
> [ 8831.234996] CPU: 0 PID: 1142 Comm: mount Not tainted 6.6.2-sama5 #1
> [ 8831.241587] Hardware name: Atmel SAMA5
> [ 8831.245478] PC is at jffs2_link_node_ref+0xe/0xe2
> [ 8831.250360] LR is at jffs2_link_node_ref+0xb9/0xe2
> [ 8831.255473] pc : [<c020969c>]    lr : [<c0209747>]    psr: 00000033
> [ 8831.261893] sp : c974dd78  ip : 00000000  fp : c09c6a5c
> [ 8831.267428] r10: c1572f18  r9 : 0000e002  r8 : c2849964
> [ 8831.272801] r7 : 00001a44  r6 : 000ae5bc  r5 : c14df4a8  r4 : c1620208
> [ 8831.279647] r3 : 00000001  r2 : 40000000  r1 : c090ce3c  r0 : 00000093
> [ 8831.286340] Flags: nzcv  IRQs on  FIQs on  Mode SVC_32  ISA Thumb  Segme
> nt none
> [ 8831.293974] Control: 50c53c7d  Table: 21470059  DAC: 00000051
> [ 8831.300025] Register r0 information: non-paged memory
> [ 8831.305239] Register r1 information: non-slab/vmalloc memory
> [ 8831.311220] Register r2 information: non-paged memory
> [ 8831.316427] Register r3 information: non-paged memory
> [ 8831.321630] Register r4 information: slab kmalloc-2k start c1620000 poin
> ter offset 520 size 2048
> [ 8831.330796] Register r5 information: slab jffs2_refblock start c14df3e0 pointer offset 200 size 248
> [ 8831.340219] Register r6 information: non-paged memory
> [ 8831.345422] Register r7 information: non-paged memory
> [ 8831.350784] Register r8 information: slab kmalloc-4k start c2849000 poin
> ter offset 2404 size 4096
> [ 8831.360032] Register r9 information: non-paged memory
> [ 8831.365243] Register r10 information: slab pde_opener start c1572f18 poi
> nter offset 0 size 24
> [ 8831.374137] Register r11 information: non-slab/vmalloc memory
> [ 8831.380041] Register r12 information: NULL pointer
> [ 8831.385140] Process mount (pid: 1142, stack limit = 0xb9d2bb39)
> [ 8831.391215] Stack: (0xc974dd78 to 0xc974e000)
> [ 8831.395884] dd60:                                                       000ad578 000ae5bc
> [ 8831.404242] dd80: 000ad578 000ad578 c2849dec c2805e00 c1620208 c2849dec 00000000 c021130d
> [ 8831.412762] dda0: c1572d50 00000694 0000069c 00000036 00010000 c2937755 00000000 20061985
> [ 8831.421280] ddc0: 0000069c 00000000 c2849964 c2805e00 c1620208 c2849964 0000069c 00000008
> [ 8831.429799] dde0: 00000000 c2849ff8 c2849000 c020c40b c09c6a5c c974de34 c974de30 00000000
> [ 8831.438154] de00: 00000004 0000069c 00001000 c2937bc0 00000208 c1620000 00000000 000a0000
> [ 8831.446665] de20: 00000000 00000000 0000000a 00070000 c2849000 00000000 00001000 00000000
> [ 8831.455184] de40: 00000000 00000000 00010000 c2805e00 00000000 00000000 00200000 c2937e00
> [ 8831.463704] de60: 00000000 00008000 c0975a98 c020e02d c1001300 00000200 c020f3eb 00000dc0
> [ 8831.472062] de80: c2937e00 00000000 c020f3eb c2805e00 c156fc80 c29b9400 00200000 c2937e00
> [ 8831.480584] dea0: 00000000 c020f42d c29b9400 c156fc80 c09c6a64 c29b9400 c1298c00 c156fc80
> [ 8831.489100] dec0: c020f5c9 c02a853d 0000003a 00000000 c156fc80 c020f5c9 c974df58 c02a85ff
> [ 8831.497458] dee0: c156fc80 c020f5c9 00000000 c020f5bf c156fc80 c156fc80 00000020 c016fdc3
> [ 8831.505976] df00: c156fc80 00000000 c1374780 c0115c75 00000000 00000000 c156fc80 c0182209
> [ 8831.514497] df20: c2937e00 c974df58 c2937f80 00000000 c2937e00 c2937f80 00008000 00000000
> [ 8831.523015] df40: 0006d71a 00008000 00068991 c0182307 00000000 c015048b c1360d90 c18b3a18
> [ 8831.531370] df60: 00001000 c2937f80 c2937e00 00000000 00000015 c0182539 00000000 0006d71a
> [ 8831.539881] df80: 0006d725 00000000 0006d70c 0006d71a 00000015 c010023c c1374780 00000015
> [ 8831.548399] dfa0: 00068991 c0100041 00000000 0006d70c 0006d70c 0006d71a 0006d725 00008000
> [ 8831.556908] dfc0: 00000000 0006d70c 0006d71a 00000015 00008000 00000000 0006d938 00068991
> [ 8831.565263] dfe0: b6ea606c beb82b9c 00039818 b6ea607c a0000010 0006d70c 00000000 00000000
> [ 8831.573779]  jffs2_link_node_ref from jffs2_sum_scan_sumnode+0x1a5/0x320
> [ 8831.580860]  jffs2_sum_scan_sumnode from jffs2_scan_medium+0x2d7/0xab0
> [ 8831.587595]  jffs2_scan_medium from jffs2_do_mount_fs+0xeb/0x356
> [ 8831.593958]  jffs2_do_mount_fs from jffs2_do_fill_super+0xf7/0x182
> [ 8831.600332]  jffs2_do_fill_super from mtd_get_sb+0x61/0x98
> [ 8831.606176]  mtd_get_sb from get_tree_mtd+0x4f/0xe8
> [ 8831.611241]  get_tree_mtd from vfs_get_tree+0x13/0x7c
> [ 8831.616648]  vfs_get_tree from path_mount+0x409/0x4d4
> [ 8831.621891]  path_mount from do_mount+0x33/0x40
> [ 8831.626593]  do_mount from sys_mount+0xeb/0xfe
> [ 8831.631367]  sys_mount from ret_fast_syscall+0x1/0x5c
> [ 8831.636591] Exception stack(0xc974dfa8 to 0xc974dff0)
> [ 8831.641961] dfa0:                   00000000 0006d70c 0006d70c 0006d71a 0006d725 00008000
> [ 8831.650314] dfc0: 00000000 0006d70c 0006d71a 00000015 00008000 00000000 0006d938 00068991
> [ 8831.658818] dfe0: b6ea606c beb82b9c 00039818 b6ea607c
> [ 8831.664195] Code: 6a63 b085 990a b903 (de02) 6ae5
> [ 8831.669135] ---[ end trace 0000000000000000 ]---
> [ 8831.673902] Kernel panic - not syncing: Fatal exception
> 
> The previous aborted I/Os from a dd may also play a role here but the crash
>  is
> clearly a cause of the interrupted transfers. It's a bit odd that it is an
> undefined instruction but probably it was a stack overflow.
> 
> Looking back in the SPI driver history I see some occasions where interrupt
> ible
> transfers were changed to non-interruptible transfers because filesystems l
> ike
> jffs2 used SIGKILL during unmount or maybe other reasons:
> 
> 775c4c0032c4 "spi: stm32-qspi: remove signal sensitive on completion"
> 26cfc0dbe43a "spi-zynq-qspi: use wait_for_completion_timeout to make zynq_q
> spi_exec_mem_op not interruptible"
> 7f3ac71ac3b0 "spi: davinci: fix spurious i/o error"
> 
> Having them in spi-atmel now seems a bit off and even a source of misbehavi
> our
> and even crashes.

It's not just spi-atmel, any spi-mem controller might be tempted to use
interruptible^Wkillable transfers just because the timeout values can
be really big as the memory sizes increase.

One solution is to change the completion helpers back to something
non-killable/non-interruptible, but the user experience will be
slightly degraded. The other would be to look into jffs2 (if it's the
only filesystem playing with signals during unmount, tbh I don't know).
But maybe this signaling mechanism can't be hacked for compatibility
reasons. Handling this at the spi level would be a mix of layers, I'm
not ready for that.

Richard, Mark, what's your opinion here?

Thanks,
Miquèl
Ronald Wahl Nov. 29, 2023, 11:05 a.m. UTC | #4
Hi Miquel,

On 29.11.23 09:49, Miquel Raynal wrote:
> Hi Ronald,
>
> + Richard, my dear jffs2 expert ;)
>
> ronald.wahl@raritan.com wrote on Mon, 27 Nov 2023 18:54:40 +0100:
>
>> On 27.11.23 16:10, Ronald Wahl wrote:
>>> On 27.11.23 10:58, Miquel Raynal wrote:
>>>> The intended move from wait_for_completion_*() to
>>>> wait_for_completion_interruptible_*() was to allow (very) long spi memor
>> y
>>>> transfers to be stopped upon user request instead of freezing the
>>>> machine forever as the timeout value could now be significantly bigger.
>>>>
>>>> However, depending on the user logic, applications can receive many
>>>> signals for their own "internal" purpose and have nothing to do with the
>>>> requested kernel operations, hence interrupting spi transfers upon any
>>>> signal is probably not a wise choice. Instead, let's switch to
>>>> wait_for_completion_killable_*() to only catch the "important"
>>>> signals. This was likely the intended behavior anyway.
>>>
>>> Actually this seems to work. But aborting a process that has a SPI
>>> transfer running causes ugly messages from kernel. This is somehow
>>> unexpected:
>>>
>>> # dd if=/dev/urandom of=/flashdisk/testfile bs=1024 count=512
>>> ^C[  380.726760] spi-nor spi0.0: spi transfer canceled
>>> [  380.731688] spi-nor spi0.0: SPI transfer failed: -512
>>> [  380.737141] spi_master spi0: failed to transfer one message from queue
>>> [  380.746495] spi-nor spi0.0: spi transfer canceled
>>> [  380.751549] spi-nor spi0.0: SPI transfer failed: -512
>>> [  380.756844] spi_master spi0: failed to transfer one message from queue
>>>
>>> JFFS2 also logs an informational message which is less visible but also
>>> may rise eyebrows:
>>> [  380.743904] jffs2: Write of 4164 bytes at 0x0016a47c failed. retu
>> rned
>>> -512, retlen 68
>>>
>>> Killing a process is something to expect in certain cases and it should
>>> not cause such messages which may create some anxiety that something bad
>>> had happened. So maybe the "kill" case should be silent (e.g. level
>>> "debug")
>>> but without out hiding real errors. But even when hiding the message in t
>> he
>>> SPI framework it may cause additional messages in upper layers like JFFS2
>> .
>>> I'm not sure whether all of this is a good idea. This is something others
>>> have to decide.
>>
>> ... and now I just got a crash when unmounting and remounting jffs2:
>>
>> unmount:
>> [ 8245.821105] spi-nor spi0.0: spi transfer canceled
>> [ 8245.826288] spi-nor spi0.0: SPI transfer failed: -512
>> [ 8245.831508] spi_master spi0: failed to transfer one message from queue
>> [ 8245.838484] jffs2: Write of 1092 bytes at 0x00181458 failed. returned -5
>> 12, retlen 68
>> [ 8245.839786] spi-nor spi0.0: spi transfer canceled
>> [ 8245.844759] spi-nor spi0.0: SPI transfer failed: -512
>> [ 8245.850145] spi_master spi0: failed to transfer one message from queue
>> [ 8245.856909] jffs2: Write of 1092 bytes at 0x0018189c failed. returned -5
>> 12, retlen 0
>> [ 8245.856942] jffs2: Not marking the space at 0x0018189c as dirty because the flash driver returned retlen zero
>>
>> mount:
>> [ 8831.213456] jffs2: error: (1142) jffs2_link_node_ref: Adding new ref 28b
>> d9da7 at (0x000ad578-0x000ae5bc) not immediately after previous (0x000ad578
>> -0x000ad578)
>> [ 8831.228212] Internal error: Oops - undefined instruction: 0 [#1] THUMB2
>> [ 8831.234996] CPU: 0 PID: 1142 Comm: mount Not tainted 6.6.2-sama5 #1
>> [ 8831.241587] Hardware name: Atmel SAMA5
>> [ 8831.245478] PC is at jffs2_link_node_ref+0xe/0xe2
>> [ 8831.250360] LR is at jffs2_link_node_ref+0xb9/0xe2
>> [ 8831.255473] pc : [<c020969c>]    lr : [<c0209747>]    psr: 00000033
>> [ 8831.261893] sp : c974dd78  ip : 00000000  fp : c09c6a5c
>> [ 8831.267428] r10: c1572f18  r9 : 0000e002  r8 : c2849964
>> [ 8831.272801] r7 : 00001a44  r6 : 000ae5bc  r5 : c14df4a8  r4 : c1620208
>> [ 8831.279647] r3 : 00000001  r2 : 40000000  r1 : c090ce3c  r0 : 00000093
>> [ 8831.286340] Flags: nzcv  IRQs on  FIQs on  Mode SVC_32  ISA Thumb  Segme
>> nt none
>> [ 8831.293974] Control: 50c53c7d  Table: 21470059  DAC: 00000051
>> [ 8831.300025] Register r0 information: non-paged memory
>> [ 8831.305239] Register r1 information: non-slab/vmalloc memory
>> [ 8831.311220] Register r2 information: non-paged memory
>> [ 8831.316427] Register r3 information: non-paged memory
>> [ 8831.321630] Register r4 information: slab kmalloc-2k start c1620000 poin
>> ter offset 520 size 2048
>> [ 8831.330796] Register r5 information: slab jffs2_refblock start c14df3e0 pointer offset 200 size 248
>> [ 8831.340219] Register r6 information: non-paged memory
>> [ 8831.345422] Register r7 information: non-paged memory
>> [ 8831.350784] Register r8 information: slab kmalloc-4k start c2849000 poin
>> ter offset 2404 size 4096
>> [ 8831.360032] Register r9 information: non-paged memory
>> [ 8831.365243] Register r10 information: slab pde_opener start c1572f18 poi
>> nter offset 0 size 24
>> [ 8831.374137] Register r11 information: non-slab/vmalloc memory
>> [ 8831.380041] Register r12 information: NULL pointer
>> [ 8831.385140] Process mount (pid: 1142, stack limit = 0xb9d2bb39)
>> [ 8831.391215] Stack: (0xc974dd78 to 0xc974e000)
>> [ 8831.395884] dd60:                                                       000ad578 000ae5bc
>> [ 8831.404242] dd80: 000ad578 000ad578 c2849dec c2805e00 c1620208 c2849dec 00000000 c021130d
>> [ 8831.412762] dda0: c1572d50 00000694 0000069c 00000036 00010000 c2937755 00000000 20061985
>> [ 8831.421280] ddc0: 0000069c 00000000 c2849964 c2805e00 c1620208 c2849964 0000069c 00000008
>> [ 8831.429799] dde0: 00000000 c2849ff8 c2849000 c020c40b c09c6a5c c974de34 c974de30 00000000
>> [ 8831.438154] de00: 00000004 0000069c 00001000 c2937bc0 00000208 c1620000 00000000 000a0000
>> [ 8831.446665] de20: 00000000 00000000 0000000a 00070000 c2849000 00000000 00001000 00000000
>> [ 8831.455184] de40: 00000000 00000000 00010000 c2805e00 00000000 00000000 00200000 c2937e00
>> [ 8831.463704] de60: 00000000 00008000 c0975a98 c020e02d c1001300 00000200 c020f3eb 00000dc0
>> [ 8831.472062] de80: c2937e00 00000000 c020f3eb c2805e00 c156fc80 c29b9400 00200000 c2937e00
>> [ 8831.480584] dea0: 00000000 c020f42d c29b9400 c156fc80 c09c6a64 c29b9400 c1298c00 c156fc80
>> [ 8831.489100] dec0: c020f5c9 c02a853d 0000003a 00000000 c156fc80 c020f5c9 c974df58 c02a85ff
>> [ 8831.497458] dee0: c156fc80 c020f5c9 00000000 c020f5bf c156fc80 c156fc80 00000020 c016fdc3
>> [ 8831.505976] df00: c156fc80 00000000 c1374780 c0115c75 00000000 00000000 c156fc80 c0182209
>> [ 8831.514497] df20: c2937e00 c974df58 c2937f80 00000000 c2937e00 c2937f80 00008000 00000000
>> [ 8831.523015] df40: 0006d71a 00008000 00068991 c0182307 00000000 c015048b c1360d90 c18b3a18
>> [ 8831.531370] df60: 00001000 c2937f80 c2937e00 00000000 00000015 c0182539 00000000 0006d71a
>> [ 8831.539881] df80: 0006d725 00000000 0006d70c 0006d71a 00000015 c010023c c1374780 00000015
>> [ 8831.548399] dfa0: 00068991 c0100041 00000000 0006d70c 0006d70c 0006d71a 0006d725 00008000
>> [ 8831.556908] dfc0: 00000000 0006d70c 0006d71a 00000015 00008000 00000000 0006d938 00068991
>> [ 8831.565263] dfe0: b6ea606c beb82b9c 00039818 b6ea607c a0000010 0006d70c 00000000 00000000
>> [ 8831.573779]  jffs2_link_node_ref from jffs2_sum_scan_sumnode+0x1a5/0x320
>> [ 8831.580860]  jffs2_sum_scan_sumnode from jffs2_scan_medium+0x2d7/0xab0
>> [ 8831.587595]  jffs2_scan_medium from jffs2_do_mount_fs+0xeb/0x356
>> [ 8831.593958]  jffs2_do_mount_fs from jffs2_do_fill_super+0xf7/0x182
>> [ 8831.600332]  jffs2_do_fill_super from mtd_get_sb+0x61/0x98
>> [ 8831.606176]  mtd_get_sb from get_tree_mtd+0x4f/0xe8
>> [ 8831.611241]  get_tree_mtd from vfs_get_tree+0x13/0x7c
>> [ 8831.616648]  vfs_get_tree from path_mount+0x409/0x4d4
>> [ 8831.621891]  path_mount from do_mount+0x33/0x40
>> [ 8831.626593]  do_mount from sys_mount+0xeb/0xfe
>> [ 8831.631367]  sys_mount from ret_fast_syscall+0x1/0x5c
>> [ 8831.636591] Exception stack(0xc974dfa8 to 0xc974dff0)
>> [ 8831.641961] dfa0:                   00000000 0006d70c 0006d70c 0006d71a 0006d725 00008000
>> [ 8831.650314] dfc0: 00000000 0006d70c 0006d71a 00000015 00008000 00000000 0006d938 00068991
>> [ 8831.658818] dfe0: b6ea606c beb82b9c 00039818 b6ea607c
>> [ 8831.664195] Code: 6a63 b085 990a b903 (de02) 6ae5
>> [ 8831.669135] ---[ end trace 0000000000000000 ]---
>> [ 8831.673902] Kernel panic - not syncing: Fatal exception
>>
>> The previous aborted I/Os from a dd may also play a role here but the crash
>>   is
>> clearly a cause of the interrupted transfers. It's a bit odd that it is an
>> undefined instruction but probably it was a stack overflow.
>>
>> Looking back in the SPI driver history I see some occasions where interrupt
>> ible
>> transfers were changed to non-interruptible transfers because filesystems l
>> ike
>> jffs2 used SIGKILL during unmount or maybe other reasons:
>>
>> 775c4c0032c4 "spi: stm32-qspi: remove signal sensitive on completion"
>> 26cfc0dbe43a "spi-zynq-qspi: use wait_for_completion_timeout to make zynq_q
>> spi_exec_mem_op not interruptible"
>> 7f3ac71ac3b0 "spi: davinci: fix spurious i/o error"
>>
>> Having them in spi-atmel now seems a bit off and even a source of misbehavi
>> our
>> and even crashes.
>
> It's not just spi-atmel, any spi-mem controller might be tempted to use
> interruptible^Wkillable transfers just because the timeout values can
> be really big as the memory sizes increase.
>
> One solution is to change the completion helpers back to something
> non-killable/non-interruptible, but the user experience will be
> slightly degraded. The other would be to look into jffs2 (if it's the
> only filesystem playing with signals during unmount, tbh I don't know).
> But maybe this signaling mechanism can't be hacked for compatibility
> reasons. Handling this at the spi level would be a mix of layers, I'm
> not ready for that.
>
> Richard, Mark, what's your opinion here?

I think you will need to revert to uninterruptible transfers.
Just tested with the more modern UBIFS:

# dd if=/dev/random of=/flashdisk/testfile bs=1024 count=512
^C

[   74.281739] spi-nor spi1.0: spi transfer canceled
[   74.286768] spi-nor spi1.0: SPI transfer failed: -512
[   74.292090] spi_master spi1: failed to transfer one message from queue
[   74.299002] ubi0 error: ubi_io_write: error -512 while writing 48 bytes to PEB 38:4224, written 0 bytes
[   74.308884] CPU: 0 PID: 1129 Comm: dd Not tainted 6.6.2-sama5 #2
[   74.315070] Hardware name: Atmel SAMA5
[   74.319159]  unwind_backtrace from show_stack+0x11/0x12
[   74.324597]  show_stack from dump_stack_lvl+0x25/0x3e
[   74.330020]  dump_stack_lvl from ubi_io_write+0x1a7/0x220
[   74.335616]  ubi_io_write from ubi_eba_write_leb+0x91/0x1dc
[   74.341554]  ubi_eba_write_leb from ubi_leb_write+0x99/0xbc
[   74.347311]  ubi_leb_write from ubifs_leb_write+0x4b/0x8c
[   74.352923]  ubifs_leb_write from ubifs_wbuf_sync_nolock+0x141/0x1d4
[   74.359649]  ubifs_wbuf_sync_nolock from ubifs_sync_wbufs_by_inode+0x51/0x6a
[   74.367061]  ubifs_sync_wbufs_by_inode from ubifs_fsync+0x6f/0xa0
[   74.373340]  ubifs_fsync from generic_file_write_iter+0x8f/0x98
[   74.379632]  generic_file_write_iter from vfs_write+0xbd/0x100
[   74.385659]  vfs_write from ksys_write+0x45/0x68
[   74.390636]  ksys_write from ret_fast_syscall+0x1/0x16
[   74.395958] Exception stack(0xd183dfa8 to 0xd183dff0)
[   74.401352] dfa0:                   00000001 01a97008 00000001 01a97008 00000400 00000004
[   74.409709] dfc0: 00000001 01a97008 bef2abd8 00000004 00000000 0005b94c 00052ac9 00000000
[   74.418234] dfe0: 0005b1f0 bef2abd8 00015ecf b6f0e6f6
[   74.482699] spi-nor spi1.0: spi transfer canceled
[   74.487825] spi-nor spi1.0: SPI transfer failed: -512
[   74.493205] spi_master spi1: failed to transfer one message from queue
[   74.500095] ubi0 error: ubi_dump_flash: err -512 while reading 48 bytes from PEB 38:4224, read 0 bytes
[   74.521967] ubi0 warning: ubi_eba_write_leb: failed to write data to PEB 38
[   74.529254] ubi0 warning: ubi_ro_mode: switch to read-only mode

I think file systems need uninterruptible transfers to ensure that the filesystem
structure stays consistent. With interruptible transfers this is just not possible.

Maybe a device tree option could be added to enable interruptible behaviour for
people that really need it but it would be unsafe at least for filesystems. I'm
not sure if this is something which is acceptible by the kernel people. I doubt.

BTW, the "Internal error: Oops - undefined instruction: 0" in the JFFS2 crash
was likely a BUG macro. It uses an illegal instruction but the trap handler
should see that it is from a BUG. It is obviously broken on ARM32.

- ron
Richard Weinberger Nov. 30, 2023, 12:46 p.m. UTC | #5
----- Ursprüngliche Mail -----
> Von: "Miquel Raynal" <miquel.raynal@bootlin.com>
> + Richard, my dear jffs2 expert ;)

:-S

> 
> ronald.wahl@raritan.com wrote on Mon, 27 Nov 2023 18:54:40 +0100:
> 
>> On 27.11.23 16:10, Ronald Wahl wrote:
>> > On 27.11.23 10:58, Miquel Raynal wrote:
>> >> The intended move from wait_for_completion_*() to
>> >> wait_for_completion_interruptible_*() was to allow (very) long spi memor
>> y
>> >> transfers to be stopped upon user request instead of freezing the
>> >> machine forever as the timeout value could now be significantly bigger.
>> >>
>> >> However, depending on the user logic, applications can receive many
>> >> signals for their own "internal" purpose and have nothing to do with the
>> >> requested kernel operations, hence interrupting spi transfers upon any
>> >> signal is probably not a wise choice. Instead, let's switch to
>> >> wait_for_completion_killable_*() to only catch the "important"
>> >> signals. This was likely the intended behavior anyway.
>> >
>> > Actually this seems to work. But aborting a process that has a SPI
>> > transfer running causes ugly messages from kernel. This is somehow
>> > unexpected:
>> >
>> > # dd if=/dev/urandom of=/flashdisk/testfile bs=1024 count=512
>> > ^C[  380.726760] spi-nor spi0.0: spi transfer canceled
>> > [  380.731688] spi-nor spi0.0: SPI transfer failed: -512
>> > [  380.737141] spi_master spi0: failed to transfer one message from queue
>> > [  380.746495] spi-nor spi0.0: spi transfer canceled
>> > [  380.751549] spi-nor spi0.0: SPI transfer failed: -512
>> > [  380.756844] spi_master spi0: failed to transfer one message from queue
>> >
>> > JFFS2 also logs an informational message which is less visible but also
>> > may rise eyebrows:
>> > [  380.743904] jffs2: Write of 4164 bytes at 0x0016a47c failed. retu
>> rned
>> > -512, retlen 68

Ugly kernel messages are a normal consequence of killing an IO.
Chances are good that we'll find bugs in the upper layers.

>> > Killing a process is something to expect in certain cases and it should
>> > not cause such messages which may create some anxiety that something bad
>> > had happened. So maybe the "kill" case should be silent (e.g. level
>> > "debug")
>> > but without out hiding real errors. But even when hiding the message in t
>> he
>> > SPI framework it may cause additional messages in upper layers like JFFS2
>> .
>> > I'm not sure whether all of this is a good idea. This is something others
>> > have to decide.
>> 
>> ... and now I just got a crash when unmounting and remounting jffs2:
>> 
>> unmount:
>> [ 8245.821105] spi-nor spi0.0: spi transfer canceled
>> [ 8245.826288] spi-nor spi0.0: SPI transfer failed: -512
>> [ 8245.831508] spi_master spi0: failed to transfer one message from queue
>> [ 8245.838484] jffs2: Write of 1092 bytes at 0x00181458 failed. returned -5
>> 12, retlen 68
>> [ 8245.839786] spi-nor spi0.0: spi transfer canceled
>> [ 8245.844759] spi-nor spi0.0: SPI transfer failed: -512
>> [ 8245.850145] spi_master spi0: failed to transfer one message from queue
>> [ 8245.856909] jffs2: Write of 1092 bytes at 0x0018189c failed. returned -5
>> 12, retlen 0
>> [ 8245.856942] jffs2: Not marking the space at 0x0018189c as dirty because the
>> flash driver returned retlen zero

jffs2 has a garbage collect thread which can be controlled using various signals.
To terminate the thread, jffs2 sends SIGKILL upon umount.
If the gc thread does IO while that, you gonna kill the IO too.
 
>> mount:
>> [ 8831.213456] jffs2: error: (1142) jffs2_link_node_ref: Adding new ref 28b
>> d9da7 at (0x000ad578-0x000ae5bc) not immediately after previous (0x000ad578
>> -0x000ad578)
>> [ 8831.228212] Internal error: Oops - undefined instruction: 0 [#1] THUMB2


I fear this is a jffs2 (summary feature) bug. Chances are great that you're able
to trigger the very same using a sudden loss of power.

> It's not just spi-atmel, any spi-mem controller might be tempted to use
> interruptible^Wkillable transfers just because the timeout values can
> be really big as the memory sizes increase.
> 
> One solution is to change the completion helpers back to something
> non-killable/non-interruptible, but the user experience will be
> slightly degraded. The other would be to look into jffs2 (if it's the
> only filesystem playing with signals during unmount, tbh I don't know).
> But maybe this signaling mechanism can't be hacked for compatibility
> reasons. Handling this at the spi level would be a mix of layers, I'm
> not ready for that.
> 
> Richard, Mark, what's your opinion here?

I *think* we can remove the signal handling code from jffs2 since it makes
already use of the kthread_should_stop() API.
That way we can keep the SPI transfer interruptible by signals.
...reading right now into the history to figure better.


Thanks,
//richard
Richard Weinberger Nov. 30, 2023, 6:26 p.m. UTC | #6
----- Ursprüngliche Mail -----
> Von: "richard" <richard@nod.at>
> An: "Miquel Raynal" <miquel.raynal@bootlin.com>
> CC: "Ronald Wahl" <ronald.wahl@raritan.com>, "Mark Brown" <broonie@kernel.org>, "linux-spi" <linux-spi@vger.kernel.org>,
> "Thomas Petazzoni" <thomas.petazzoni@bootlin.com>, "Ryan Wanner" <ryan.wanner@microchip.com>, "stable"
> <stable@vger.kernel.org>, "Richard Weinberger" <richard.weinberger@gmail.com>
> Gesendet: Donnerstag, 30. November 2023 13:46:14
> Betreff: Re: [PATCH 1/2] spi: atmel: Do not cancel a transfer upon any signal

> ----- Ursprüngliche Mail -----
>> Von: "Miquel Raynal" <miquel.raynal@bootlin.com>
>> + Richard, my dear jffs2 expert ;)
> 
> :-S
> 
>> 
>> ronald.wahl@raritan.com wrote on Mon, 27 Nov 2023 18:54:40 +0100:
>> 
>>> On 27.11.23 16:10, Ronald Wahl wrote:
>>> > On 27.11.23 10:58, Miquel Raynal wrote:
>>> >> The intended move from wait_for_completion_*() to
>>> >> wait_for_completion_interruptible_*() was to allow (very) long spi memor
>>> y
>>> >> transfers to be stopped upon user request instead of freezing the
>>> >> machine forever as the timeout value could now be significantly bigger.
>>> >>
>>> >> However, depending on the user logic, applications can receive many
>>> >> signals for their own "internal" purpose and have nothing to do with the
>>> >> requested kernel operations, hence interrupting spi transfers upon any
>>> >> signal is probably not a wise choice. Instead, let's switch to
>>> >> wait_for_completion_killable_*() to only catch the "important"
>>> >> signals. This was likely the intended behavior anyway.
>>> >
>>> > Actually this seems to work. But aborting a process that has a SPI
>>> > transfer running causes ugly messages from kernel. This is somehow
>>> > unexpected:
>>> >
>>> > # dd if=/dev/urandom of=/flashdisk/testfile bs=1024 count=512
>>> > ^C[  380.726760] spi-nor spi0.0: spi transfer canceled
>>> > [  380.731688] spi-nor spi0.0: SPI transfer failed: -512
>>> > [  380.737141] spi_master spi0: failed to transfer one message from queue
>>> > [  380.746495] spi-nor spi0.0: spi transfer canceled
>>> > [  380.751549] spi-nor spi0.0: SPI transfer failed: -512
>>> > [  380.756844] spi_master spi0: failed to transfer one message from queue
>>> >
>>> > JFFS2 also logs an informational message which is less visible but also
>>> > may rise eyebrows:
>>> > [  380.743904] jffs2: Write of 4164 bytes at 0x0016a47c failed. retu
>>> rned
>>> > -512, retlen 68
> 
> Ugly kernel messages are a normal consequence of killing an IO.
> Chances are good that we'll find bugs in the upper layers.
> 
>>> > Killing a process is something to expect in certain cases and it should
>>> > not cause such messages which may create some anxiety that something bad
>>> > had happened. So maybe the "kill" case should be silent (e.g. level
>>> > "debug")
>>> > but without out hiding real errors. But even when hiding the message in t
>>> he
>>> > SPI framework it may cause additional messages in upper layers like JFFS2
>>> .
>>> > I'm not sure whether all of this is a good idea. This is something others
>>> > have to decide.
>>> 
>>> ... and now I just got a crash when unmounting and remounting jffs2:
>>> 
>>> unmount:
>>> [ 8245.821105] spi-nor spi0.0: spi transfer canceled
>>> [ 8245.826288] spi-nor spi0.0: SPI transfer failed: -512
>>> [ 8245.831508] spi_master spi0: failed to transfer one message from queue
>>> [ 8245.838484] jffs2: Write of 1092 bytes at 0x00181458 failed. returned -5
>>> 12, retlen 68
>>> [ 8245.839786] spi-nor spi0.0: spi transfer canceled
>>> [ 8245.844759] spi-nor spi0.0: SPI transfer failed: -512
>>> [ 8245.850145] spi_master spi0: failed to transfer one message from queue
>>> [ 8245.856909] jffs2: Write of 1092 bytes at 0x0018189c failed. returned -5
>>> 12, retlen 0
>>> [ 8245.856942] jffs2: Not marking the space at 0x0018189c as dirty because the
>>> flash driver returned retlen zero
> 
> jffs2 has a garbage collect thread which can be controlled using various
> signals.
> To terminate the thread, jffs2 sends SIGKILL upon umount.
> If the gc thread does IO while that, you gonna kill the IO too.
> 
>>> mount:
>>> [ 8831.213456] jffs2: error: (1142) jffs2_link_node_ref: Adding new ref 28b
>>> d9da7 at (0x000ad578-0x000ae5bc) not immediately after previous (0x000ad578
>>> -0x000ad578)
>>> [ 8831.228212] Internal error: Oops - undefined instruction: 0 [#1] THUMB2
> 
> 
> I fear this is a jffs2 (summary feature) bug. Chances are great that you're able
> to trigger the very same using a sudden loss of power.
> 
>> It's not just spi-atmel, any spi-mem controller might be tempted to use
>> interruptible^Wkillable transfers just because the timeout values can
>> be really big as the memory sizes increase.
>> 
>> One solution is to change the completion helpers back to something
>> non-killable/non-interruptible, but the user experience will be
>> slightly degraded. The other would be to look into jffs2 (if it's the
>> only filesystem playing with signals during unmount, tbh I don't know).
>> But maybe this signaling mechanism can't be hacked for compatibility
>> reasons. Handling this at the spi level would be a mix of layers, I'm
>> not ready for that.
>> 
>> Richard, Mark, what's your opinion here?
> 
> I *think* we can remove the signal handling code from jffs2 since it makes
> already use of the kthread_should_stop() API.
> That way we can keep the SPI transfer interruptible by signals.
> ...reading right now into the history to figure better.

After a brief discussion with dwmw2 another question came up, if an spi transfer
is cancelled, *all* other IO do the filesystem has to stop too.
IO can happen concurrently, if only one IO path dies but the other ones can
make progress, the filesystem becomes inconsistent and all hope is lost.

Miquel, is this guaranteed by your changes?

Thanks,
//richard
Ronald Wahl Nov. 30, 2023, 6:36 p.m. UTC | #7
On 30.11.23 19:26, Richard Weinberger wrote:
> [You don't often get email from richard@nod.at. Learn why this is important at https://aka.ms/LearnAboutSenderIdentification ]
>
> ----- Ursprüngliche Mail -----
>> Von: "richard" <richard@nod.at>
>> An: "Miquel Raynal" <miquel.raynal@bootlin.com>
>> CC: "Ronald Wahl" <ronald.wahl@raritan.com>, "Mark Brown" <broonie@kernel.org>, "linux-spi" <linux-spi@vger.kernel.org>,
>> "Thomas Petazzoni" <thomas.petazzoni@bootlin.com>, "Ryan Wanner" <ryan.wanner@microchip.com>, "stable"
>> <stable@vger.kernel.org>, "Richard Weinberger" <richard.weinberger@gmail.com>
>> Gesendet: Donnerstag, 30. November 2023 13:46:14
>> Betreff: Re: [PATCH 1/2] spi: atmel: Do not cancel a transfer upon any signal
>
>> ----- Ursprüngliche Mail -----
>>> Von: "Miquel Raynal" <miquel.raynal@bootlin.com>
>>> + Richard, my dear jffs2 expert ;)
>>
>> :-S
>>
>>>
>>> ronald.wahl@raritan.com wrote on Mon, 27 Nov 2023 18:54:40 +0100:
>>>
>>>> On 27.11.23 16:10, Ronald Wahl wrote:
>>>>> On 27.11.23 10:58, Miquel Raynal wrote:
>>>>>> The intended move from wait_for_completion_*() to
>>>>>> wait_for_completion_interruptible_*() was to allow (very) long spi memor
>>>> y
>>>>>> transfers to be stopped upon user request instead of freezing the
>>>>>> machine forever as the timeout value could now be significantly bigger.
>>>>>>
>>>>>> However, depending on the user logic, applications can receive many
>>>>>> signals for their own "internal" purpose and have nothing to do with the
>>>>>> requested kernel operations, hence interrupting spi transfers upon any
>>>>>> signal is probably not a wise choice. Instead, let's switch to
>>>>>> wait_for_completion_killable_*() to only catch the "important"
>>>>>> signals. This was likely the intended behavior anyway.
>>>>>
>>>>> Actually this seems to work. But aborting a process that has a SPI
>>>>> transfer running causes ugly messages from kernel. This is somehow
>>>>> unexpected:
>>>>>
>>>>> # dd if=/dev/urandom of=/flashdisk/testfile bs=1024 count=512
>>>>> ^C[  380.726760] spi-nor spi0.0: spi transfer canceled
>>>>> [  380.731688] spi-nor spi0.0: SPI transfer failed: -512
>>>>> [  380.737141] spi_master spi0: failed to transfer one message from queue
>>>>> [  380.746495] spi-nor spi0.0: spi transfer canceled
>>>>> [  380.751549] spi-nor spi0.0: SPI transfer failed: -512
>>>>> [  380.756844] spi_master spi0: failed to transfer one message from queue
>>>>>
>>>>> JFFS2 also logs an informational message which is less visible but also
>>>>> may rise eyebrows:
>>>>> [  380.743904] jffs2: Write of 4164 bytes at 0x0016a47c failed. retu
>>>> rned
>>>>> -512, retlen 68
>>
>> Ugly kernel messages are a normal consequence of killing an IO.
>> Chances are good that we'll find bugs in the upper layers.
>>
>>>>> Killing a process is something to expect in certain cases and it should
>>>>> not cause such messages which may create some anxiety that something bad
>>>>> had happened. So maybe the "kill" case should be silent (e.g. level
>>>>> "debug")
>>>>> but without out hiding real errors. But even when hiding the message in t
>>>> he
>>>>> SPI framework it may cause additional messages in upper layers like JFFS2
>>>> .
>>>>> I'm not sure whether all of this is a good idea. This is something others
>>>>> have to decide.
>>>>
>>>> ... and now I just got a crash when unmounting and remounting jffs2:
>>>>
>>>> unmount:
>>>> [ 8245.821105] spi-nor spi0.0: spi transfer canceled
>>>> [ 8245.826288] spi-nor spi0.0: SPI transfer failed: -512
>>>> [ 8245.831508] spi_master spi0: failed to transfer one message from queue
>>>> [ 8245.838484] jffs2: Write of 1092 bytes at 0x00181458 failed. returned -5
>>>> 12, retlen 68
>>>> [ 8245.839786] spi-nor spi0.0: spi transfer canceled
>>>> [ 8245.844759] spi-nor spi0.0: SPI transfer failed: -512
>>>> [ 8245.850145] spi_master spi0: failed to transfer one message from queue
>>>> [ 8245.856909] jffs2: Write of 1092 bytes at 0x0018189c failed. returned -5
>>>> 12, retlen 0
>>>> [ 8245.856942] jffs2: Not marking the space at 0x0018189c as dirty because the
>>>> flash driver returned retlen zero
>>
>> jffs2 has a garbage collect thread which can be controlled using various
>> signals.
>> To terminate the thread, jffs2 sends SIGKILL upon umount.
>> If the gc thread does IO while that, you gonna kill the IO too.
>>
>>>> mount:
>>>> [ 8831.213456] jffs2: error: (1142) jffs2_link_node_ref: Adding new ref 28b
>>>> d9da7 at (0x000ad578-0x000ae5bc) not immediately after previous (0x000ad578
>>>> -0x000ad578)
>>>> [ 8831.228212] Internal error: Oops - undefined instruction: 0 [#1] THUMB2
>>
>>
>> I fear this is a jffs2 (summary feature) bug. Chances are great that you're able
>> to trigger the very same using a sudden loss of power.
>>
>>> It's not just spi-atmel, any spi-mem controller might be tempted to use
>>> interruptible^Wkillable transfers just because the timeout values can
>>> be really big as the memory sizes increase.
>>>
>>> One solution is to change the completion helpers back to something
>>> non-killable/non-interruptible, but the user experience will be
>>> slightly degraded. The other would be to look into jffs2 (if it's the
>>> only filesystem playing with signals during unmount, tbh I don't know).
>>> But maybe this signaling mechanism can't be hacked for compatibility
>>> reasons. Handling this at the spi level would be a mix of layers, I'm
>>> not ready for that.
>>>
>>> Richard, Mark, what's your opinion here?
>>
>> I *think* we can remove the signal handling code from jffs2 since it makes
>> already use of the kthread_should_stop() API.
>> That way we can keep the SPI transfer interruptible by signals.
>> ...reading right now into the history to figure better.
>
> After a brief discussion with dwmw2 another question came up, if an spi transfer
> is cancelled, *all* other IO do the filesystem has to stop too.
> IO can happen concurrently, if only one IO path dies but the other ones can
> make progress, the filesystem becomes inconsistent and all hope is lost.

This sounds very logical. And as far as I understand a user space action
like
killing a process should not be able to trigger such a scenario. I think
this
is the reason why filesystems typically rely on uninterruptible transfers.
As I showed with UBIFS the filesystem immediately mounts the FS in read-only
mode when a transfer is canceled.

- ron
Miquel Raynal Nov. 30, 2023, 8:15 p.m. UTC | #8
Hi Richard,

richard@nod.at wrote on Thu, 30 Nov 2023 19:26:07 +0100 (CET):

> ----- Ursprüngliche Mail -----
> > Von: "richard" <richard@nod.at>
> > An: "Miquel Raynal" <miquel.raynal@bootlin.com>
> > CC: "Ronald Wahl" <ronald.wahl@raritan.com>, "Mark Brown" <broonie@kernel.org>, "linux-spi" <linux-spi@vger.kernel.org>,
> > "Thomas Petazzoni" <thomas.petazzoni@bootlin.com>, "Ryan Wanner" <ryan.wanner@microchip.com>, "stable"
> > <stable@vger.kernel.org>, "Richard Weinberger" <richard.weinberger@gmail.com>
> > Gesendet: Donnerstag, 30. November 2023 13:46:14
> > Betreff: Re: [PATCH 1/2] spi: atmel: Do not cancel a transfer upon any signal  
> 
> > ----- Ursprüngliche Mail -----  
> >> Von: "Miquel Raynal" <miquel.raynal@bootlin.com>
> >> + Richard, my dear jffs2 expert ;)  
> > 
> > :-S
> >   
> >> 
> >> ronald.wahl@raritan.com wrote on Mon, 27 Nov 2023 18:54:40 +0100:
> >>   
> >>> On 27.11.23 16:10, Ronald Wahl wrote:  
> >>> > On 27.11.23 10:58, Miquel Raynal wrote:  
> >>> >> The intended move from wait_for_completion_*() to
> >>> >> wait_for_completion_interruptible_*() was to allow (very) long spi memor  
> >>> y  
> >>> >> transfers to be stopped upon user request instead of freezing the
> >>> >> machine forever as the timeout value could now be significantly bigger.
> >>> >>
> >>> >> However, depending on the user logic, applications can receive many
> >>> >> signals for their own "internal" purpose and have nothing to do with the
> >>> >> requested kernel operations, hence interrupting spi transfers upon any
> >>> >> signal is probably not a wise choice. Instead, let's switch to
> >>> >> wait_for_completion_killable_*() to only catch the "important"
> >>> >> signals. This was likely the intended behavior anyway.  
> >>> >
> >>> > Actually this seems to work. But aborting a process that has a SPI
> >>> > transfer running causes ugly messages from kernel. This is somehow
> >>> > unexpected:
> >>> >
> >>> > # dd if=/dev/urandom of=/flashdisk/testfile bs=1024 count=512
> >>> > ^C[  380.726760] spi-nor spi0.0: spi transfer canceled
> >>> > [  380.731688] spi-nor spi0.0: SPI transfer failed: -512
> >>> > [  380.737141] spi_master spi0: failed to transfer one message from queue
> >>> > [  380.746495] spi-nor spi0.0: spi transfer canceled
> >>> > [  380.751549] spi-nor spi0.0: SPI transfer failed: -512
> >>> > [  380.756844] spi_master spi0: failed to transfer one message from queue
> >>> >
> >>> > JFFS2 also logs an informational message which is less visible but also
> >>> > may rise eyebrows:
> >>> > [  380.743904] jffs2: Write of 4164 bytes at 0x0016a47c failed. retu  
> >>> rned  
> >>> > -512, retlen 68  
> > 
> > Ugly kernel messages are a normal consequence of killing an IO.
> > Chances are good that we'll find bugs in the upper layers.
> >   
> >>> > Killing a process is something to expect in certain cases and it should
> >>> > not cause such messages which may create some anxiety that something bad
> >>> > had happened. So maybe the "kill" case should be silent (e.g. level
> >>> > "debug")
> >>> > but without out hiding real errors. But even when hiding the message in t  
> >>> he  
> >>> > SPI framework it may cause additional messages in upper layers like JFFS2  
> >>> .  
> >>> > I'm not sure whether all of this is a good idea. This is something others
> >>> > have to decide.  
> >>> 
> >>> ... and now I just got a crash when unmounting and remounting jffs2:
> >>> 
> >>> unmount:
> >>> [ 8245.821105] spi-nor spi0.0: spi transfer canceled
> >>> [ 8245.826288] spi-nor spi0.0: SPI transfer failed: -512
> >>> [ 8245.831508] spi_master spi0: failed to transfer one message from queue
> >>> [ 8245.838484] jffs2: Write of 1092 bytes at 0x00181458 failed. returned -5
> >>> 12, retlen 68
> >>> [ 8245.839786] spi-nor spi0.0: spi transfer canceled
> >>> [ 8245.844759] spi-nor spi0.0: SPI transfer failed: -512
> >>> [ 8245.850145] spi_master spi0: failed to transfer one message from queue
> >>> [ 8245.856909] jffs2: Write of 1092 bytes at 0x0018189c failed. returned -5
> >>> 12, retlen 0
> >>> [ 8245.856942] jffs2: Not marking the space at 0x0018189c as dirty because the
> >>> flash driver returned retlen zero  
> > 
> > jffs2 has a garbage collect thread which can be controlled using various
> > signals.
> > To terminate the thread, jffs2 sends SIGKILL upon umount.
> > If the gc thread does IO while that, you gonna kill the IO too.
> >   
> >>> mount:
> >>> [ 8831.213456] jffs2: error: (1142) jffs2_link_node_ref: Adding new ref 28b
> >>> d9da7 at (0x000ad578-0x000ae5bc) not immediately after previous (0x000ad578
> >>> -0x000ad578)
> >>> [ 8831.228212] Internal error: Oops - undefined instruction: 0 [#1] THUMB2  
> > 
> > 
> > I fear this is a jffs2 (summary feature) bug. Chances are great that you're able
> > to trigger the very same using a sudden loss of power.
> >   
> >> It's not just spi-atmel, any spi-mem controller might be tempted to use
> >> interruptible^Wkillable transfers just because the timeout values can
> >> be really big as the memory sizes increase.
> >> 
> >> One solution is to change the completion helpers back to something
> >> non-killable/non-interruptible, but the user experience will be
> >> slightly degraded. The other would be to look into jffs2 (if it's the
> >> only filesystem playing with signals during unmount, tbh I don't know).
> >> But maybe this signaling mechanism can't be hacked for compatibility
> >> reasons. Handling this at the spi level would be a mix of layers, I'm
> >> not ready for that.
> >> 
> >> Richard, Mark, what's your opinion here?  
> > 
> > I *think* we can remove the signal handling code from jffs2 since it makes
> > already use of the kthread_should_stop() API.
> > That way we can keep the SPI transfer interruptible by signals.
> > ...reading right now into the history to figure better.  
> 
> After a brief discussion with dwmw2 another question came up, if an spi transfer
> is cancelled, *all* other IO do the filesystem has to stop too.
> IO can happen concurrently, if only one IO path dies but the other ones can
> make progress, the filesystem becomes inconsistent and all hope is lost.
> 
> Miquel, is this guaranteed by your changes?

Absolutely not, the changes are in a spi controller, there is nothing
specific to the user there. If a filesystem transfer get interrupted,
it's the filesystem responsibility to cancel the other IOs if that's
relevant for its own consistency?

Thanks,
Miquèl
Ronald Wahl Nov. 30, 2023, 8:43 p.m. UTC | #9
On 30.11.23 21:15, Miquel Raynal wrote:
> Hi Richard,
>
> richard@nod.at wrote on Thu, 30 Nov 2023 19:26:07 +0100 (CET):
>
>> ----- Ursprüngliche Mail -----
>>> Von: "richard" <richard@nod.at>
>>> An: "Miquel Raynal" <miquel.raynal@bootlin.com>
>>> CC: "Ronald Wahl" <ronald.wahl@raritan.com>, "Mark Brown" <broonie@kernel.org>, "linux-spi" <linux-spi@vger.kernel.org>,
>>> "Thomas Petazzoni" <thomas.petazzoni@bootlin.com>, "Ryan Wanner" <ryan.wanner@microchip.com>, "stable"
>>> <stable@vger.kernel.org>, "Richard Weinberger" <richard.weinberger@gmail.com>
>>> Gesendet: Donnerstag, 30. November 2023 13:46:14
>>> Betreff: Re: [PATCH 1/2] spi: atmel: Do not cancel a transfer upon any signal
>>
>>> ----- Ursprüngliche Mail -----
>>>> Von: "Miquel Raynal" <miquel.raynal@bootlin.com>
>>>> + Richard, my dear jffs2 expert ;)
>>>
>>> :-S
>>>
>>>>
>>>> ronald.wahl@raritan.com wrote on Mon, 27 Nov 2023 18:54:40 +0100:
>>>>
>>>>> On 27.11.23 16:10, Ronald Wahl wrote:
>>>>>> On 27.11.23 10:58, Miquel Raynal wrote:
>>>>>>> The intended move from wait_for_completion_*() to
>>>>>>> wait_for_completion_interruptible_*() was to allow (very) long spi memor
>>>>> y
>>>>>>> transfers to be stopped upon user request instead of freezing the
>>>>>>> machine forever as the timeout value could now be significantly bigger.
>>>>>>>
>>>>>>> However, depending on the user logic, applications can receive many
>>>>>>> signals for their own "internal" purpose and have nothing to do with the
>>>>>>> requested kernel operations, hence interrupting spi transfers upon any
>>>>>>> signal is probably not a wise choice. Instead, let's switch to
>>>>>>> wait_for_completion_killable_*() to only catch the "important"
>>>>>>> signals. This was likely the intended behavior anyway.
>>>>>>
>>>>>> Actually this seems to work. But aborting a process that has a SPI
>>>>>> transfer running causes ugly messages from kernel. This is somehow
>>>>>> unexpected:
>>>>>>
>>>>>> # dd if=/dev/urandom of=/flashdisk/testfile bs=1024 count=512
>>>>>> ^C[  380.726760] spi-nor spi0.0: spi transfer canceled
>>>>>> [  380.731688] spi-nor spi0.0: SPI transfer failed: -512
>>>>>> [  380.737141] spi_master spi0: failed to transfer one message from queue
>>>>>> [  380.746495] spi-nor spi0.0: spi transfer canceled
>>>>>> [  380.751549] spi-nor spi0.0: SPI transfer failed: -512
>>>>>> [  380.756844] spi_master spi0: failed to transfer one message from queue
>>>>>>
>>>>>> JFFS2 also logs an informational message which is less visible but also
>>>>>> may rise eyebrows:
>>>>>> [  380.743904] jffs2: Write of 4164 bytes at 0x0016a47c failed. retu
>>>>> rned
>>>>>> -512, retlen 68
>>>
>>> Ugly kernel messages are a normal consequence of killing an IO.
>>> Chances are good that we'll find bugs in the upper layers.
>>>
>>>>>> Killing a process is something to expect in certain cases and it should
>>>>>> not cause such messages which may create some anxiety that something bad
>>>>>> had happened. So maybe the "kill" case should be silent (e.g. level
>>>>>> "debug")
>>>>>> but without out hiding real errors. But even when hiding the message in t
>>>>> he
>>>>>> SPI framework it may cause additional messages in upper layers like JFFS2
>>>>> .
>>>>>> I'm not sure whether all of this is a good idea. This is something others
>>>>>> have to decide.
>>>>>
>>>>> ... and now I just got a crash when unmounting and remounting jffs2:
>>>>>
>>>>> unmount:
>>>>> [ 8245.821105] spi-nor spi0.0: spi transfer canceled
>>>>> [ 8245.826288] spi-nor spi0.0: SPI transfer failed: -512
>>>>> [ 8245.831508] spi_master spi0: failed to transfer one message from queue
>>>>> [ 8245.838484] jffs2: Write of 1092 bytes at 0x00181458 failed. returned -5
>>>>> 12, retlen 68
>>>>> [ 8245.839786] spi-nor spi0.0: spi transfer canceled
>>>>> [ 8245.844759] spi-nor spi0.0: SPI transfer failed: -512
>>>>> [ 8245.850145] spi_master spi0: failed to transfer one message from queue
>>>>> [ 8245.856909] jffs2: Write of 1092 bytes at 0x0018189c failed. returned -5
>>>>> 12, retlen 0
>>>>> [ 8245.856942] jffs2: Not marking the space at 0x0018189c as dirty because the
>>>>> flash driver returned retlen zero
>>>
>>> jffs2 has a garbage collect thread which can be controlled using various
>>> signals.
>>> To terminate the thread, jffs2 sends SIGKILL upon umount.
>>> If the gc thread does IO while that, you gonna kill the IO too.
>>>
>>>>> mount:
>>>>> [ 8831.213456] jffs2: error: (1142) jffs2_link_node_ref: Adding new ref 28b
>>>>> d9da7 at (0x000ad578-0x000ae5bc) not immediately after previous (0x000ad578
>>>>> -0x000ad578)
>>>>> [ 8831.228212] Internal error: Oops - undefined instruction: 0 [#1] THUMB2
>>>
>>>
>>> I fear this is a jffs2 (summary feature) bug. Chances are great that you're able
>>> to trigger the very same using a sudden loss of power.
>>>
>>>> It's not just spi-atmel, any spi-mem controller might be tempted to use
>>>> interruptible^Wkillable transfers just because the timeout values can
>>>> be really big as the memory sizes increase.
>>>>
>>>> One solution is to change the completion helpers back to something
>>>> non-killable/non-interruptible, but the user experience will be
>>>> slightly degraded. The other would be to look into jffs2 (if it's the
>>>> only filesystem playing with signals during unmount, tbh I don't know).
>>>> But maybe this signaling mechanism can't be hacked for compatibility
>>>> reasons. Handling this at the spi level would be a mix of layers, I'm
>>>> not ready for that.
>>>>
>>>> Richard, Mark, what's your opinion here?
>>>
>>> I *think* we can remove the signal handling code from jffs2 since it makes
>>> already use of the kthread_should_stop() API.
>>> That way we can keep the SPI transfer interruptible by signals.
>>> ...reading right now into the history to figure better.
>>
>> After a brief discussion with dwmw2 another question came up, if an spi transfer
>> is cancelled, *all* other IO do the filesystem has to stop too.
>> IO can happen concurrently, if only one IO path dies but the other ones can
>> make progress, the filesystem becomes inconsistent and all hope is lost.
>>
>> Miquel, is this guaranteed by your changes?
>
> Absolutely not, the changes are in a spi controller, there is nothing
> specific to the user there. If a filesystem transfer get interrupted,
> it's the filesystem responsibility to cancel the other IOs if that's
> relevant for its own consistency?

I think yes. But the only thing the FS can do is stop any writes from now
on which is not a useful consequence of killing a process.

Anyway, the whole issue started with commit e0205d6203c2 "spi: atmel:
Prevent
false timeouts on long transfers". Citing the commit message here:
     "spi: atmel: Prevent false timeouts on long transfers

     A slow SPI bus clocks at ~20MHz, which means it would transfer about
     2500 bytes per second with a single data line. Big transfers, like when
     dealing with flashes can easily reach a few MiB. The current DMA
timeout
     is set to 1 second, which means any working transfer of about 4MiB will
     always be cancelled.

     With the above derivations, on a slow bus, we can assume every byte
will
     take at most 0.4ms. Said otherwise, we could add 4ms to the 1-second
     timeout delay every 10kiB. On a 4MiB transfer, it would bring the
     timeout delay up to 2.6s which still seems rather acceptable for a
     timeout.

     The consequence of this is that long transfers might be allowed, which
     hence requires the need to interrupt the transfer if wanted by the
     user. We can hence switch to the _interruptible variant of
     wait_for_completion. This leads to a little bit more handling to also
     handle the interrupted case but looks really acceptable overall.

     While at it, we drop the useless, noisy and redundant WARN_ON() call."

This calculation is actually wrong by factor 1000. A 20MHz SPI bus is not
really slow and it will transfer ~2.5MB/s over a single lane.
The calculation would be right for 20kHz but I think this is a more
esoteric case, isn't it?

- ron
Richard Weinberger Nov. 30, 2023, 8:58 p.m. UTC | #10
----- Ursprüngliche Mail -----
> Von: "Ronald Wahl" <ronald.wahl@raritan.com>
> I think yes. But the only thing the FS can do is stop any writes from now
> on which is not a useful consequence of killing a process.

Exactly. If I understand the spi code correctly, now an *unprivileged*
user can abort a file operation on UBIFS and UBIFS will switch to read-only mode.
...which is pretty bad.

Thanks,
//richard
David Laight Dec. 1, 2023, 11:13 a.m. UTC | #11
...
> Anyway, the whole issue started with commit e0205d6203c2 "spi: atmel:
> Prevent
> false timeouts on long transfers". Citing the commit message here:
>      "spi: atmel: Prevent false timeouts on long transfers
> 
>      A slow SPI bus clocks at ~20MHz, which means it would transfer about
>      2500 bytes per second with a single data line. Big transfers, like when
>      dealing with flashes can easily reach a few MiB. The current DMA
> timeout
>      is set to 1 second, which means any working transfer of about 4MiB will
>      always be cancelled.
> 
>      With the above derivations, on a slow bus, we can assume every byte
> will
>      take at most 0.4ms. Said otherwise, we could add 4ms to the 1-second
>      timeout delay every 10kiB. On a 4MiB transfer, it would bring the
>      timeout delay up to 2.6s which still seems rather acceptable for a
>      timeout.
> 
>      The consequence of this is that long transfers might be allowed, which
>      hence requires the need to interrupt the transfer if wanted by the
>      user. We can hence switch to the _interruptible variant of
>      wait_for_completion. This leads to a little bit more handling to also
>      handle the interrupted case but looks really acceptable overall.
> 
>      While at it, we drop the useless, noisy and redundant WARN_ON() call."
> 
> This calculation is actually wrong by factor 1000. A 20MHz SPI bus is not
> really slow and it will transfer ~2.5MB/s over a single lane.
> The calculation would be right for 20kHz but I think this is a more
> esoteric case, isn't it?

Some of the sums are wrong, but the conclusion might be right.
A 4MB transfer at 20MHz only has 5 clocks/byte - seems low if it
is only using 1 data bit.
The spi devices usually support 'nibble mode' for read/write that
will speed things up - provided the data lines are connected.

OTOH a better fix is (probably) to do the transfer in sane sized chunks.
The extra interrupt and code won't make much difference to something
that takes that long.

As an aside, has anyone managed to get an spi memory device to calculate
a CRC? The ones we have claim to support the request but I've failed to
get it to work.

	David

-
Registered Address Lakeside, Bramley Road, Mount Farm, Milton Keynes, MK1 1PT, UK
Registration No: 1397386 (Wales)
Ronald Wahl Dec. 1, 2023, 1:38 p.m. UTC | #12
On 01.12.23 12:13, David Laight wrote:
> [You don't often get email from david.laight@aculab.com. Learn why this is important at https://aka.ms/LearnAboutSenderIdentification ]
>
> ...
>> Anyway, the whole issue started with commit e0205d6203c2 "spi: atmel:
>> Prevent
>> false timeouts on long transfers". Citing the commit message here:
>>       "spi: atmel: Prevent false timeouts on long transfers
>>
>>       A slow SPI bus clocks at ~20MHz, which means it would transfer about
>>       2500 bytes per second with a single data line. Big transfers, like when
>>       dealing with flashes can easily reach a few MiB. The current DMA
>> timeout
>>       is set to 1 second, which means any working transfer of about 4MiB will
>>       always be cancelled.
>>
>>       With the above derivations, on a slow bus, we can assume every byte
>> will
>>       take at most 0.4ms. Said otherwise, we could add 4ms to the 1-second
>>       timeout delay every 10kiB. On a 4MiB transfer, it would bring the
>>       timeout delay up to 2.6s which still seems rather acceptable for a
>>       timeout.
>>
>>       The consequence of this is that long transfers might be allowed, which
>>       hence requires the need to interrupt the transfer if wanted by the
>>       user. We can hence switch to the _interruptible variant of
>>       wait_for_completion. This leads to a little bit more handling to also
>>       handle the interrupted case but looks really acceptable overall.
>>
>>       While at it, we drop the useless, noisy and redundant WARN_ON() call."
>>
>> This calculation is actually wrong by factor 1000. A 20MHz SPI bus is not
>> really slow and it will transfer ~2.5MB/s over a single lane.
>> The calculation would be right for 20kHz but I think this is a more
>> esoteric case, isn't it?
>
> Some of the sums are wrong, but the conclusion might be right.
> A 4MB transfer at 20MHz only has 5 clocks/byte - seems low if it
> is only using 1 data bit.

Can't really follow. Each data bit requires one clock on single wire
SPI. Adressing and the like may require a bit of overhead but that
should not be that much (12.5%?).

> The spi devices usually support 'nibble mode' for read/write that
> will speed things up - provided the data lines are connected.

We use SPI (single wire) in our devices with ~40MHz (older hat even just
12MHz) and we never had issues with transfers lasting to long. This is
because file systems transfer much smaller blocks in the multi kB range.

The speed is ~4-5 MB/s with ~40MHz - with 20MHz it would be half.

> OTOH a better fix is (probably) to do the transfer in sane sized chunks.
> The extra interrupt and code won't make much difference to something
> that takes that long.

Exactly. This is what file systems usually do.

- ron
Mark Brown Dec. 1, 2023, 2:16 p.m. UTC | #13
On Mon, 27 Nov 2023 10:58:41 +0100, Miquel Raynal wrote:
> The intended move from wait_for_completion_*() to
> wait_for_completion_interruptible_*() was to allow (very) long spi memory
> transfers to be stopped upon user request instead of freezing the
> machine forever as the timeout value could now be significantly bigger.
> 
> However, depending on the user logic, applications can receive many
> signals for their own "internal" purpose and have nothing to do with the
> requested kernel operations, hence interrupting spi transfers upon any
> signal is probably not a wise choice. Instead, let's switch to
> wait_for_completion_killable_*() to only catch the "important"
> signals. This was likely the intended behavior anyway.
> 
> [...]

Applied to

   https://git.kernel.org/pub/scm/linux/kernel/git/broonie/sound.git for-next

Thanks!

[1/2] spi: atmel: Do not cancel a transfer upon any signal
      commit: 595d2639451d3490c545c644ece726a0410ad39b
[2/2] spi: atmel: Drop unused defines
      commit: 28d8051efae17b6d83544f3c1cf06f6a71677e91

All being well this means that it will be integrated into the linux-next
tree (usually sometime in the next 24 hours) and sent to Linus during
the next merge window (or sooner if it is a bug fix), however if
problems are discovered then the patch may be dropped or reverted.

You may get further e-mails resulting from automated or manual testing
and review of the tree, please engage with people reporting problems and
send followup patches addressing any issues that are reported if needed.

If any updates are required or you are submitting further changes they
should be sent as incremental updates against current git, existing
patches will not be replaced.

Please add any relevant lists and maintainers to the CCs when replying
to this mail.

Thanks,
Mark
Ronald Wahl Dec. 4, 2023, 11:54 a.m. UTC | #14
On 01.12.23 14:38, Ronald Wahl wrote:
> On 01.12.23 12:13, David Laight wrote:
>> [You don't often get email from david.laight@aculab.com. Learn why
>> this is important at https://aka.ms/LearnAboutSenderIdentification ]
>>
>> ...
>>> Anyway, the whole issue started with commit e0205d6203c2 "spi: atmel:
>>> Prevent
>>> false timeouts on long transfers". Citing the commit message here:
>>>       "spi: atmel: Prevent false timeouts on long transfers
>>>
>>>       A slow SPI bus clocks at ~20MHz, which means it would transfer
>>> about
>>>       2500 bytes per second with a single data line. Big transfers,
>>> like when
>>>       dealing with flashes can easily reach a few MiB. The current DMA
>>> timeout
>>>       is set to 1 second, which means any working transfer of about
>>> 4MiB will
>>>       always be cancelled.
>>>
>>>       With the above derivations, on a slow bus, we can assume every
>>> byte
>>> will
>>>       take at most 0.4ms. Said otherwise, we could add 4ms to the
>>> 1-second
>>>       timeout delay every 10kiB. On a 4MiB transfer, it would bring the
>>>       timeout delay up to 2.6s which still seems rather acceptable for a
>>>       timeout.
>>>
>>>       The consequence of this is that long transfers might be
>>> allowed, which
>>>       hence requires the need to interrupt the transfer if wanted by the
>>>       user. We can hence switch to the _interruptible variant of
>>>       wait_for_completion. This leads to a little bit more handling
>>> to also
>>>       handle the interrupted case but looks really acceptable overall.
>>>
>>>       While at it, we drop the useless, noisy and redundant WARN_ON()
>>> call."
>>>
>>> This calculation is actually wrong by factor 1000. A 20MHz SPI bus is
>>> not
>>> really slow and it will transfer ~2.5MB/s over a single lane.
>>> The calculation would be right for 20kHz but I think this is a more
>>> esoteric case, isn't it?
>>
>> Some of the sums are wrong, but the conclusion might be right.
>> A 4MB transfer at 20MHz only has 5 clocks/byte - seems low if it
>> is only using 1 data bit.
>
> Can't really follow. Each data bit requires one clock on single wire
> SPI. Adressing and the like may require a bit of overhead but that
> should not be that much (12.5%?).
>
>> The spi devices usually support 'nibble mode' for read/write that
>> will speed things up - provided the data lines are connected.
>
> We use SPI (single wire) in our devices with ~40MHz (older hat even just
> 12MHz) and we never had issues with transfers lasting to long. This is
> because file systems transfer much smaller blocks in the multi kB range.
>
> The speed is ~4-5 MB/s with ~40MHz - with 20MHz it would be half.
>
>> OTOH a better fix is (probably) to do the transfer in sane sized chunks.
>> The extra interrupt and code won't make much difference to something
>> that takes that long.
>
> Exactly. This is what file systems usually do.

Anyway, at the moment the code breaks at least two file systems
(JFFS2, UBIFS) and probably more. So I request the following:

Revert e0205d6203c2 "spi: atmel: Prevent false timeouts on long transfers"
and the two new patches that are already added to one or more devel trees
[1/2] spi: atmel: Do not cancel a transfer upon any signal
       commit: 595d2639451d3490c545c644ece726a0410ad39b
[2/2] spi: atmel: Drop unused defines
       commit: 28d8051efae17b6d83544f3c1cf06f6a71677e91

Any potential improvements can then be done without hurry.

- ron
David Laight Dec. 4, 2023, 12:19 p.m. UTC | #15
...
> >> This calculation is actually wrong by factor 1000. A 20MHz SPI bus is not
> >> really slow and it will transfer ~2.5MB/s over a single lane.
> >> The calculation would be right for 20kHz but I think this is a more
> >> esoteric case, isn't it?
> >
> > Some of the sums are wrong, but the conclusion might be right.
> > A 4MB transfer at 20MHz only has 5 clocks/byte - seems low if it
> > is only using 1 data bit.
> 
> Can't really follow. Each data bit requires one clock on single wire
> SPI. Adressing and the like may require a bit of overhead but that
> should not be that much (12.5%?).

That is for 4MB in one second at 20MHz.

An SPI read transfer can be pretty much any length - you just keep
on clocking out data. The overhead is independent of the length.

A memory cell just reminded me that some SPI devices are made
of two (or more) memory blocks - and you can't do sequential
reads from one block to the next.
(It might be lying...)

	David

-
Registered Address Lakeside, Bramley Road, Mount Farm, Milton Keynes, MK1 1PT, UK
Registration No: 1397386 (Wales)
Mark Brown Dec. 4, 2023, 12:26 p.m. UTC | #16
On Mon, Dec 04, 2023 at 12:54:50PM +0100, Ronald Wahl wrote:

> Revert e0205d6203c2 "spi: atmel: Prevent false timeouts on long transfers"
> and the two new patches that are already added to one or more devel trees
> [1/2] spi: atmel: Do not cancel a transfer upon any signal
>       commit: 595d2639451d3490c545c644ece726a0410ad39b
> [2/2] spi: atmel: Drop unused defines
>       commit: 28d8051efae17b6d83544f3c1cf06f6a71677e91

If you want to submit changes please follow the process in
submitting-patches.rst.
Ronald Wahl Dec. 4, 2023, 12:39 p.m. UTC | #17
On 04.12.23 13:26, Mark Brown wrote:
> On Mon, Dec 04, 2023 at 12:54:50PM +0100, Ronald Wahl wrote:
>
>> Revert e0205d6203c2 "spi: atmel: Prevent false timeouts on long transfers"
>> and the two new patches that are already added to one or more devel trees
>> [1/2] spi: atmel: Do not cancel a transfer upon any signal
>>        commit: 595d2639451d3490c545c644ece726a0410ad39b
>> [2/2] spi: atmel: Drop unused defines
>>        commit: 28d8051efae17b6d83544f3c1cf06f6a71677e91
>
> If you want to submit changes please follow the process in
> submitting-patches.rst.

I can actually do this but I wanted to give Miquel the chance to do the
work.

- ron
Mark Brown Dec. 4, 2023, 3:47 p.m. UTC | #18
On Mon, 27 Nov 2023 10:58:41 +0100, Miquel Raynal wrote:
> The intended move from wait_for_completion_*() to
> wait_for_completion_interruptible_*() was to allow (very) long spi memory
> transfers to be stopped upon user request instead of freezing the
> machine forever as the timeout value could now be significantly bigger.
> 
> However, depending on the user logic, applications can receive many
> signals for their own "internal" purpose and have nothing to do with the
> requested kernel operations, hence interrupting spi transfers upon any
> signal is probably not a wise choice. Instead, let's switch to
> wait_for_completion_killable_*() to only catch the "important"
> signals. This was likely the intended behavior anyway.
> 
> [...]

Applied to

   https://git.kernel.org/pub/scm/linux/kernel/git/broonie/spi.git for-next

Thanks!

[1/2] spi: atmel: Do not cancel a transfer upon any signal
      commit: 1ca2761a7734928ffe0678f88789266cf3d05362
[2/2] spi: atmel: Drop unused defines
      commit: 49d8575ca6135a533218e40ddcb85462fd9ff1d2

All being well this means that it will be integrated into the linux-next
tree (usually sometime in the next 24 hours) and sent to Linus during
the next merge window (or sooner if it is a bug fix), however if
problems are discovered then the patch may be dropped or reverted.

You may get further e-mails resulting from automated or manual testing
and review of the tree, please engage with people reporting problems and
send followup patches addressing any issues that are reported if needed.

If any updates are required or you are submitting further changes they
should be sent as incremental updates against current git, existing
patches will not be replaced.

Please add any relevant lists and maintainers to the CCs when replying
to this mail.

Thanks,
Mark
Miquel Raynal Dec. 5, 2023, 7:49 a.m. UTC | #19
Hi Ronald,

> >>> I fear this is a jffs2 (summary feature) bug. Chances are great that yo  
> u're able
> >>> to trigger the very same using a sudden loss of power.
> >>>  
> >>>> It's not just spi-atmel, any spi-mem controller might be tempted to us  
> e
> >>>> interruptible^Wkillable transfers just because the timeout values can
> >>>> be really big as the memory sizes increase.
> >>>>
> >>>> One solution is to change the completion helpers back to something
> >>>> non-killable/non-interruptible, but the user experience will be
> >>>> slightly degraded. The other would be to look into jffs2 (if it's the
> >>>> only filesystem playing with signals during unmount, tbh I don't know)  
> .
> >>>> But maybe this signaling mechanism can't be hacked for compatibility
> >>>> reasons. Handling this at the spi level would be a mix of layers, I'm
> >>>> not ready for that.
> >>>>
> >>>> Richard, Mark, what's your opinion here?  
> >>>
> >>> I *think* we can remove the signal handling code from jffs2 since it ma  
> kes
> >>> already use of the kthread_should_stop() API.
> >>> That way we can keep the SPI transfer interruptible by signals.
> >>> ...reading right now into the history to figure better.  
> >>
> >> After a brief discussion with dwmw2 another question came up, if an spi transfer
> >> is cancelled, *all* other IO do the filesystem has to stop too.
> >> IO can happen concurrently, if only one IO path dies but the other ones can
> >> make progress, the filesystem becomes inconsistent and all hope is lost.
> >>
> >> Miquel, is this guaranteed by your changes?  
> >
> > Absolutely not, the changes are in a spi controller, there is nothing
> > specific to the user there. If a filesystem transfer get interrupted,
> > it's the filesystem responsibility to cancel the other IOs if that's
> > relevant for its own consistency?  
> 
> I think yes. But the only thing the FS can do is stop any writes from now
> on which is not a useful consequence of killing a process.
> 
> Anyway, the whole issue started with commit e0205d6203c2 "spi: atmel:
> Prevent
> false timeouts on long transfers". Citing the commit message here:
>      "spi: atmel: Prevent false timeouts on long transfers
> 
>      A slow SPI bus clocks at ~20MHz, which means it would transfer about
>      2500 bytes per second with a single data line. Big transfers, like whe
> n
>      dealing with flashes can easily reach a few MiB. The current DMA
> timeout
>      is set to 1 second, which means any working transfer of about 4MiB wil
> l
>      always be cancelled.
> 
>      With the above derivations, on a slow bus, we can assume every byte
> will
>      take at most 0.4ms. Said otherwise, we could add 4ms to the 1-second
>      timeout delay every 10kiB. On a 4MiB transfer, it would bring the
>      timeout delay up to 2.6s which still seems rather acceptable for a
>      timeout.
> 
>      The consequence of this is that long transfers might be allowed, which
>      hence requires the need to interrupt the transfer if wanted by the
>      user. We can hence switch to the _interruptible variant of
>      wait_for_completion. This leads to a little bit more handling to also
>      handle the interrupted case but looks really acceptable overall.
> 
>      While at it, we drop the useless, noisy and redundant WARN_ON() call."
> 
> This calculation is actually wrong by factor 1000. A 20MHz SPI bus is not
> really slow and it will transfer ~2.5MB/s over a single lane.
> The calculation would be right for 20kHz but I think this is a more
> esoteric case, isn't it?

Please, I would appreciate if you would adopt a more constructive
approach. Yes I am the ugly villain who broke your setup and I am sorry
about that. But let's face the reality:

- Filesystems being sensible to user signals is probably not an ideal
  choice but this was made a decade ago, so there is no blame here,
  but IMO it was not straightforward to think about this case.
  Anyway, as rightfully pointed out by David and Richard, there is the
  coherency problem of the filesystem, with which we don't want to
  play.

- The introduction you point above is indeed wrong by a factor
  1000, as the throughput should be 2.5MB/s and not 2.5kB/s, of
  course. But then if we transfer 2.5MB/s don't you feel like a
  transfer of 4MB is actually going to be interrupted for no reason?
  Sorry for messing the commit log, but the problem is real and the
  diff is relevant.

So instead of nervously insisting for a global revert, I believe the
right approach will be to accept 'big' timeout delays for now on spi
transfers and the final fix is probably to remove the
'interruptible/killable' keyword from our waits. And as (the other)
David said, maybe at some point we will decide to split spi transfers
if they are too big, even though heuristics in this case are not
straightforward.

Thanks,
Miquèl
diff mbox series

Patch

diff --git a/drivers/spi/spi-atmel.c b/drivers/spi/spi-atmel.c
index 6aa8adbe4170..2e8860865af9 100644
--- a/drivers/spi/spi-atmel.c
+++ b/drivers/spi/spi-atmel.c
@@ -1336,8 +1336,8 @@  static int atmel_spi_one_transfer(struct spi_controller *host,
 		}
 
 		dma_timeout = msecs_to_jiffies(spi_controller_xfer_timeout(host, xfer));
-		ret_timeout = wait_for_completion_interruptible_timeout(&as->xfer_completion,
-									dma_timeout);
+		ret_timeout = wait_for_completion_killable_timeout(&as->xfer_completion,
+								   dma_timeout);
 		if (ret_timeout <= 0) {
 			dev_err(&spi->dev, "spi transfer %s\n",
 				!ret_timeout ? "timeout" : "canceled");