5.11.0-rc1+: "Division by zero in kernel." when writing to spidev

5.11.0-rc1+: "Division by zero in kernel." when writing to spidev

[Vincent Pelletier]

Hello,

I am somehow triggering a division by zero when writing to spidev
(a pair of traces at the end of this email).

This kernel was built from Linus's tree as of:
commit 139711f033f636cc78b6aaf7363252241b9698ef
Merge: dea8dcf2a9fa 1f3147b49d75
Author: Linus Torvalds <torvalds@linux-foundation.org>
Date:   Tue Dec 29 15:45:49 2020 -0800

   Merge branch 'akpm' (patches from Andrew)

targeting a raspberry pi zero w (armv6l), with the device tree rebuilt
with dtc's "-@" option and the overlay pasted below applied on top of the
vanilla device tree by the bootloader, precisely to enable the spi bus
and declare one SPI device (with a dirty hack to get spidev to handle
the device without having to patch the kernel...).

I am not a devicetree expert, so I may be doing something dumb
(besides twisting spidev's arm to get it to do what I want).
I cannot at a glance map the div-by-zero traceback to the source
code: I do not see a division in the mentioned functions at all,
so I could not debug this further on my own so far.

This code is working with 5.9.11 (as of Debian sid from a few days ago).

I picked an rc kernel to test an unrelated patch (one-liner in
drivers/usb/dwc2/gadget.c provided by its maintainer).

At a glance I do not find a related fix in linus's tree (I do see a
div-by-zero fix, but in networking).

The code triggering the issue is a simple open-devfile-then-write
implemented in python, without any SPI-specific ioctl to configure
the device beyond what devicetree is already setting up. I know
python does one ioctl on every opened file, although I do not remember
which one (I remember it being about detecting whether the file is a
terminal).

/dts-v1/;
/plugin/;

/ {
 compatible = "brcm,bcm2835";
};

&gpio {
 alt0 {
   brcm,pins = <4 5>; // removed 7, 8, 9, 10, 11
 };
 spi0_cs_pins: spi0_cs_pins {
   brcm,function = <1>; // out
   brcm,pins = <7 8>;
 };
 spi0_pins: spi0_pins {
   brcm,function = <4>; // alt0
   brcm,pins = <9 10 11>;
 };
};

&spi {
 cs-gpios = <&gpio 8 0x01>, <&gpio 7 0x01>; // CE0 is gpio 8, CE1 is
gpio 7, both active low
 status = "okay";
 pinctrl-0 = <&spi0_cs_pins &spi0_pins>;
 pinctrl-names = "default";
 #address-cells = <1>;
 #size-cells = <0>;
 spidev@0 {
   // "waveshare,epaper-display-v1": because that's what it really is.
   // "rohm,dh2228fv": because this triggers spidev to handle this device.
   compatible = "waveshare,epaper-display-v1", "rohm,dh2228fv";
   reg = <0>; // uses CS0
   #address-cells = <1>;
   #size-cells = <0>;
   spi-max-frequency = <4000000>; // 4MHz: tcycle >= 250ns
 };
};

