Re: MCP2518FD Drivers Rarely Working with Custom Kernel 5.10.Y

Marc,

I tried adding "#define DEBUG" to the top of spi-bcm2835.c, but I
don't see any additional logging in the output of dmesg. Any other
ideas? Anything you all notice in the Saleae data worth mentioning?

Thanks!

Josh Q

On Fri, Jun 25, 2021 at 12:55 PM Joshua Quesenberry [off-list ref] wrote:

Forgive me, I forgot can0 = spi0.1 and can1 = spi0.0 right now because I killed my UDEV rule so I was tapped onto the wrong CS line. Attached is a snapshot of what I'm seeing AND an export of the data from Saleae which may prove more useful than snapshots.

Thanks,

Josh Q

-----Original Message-----
From: Joshua Quesenberry <redacted>
Sent: Friday, June 25, 2021 11:56 AM
To: 'Marc Kleine-Budde' <mkl@pengutronix.de>
Cc: 'Patrick Menschel' <redacted>; kernel@pengutronix.de; linux-can@vger.kernel.org; engnfrc@gmail.com
Subject: RE: MCP2518FD Drivers Rarely Working with Custom Kernel 5.10.Y

Marc,

I had already switched back to the normal clock speed in a previous email, so should be good there. It's been a while, but we're pushing the RPi pretty hard and either there was a drop in overall resource usage or it was a matter of less dropped video frames (which is something we strive to minimize for the research we do) from the three USB cameras. At the moment I've got all the add-ons turned off and the load is minimal.

I was able to get my hands on a Saleae and am attaching a snapshot of what happens when I run the ip link command. I am noticing that the chip select is never being toggled right now with the ip link command failing... so that just might be our root issue. So what can we do to figure out WHY the chip select isn't acting as expected?

I have probes attached to the following for CAN0:

Pin Function
19  SPI0_MOSI
21  SPI0_MISO
23  SPI0_SCLK
24  GPIO8 / CS0

Thanks,

Josh Q

-----Original Message-----
From: Marc Kleine-Budde <mkl@pengutronix.de>
Sent: Friday, June 25, 2021 8:17 AM
To: Joshua Quesenberry <redacted>
Cc: 'Patrick Menschel' <redacted>; kernel@pengutronix.de; linux-can@vger.kernel.org
Subject: Re: MCP2518FD Drivers Rarely Working with Custom Kernel 5.10.Y

On 25.06.2021 08:56:26, Marc Kleine-Budde wrote:

quoted

On 23.06.2021 13:34:10, Joshua Quesenberry wrote:

quoted

I added printing the error number as Marc suggested and the number
appears to be -110 every time.

#define       ETIMEDOUT       110     /* Connection timed out */
https://elixir.bootlin.com/linux/latest/source/include/uapi/asm-generi
c/errno.h#L93

That means something has timed out, we see this in the previous log
message, too:

quoted

[   25.660006] CAN device driver interface
[   25.668720] spi_master spi0: will run message pump with realtime
priority
[   25.676697] mcp251xfd spi0.1 can0: MCP2518FD rev0.0
(-RX_INT -MAB_NO_WARN +CRC_REG +CRC_RX +CRC_TX +ECC -HD c:40.00MHz
m:20.00MHz r:17.00MHz e:16.66MHz) successfully initialized.
[   25.684900] mcp251xfd spi0.0 can1: MCP2518FD rev0.0
(-RX_INT -MAB_NO_WARN +CRC_REG +CRC_RX +CRC_TX +ECC -HD c:40.00MHz
m:20.00MHz r:17.00MHz e:16.66MHz) successfully initialized.
[   28.098033] mcp251xfd spi0.1 rename4: renamed from can0
[   28.175644] mcp251xfd spi0.0 can0: renamed from can1
[   28.225891] mcp251xfd spi0.1 can1: renamed from rename4

                                   VVVVVVVVVVVVVVVVVVVVVV

quoted

[  146.964971] mcp251xfd spi0.0: SPI transfer timed out [
146.965023] spi_master spi0: failed to transfer one message from
queue (ret=-110)

quoted

