Extra clock transition when using SPIDEV with longer transactions

[dmc]

I have been debugging strange interactions between a Xavier NX and a SPI-controlled IMU.

When I transfer a single word, such as 16-bits at a time the IMU behaves normally:

The IMU has a feature that allows the user to transfer a ‘burst’ packet between the IMU and the Host. At the end, I see that the SPI controller will de-assert the clock before the chip select is sent high:

this can be interpreted as a falling edge in the IMU and it is not the correct behavior:

Zoomed out to show the entire packet:

Zoomed in to show the clock transition before CS is de-asserted (set high):

I don’t believe I am doing anything out of the ordinary while configuring a transfer, Here is a relevant snippet of the code:

  m_spi_transfer[0].tx_buf = (unsigned long)tx_buf;
  m_spi_transfer[0].rx_buf = (unsigned long)rx_buf;
  m_spi_transfer[0].cs_change = 0;
  m_spi_transfer[0].len = 22;
  m_spi_transfer[0].bits_per_word = 16;

...

rv = ioctl(spidev_fd, SPI_IOC_MESSAGE(1), m_spi_transfer);

Here is my SPI configuration:

SPI Dev Configuration
  SPI Dev Path:     /dev/spid
  32-bit Read Mode: 3
  LSB First:        no
  Bits Per Word:    16
  Max Speed:        100

Here is my spidev dtsi file:

/*
 * Copyright (c) 2017, NVIDIA CORPORATION.  All rights reserved.
 *
 * This program is free software; you can redistribute it and/or modify
 * it under the terms of the GNU General Public License as published by
 * the Free Software Foundation; either version 2 of the License, or
 * (at your option) any later version.
 *
 * This program is distributed in the hope that it will be useful, but WITHOUT
 * ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or
 * FITNESS FOR A PARTICULAR PURPOSE.  See the GNU General Public License for
 * more details.
 */

#include <dt-bindings/gpio/tegra-gpio.h>

/ {
  spi@3230000{ /* SPI3 in 40 pin conn */
    status = "okay";
    spi-max-frequency = <50000000>;
    //nvidia,polling-mode = <1>;
    nvidia,polling-mode = <0>;
    //nvidia,clock-always-on
    //nvidia,maximum-dma-buffer-size

    spi@0 { /* chip select 0 */
      compatible = "tegra-spidev";
      reg = <0x0>;
      spi-max-frequency = <50000000>;
      //spi-max-frequency = <65000000>;
      //spi-max-frequency = <25000000>; /* 25MHz */
      controller-data {
        nvidia,enable-hw-based-cs;
        nvidia,rx-clk-tap-delay = <0x10>;
        //nvidia,rx-clk-tap-delay = <0x20>;
        nvidia,tx-clk-tap-delay = <0x0>;
        //nvidia,tx-clk-tap-delay = <0x20>;

        //Configurable Values

        //nvidia,cs-setup-clk-count = <0x01>;
        //nvidia,cs-hold-clk-count = <0x01>;
        //nvidia,cs-inactive-cycles = <0x20>;
        //nvidia,clk-delay-between-packets = <0x08>;

      };
    };

    spi@1 { /* chips select 1 */
      compatible = "tegra-spidev";
      reg = <0x1>;
      spi-max-frequency = <50000000>;
      controller-data {
        nvidia,enable-hw-based-cs;
        nvidia,rx-clk-tap-delay = <0x10>;
        nvidia,tx-clk-tap-delay = <0x0>;
      };
    };
  };
};

Is there some configuration value that I didn’t set correctly?

Thanks for any help.

Dave

[DaneLLL]

Hi,
Please add prints in tegra_spi_start_dma_based_transfer() to check if the fucntion is called. And if it is called, please check what value is set to dma_burst. The driver code is in

kernel-5.10/drivers/spi/spi-tegra114.c

[dmc]

Thanks for getting back to me.

Adding the print statement

here is the diff of the spi-tegra114.c