[  +2.762703] Division by zero in kernel.
[  +0.004106] CPU: 0 PID: 262 Comm: smartcard-openp Tainted: G
C  E     5.11.0-rc1+ #16
[  +0.008861] Hardware name: BCM2835
[  +0.003520] Backtrace:
[  +0.002574] [<c0883d1c>] (dump_backtrace) from [<c08840c4>]
(show_stack+0x20/0x24)
[  +0.007892]  r7:c1fd1df4 r6:c1fd1e2c r5:c372cc00 r4:c0a43d94
[  +0.005866] [<c08840a4>] (show_stack) from [<c08875c8>] (dump_stack+0x28/0x30)
[  +0.007495] [<c08875a0>] (dump_stack) from [<c0883e9c>] (__div0+0x20/0x28)
[  +0.007158]  r5:c372cc00 r4:00000000
[  +0.003728] [<c0883e7c>] (__div0) from [<c04ae4cc>] (Ldiv0+0x8/0x10)
[  +0.006618] [<c05e34a4>] (spi_transfer_one_message) from
[<c05e540c>] (__spi_pump_messages+0x45c/0x6e8)
[  +0.009811]  r10:c1192e10 r9:c1192e10 r8:c1fd1e18 r7:c1fd1df4
r6:c05e9228 r5:c1fd1da0
[  +0.008114]  r4:c372cc00
[  +0.002659] [<c05e4fb0>] (__spi_pump_messages) from [<c05e58d0>]
(__spi_sync+0x214/0x23c)
[  +0.008509]  r10:c1fd1e18 r9:60000013 r8:c372cc00 r7:c05e1e60
r6:c372cc00 r5:c372c000
[  +0.008095]  r4:c1fd1df4
[  +0.002658] [<c05e56bc>] (__spi_sync) from [<c05e592c>] (spi_sync+0x34/0x4c)
[  +0.007345]  r10:00000051 r9:c2724000 r8:c1167550 r7:c1167540
r6:00000001 r5:c1fd1df4
[  +0.008093]  r4:c372c000
[  +0.002620] [<c05e58f8>] (spi_sync) from [<c05e73d0>]
(spidev_sync_write+0xb8/0xf8)
[  +0.007948]  r5:c1167540 r4:c1fd1df4
[  +0.005745] [<c05e7318>] (spidev_sync_write) from [<c05e74d0>]
(spidev_write+0xc0/0x138)
[  +0.012392]  r6:b5b3d0d8 r5:00000000 r4:00000001
[  +0.006846] [<c05e7410>] (spidev_write) from [<c0310e90>]
(vfs_write+0xf4/0x418)
[  +0.009722]  r10:00000000 r9:c05e7410 r8:00000000 r7:b5b3d0d8
r6:00000001 r5:c2829b40
[  +0.010160]  r4:00000000 r3:00000000
[  +0.005781] [<c0310d9c>] (vfs_write) from [<c0311390>] (ksys_write+0xc4/0xfc)
[  +0.009493]  r9:c1fd0000 r8:c0100244 r7:b5b3d0d8 r6:00000001
r5:c2829b40 r4:c2829b40
[  +0.010065] [<c03112cc>] (ksys_write) from [<c03113e0>] (sys_write+0x18/0x1c)
[  +0.009534]  r7:00000004 r6:b6fee7e0 r5:b6fee7d0 r4:00000003
[  +0.007999] [<c03113c8>] (sys_write) from [<c0100060>]
(ret_fast_syscall+0x0/0x58)
[  +0.009984] Exception stack(0xc1fd1fa8 to 0xc1fd1ff0)
[  +0.007393] 1fa0:                   00000003 b6fee7d0 00000003
b5b3d0d8 00000001 00000000
[  +0.012702] 1fc0: 00000003 b6fee7d0 b6fee7e0 00000004 00000003
0099bfd8 00000000 00490f20
[  +0.012833] 1fe0: b6fae328 beed3460 b6fae334 b6fae350
[  +0.043666] Division by zero in kernel.
[  +0.006298] CPU: 0 PID: 262 Comm: smartcard-openp Tainted: G
C  E     5.11.0-rc1+ #16
[  +0.013146] Hardware name: BCM2835
[  +0.005666] Backtrace:
[  +0.004655] [<c0883d1c>] (dump_backtrace) from [<c08840c4>]
(show_stack+0x20/0x24)
[  +0.009977]  r7:c1fd1df4 r6:c1fd1e2c r5:c372cc00 r4:c0a43d94
[  +0.007930] [<c08840a4>] (show_stack) from [<c08875c8>] (dump_stack+0x28/0x30)
[  +0.009568] [<c08875a0>] (dump_stack) from [<c0883e9c>] (__div0+0x20/0x28)
[  +0.009236]  r5:c372cc00 r4:00000000
[  +0.005772] [<c0883e7c>] (__div0) from [<c04ae4cc>] (Ldiv0+0x8/0x10)
[  +0.008670] [<c05e34a4>] (spi_transfer_one_message) from
[<c05e540c>] (__spi_pump_messages+0x45c/0x6e8)
[  +0.013782]  r10:c1192e10 r9:c1192e10 r8:c1fd1e18 r7:c1fd1df4
r6:c05e9228 r5:c1fd1da0
[  +0.010143]  r4:c372cc00
[  +0.004686] [<c05e4fb0>] (__spi_pump_messages) from [<c05e58d0>]
(__spi_sync+0x214/0x23c)
[  +0.012613]  r10:c1fd1e18 r9:60000013 r8:c372cc00 r7:c05e1e60
r6:c372cc00 r5:c372c000
[  +0.010171]  r4:c1fd1df4
[  +0.004735] [<c05e56bc>] (__spi_sync) from [<c05e592c>] (spi_sync+0x34/0x4c)
[  +0.009421]  r10:00000051 r9:c2724000 r8:c1167550 r7:c1167540
r6:00000002 r5:c1fd1df4
[  +0.010200]  r4:c372c000
[  +0.004730] [<c05e58f8>] (spi_sync) from [<c05e73d0>]
(spidev_sync_write+0xb8/0xf8)
[  +0.010053]  r5:c1167540 r4:c1fd1df4
[  +0.005796] [<c05e7318>] (spidev_sync_write) from [<c05e74d0>]
(spidev_write+0xc0/0x138)
[  +0.012553]  r6:b5b60348 r5:00000000 r4:00000002
[  +0.006847] [<c05e7410>] (spidev_write) from [<c0310e90>]
(vfs_write+0xf4/0x418)
[  +0.009740]  r10:00000000 r9:c05e7410 r8:00000000 r7:b5b60348
r6:00000002 r5:c2829b40
[  +0.010147]  r4:00000000 r3:00000000
[  +0.005819] [<c0310d9c>] (vfs_write) from [<c0311390>] (ksys_write+0xc4/0xfc)
[  +0.009508]  r9:c1fd0000 r8:c0100244 r7:b5b60348 r6:00000002
r5:c2829b40 r4:c2829b40
[  +0.010048] [<c03112cc>] (ksys_write) from [<c03113e0>] (sys_write+0x18/0x1c)
[  +0.009516]  r7:00000004 r6:b6fee7e0 r5:b6fee7d0 r4:00000003
[  +0.007967] [<c03113c8>] (sys_write) from [<c0100060>]
(ret_fast_syscall+0x0/0x58)
[  +0.009975] Exception stack(0xc1fd1fa8 to 0xc1fd1ff0)
[  +0.007392] 1fa0:                   00000003 b6fee7d0 00000003
b5b60348 00000002 00000000
[  +0.012755] 1fc0: 00000003 b6fee7d0 b6fee7e0 00000004 00000003
0099bfd8 00000000 00490f20
[  +0.012845] 1fe0: 0048026c beed3460 b6fae334 b6fae350