[  146.965216] mcp251xfd spi0.0 can0: CRC read error at address
0x0e0c (length=4, data=00 00 00 00, CRC=0x0000) retrying.
[  146.965247] mcp251xfd spi0.0 can0: CRC read error at address
0x0e0c (length=4, data=00 00 00 00, CRC=0x0000) retrying.
[  146.965277] mcp251xfd spi0.0 can0: CRC read error at address
0x0e0c (length=4, data=00 00 00 00, CRC=0x0000) retrying.
[  146.965286] mcp251xfd spi0.0 can0: CRC read error at address
0x0e0c (length=4, data=00 00 00 00, CRC=0x0000).
[  146.965331] mcp251xfd spi0.0 can0: CRC read error at address
0x0000 (length=4, data=00 00 00 00, CRC=0x0000) retrying.
[  146.965360] mcp251xfd spi0.0 can0: CRC read error at address
0x0000 (length=4, data=00 00 00 00, CRC=0x0000) retrying.
[  146.965389] mcp251xfd spi0.0 can0: CRC read error at address
0x0000 (length=4, data=00 00 00 00, CRC=0x0000) retrying.
[  146.965397] mcp251xfd spi0.0 can0: CRC read error at address
0x0000 (length=4, data=00 00 00 00, CRC=0x0000).
[  146.965413] A link change request failed with some changes
committed already. Interface can0 may have been left with an
inconsistent configuration, please check.

Regarding the discussion about Kconfig flags, I went ahead and
rebuilt kernel 5.10.44 using a config that was essentially
arch/arm/configs/bcm2711_defconfig with these additions needed to
get our I2S working. This should have undone the switch to ONDEMAND
governor and enabling 1000 Hz clock.

Please switch back the clock to the standard HZ setting.

I compiled my 64 bit raspi kernel with HZ=1000 and my mcp2518fd board works without problem on my raspi4b.

| static int bcm2835_spi_transfer_one_poll(struct spi_controller *ctlr,
|                                        struct spi_device *spi,
|                                        struct spi_transfer *tfr,
|                                        u32 cs)
| {
[...]
|       /* set the timeout to at least 2 jiffies */
|       timeout = jiffies + 2 + HZ * polling_limit_us / 1000000;

The timeout is calculated in jiffies. The jiffies variable is incremented once per timer tick (which depends on the clock HZ configuration). There are "HZ" jiffies per second. This means the above "2" equals 8ms (HZ=250), but with HZ=1000 only 2ms.

To keep the timeout constant, you can change this into:

        timeout = jiffies + (HZ * 8) / 1000 + HZ * polling_limit_us / 1000000;

However, the polling mode will only be used for transfers that should finish in 30 µs. So even 2ms is far of...

|
|       /* loop until finished the transfer */
|       while (bs->rx_len) {
|               /* fill in tx fifo with remaining data */
|               bcm2835_wr_fifo(bs);
|
|               /* read from fifo as much as possible */
|               bcm2835_rd_fifo(bs);
|
|               /* if there is still data pending to read
|                * then check the timeout
|                */
|               if (bs->rx_len && time_after(jiffies, timeout)) {

If there is a timeout, the driver will fall back to IRQ mode.


Can you add a "#define DEBUG" in spi-bcm2835.c, even before the other "#include" directives. That should give you this debug message:

|                       dev_dbg_ratelimited(&spi->dev,
|                                           "timeout period reached: jiffies: %lu remaining tx/rx: %d/%d
| -
falling back to interrupt mode\n",
|                                           jiffies - timeout,
|                                           bs->tx_len, bs->rx_len);
|                       /* fall back to interrupt mode */
|
|                       /* update usage statistics */
|                       bs->count_transfer_irq_after_polling++;
|
|                       return bcm2835_spi_transfer_one_irq(ctlr, spi,
|                                                           tfr, cs, false);

here it activates the IRQ. But I'm not sure if the fallback works correctly....

|               }
|       }
|

Marc

--
Pengutronix e.K.                 | Marc Kleine-Budde           |
Embedded Linux                   | https://www.pengutronix.de  |
Vertretung West/Dortmund         | Phone: +49-231-2826-924     |
Amtsgericht Hildesheim, HRA 2686 | Fax:   +49-5121-206917-5555 |