diff --git a/drivers/spi/spi-tegra114.c b/drivers/spi/spi-tegra114.c
index d50705047a02..26895cc5be78 100644
--- a/drivers/spi/spi-tegra114.c
+++ b/drivers/spi/spi-tegra114.c
@@ -634,6 +634,7 @@ static int tegra_spi_start_dma_based_transfer(
        int ret = 0;
        u8 dma_burst;
        struct dma_slave_config dma_sconfig = {0};
+  dev_info(tspi->dev, "Entered Start DMA based transfer\n");

        /* Make sure that Rx and Tx fifo are empty */
        ret = tegra_spi_clear_fifo(tspi);

This is embarrassing, it turns out there was an error I haven’t never noticed before:

Dump of DMESG

[   67.161534] spi-tegra114 3230000.spi: interrupt raised in polling mode
[   67.192502] spi-tegra114 3230000.spi: transfer timeout (polling)
[   67.192791] ------------[ cut here ]------------
[   67.192811] WARNING: CPU: 0 PID: 3048 at drivers/spi/spi-tegra114.c:1461 tegra_spi_transfer_one_message+0x5a0/0xcac [spi_tegra114]
[   67.193084] Modules linked in: fuse aes_ce_ccm rtl8xxxu rtl8192cu rtl_usb rtl8192c_common rtlwifi mac80211 cfg80211 snd_soc_tegra210_ope snd_soc_tegra186_asrc snd_soc_tegra210_iqc snd_soc_tegra186_dspk snd_soc_tegra210_mvc snd_soc_tegra186_arad snd_soc_tegra210_afc snd_soc_tegra210_amx snd_soc_tegra210_dmic snd_soc_tegra210_adx snd_soc_tegra210_i2s snd_soc_tegra210_mixer ofpart snd_soc_tegra210_admaif cmdlinepart qspi_mtd snd_soc_tegra210_sfc snd_soc_tegra_pcm mtd xt_conntrack xt_MASQUERADE nf_conntrack_netlink nfnetlink xt_addrtype iptable_filter iptable_nat nf_nat nf_conntrack nf_defrag_ipv6 nf_defrag_ipv4 libcrc32c br_netfilter aes_ce_blk crypto_simd cryptd aes_ce_cipher ghash_ce sha2_ce sha256_arm64 sha1_ce lzo_rle lzo_compress zram overlay leds_gpio snd_soc_spdif_tx snd_soc_tegra_machine_driver snd_soc_tegra210_adsp realtek snd_soc_tegra_utils snd_soc_simple_card_utils nvadsp loop max77620_thermal tegra210_adma snd_soc_tegra210_ahub snd_hda_codec_hdmi spidev tegra_bpmp_thermal
[   67.193339]  userspace_alert ina3221 snd_hda_tegra pwm_fan snd_hda_codec imx265 snd_hda_core imx265_fpga nvgpu spi_tegra114 spi_tegra210_qspi binfmt_misc nvmap ramoops reed_solomon ip_tables x_tables
[   67.193401] CPU: 0 PID: 3048 Comm: adis-imu-contro Tainted: G           OE     5.10.104-tegra #3
[   67.193406] Hardware name: Unknown NVIDIA Jetson Xavier NX Developer Kit/NVIDIA Jetson Xavier NX Developer Kit, BIOS 1.0-d7fb19b 08/10/2022
[   67.193412] pstate: 60400009 (nZCv daif +PAN -UAO -TCO BTYPE=--)
[   67.193422] pc : tegra_spi_transfer_one_message+0x5a0/0xcac [spi_tegra114]
[   67.193430] lr : tegra_spi_transfer_one_message+0xbb4/0xcac [spi_tegra114]
[   67.193434] sp : ffff80001f94ba60
[   67.193440] x29: ffff80001f94ba60 x28: ffff73b8d4caaf80
[   67.193450] x27: ffff73b8cf6fe680 x26: ffff73bc3fe9a3a0
[   67.193461] x25: 00000000000f4240 x24: 0000000000000001
[   67.193471] x23: ffff73b8cf6fe680 x22: 0000000000000000
[   67.193498] x21: ffff73b8ee161800 x20: ffff73b8cf6fe680
[   67.193508] x19: ffff73b8ee17fe00 x18: 0000000000000010
[   67.193518] x17: 0000000000000000 x16: 0000000000000000
[   67.193541] x15: ffff73b8fba83f70 x14: ffffffffffffffff
[   67.193551] x13: ffff80009f94b667 x12: ffff80001f94b66f
[   67.193561] x11: 0000000000000003 x10: 0101010101010101
[   67.193585] x9 : 00000000fffffffe x8 : 3332332034313161
[   67.193595] x7 : 726765742d697073 x6 : c0000000ffffefff
[   67.193605] x5 : 0000000000000000 x4 : ffff73bc3fd9b958
[   67.193615] x3 : ffff73bc3fdaab08 x2 : 0000000000000000
[   67.193649] x1 : 0000000000000000 x0 : 0000000000000000
[   67.193660] Call trace:
[   67.193669]  tegra_spi_transfer_one_message+0x5a0/0xcac [spi_tegra114]
[   67.193680]  __spi_pump_messages+0x374/0x830
[   67.193686]  __spi_sync+0x2a4/0x2e0
[   67.193692]  spi_sync+0x38/0x60
[   67.193700]  spidev_sync+0x50/0x80 [spidev]
[   67.193707]  spidev_message+0x3dc/0x5e0 [spidev]
[   67.193714]  spidev_ioctl+0x764/0xba0 [spidev]
[   67.193723]  __arm64_sys_ioctl+0xac/0xf0
[   67.193732]  el0_svc_common.constprop.0+0x80/0x1d0
[   67.193739]  do_el0_svc+0x38/0xb0
[   67.193748]  el0_svc+0x1c/0x30
[   67.193754]  el0_sync_handler+0xa8/0xb0
[   67.193760]  el0_sync+0x16c/0x180
[   67.193765] ---[ end trace f873c89474799f94 ]---
[   67.193928] spi-tegra114 3230000.spi: spi transfer timeout, err 0
[   67.194765] spi_master spi2: failed to transfer one message from queue

In the serial console I see the following relevant messages:

[   67.161534] spi-tegra114 3230000.spi: interrupt raised in polling mode
[   67.192502] spi-tegra114 3230000.spi: transfer timeout (polling)
[   67.192811] WARNING: CPU: 0 PID: 3048 at drivers/spi/spi-tegra114.c:1461 tegra_spi_transfer_one_message+0x5a0/0xcac [spi_tegra114]
[   67.193765] ---[ end trace f873c89474799f94 ]---
[   67.193928] spi-tegra114 3230000.spi: spi transfer timeout, err 0
[   67.194765] spi_master spi2: failed to transfer one message from queue

Some observations

Since I see there are messages relating to polling I’m removing it and running again:

Removed Polling Mode

I removed the ‘Polling Mode’ flag and it stopped the kernel error, I see no messages on either dmesg or the serial console but the problem still persists. I added more print statements but I don’t want to fill this post with all the intermediate steps I went through, here is where I am currently:

Skipping Ahead

I’ve added more print statements and now here is the diff of the spi-tegra114.c

diff --git a/drivers/spi/spi-tegra114.c b/drivers/spi/spi-tegra114.c
index d50705047a02..771fd226a5aa 100644
--- a/drivers/spi/spi-tegra114.c
+++ b/drivers/spi/spi-tegra114.c
@@ -634,6 +634,7 @@ static int tegra_spi_start_dma_based_transfer(
 	int ret = 0;
 	u8 dma_burst;
 	struct dma_slave_config dma_sconfig = {0};
+  dev_info(tspi->dev, "Entered Start DMA based transfer\n");
 
 	/* Make sure that Rx and Tx fifo are empty */
 	ret = tegra_spi_clear_fifo(tspi);
@@ -735,6 +736,7 @@ static int tegra_spi_start_cpu_based_transfer(
 	u32 val;
 	unsigned cur_words;
 	int ret;
+  dev_info(tspi->dev, "Entered Start CPU based transfer\n");
 
 	ret = tegra_spi_clear_fifo(tspi);
 	if (ret != 0)
@@ -1496,11 +1498,17 @@ static int tegra_spi_transfer_one_message(struct spi_controller *ctrl,
 		msg->actual_length += xfer->len;
 
 complete_xfer:
-		if (prefer_last_used_cs)
+    dev_info(tspi->dev, "xfer_1_msg: Complete Transfer\n");
+		if (prefer_last_used_cs){
+      dev_info(tspi->dev, "xfer_1_msg: prefer last used cs\n");
 			cmd1 = tspi->command1_reg;
-		else
+    }
+		else{
+      dev_info(tspi->dev, "xfer_1_msg: NOT prefer last used cs\n");
 			cmd1 = tspi->def_command1_reg;
+    }
 		if (ret < 0 || skip) {
+      dev_info(tspi->dev, "xfer_1_msg: ret: %d, skip: %s\n", ret, skip ? "yes": "no");
 			if (cstate && cstate->cs_gpio_valid)
 				gpio_set_value(spi->cs_gpio, gval);
 			tegra_spi_writel(tspi, cmd1, SPI_COMMAND1);
@@ -1508,6 +1516,7 @@ static int tegra_spi_transfer_one_message(struct spi_controller *ctrl,
 			goto exit;
 		} else if (list_is_last(&xfer->transfer_list,
 					&msg->transfers)) {
+      dev_info(tspi->dev, "xfer_1_msg: List is last\n");
 			if (xfer->cs_change)
 				tspi->cs_control = spi;
 			else {
@@ -1517,6 +1526,7 @@ static int tegra_spi_transfer_one_message(struct spi_controller *ctrl,
 				tegra_spi_transfer_delay(xfer->delay_usecs);
 			}
 		} else if (xfer->cs_change) {
+      dev_info(tspi->dev, "xfer_1_msg: CS Change\n");
 			if (cstate && cstate->cs_gpio_valid)
 				gpio_set_value(spi->cs_gpio, gval);
 			tegra_spi_writel(tspi, cmd1, SPI_COMMAND1);
@@ -1526,14 +1536,19 @@ static int tegra_spi_transfer_one_message(struct spi_controller *ctrl,
 	}
 	ret = 0;
 exit:
-	if (prefer_last_used_cs)
+	if (prefer_last_used_cs){
+    dev_info(tspi->dev, "xfer_1_msg: Exit, prefer last used cs\n");
 		cmd1 = SPI_CMD1_GR_MASK & tspi->command1_reg;
-	else
+  }
+	else{
+    dev_info(tspi->dev, "xfer_1_msg: Exit, NOT prefer last used cs\n");
 		cmd1 = tegra_spi_readl(tspi, SPI_COMMAND1);
+  }
 	/* CS de-assert is required before clock
 	 * goes to it's default state.
 	 */
 	if (!tspi->is_hw_based_cs) {
+    dev_info(tspi->dev, "xfer_1_msg: Exit, NOT HW BASED CS, De-assert CS\n");
 		if (spi->mode & SPI_CS_HIGH) {
 			/* Active high. Reset the value to make it deactive */
 			cmd1 &= ~SPI_CS_SW_VAL;
@@ -1544,11 +1559,14 @@ static int tegra_spi_transfer_one_message(struct spi_controller *ctrl,
 	}
 
 	tegra_spi_writel(tspi, cmd1, SPI_COMMAND1);
-	if (!prefer_last_used_cs)
+	if (!prefer_last_used_cs){
+    dev_info(tspi->dev, "xfer_1_msg: Exit, NOT prefer last used cs, send command: 0x%08X\n", tspi->def_command1_reg);
 		tegra_spi_writel(tspi, tspi->def_command1_reg, SPI_COMMAND1);
+  }
 
 	msg->status = ret;
 	spi_finalize_current_message(ctrl);
+  dev_info(tspi->dev, "xfer_1_msg: Exit, Exiting with status: %d\n", ret);
 	return ret;
 }
 
@@ -1583,6 +1601,7 @@ static irqreturn_t handle_cpu_based_xfer(struct tegra_spi_data *tspi)
 		tspi->cur_pos = tspi->cur_rx_pos;
 
 	if (tspi->cur_pos == t->len) {
+    dev_info(tspi->dev, "CpuXfer: CUR POS == LEN\n");
 		complete(&tspi->xfer_completion);
 		goto exit;
 	}
@@ -1721,6 +1740,7 @@ static int tegra_spi_status_poll(struct tegra_spi_data *tspi)
 static irqreturn_t tegra_spi_isr_thread(int irq, void *context_data)
 {
 	struct tegra_spi_data *tspi = context_data;
+  dev_info(tspi->dev, "spi_threaded_isr entered\n");
 
 	if (!tspi->is_curr_dma_xfer)
 		return handle_cpu_based_xfer(tspi);
@@ -1734,7 +1754,9 @@ static irqreturn_t tegra_spi_isr(int irq, void *context_data)
 	if (tspi->polling_mode)
 		dev_warn(tspi->dev, "interrupt raised in polling mode\n");
 
+
 	tspi->status_reg = tegra_spi_readl(tspi, SPI_FIFO_STATUS);
+  dev_info(tspi->dev, "spi_isr entered, FIFO status: 0x%08X\n", tspi->status_reg);
 	if (tspi->cur_direction & DATA_DIR_TX)
 		tspi->tx_status = tspi->status_reg &
 					(SPI_TX_FIFO_UNF | SPI_TX_FIFO_OVF);

I’ve reduced the number of SPI transactions so the application terminates when it transfers one large packet, this will help with the number of messages received.

[  310.783980] spi-tegra114 3230000.spi: Entered Start CPU based transfer
[  310.784113] spi-tegra114 3230000.spi: spi_isr entered, FIFO status: 0x00C00004
[  310.784165] spi-tegra114 3230000.spi: spi_threaded_isr entered
[  310.784179] spi-tegra114 3230000.spi: CpuXfer: CUR POS == LEN
[  310.790287] spi-tegra114 3230000.spi: xfer_1_msg: Complete Transfer
[  310.790296] spi-tegra114 3230000.spi: xfer_1_msg: NOT prefer last used cs
[  310.790301] spi-tegra114 3230000.spi: xfer_1_msg: List is last
[  310.790306] spi-tegra114 3230000.spi: xfer_1_msg: Exit, NOT prefer last used cs
[  310.790314] spi-tegra114 3230000.spi: xfer_1_msg: Exit, NOT HW BASED CS, De-assert CS
[  310.790322] spi-tegra114 3230000.spi: xfer_1_msg: Exit, NOT prefer last used cs, send command: 0x40C08000
[  310.791090] spi-tegra114 3230000.spi: xfer_1_msg: Exit, Exiting with status: 0
[  310.792532] spi-tegra114 3230000.spi: Entered Start CPU based transfer
[  310.792600] spi-tegra114 3230000.spi: spi_isr entered, FIFO status: 0x00C00004
[  310.792712] spi-tegra114 3230000.spi: spi_threaded_isr entered
[  310.792721] spi-tegra114 3230000.spi: CpuXfer: CUR POS == LEN
[  310.793096] spi-tegra114 3230000.spi: xfer_1_msg: Complete Transfer
[  310.793103] spi-tegra114 3230000.spi: xfer_1_msg: NOT prefer last used cs
[  310.793108] spi-tegra114 3230000.spi: xfer_1_msg: List is last
[  310.793113] spi-tegra114 3230000.spi: xfer_1_msg: Exit, NOT prefer last used cs
[  310.793121] spi-tegra114 3230000.spi: xfer_1_msg: Exit, NOT prefer last used cs, send command: 0x40C08000
[  310.793575] spi-tegra114 3230000.spi: xfer_1_msg: Exit, Exiting with status: 0
[  311.229065] spi-tegra114 3230000.spi: Entered Start CPU based transfer
[  311.229146] spi-tegra114 3230000.spi: spi_isr entered, FIFO status: 0x00C00004
[  311.229181] spi-tegra114 3230000.spi: spi_threaded_isr entered
[  311.229193] spi-tegra114 3230000.spi: CpuXfer: CUR POS == LEN
[  311.229235] spi-tegra114 3230000.spi: xfer_1_msg: Complete Transfer
[  311.229246] spi-tegra114 3230000.spi: xfer_1_msg: NOT prefer last used cs
[  311.229255] spi-tegra114 3230000.spi: xfer_1_msg: List is last
[  311.229263] spi-tegra114 3230000.spi: xfer_1_msg: Exit, NOT prefer last used cs
[  311.229274] spi-tegra114 3230000.spi: xfer_1_msg: Exit, NOT prefer last used cs, send command: 0x40C08000
[  311.231682] spi-tegra114 3230000.spi: xfer_1_msg: Exit, Exiting with status: 0
[  311.243216] spi-tegra114 3230000.spi: Entered Start CPU based transfer
[  311.243291] spi-tegra114 3230000.spi: spi_isr entered, FIFO status: 0x00C00004
[  311.243314] spi-tegra114 3230000.spi: spi_threaded_isr entered
[  311.243323] spi-tegra114 3230000.spi: CpuXfer: CUR POS == LEN
[  311.243397] spi-tegra114 3230000.spi: xfer_1_msg: Complete Transfer
[  311.243404] spi-tegra114 3230000.spi: xfer_1_msg: NOT prefer last used cs
[  311.243409] spi-tegra114 3230000.spi: xfer_1_msg: List is last
[  311.243413] spi-tegra114 3230000.spi: xfer_1_msg: Exit, NOT prefer last used cs
[  311.243421] spi-tegra114 3230000.spi: xfer_1_msg: Exit, NOT prefer last used cs, send command: 0x40C08000
[  311.245802] spi-tegra114 3230000.spi: xfer_1_msg: Exit, Exiting with status: 0
[  311.260508] spi-tegra114 3230000.spi: Entered Start CPU based transfer
[  311.260628] spi-tegra114 3230000.spi: spi_isr entered, FIFO status: 0x00C00004
[  311.260653] spi-tegra114 3230000.spi: spi_threaded_isr entered
[  311.260662] spi-tegra114 3230000.spi: CpuXfer: CUR POS == LEN
[  311.260738] spi-tegra114 3230000.spi: xfer_1_msg: Complete Transfer
[  311.260745] spi-tegra114 3230000.spi: xfer_1_msg: NOT prefer last used cs
[  311.260750] spi-tegra114 3230000.spi: xfer_1_msg: List is last
[  311.260755] spi-tegra114 3230000.spi: xfer_1_msg: Exit, NOT prefer last used cs
[  311.260763] spi-tegra114 3230000.spi: xfer_1_msg: Exit, NOT prefer last used cs, send command: 0x40C08000
[  311.262455] spi-tegra114 3230000.spi: xfer_1_msg: Exit, Exiting with status: 0
[  311.264362] spi-tegra114 3230000.spi: Entered Start CPU based transfer
[  311.264434] spi-tegra114 3230000.spi: spi_isr entered, FIFO status: 0x00C00004
[  311.264533] spi-tegra114 3230000.spi: spi_threaded_isr entered
[  311.264544] spi-tegra114 3230000.spi: CpuXfer: CUR POS == LEN
[  311.265340] spi-tegra114 3230000.spi: xfer_1_msg: Complete Transfer
[  311.265349] spi-tegra114 3230000.spi: xfer_1_msg: NOT prefer last used cs
[  311.265354] spi-tegra114 3230000.spi: xfer_1_msg: List is last
[  311.265360] spi-tegra114 3230000.spi: xfer_1_msg: Exit, NOT prefer last used cs
[  311.265369] spi-tegra114 3230000.spi: xfer_1_msg: Exit, NOT prefer last used cs, send command: 0x40C08000
[  311.266588] spi-tegra114 3230000.spi: xfer_1_msg: Exit, Exiting with status: 0
[  311.269491] spi-tegra114 3230000.spi: Entered Start CPU based transfer
[  311.269558] spi-tegra114 3230000.spi: spi_isr entered, FIFO status: 0x00C00004
[  311.269582] spi-tegra114 3230000.spi: spi_threaded_isr entered
[  311.269591] spi-tegra114 3230000.spi: CpuXfer: CUR POS == LEN
[  311.269646] spi-tegra114 3230000.spi: xfer_1_msg: Complete Transfer
[  311.269653] spi-tegra114 3230000.spi: xfer_1_msg: NOT prefer last used cs
[  311.269658] spi-tegra114 3230000.spi: xfer_1_msg: List is last
[  311.269663] spi-tegra114 3230000.spi: xfer_1_msg: Exit, NOT prefer last used cs
[  311.269670] spi-tegra114 3230000.spi: xfer_1_msg: Exit, NOT prefer last used cs, send command: 0x40C08000
[  311.271221] spi-tegra114 3230000.spi: xfer_1_msg: Exit, Exiting with status: 0
[  311.272851] spi-tegra114 3230000.spi: Entered Start CPU based transfer
[  311.272915] spi-tegra114 3230000.spi: spi_isr entered, FIFO status: 0x00C00004
[  311.272936] spi-tegra114 3230000.spi: spi_threaded_isr entered
[  311.272944] spi-tegra114 3230000.spi: CpuXfer: CUR POS == LEN
[  311.273021] spi-tegra114 3230000.spi: xfer_1_msg: Complete Transfer
[  311.273028] spi-tegra114 3230000.spi: xfer_1_msg: NOT prefer last used cs
[  311.273033] spi-tegra114 3230000.spi: xfer_1_msg: List is last
[  311.273038] spi-tegra114 3230000.spi: xfer_1_msg: Exit, NOT prefer last used cs
[  311.273045] spi-tegra114 3230000.spi: xfer_1_msg: Exit, NOT prefer last used cs, send command: 0x40C08000
[  311.274473] spi-tegra114 3230000.spi: xfer_1_msg: Exit, Exiting with status: 0
[  311.276176] spi-tegra114 3230000.spi: Entered Start CPU based transfer
[  311.276241] spi-tegra114 3230000.spi: spi_isr entered, FIFO status: 0x00C00004
[  311.276266] spi-tegra114 3230000.spi: spi_threaded_isr entered
[  311.276273] spi-tegra114 3230000.spi: CpuXfer: CUR POS == LEN
[  311.277193] spi-tegra114 3230000.spi: xfer_1_msg: Complete Transfer
[  311.277201] spi-tegra114 3230000.spi: xfer_1_msg: NOT prefer last used cs
[  311.277206] spi-tegra114 3230000.spi: xfer_1_msg: List is last
[  311.277210] spi-tegra114 3230000.spi: xfer_1_msg: Exit, NOT prefer last used cs
[  311.277218] spi-tegra114 3230000.spi: xfer_1_msg: Exit, NOT prefer last used cs, send command: 0x40C08000
[  311.278232] spi-tegra114 3230000.spi: xfer_1_msg: Exit, Exiting with status: 0
[  311.279242] spi-tegra114 3230000.spi: Entered Start CPU based transfer
[  311.279305] spi-tegra114 3230000.spi: spi_isr entered, FIFO status: 0x00C00004
[  311.279332] spi-tegra114 3230000.spi: spi_threaded_isr entered
[  311.279340] spi-tegra114 3230000.spi: CpuXfer: CUR POS == LEN
[  311.279506] spi-tegra114 3230000.spi: xfer_1_msg: Complete Transfer
[  311.279513] spi-tegra114 3230000.spi: xfer_1_msg: NOT prefer last used cs
[  311.279518] spi-tegra114 3230000.spi: xfer_1_msg: List is last
[  311.279523] spi-tegra114 3230000.spi: xfer_1_msg: Exit, NOT prefer last used cs
[  311.279531] spi-tegra114 3230000.spi: xfer_1_msg: Exit, NOT prefer last used cs, send command: 0x40C08000
[  311.280932] spi-tegra114 3230000.spi: xfer_1_msg: Exit, Exiting with status: 0
[  311.293071] spi-tegra114 3230000.spi: Entered Start CPU based transfer
[  311.293311] spi-tegra114 3230000.spi: spi_isr entered, FIFO status: 0x03400004
[  311.293338] spi-tegra114 3230000.spi: spi_threaded_isr entered
[  311.293353] spi-tegra114 3230000.spi: CpuXfer: CUR POS == LEN
[  311.293646] spi-tegra114 3230000.spi: xfer_1_msg: Complete Transfer
[  311.293653] spi-tegra114 3230000.spi: xfer_1_msg: NOT prefer last used cs
[  311.293658] spi-tegra114 3230000.spi: xfer_1_msg: List is last
[  311.293663] spi-tegra114 3230000.spi: xfer_1_msg: Exit, NOT prefer last used cs
[  311.293670] spi-tegra114 3230000.spi: xfer_1_msg: Exit, NOT HW BASED CS, De-assert CS
[  311.293676] spi-tegra114 3230000.spi: xfer_1_msg: Exit, NOT prefer last used cs, send command: 0x40C08000
[  311.295433] spi-tegra114 3230000.spi: xfer_1_msg: Exit, Exiting with status: 0

Looking at the SPI_FIFO_STATUS_0 register received within the ISR, I decoded it:

According to the SPI_FIFO_STATUS_0 register in the TRM:
Status: 0x00C00004
bit 2: 1 = TX_FIFO_EMPTY
bits 22:16: TX_FIFO_EMPTY_COUNT: 0x40
bits 29:23: RX_FIFO_FULL_COUNT: 0x01

Status: 0x03400004
bits 2: 1 = TX_FIFO_EMPTY
bits 22: 16: TX_FIFO_EMPTY_COUNT: 0x40
bits 29:23: RX_FIFO_FULL_COUNT: 0x06

Observations

I just verified that the 11 word large transfer was the last transaction and the error occurs when the TX FIFO status register says: 0x03400004

1 word transfer: Status: 0x00C00004
11 word transfer: Status: 0x03400004

This line is interesting:

[  311.293670] spi-tegra114 3230000.spi: xfer_1_msg: Exit, NOT HW BASED CS, De-assert CS

it corresponds to these lines:

  /* CS de-assert is required before clock
   * goes to it's default state.
   */
  if (!tspi->is_hw_based_cs) {
    dev_info(tspi->dev, "xfer_1_msg: Exit, NOT HW BASED CS, De-assert CS\n");
    if (spi->mode & SPI_CS_HIGH) {
      /* Active high. Reset the value to make it deactive */
      cmd1 &= ~SPI_CS_SW_VAL;
    } else {
      /* Active low. Set the value to make it deactive */
      cmd1 |= SPI_CS_SW_VAL;
    }
  }

  tegra_spi_writel(tspi, cmd1, SPI_COMMAND1);

The CS line is being set high but the clock has already, seemingly, gone to a ‘default’ state on the larger transaction. If anyone has any suggestions I’ll try it out.

I’ll dig into this more.

Dave

[dmc]

If I set ‘cs_change’ in the transfer function then it works!

I’m still trying to understand this but here is my idea:

Within the function ‘tegra_spi_setup_transfer_one’ there is the following check:

static u32 tegra_spi_setup_transfer_one(struct spi_device *spi,
          struct spi_transfer *t,
          bool is_first_of_msg,
          bool is_single_xfer)
{
...
    if (cdata && cdata->is_hw_based_cs && is_single_xfer &&

        ((tspi->curr_dma_words * tspi->bytes_per_word) ==
         (t->len - tspi->cur_pos))) {

      tegra_spi_set_timing1(spi);
      tspi->is_hw_based_cs = true;
    }
...

This disables the hardware CS control when the ‘is_single_xfer’ is set to false, presumably because it is a larger transfer, it looks like the ‘wait_for_completion_timeout’ within tegra_spi_transfer_one_message waits for the entire transaction to finish.

Then after the label ‘complete_xfer’ there is a check to see if this is the last transfer:

static int tegra_spi_transfer_one_message(struct spi_controller *ctrl,
            struct spi_message *msg)
{
...
    } else if (list_is_last(&xfer->transfer_list,
          &msg->transfers)) {
      dev_info(tspi->dev, "xfer_1_msg: List is last\n");
      if (xfer->cs_change)
        tspi->cs_control = spi;
      else {
        if (cstate && cstate->cs_gpio_valid)
          gpio_set_value(spi->cs_gpio, gval);
        tegra_spi_writel(tspi, cmd1, SPI_COMMAND1);
        tegra_spi_transfer_delay(xfer->delay_usecs);
      }
    } 
...

This checks if ‘cs_change’ is set, if not then it lets the cs stay active, I looked up how ‘spi_transfer’ is supposed to behave here: Kernel SPI Summary

...hinting whether the next message is likely to go to this same device … using the spi_transfer.cs_change flag on the last transfer in that atomic group, and potentially saving costs for chip deselect and select operations.

It would make sense to keep the CS low with the assumption that there will be further transactions but this behavior changes between a small transfer and a larger one.

I would assume if the CS is software-controlled then this functionality should be available (single transfer and longer transfer) but for hardware-based CS control seems that it should allow the driver to disable it.

[DaneLLL]

Hi,
Thanks for the sharing. One thing may be related is this setting in spi-tegra114.c of Jetpack 5 :

		val |= SPI_TX_TRIG_16 | SPI_RX_TRIG_16;
		dma_burst = 16;

In Jetpack 4, maximum burst is

		val |= SPI_TX_TRIG_8 | SPI_RX_TRIG_8;
		maxburst = 8;

Would like to suggest remove setting dma_burst to 16 for a try. But you have worked out a solution, so this may not be the cause.

[dmc]

Thanks for getting back to me,

Since I have a decent setup it would be interesting to explore this:

here is my change in spi-tegra114.c

  /* Set attention level based on length of transfer */
  if (len & 0xF) {
    val |= SPI_TX_TRIG_1 | SPI_RX_TRIG_1;
    dma_burst = 1;
  } else if (((len) >> 4) & 0x1) {
    val |= SPI_TX_TRIG_4 | SPI_RX_TRIG_4;
    dma_burst = 4;
  //} else if (((len) >> 5) & 0x1) {
  }else {
    val |= SPI_TX_TRIG_8 | SPI_RX_TRIG_8;
    dma_burst = 8;
  //} else {
  //  val |= SPI_TX_TRIG_16 | SPI_RX_TRIG_16;
  //  dma_burst = 16;
  }

Looking at a 16-bit transaction here is a capture with cs_change set to ‘0’:

Here is what happens when the cs_change is set to ‘1’:

It looks like there is no discernable change between the two ‘cs_change’ settings.

It does look like the cs de-asserting is timing out and but the clock line is not going low before the timeout happens on a 16-bit capture in contrast to the 11 x 16-bit capture.

As a reference this is what it looks like when the dma_burst goes up to 16-bits (before I changed the dma_burst to 8):

Let me know if you want me to try something else.

Thanks,
Dave