Regards,
-- 
Vincent Pelletier

Re: 5.11.0-rc1+: "Division by zero in kernel." when writing to spidev

[Mark Brown]

[-- Attachment #1: Type: text/plain, Size: 301 bytes --]

On Wed, Jan 06, 2021 at 09:55:45PM +0900, Vincent Pelletier wrote:
> Hello,
> 
> I am somehow triggering a division by zero when writing to spidev
> (a pair of traces at the end of this email).

Please check with the latest SPI tree, there were some issues fixed
there that might be relevant.

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 488 bytes --]

Re: 5.11.0-rc1+: "Division by zero in kernel." when writing to spidev

[Vincent Pelletier]

On Wed, Jan 6, 2021 at 10:01 PM Mark Brown <broonie@kernel.org> wrote:
> Please check with the latest SPI tree, there were some issues fixed
> there that might be relevant.

I confirm this fixed the division by zero, thanks for the super-fast reply.

FWIW, I am now getting a "normal" error message now:
[  +1.046688] spidev spi0.0: SPI transfer timed out
[  +0.005210] spi_master spi0: failed to transfer one message from queue
[  +0.922799] spidev spi0.0: SPI transfer timed out
[  +0.012172] spi_master spi0: failed to transfer one message from queue
but it is getting late here and I have not investigated why (my overlay
needs tweaking for 5.11 maybe ?).

Regards,
-- 
Vincent Pelletier

Re: 5.11.0-rc1+: "Division by zero in kernel." when writing to spidev

