| 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 |
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
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
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
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
----- 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
----- 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
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
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
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
----- 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
... > 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)
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
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
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
... > >> 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)
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.
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
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
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 --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");
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(-)