[Mark Brown]

[-- Attachment #1: Type: text/plain, Size: 687 bytes --]

On Thu, Jan 07, 2021 at 12:06:19AM +0900, Vincent Pelletier wrote:

> FWIW, I am now getting a "normal" error message now:
> [  +1.046688] spidev spi0.0: SPI transfer timed out
> [  +0.005210] spi_master spi0: failed to transfer one message from queue
> [  +0.922799] spidev spi0.0: SPI transfer timed out
> [  +0.012172] spi_master spi0: failed to transfer one message from queue
> but it is getting late here and I have not investigated why (my overlay
> needs tweaking for 5.11 maybe ?).

I wouldn't have thought that would be something in your DT, unless it
was previously buggy and some issue has been exposed, but then nothing
springs to mind as being potentially relevant either.

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 488 bytes --]

Re: 5.11.0-rc1+: "Division by zero in kernel." when writing to spidev

[Vincent Pelletier]

On Thu, Jan 7, 2021 at 2:38 AM Mark Brown <broonie@kernel.org> wrote:
> I wouldn't have thought that would be something in your DT, unless it
> was previously buggy and some issue has been exposed, but then nothing
> springs to mind as being potentially relevant either.

I've started reading spi-bcm2835.c, and while I cannot claim that I understand
everything I'm reading, it raises some flags:
- it does not use "spi_finalize_current_transfer(...)" at all, but rather
  "complete(&...->xfer_completion)". The former only calls the latter,
  so this code seems technically correct, but this looks like an
  abstraction layer bust.
- while it uses "complete(...)" on its IRQ and DMA transfer codepaths,
  I do not see it being called on its polled codepath
  (bcm2835_spi_transfer_one_poll).
- ...polled codepath which checks bs->rx_len to tell when it's done,
  independently of transfer direction. And while tx_len and rx_len are
initialised
  to the same value, only the field actually corresponding to the
actual transfer
  direction will be updated within this polling loop.
  So maybe some transfers could timeout in the polled codepath and would
  still end up in the IRQ one which would end up calling "complete", but this
  looks suspicious.

Checking on 5.10.4, I see:
root@sushi:/sys/kernel/debug/spi-bcm2835-20204000.spi# cat count_transfer_dma
2
root@sushi:/sys/kernel/debug/spi-bcm2835-20204000.spi# cat count_transfer_irq
1
root@sushi:/sys/kernel/debug/spi-bcm2835-20204000.spi# cat
count_transfer_polling
27
root@sushi:/sys/kernel/debug/spi-bcm2835-20204000.spi# cat
count_transfer_irq_after_polling
0

so I am apparently not triggering the poll-then-IRQ case, but am
triggering the others
on this kernel version.

On 5.11, this becomes:
root@sushi:/sys/kernel/debug/spi-bcm2835-20204000.spi# cat count_transfer_dma
2
root@sushi:/sys/kernel/debug/spi-bcm2835-20204000.spi# cat count_transfer_irq
24
root@sushi:/sys/kernel/debug/spi-bcm2835-20204000.spi# cat
count_transfer_polling
0
root@sushi:/sys/kernel/debug/spi-bcm2835-20204000.spi# cat
count_transfer_irq_after_polling
0

so somehow this is not triggering polling transfers anymore, so the
maybe-missing
completion call would probably not matter.

Also, it sets can_dma with a function pointer, but ends up only
checking can_dma as
a boolean and then calls the function by name rather than using the
value stored in
can_dma. Again this looks technically correct (and is very much
unrelated to my issue)
as can_dma does not take any other value and a valid function address would not
evaluate as false, but it is surprising to my naive reading.

I'll continue poking around later (especially checking computed timeout values),
should I submit patches for s/complete/spi_finalize_current_transfer/ ?

Regards,
-- 
Vincent Pelletier

Re: 5.11.0-rc1+: "Division by zero in kernel." when writing to spidev

[Mark Brown]

[-- Attachment #1: Type: text/plain, Size: 3092 bytes --]

On Thu, Jan 07, 2021 at 09:57:01AM +0900, Vincent Pelletier wrote:

> I've started reading spi-bcm2835.c, and while I cannot claim that I understand
> everything I'm reading, it raises some flags:

Copying in a bunch of people for that driver.

> - it does not use "spi_finalize_current_transfer(...)" at all, but rather
>   "complete(&...->xfer_completion)". The former only calls the latter,
>   so this code seems technically correct, but this looks like an
>   abstraction layer bust.

Yes.

> - while it uses "complete(...)" on its IRQ and DMA transfer codepaths,
>   I do not see it being called on its polled codepath
>   (bcm2835_spi_transfer_one_poll).

I'd not expect this to be required with a polled path, it's only needed
if the transfer function returns a positive value indicating that the
transfer is still in progress which shouldn't be the case when things
are polled.

> - ...polled codepath which checks bs->rx_len to tell when it's done,
>   independently of transfer direction. And while tx_len and rx_len are
> initialised
>   to the same value, only the field actually corresponding to the
> actual transfer
>   direction will be updated within this polling loop.
>   So maybe some transfers could timeout in the polled codepath and would
>   still end up in the IRQ one which would end up calling "complete", but this
>   looks suspicious.
> 
> Checking on 5.10.4, I see:
> root@sushi:/sys/kernel/debug/spi-bcm2835-20204000.spi# cat count_transfer_dma
> 2
> root@sushi:/sys/kernel/debug/spi-bcm2835-20204000.spi# cat count_transfer_irq
> 1
> root@sushi:/sys/kernel/debug/spi-bcm2835-20204000.spi# cat
> count_transfer_polling
> 27
> root@sushi:/sys/kernel/debug/spi-bcm2835-20204000.spi# cat
> count_transfer_irq_after_polling
> 0
> 
> so I am apparently not triggering the poll-then-IRQ case, but am
> triggering the others
> on this kernel version.
> 
> On 5.11, this becomes:
> root@sushi:/sys/kernel/debug/spi-bcm2835-20204000.spi# cat count_transfer_dma
> 2
> root@sushi:/sys/kernel/debug/spi-bcm2835-20204000.spi# cat count_transfer_irq
> 24
> root@sushi:/sys/kernel/debug/spi-bcm2835-20204000.spi# cat
> count_transfer_polling
> 0
> root@sushi:/sys/kernel/debug/spi-bcm2835-20204000.spi# cat
> count_transfer_irq_after_polling
> 0
> 
> so somehow this is not triggering polling transfers anymore, so the
> maybe-missing
> completion call would probably not matter.
> 
> Also, it sets can_dma with a function pointer, but ends up only
> checking can_dma as
> a boolean and then calls the function by name rather than using the
> value stored in
> can_dma. Again this looks technically correct (and is very much
> unrelated to my issue)
> as can_dma does not take any other value and a valid function address would not
> evaluate as false, but it is surprising to my naive reading.
> 
> I'll continue poking around later (especially checking computed timeout values),
> should I submit patches for s/complete/spi_finalize_current_transfer/ ?

Probably send the completion patch, yes.

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 488 bytes --]

Re: 5.11.0-rc1+: "Division by zero in kernel." when writing to spidev

[Vincent Pelletier]

[-- Attachment #1: Type: text/plain, Size: 3038 bytes --]

On Thu, 7 Jan 2021 15:35:46 +0000, Mark Brown <broonie@kernel.org> wrote:
> Copying in a bunch of people for that driver.

Thanks.
I added Tudor Ambarus as well as my debugging points in the direction
of:
commit 9326e4f1e5dd1a4410c429638d3c412b6fc17040 (spi/for-5.10)
Author: Tudor Ambarus <tudor.ambarus@microchip.com>
Date:   Wed Dec 9 19:35:14 2020 +0200

    spi: Limit the spi device max speed to controller's max speed

    Make sure the max_speed_hz of spi_device does not override
    the max_speed_hz of controller.

> I'd not expect this to be required with a polled path, it's only needed
> if the transfer function returns a positive value indicating that the
> transfer is still in progress which shouldn't be the case when things
> are polled.

Oh, indeed. And the driver is indeed returning 0 in this case.

> > I'll continue poking around later (especially checking computed timeout values),
> > should I submit patches for s/complete/spi_finalize_current_transfer/ ?  

Reverting 
    spi: Limit the spi device max speed to controller's max speed
fixes the timeout.

Which brings be back to devicetree:
- the controller node does not define the max clock rate
- the device I add in my overlay does define one
So spi->max_speed_hz is initially non-zero, but
spi->controller->max_speed_hz is zero, then:
-       if (!spi->max_speed_hz)
+       if (!spi->max_speed_hz ||
+           spi->max_speed_hz > spi->controller->max_speed_hz)
                spi->max_speed_hz = spi->controller->max_speed_hz;
it becomes zero in 5.11.
Then, because I do not specify a transfer speed in my userland code:
                if (!xfer->speed_hz)
                        xfer->speed_hz = spi->max_speed_hz;
it gets zero instead of the (as of 5.10) 4MHz, which led to my original
division-by-zero issue.

What would be the correct fix ?
- declare controller max clock ?
  If so, I think spi.c should warn about this missing value.
- do not cap transfer speed to controller speed when the latter is
  zero ?
- both ?

My working out, for whatever it's worth:
I ran my userland code under "strace -tt -T" and get:
00:31:21.449837 write(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 4000) = -1 ETIMEDOUT (Connection timed out) <0.885552>
Given the previous divide-by-zero issue, spi.c is now assuming 100kHz,
which for this 4000 bytes buffer means:
  >>> ((8*1000*4000)/100000) * 2 + 200
  844.96
milliseconds, which roughly matches the call duration measured by
strace.
But this device is declared in my DT as supporting transfer rates up to
4MHz (so period of 250ns), which would mean an actual transfer duration
of:
  >>> 4000*8*250e-9
  0.008
assuming bytes being sent back-to-back (which I believe is the case for
SPI, but worst case I do not expect this to multiply the transfer time
by 100...). So there is something wrong with the transfer speed.

> Probably send the completion patch, yes.

Done.

Regards,
-- 
Vincent Pelletier

[-- Attachment #2: Signature digitale OpenPGP --]
[-- Type: application/pgp-signature, Size: 833 bytes --]

Re: 5.11.0-rc1+: "Division by zero in kernel." when writing to spidev

[Fabio Estevam]

Hi Vincent,

On Thu, Jan 7, 2021 at 10:16 PM Vincent Pelletier <plr.vincent@gmail.com> wrote:

> Thanks.
> I added Tudor Ambarus as well as my debugging points in the direction
> of:
> commit 9326e4f1e5dd1a4410c429638d3c412b6fc17040 (spi/for-5.10)
> Author: Tudor Ambarus <tudor.ambarus@microchip.com>
> Date:   Wed Dec 9 19:35:14 2020 +0200
>
>     spi: Limit the spi device max speed to controller's max speed
>
>     Make sure the max_speed_hz of spi_device does not override
>     the max_speed_hz of controller.

There is a fix for this:
https://git.kernel.org/pub/scm/linux/kernel/git/broonie/spi.git/commit/?h=for-linus&id=6820e812dafb4258bc14692f686eec5bde6fba86

Re: 5.11.0-rc1+: "Division by zero in kernel." when writing to spidev

[Vincent Pelletier]

Hello Fabio,

On Thu, 7 Jan 2021 22:53:05 -0300, Fabio Estevam <festevam@gmail.com> wrote:
> There is a fix for this:
> https://git.kernel.org/pub/scm/linux/kernel/git/broonie/spi.git/commit/?h=for-linus&id=6820e812dafb4258bc14692f686eec5bde6fba86

Indeed, and I missed it (I somehow thought there was only one commit
not pulled to Linus' master yet...).

I confirm the issue is fixed as of Linus'

commit f5e6c330254ae691f6d7befe61c786eb5056007e (linus/master)
Merge: a1a7b4f32433 6170d077bf92
Author: Linus Torvalds <torvalds@linux-foundation.org>
Date:   Thu Jan 7 12:21:32 2021 -0800

    Merge tag 'spi-fix-v5.11-rc2' of git://git.kernel.org/pub/scm/linux/kernel/git/broonie/spi

My apologies for the noise.

Regards,
-- 
Vincent Pelletier