Linux/AM3352: SPI CS signal always low

hello

there are some doubts in spi_transfer_one_message function which is in the file drivers/spi/spi.c

......

if (xfer->delay_usecs)

udelay(xfer->delay_usecs);

if (xfer->cs_change) {

if (list_is_last(&xfer->transfer_list,

&msg->transfers)) {

keep_cs = true;  //if it is the last transfer, why set keep_cs to true? if it is true, follow code which was blue will not be executed, and the spi_cs will not be set to false.

} else {

spi_set_cs(msg->spi, false);

udelay(10);

spi_set_cs(msg->spi, true);

}

}

msg->actual_length += xfer->len;

}

out:

if (ret != 0 || !keep_cs)

spi_set_cs(msg->spi, false);

if (msg->status == -EINPROGRESS)

msg->status = ret;

......

is it an error?

Hi Longfei,

I reviewed the AM335x MCSPI driver (linux-kernel/drivers/spi/spi-omap2-mcspi.c) and I see that McSPI_CH(i)CONF [20] FORCE bit can be set to 1 only in function omap2_mcspi_set_cs(). Bit FORCE is set to 1, if SPI_CS_HIGH flag is set to 1, which makes the "active low" default state to be overriden.

Please put printk statements in  omap2_mcspi_set_cs() function and check what values you have there for SPI_CS_HIGH and l.

static void omap2_mcspi_set_cs(struct spi_device *spi, bool enable)
{
    struct omap2_mcspi *mcspi = spi_master_get_devdata(spi->master);
    u32 l;

    /* The controller handles the inverted chip selects
     * using the OMAP2_MCSPI_CHCONF_EPOL bit so revert
     * the inversion from the core spi_set_cs function.
     */
    if (spi->mode & SPI_CS_HIGH)

{

       printk("SPI_CS_HIGH is selected\n");
        enable = !enable;
}
    if (spi->controller_state) {
        int err = pm_runtime_get_sync(mcspi->dev);
        if (err < 0) {
            dev_err(mcspi->dev, "failed to get sync: %d\n", err);
            return;
        }

        l = mcspi_cached_chconf0(spi);

        if (enable)
            l &= ~OMAP2_MCSPI_CHCONF_FORCE;
        else
            l |= OMAP2_MCSPI_CHCONF_FORCE;

          printk("l = %x\n");

         mcspi_write_chconf0(spi, l);

        pm_runtime_mark_last_busy(mcspi->dev);
        pm_runtime_put_autosuspend(mcspi->dev);
    }
}

Hello Pavel Botev
I do the test like you say, the result is that:
printk("SPI_CS_HIGH is selected\n") can't be printed, and printk("l = %x\n") can be printed which is l = 80.

Longfei,

LONGFEI LI said:

printk("SPI_CS_HIGH is selected\n") can't be printed, and printk("l = %x\n") can be printed which is l = 80.

Looks like omap2_mcspi_set_cs() function is NOT setting McSPI_CH0CONF [20] FORCE bit to 1.

Please add below printk() statements and provide the result:

static void omap2_mcspi_set_cs(struct spi_device *spi, bool enable)
{

printk("Enter omap2_mcspi_set_cs()\n");

.....

printk("Exit omap2_mcspi_set_cs()\n");

}

static inline void mcspi_write_chconf0(const struct spi_device *spi, u32 val)
{

 u32 val1;

    printk("Enter mcspi_write_chconf0()\n");
    struct omap2_mcspi_cs *cs = spi->controller_state;

    printk("val = %x\n",val);

    cs->chconf0 = val;
    mcspi_write_cs_reg(spi, OMAP2_MCSPI_CHCONF0, val);
    val1 = mcspi_read_cs_reg(spi, OMAP2_MCSPI_CHCONF0);

    printk("OMAP2_MCSPI_CHCONF0 = %x\n",val1);

   printk("Exit mcspi_write_chconf0()\n");
}

Part Number: AM3352

Tool/software: Linux

Hello

A month ago, I ask this question in this community, following is the last reply from TI engineer:

Looks like omap2_mcspi_set_cs() function is NOT setting McSPI_CH0CONF [20] FORCE bit to 1.

Please add below printk() statements and provide the result:

static void omap2_mcspi_set_cs(struct spi_device *spi, bool enable)
{

printk("Enter omap2_mcspi_set_cs()\n");

.....

printk("Exit omap2_mcspi_set_cs()\n");

}

static inline void mcspi_write_chconf0(const struct spi_device *spi, u32 val)
{

 u32 val1;

    printk("Enter mcspi_write_chconf0()\n");
    struct omap2_mcspi_cs *cs = spi->controller_state;

    printk("val = %x\n",val);

    cs->chconf0 = val;
    mcspi_write_cs_reg(spi, OMAP2_MCSPI_CHCONF0, val);
    val1 = mcspi_read_cs_reg(spi, OMAP2_MCSPI_CHCONF0);

    printk("OMAP2_MCSPI_CHCONF0 = %x\n",val1);

   printk("Exit mcspi_write_chconf0()\n");
}

Because of  some reasons, I didn't do the test. I do the test now, and  this is the result:

[ 1.904067] Enter omap2_mcspi_set_cs()
[ 1.907991] val = 201103fc
[ 1.910889] OMAP2_MCSPI_CHCONF0 = 201103fc
[ 1.915172] Exit mcspi_write_chconf0()
[ 1.919090] Exit omap2_mcspi_set_cs()
[ 1.922943] val = 201103fc
[ 1.925774] OMAP2_MCSPI_CHCONF0 = 201103fc
[ 1.930073] Exit mcspi_write_chconf0()
[ 1.934018] Enter omap2_mcspi_set_cs()
[ 1.937939] val = 200103fc
[ 1.940809] OMAP2_MCSPI_CHCONF0 = 200103fc
[ 1.945094] Exit mcspi_write_chconf0()
[ 1.949012] Exit omap2_mcspi_set_cs()

Longfei,

LONGFEI LI said:

[ 1.940809] OMAP2_MCSPI_CHCONF0 = 200103fc

The last value you have in FORCE bit is 0. Can you check also what value you have in McSPI0.MCSPI_CH0CONF/0x4803012C register in user space? You can use devmem2 tool. Do you need to have FORCE = 0 in user space only, or you need to have FORCE = 0 in kernel also?

Please add also the below prints and provide me the result:

static void omap2_mcspi_set_cs(struct spi_device *spi, bool enable)
{

struct omap2_mcspi *mcspi = spi_master_get_devdata(spi->master);
    u32 l;

    /* The controller handles the inverted chip selects
     * using the OMAP2_MCSPI_CHCONF_EPOL bit so revert
     * the inversion from the core spi_set_cs function.
     */

   +printk("enable = %x\n",enable);
    if (spi->mode & SPI_CS_HIGH)
        enable = !enable;
   +printk("enable = %x\n",enable);

    if (spi->controller_state) {
        int err = pm_runtime_get_sync(mcspi->dev);
        if (err < 0) {
            dev_err(mcspi->dev, "failed to get sync: %d\n", err);
            return;
        }

         +printk("l = %x\n",l);
         l = mcspi_cached_chconf0(spi);
        +printk("l = %x\n",l);

        if (enable)
            l &= ~OMAP2_MCSPI_CHCONF_FORCE;
        else
            l |= OMAP2_MCSPI_CHCONF_FORCE;

        mcspi_write_chconf0(spi, l);

        pm_runtime_mark_last_busy(mcspi->dev);
        pm_runtime_put_autosuspend(mcspi->dev);
    }
}

Hello Pavel Botev
Thanks for your reply first.
Following is the result:
[ 1.722093] omap_voltage_late_init: Voltage driver support not added
[ 1.736128] Enter omap2_mcspi_set_cs()
[ 1.740071] enable = 0
[ 1.742799] enable = 0
[ 1.745273] l = 200103fc
[ 1.747922] l = 201103fc
[ 1.750630] val = 201103fc
[ 1.753465] OMAP2_MCSPI_CHCONF0 = 201103fc
[ 1.757750] Exit mcspi_write_chconf0()
[ 1.761734] Exit omap2_mcspi_set_cs()
[ 1.765576] val = 201103fc
[ 1.768408] OMAP2_MCSPI_CHCONF0 = 201103fc
[ 1.772721] Exit mcspi_write_chconf0()
[ 1.800342] ttysWK4 at I/O 0x1 (irq = 40, base_baud = 230400) is a wk2xxx
[ 1.808003] ttysWK5 at I/O 0x2 (irq = 40, base_baud = 230400) is a wk2xxx
[ 1.815552] ttysWK6 at I/O 0x3 (irq = 40, base_baud = 230400) is a wk2xxx
[ 1.823053] ttysWK7 at I/O 0x4 (irq = 40, base_baud = 230400) is a wk2xxx
[ 1.830571] uart_add_one_port = 0x0
[ 1.834282] register spi return v = :0
[ 1.839676] ubi0: attaching mtd9
[ 2.107705] ubi0: scanning is finished

Maybe you can find there are some different with the front result, It is my mistake, please use this result to analyze the question.

OMAP2_MCSPI_CHCONF0 = 201103fc
It means that FORCE bit is 1, and EPOL bit is 1, then the SPIEN line is to low, it is consistent with my test that I use scope to test the voltage of spi0_cs0.
But I think it is unusual, I want the SPIEN line to high when free.

More test result:

Add the prints in spi_transfer_one_message function:

static int spi_transfer_one_message(struct spi_master *master,

   struct spi_message *msg)

{

struct spi_transfer *xfer;

bool keep_cs = false;

int ret = 0;

unsigned long long ms = 1;

struct spi_statistics *statm = &master->statistics;

struct spi_statistics *stats = &msg->spi->statistics;

spi_set_cs(msg->spi, true);

printk("%s-%d:set cs to true\n",__func__,__LINE__);

SPI_STATISTICS_INCREMENT_FIELD(statm, messages);

SPI_STATISTICS_INCREMENT_FIELD(stats, messages);

list_for_each_entry(xfer, &msg->transfers, transfer_list) {

trace_spi_transfer_start(msg, xfer);

spi_statistics_add_transfer_stats(statm, xfer, master);

spi_statistics_add_transfer_stats(stats, xfer, master);

if (xfer->tx_buf || xfer->rx_buf) {

reinit_completion(&master->xfer_completion);

ret = master->transfer_one(master, msg->spi, xfer);

if (ret < 0) {

SPI_STATISTICS_INCREMENT_FIELD(statm,

      errors);

SPI_STATISTICS_INCREMENT_FIELD(stats,

      errors);

dev_err(&msg->spi->dev,

"SPI transfer failed: %d\n", ret);

goto out;

}

if (ret > 0) {

ret = 0;

ms = 8LL * 1000LL * xfer->len;

do_div(ms, xfer->speed_hz);

ms += ms + 100; /* some tolerance */

if (ms > UINT_MAX)

ms = UINT_MAX;

ms = wait_for_completion_timeout(&master->xfer_completion,

msecs_to_jiffies(ms));

}

if (ms == 0) {

SPI_STATISTICS_INCREMENT_FIELD(statm,

      timedout);

SPI_STATISTICS_INCREMENT_FIELD(stats,

      timedout);

dev_err(&msg->spi->dev,

"SPI transfer timed out\n");

msg->status = -ETIMEDOUT;

}

} else {

if (xfer->len)

dev_err(&msg->spi->dev,

"Bufferless transfer has length %u\n",

xfer->len);

}

trace_spi_transfer_stop(msg, xfer);

if (msg->status != -EINPROGRESS)

goto out;

if (xfer->delay_usecs)

udelay(xfer->delay_usecs);

if (xfer->cs_change) {

if (list_is_last(&xfer->transfer_list,

&msg->transfers)) {

keep_cs = true;

} else {

spi_set_cs(msg->spi, false);

printk("%s-%d:set cs to false\n",__func__,__LINE__);

udelay(10);

spi_set_cs(msg->spi, true);

printk("%s-%d:set cs to ture\n",__func__,__LINE__);

}

}

msg->actual_length += xfer->len;

}

out:

if (ret != 0 || !keep_cs){

spi_set_cs(msg->spi, false);

printk("%s-%d:set cs to false\n",__func__,__LINE__);

}

if (msg->status == -EINPROGRESS)

msg->status = ret;

if (msg->status && master->handle_err)

master->handle_err(master, msg);

spi_res_release(master, msg);

spi_finalize_current_message(master);

return ret;

}

the result of the test is that in spi_transfer_one_message function, only setting cs to true and not set cs to false:

1.730103] enable = 0
[ 1.732830] enable = 0
[ 1.735306] l = 200103fc
[ 1.737954] l = 201103fc
[ 1.740666] val = 201103fc
[ 1.743499] OMAP2_MCSPI_CHCONF0 = 201103fc
[ 1.747782] Exit mcspi_write_chconf0()
[ 1.751764] Exit omap2_mcspi_set_cs()
[ 1.755599] spi_transfer_one_message-985:set cs to true
[ 1.761096] val = 201103fc
[ 1.763927] OMAP2_MCSPI_CHCONF0 = 201103fc
[ 1.768211] Exit mcspi_write_chconf0()
[ 1.800291] ttysWK4 at I/O 0x1 (irq = 40, base_baud = 230400) is a wk2xxx
[ 1.807956] ttysWK5 at I/O 0x2 (irq = 40, base_baud = 230400) is a wk2xxx
[ 1.815489] ttysWK6 at I/O 0x3 (irq = 40, base_baud = 230400) is a wk2xxx
[ 1.823041] ttysWK7 at I/O 0x4 (irq = 40, base_baud = 230400) is a wk2xxx
[ 1.830524] uart_add_one_port = 0x0
[ 1.834237] register spi return v = :0
[ 1.839625] ubi0: attaching mtd9
[ 2.107665] ubi0: scanning is finished

So this can explain why the spi0_cs line is low in my system, the driver of spi slave device use the spi driver to access the spi slave device in probe function.

And I modify the driver of spi slave device(wk2166) that the probe function not use spi driver to read and write the slave device. In the other words, the system only run spi_setup function to set cs to false and not run spi_transfer_one_message function to send message to spi slave device.  The system run up and test voltage of the spi0_cs0 using scope, the spi0_cs0 is high.

So, I think there maybe some error in spi driver, am I right? 

Thanks a lot.

Longfei,

Looking into the spi-omap2-mcspi.c driver, the FORCE bit is setup only when GPIO pin is used for CS (not McSPI CS pin, spi0_cs0). Do you use GPIO pin for CS or not? Please provide me your latest DTS file for review.

Please put also the below printk() and provide me the result:

static int omap2_mcspi_transfer_one(struct spi_master *master,
struct spi_device *spi,
struct spi_transfer *t)
{

if (gpio_is_valid(spi->cs_gpio))
+{
+printk("gpio_is_valid, spi->mode & SPI_CS_HIGH\n");
+printk("spi->cs_gpio = %d\n", spi->cs_gpio);
omap2_mcspi_set_cs(spi, spi->mode & SPI_CS_HIGH);
+}

..............

if (gpio_is_valid(spi->cs_gpio))
+{
+printk("gpio_is_valid, !(spi->mode & SPI_CS_HIGH)\n");
+printk("spi->cs_gpio = %d\n", spi->cs_gpio);
omap2_mcspi_set_cs(spi, !(spi->mode & SPI_CS_HIGH));
+}


Regards,
Pavel

LONGFEI LI said:

So, I think there maybe some error in spi driver, am I right? 

Which SPI driver exactly? spi-omap2-mcspi.c?

I think the error is in your DTS file, SPI node.

Regards,
Pavel

Hello Pavel

I don't use gpio, following is my dts, and add prints in omap2_mcspi_transfer_one function, when system running up, I couldn't get any message of that print. It means the omap2_mcspi_transfer_one function don't run when system up.

spi_transfer_one_message function is in drivers/spi/spi.c

spi0_pins:pinmux_spi0_pins {
pinctrl-single,pins = <
AM33XX_IOPAD(0x950, PIN_INPUT_PULLUP | MUX_MODE0) /* spi0_sclk.spi0_sclk */
AM33XX_IOPAD(0x954, PIN_INPUT_PULLUP | MUX_MODE0) /* spi0_d0.spi0_d0 */
AM33XX_IOPAD(0x958, PIN_INPUT_PULLUP | MUX_MODE0) /* spi0_d1.spi0_d1 */
AM33XX_IOPAD(0x95C, PIN_OUTPUT_PULLUP | MUX_MODE0) /* spi0_cs0.spi0_cs0 */
/*SPI0_IRQ*/
AM33XX_IOPAD(0x97C, PIN_INPUT_PULLUP | MUX_MODE7) /* uart1_rtsn.gpio0_13 */
/*SPI0_RST*/
AM33XX_IOPAD(0x964, PIN_OUTPUT_PULLUP | MUX_MODE7) /* ecap0_in_pwm0_out.gpio0_7 */
>;
};

&spi0 {
pinctrl-names = "default";
pinctrl-0 = <&spi0_pins>;
status = "okay";
/*cs-gpios = <&gpio0 5 GPIO_ACTIVE_LOW>;*/

wk2166@0{
compatible = "wk2xxxspi";
spi-max-frequency = <1000000>;
reg = <0>;
irq-gpio = <&gpio0 13 GPIO_ACTIVE_LOW>;
rst-gpio = <&gpio0 7 GPIO_ACTIVE_LOW>;
};
};

LONGFEI LI said:

I don't use gpio, following is my dts, and add prints in omap2_mcspi_transfer_one function, when system running up, I couldn't get any message of that print. It means the omap2_mcspi_transfer_one function don't run when system up.

spi_transfer_one_message function is in drivers/spi/spi.c

I do not think there is a bug in linux-kernel/drivers/spi/spi.c, but we can trace why FORCE bit is set to 1. Please put the below printk functions and provide me the result:

static void spi_set_cs(struct spi_device *spi, bool enable)
{
    printk("Enter spi_set_cs.\n");

    printk("enable = %d\n",enable);

    if (spi->mode & SPI_CS_HIGH)
        enable = !enable;

   printk("enable = %d\n",enable);

    if (gpio_is_valid(spi->cs_gpio))

{

        printk("gpio_is_valid\n");
        printk("spi->cs_gpio = %d\n",spi->cs_gpio);
        gpio_set_value(spi->cs_gpio, !enable);

}
    else if (spi->master->set_cs)

{

        printk("spi->master->set_cs\n");
        printk("enable = %d\n",enable);      
        spi->master->set_cs(spi, !enable);

}

}

 

static int spi_transfer_one_message(struct spi_master *master,
                    struct spi_message *msg)
{

....

printk("Enter spi_transfer_one_message.\n");

printk("true = %d\n");

printk("invoke spi_set_cs(msg->spi, true) \n");

spi_set_cs(msg->spi, true);

....

if (xfer->cs_change) {

           printk("xfer->cs_change = %d\n",xfer->cs_change);           
            if (list_is_last(&xfer->transfer_list, &msg->transfers)) {
                keep_cs = true;
            } else {

                printk("keep_cs = %d\n",keep_cs);
                spi_set_cs(msg->spi, false);
                udelay(10);
                spi_set_cs(msg->spi, true);
            }
        }

......

out:
    if (ret != 0 || !keep_cs)

{      
        printk("ret != 0 || !keep_cs\n");
       printk("keep_cs = %d\n",keep_cs);
        spi_set_cs(msg->spi, false);

}

 

int spi_setup(struct spi_device *spi)
{

printk("Enter spi_setup.\n");

......

printk("Invoke spi_set_cs(spi, false) \n");

spi_set_cs(spi, false);

}

 

LONGFEI LI said:

wk2166@0{
compatible = "wk2xxxspi";
spi-max-frequency = <1000000>;
reg = <0>;
irq-gpio = <&gpio0 13 GPIO_ACTIVE_LOW>;
rst-gpio = <&gpio0 7 GPIO_ACTIVE_LOW>;
};

This DTS node looks suspicious. compatible entry usually points to a valid driver, while I do not find wk2xxxspi driver in 4.9.69 kernel. See for example below DTS files:

am335x-boneblack-spi0.dtsi -> compatible = "spidev"; -> drivers/spi/spidev.c

am335x-icev2.dts -> compatible = "pisosr-gpio"; -> drivers/gpio/gpio-pisosr.c

am335x-icev2.dts -> compatible = "winbond,w25q64", "jedec,spi-nor"; -> drivers/mtd/devices/m25p80.c

Also I do not find rst-gpio option in 4.9.69 kernel.

Regards,
Pavel

Hello Pavel

Firstly, I need to explain my dts about spi0, wk2166 is an chip whichi is made in china, and this chip is used to expand the serial port(one chip use a spi bus to expand four serial port). The driver of this chip is provided by manufacturer that is not include in linux kernel.

irq-gpio and rst-gpio is added by myself, because the chip need a gpio connect to its irq pin used to respond the chip irq and a gpio connect to chip reset pin used to reset the chip when needed. In wk2166 driver, I used following method to get irq gpio and rst gpio:

   iIrq = of_get_named_gpio(spi->dev.of_node,"irq-gpio",0);

   if(iIrq > 0){

   //printk("irq_gpio=%d\n",iIrq);

   gpio_request(iIrq,"SPI_IRQ");

   gpio_direction_input(iIrq);

   }    

   iRst = of_get_named_gpio(spi->dev.of_node,"rst-gpio",0);

   if(iRst > 0){

   //printk("rst_gpio=%d\n",iRst);

   gpio_request(iRst,"SPI_IRQ");

   gpio_direction_output(iRst,0);

   msleep(1);

   gpio_direction_output(iRst,1);

   }

Secondly, when adding prints as you say, following is the teset result:

[    0.000000] Booting Linux on physical CPU 0x0

[    0.000000] Linux version 4.9.28-geed43d1050 (llf@llf-virtual-machine) (gcc version 6.2.1 20161016 (Linaro GCC 6.2-2016.11) ) #11 PREEMPT Wed Jun 6 11:07:40 CST 2018

[    0.000000] CPU: ARMv7 Processor [413fc082] revision 2 (ARMv7), cr=10c5387d

[    0.000000] CPU: PIPT / VIPT nonaliasing data cache, VIPT aliasing instruction cache

[    0.000000] OF: fdt:Machine model: TI AM335x EVM

[    0.000000] efi: Getting EFI parameters from FDT:

[    0.000000] efi: UEFI not found.

[    0.000000] cma: Reserved 48 MiB at 0x8a800000

[    0.000000] Memory policy: Data cache writeback

[    0.000000] CPU: All CPU(s) started in SVC mode.

[    0.000000] AM335X ES2.1 (neon)

[    0.000000] Built 1 zonelists in Zone order, mobility grouping on.  Total pages: 64960

[    0.000000] Kernel command line: console=ttyO0,115200n8 root=ubi0:rootfs rw ubi.mtd=NAND.file-system,2048 rootfstype=ubifs rootwait=1

[    0.000000] PID hash table entries: 1024 (order: 0, 4096 bytes)

[    0.000000] Dentry cache hash table entries: 32768 (order: 5, 131072 bytes)

[    0.000000] Inode-cache hash table entries: 16384 (order: 4, 65536 bytes)

[    0.000000] Memory: 198348K/262144K available (7168K kernel code, 264K rwdata, 2340K rodata, 1024K init, 276K bss, 14644K reserved, 49152K cma-reserved, 0K highmem)

[    0.000000] Virtual kernel memory layout:

[    0.000000]     vector  : 0xffff0000 - 0xffff1000   (   4 kB)

[    0.000000]     fixmap  : 0xffc00000 - 0xfff00000   (3072 kB)

[    0.000000]     vmalloc : 0xd0800000 - 0xff800000   ( 752 MB)

[    0.000000]     lowmem  : 0xc0000000 - 0xd0000000   ( 256 MB)

[    0.000000]     pkmap   : 0xbfe00000 - 0xc0000000   (   2 MB)

[    0.000000]     modules : 0xbf000000 - 0xbfe00000   (  14 MB)

[    0.000000]       .text : 0xc0008000 - 0xc0800000   (8160 kB)

[    0.000000]       .init : 0xc0b00000 - 0xc0c00000   (1024 kB)

[    0.000000]       .data : 0xc0c00000 - 0xc0c42110   ( 265 kB)

[    0.000000]        .bss : 0xc0c42110 - 0xc0c87234   ( 277 kB)

[    0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=1, Nodes=1

[    0.000000] Preemptible hierarchical RCU implementation.

[    0.000000]  Build-time adjustment of leaf fanout to 32.

[    0.000000] NR_IRQS:16 nr_irqs:16 16

[    0.000000] IRQ: Found an INTC at 0xfa200000 (revision 5.0) with 128 interrupts

[    0.000000] OMAP clockevent source: timer2 at 24000000 Hz

[    0.000020] sched_clock: 32 bits at 24MHz, resolution 41ns, wraps every 89478484971ns

[    0.000049] clocksource: timer1: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 79635851949 ns

[    0.000064] OMAP clocksource: timer1 at 24000000 Hz

[    0.000286] clocksource_probe: no matching clocksources found

[    0.000524] Console: colour dummy device 80x30

[    0.000561] Calibrating delay loop... 597.60 BogoMIPS (lpj=2988032)

[    0.118860] pid_max: default: 32768 minimum: 301

[    0.119033] Mount-cache hash table entries: 1024 (order: 0, 4096 bytes)

[    0.119048] Mountpoint-cache hash table entries: 1024 (order: 0, 4096 bytes)

[    0.120134] CPU: Testing write buffer coherency: ok

[    0.120636] Setting up static identity map for 0x80100000 - 0x80100060

[    0.121808] EFI services will not be available.

[    0.123632] devtmpfs: initialized

[    0.140037] VFP support v0.3: implementor 41 architecture 3 part 30 variant c rev 3

[    0.140513] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604462750000 ns

[    0.140550] futex hash table entries: 256 (order: -1, 3072 bytes)

[    0.145437] pinctrl core: initialized pinctrl subsystem

[    0.147144] NET: Registered protocol family 16

[    0.150007] DMA: preallocated 256 KiB pool for atomic coherent allocations

[    0.168505] omap_hwmod: debugss: _wait_target_disable failed

[    0.258870] cpuidle: using governor ladder

[    0.288852] cpuidle: using governor menu

[    0.297156] OMAP GPIO hardware version 0.1

[    0.320799] hw-breakpoint: debug architecture 0x4 unsupported.

[    0.370516] edma 49000000.edma: TI EDMA DMA engine driver

[    0.371033] reg-fixed-voltage fixedregulator0: Fixed regulator specified with variable voltages

[    0.371080] reg-fixed-voltage: probe of fixedregulator0 failed with error -22

[    0.375976] media: Linux media interface: v0.10

[    0.376058] Linux video capture interface: v2.00

[    0.376118] pps_core: LinuxPPS API ver. 1 registered

[    0.376129] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti <giometti@linux.it>

[    0.376162] PTP clock support registered

[    0.376219] EDAC MC: Ver: 3.0.0

[    0.377829] omap-mailbox 480c8000.mailbox: omap mailbox rev 0x400

[    0.378330] Advanced Linux Sound Architecture Driver Initialized.

[    0.380155] clocksource: Switched to clocksource timer1

[    0.394711] NET: Registered protocol family 2

[    0.395800] TCP established hash table entries: 2048 (order: 1, 8192 bytes)

[    0.395850] TCP bind hash table entries: 2048 (order: 1, 8192 bytes)

[    0.395887] TCP: Hash tables configured (established 2048 bind 2048)

[    0.395989] UDP hash table entries: 256 (order: 0, 4096 bytes)

[    0.396015] UDP-Lite hash table entries: 256 (order: 0, 4096 bytes)

[    0.396197] NET: Registered protocol family 1

[    0.396799] RPC: Registered named UNIX socket transport module.

[    0.396819] RPC: Registered udp transport module.

[    0.396828] RPC: Registered tcp transport module.

[    0.396837] RPC: Registered tcp NFSv4.1 backchannel transport module.

[    0.398144] hw perfevents: enabled with armv7_cortex_a8 PMU driver, 5 counters available

[    0.401684] workingset: timestamp_bits=14 max_order=16 bucket_order=2

[    0.412512] squashfs: version 4.0 (2009/01/31) Phillip Lougher

[    0.413837] NFS: Registering the id_resolver key type

[    0.413902] Key type id_resolver registered

[    0.413913] Key type id_legacy registered

[    0.413979] ntfs: driver 2.1.32 [Flags: R/O].

[    0.416616] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 246)

[    0.416644] io scheduler noop registered

[    0.416655] io scheduler deadline registered

[    0.416868] io scheduler cfq registered (default)

[    0.418240] pinctrl-single 44e10800.pinmux: please update dts to use #pinctrl-cells = <1>

[    0.418783] pinctrl-single 44e10800.pinmux: 142 pins at pa f9e10800 size 568

[    0.507372] omap_uart 44e09000.serial: no wakeirq for uart0

[    0.507527] 44e09000.serial: ttyO0 at MMIO 0x44e09000 (irq = 158, base_baud = 3000000) is a OMAP UART0

[    1.107064] console [ttyO0] enabled

[    1.111647] omap_uart 48022000.serial: no wakeirq for uart1

[    1.117701] 48022000.serial: ttyO1 at MMIO 0x48022000 (irq = 159, base_baud = 3000000) is a OMAP UART1

[    1.128191] omap_uart 48024000.serial: no wakeirq for uart2

[    1.134332] 48024000.serial: ttyO2 at MMIO 0x48024000 (irq = 160, base_baud = 3000000) is a OMAP UART2

[    1.144756] omap_uart 481a6000.serial: no wakeirq for uart3

[    1.150859] 481a6000.serial: ttyO3 at MMIO 0x481a6000 (irq = 161, base_baud = 3000000) is a OMAP UART3

[    1.161268] omap_uart 481a8000.serial: no wakeirq for uart4

[    1.167312] 481a8000.serial: ttyO4 at MMIO 0x481a8000 (irq = 162, base_baud = 3000000) is a OMAP UART4

[    1.177742] omap_uart 481aa000.serial: no wakeirq for uart5

[    1.183828] 481aa000.serial: ttyO5 at MMIO 0x481aa000 (irq = 163, base_baud = 3000000) is a OMAP UART5

[    1.195319] omap_rng 48310000.rng: OMAP Random Number Generator ver. 20

[    1.202663] build device:/dev/nts_io dev_irq=0

[    1.207406] [drm] Initialized

[    1.229727] brd: module loaded

[    1.242186] loop: module loaded

[    1.248979] Enter spi_setup.

[    1.252322] Invoke spi_set_cs(spi, false)

[    1.256622] Enter spi_set_cs.

[    1.259729] enable = 0

[    1.262240] enable = 0

[    1.264710] spi->master->set_cs

[    1.267999] enable = 0

[    1.272108] libphy: Fixed MDIO Bus: probed

[    1.279308] mousedev: PS/2 mouse device common for all mice

[    1.286026] i2c /dev entries driver

[    1.321309] rtc-rx8025 0-0032: rtc core: registered rx8025 as rtc0

[    1.327868] omap_i2c 44e0b000.i2c: bus 0 rev0.11 at 400 kHz

[    1.336440] omap_wdt: OMAP Watchdog Timer Rev 0x01: initial timeout 60 sec

[    1.344395] sp706s watchdog driver registered.

[    1.350437] cpuidle: enable-method property 'ti,am3352' found operations

[    1.358831] omap_hsmmc 48060000.mmc: Got CD GPIO

[    1.363825] omap_hsmmc 48060000.mmc: Got WP GPIO

[    1.426777] ledtrig-cpu: registered to indicate activity on CPUs

[    1.434360] omap-gpmc 50000000.gpmc: GPMC revision 6.0

[    1.439835] gpmc_mem_init: disabling cs 0 mapped at 0x0-0x1000000

[    1.451800] nand: device found, Manufacturer ID: 0x01, Chip ID: 0xda

[    1.458472] nand: AMD/Spansion S34ML02G1

[    1.462779] nand: 256 MiB, SLC, erase size: 128 KiB, page size: 2048, OOB size: 64

[    1.470835] nand: using OMAP_ECC_BCH8_CODE_HW ECC scheme

[    1.476573] 11 ofpart partitions found on MTD device 8000000.nand

[    1.482996] Creating 11 MTD partitions on "8000000.nand":

[    1.488669] 0x000000000000-0x000000020000 : "NAND.SPL"

[    1.496040] 0x000000020000-0x000000040000 : "NAND.SPL.backup1"

[    1.504189] 0x000000040000-0x000000060000 : "NAND.SPL.backup2"

[    1.512383] 0x000000060000-0x000000080000 : "NAND.SPL.backup3"

[    1.520517] 0x000000080000-0x0000000c0000 : "NAND.u-boot-spl-os"

[    1.526980] mmc0: new high speed SDHC card at address 8bf6

[    1.527853] mmcblk0: mmc0:8bf6 SE08G 7.29 GiB

[    1.534938]  mmcblk0: p1 p2 p3

[    1.546293] 0x0000000c0000-0x0000001c0000 : "NAND.u-boot"

[    1.554061] 0x0000001c0000-0x0000001e0000 : "NAND.u-boot-env"

[    1.561809] 0x0000001e0000-0x000000200000 : "NAND.u-boot-env.backup1"

[    1.570131] 0x000000200000-0x000001200000 : "NAND.kernel"

[    1.583473] 0x000001200000-0x000005200000 : "NAND.file-system"

[    1.615092] 0x000005200000-0x000010000000 : "user"

[    1.688239] NET: Registered protocol family 10

[    1.694697] sit: IPv6, IPv4 and MPLS over IPv4 tunneling driver

[    1.702169] NET: Registered protocol family 17

[    1.707238] Key type dns_resolver registered

[    1.712229] omap_voltage_late_init: Voltage driver support not added

[    1.726301] Enter spi_transfer_one_message.

[    1.730972] true = 1

[    1.733267] invoke spi_set_cs(msg->spi, true)

[    1.737921] Enter spi_set_cs.

[    1.741097] enable = 1

[    1.743570] enable = 1

[    1.746039] spi->master->set_cs

[    1.749328] enable = 1

[    1.751902] xfer->cs_change = 1

[    1.780295] ttysWK4 at I/O 0x1 (irq = 40, base_baud = 230400) is a wk2xxx

[    1.787960] ttysWK5 at I/O 0x2 (irq = 40, base_baud = 230400) is a wk2xxx

[    1.795501] ttysWK6 at I/O 0x3 (irq = 40, base_baud = 230400) is a wk2xxx

[    1.803011] ttysWK7 at I/O 0x4 (irq = 40, base_baud = 230400) is a wk2xxx

[    1.810486] uart_add_one_port = 0x0

[    1.814204] register spi return v = :0

[    1.819595] ubi0: attaching mtd9

[    2.087595] ubi0: scanning is finished

[    2.098358] ubi0 warning: ubi_eba_init: cannot reserve enough PEBs for bad PEB handling, reserved 11, need 39

[    2.110003] ubi0: attached mtd9 (name "NAND.file-system", size 64 MiB)

[    2.116954] ubi0: PEB size: 131072 bytes (128 KiB), LEB size: 126976 bytes

[    2.124224] ubi0: min./max. I/O unit sizes: 2048/2048, sub-page size 512

[    2.131278] ubi0: VID header offset: 2048 (aligned 2048), data offset: 4096

[    2.138579] ubi0: good PEBs: 511, bad PEBs: 1, corrupted PEBs: 0

[    2.144894] ubi0: user volume: 1, internal volumes: 1, max. volumes count: 128

[    2.152508] ubi0: max/mean erase counter: 2/0, WL threshold: 4096, image sequence number: 2121165256

[    2.162104] ubi0: available PEBs: 0, total reserved PEBs: 511, PEBs reserved for bad PEB handling: 11

[    2.171803] ubi0: background thread "ubi_bgt0d" started, PID 78

[    2.250218] random: fast init done

[    2.253872] davinci_mdio 4a101000.mdio: davinci mdio revision 1.6

[    2.260303] davinci_mdio 4a101000.mdio: detected phy mask ffffffdd

[    2.268499] libphy: 4a101000.mdio: probed

[    2.272854] davinci_mdio 4a101000.mdio: phy[1]: device 4a101000.mdio:01, driver unknown

[    2.281356] davinci_mdio 4a101000.mdio: phy[5]: device 4a101000.mdio:05, driver unknown

[    2.291696] cpsw 4a100000.ethernet: Detected MACID = 98:5d:ad:b3:3f:be

[    2.360331] cpsw 4a100000.ethernet: cpts: overflow check period 500 (jiffies)

[    2.369719] cpsw 4a100000.ethernet: cpsw: Detected MACID = 98:5d:ad:b3:3f:c0

[    2.380629] rtc-rx8025 0-0032: setting system clock to 2018-06-06 11:10:40 UTC (1528283440)

[    2.390066] lis3_reg: disabling

[    2.393452] wlan-en-regulator: disabling

[    2.397570] ALSA device list:

[    2.400764]   No soundcards found.

[    2.410300] UBIFS (ubi0:0): background thread "ubifs_bgt0_0" started, PID 81

[    2.484452] UBIFS (ubi0:0): UBIFS: mounted UBI device 0, volume 0, name "rootfs"

[    2.492360] UBIFS (ubi0:0): LEB size: 126976 bytes (124 KiB), min.

LONGFEI LI said:

Secondly, when adding prints as you say, following is the teset result:

LONGFEI LI said:

[    1.248979] Enter spi_setup.

[    1.252322] Invoke spi_set_cs(spi, false)

[    1.256622] Enter spi_set_cs.

[    1.259729] enable = 0

[    1.262240] enable = 0

[    1.264710] spi->master->set_cs

[    1.267999] enable = 0

LONGFEI LI said:

[    1.712229] omap_voltage_late_init: Voltage driver support not added

[    1.726301] Enter spi_transfer_one_message.

[    1.730972] true = 1

[    1.733267] invoke spi_set_cs(msg->spi, true)

[    1.737921] Enter spi_set_cs.

[    1.741097] enable = 1

[    1.743570] enable = 1

[    1.746039] spi->master->set_cs

[    1.749328] enable = 1

[    1.751902] xfer->cs_change = 1

From this log, I see that your flow invoke spi_set_cs() function two times:

1st from spi_setup(), and set bit FORCE to 1

2nd from spi_transfer_one_message(), and set bit FORCE to 0

Thus you should end up with FORCE bit = 0. And this match with your flow provided in the below e2e post:

[ 1.904067] Enter omap2_mcspi_set_cs()
[ 1.907991] val = 201103fc
[ 1.910889] OMAP2_MCSPI_CHCONF0 = 201103fc
[ 1.915172] Exit mcspi_write_chconf0()
[ 1.919090] Exit omap2_mcspi_set_cs()
[ 1.922943] val = 201103fc
[ 1.925774] OMAP2_MCSPI_CHCONF0 = 201103fc
[ 1.930073] Exit mcspi_write_chconf0()
[ 1.934018] Enter omap2_mcspi_set_cs()
[ 1.937939] val = 200103fc
[ 1.940809] OMAP2_MCSPI_CHCONF0 = 200103fc
[ 1.945094] Exit mcspi_write_chconf0()
[ 1.949012] Exit omap2_mcspi_set_cs()

How do you define that your FORCE bit is 1? Where and how you check this? From what I can see in your log, bit FORCE should be 0 when kernel boot up.

Regards,
Pavel

Hello Pavel

I think there are  some mistakes in your analysis:

[   1.248979] Enter spi_setup.

[    1.252322] Invoke spi_set_cs(spi, false)

[    1.256622] Enter spi_set_cs.

[    1.259729] enable = 0

[    1.262240] enable = 0

[    1.264710] spi->master->set_cs

[    1.267999] enable = 0

this is the print message in spi_setup function, set enable=0, and in spi_set_cs funciton, the following code (red part) would be run:

static void spi_set_cs(struct spi_device *spi, bool enable)

{

   printk("Enter spi_set_cs.\n");

   printk("enable = %d\n",enable);

if (spi->mode & SPI_CS_HIGH)

enable = !enable;

 printk("enable = %d\n",enable);

if (gpio_is_valid(spi->cs_gpio))

{

       printk("gpio_is_valid\n");

       printk("spi->cs_gpio = %d\n",spi->cs_gpio);

gpio_set_value(spi->cs_gpio, !enable);

}

else if (spi->master->set_cs)

{

       printk("spi->master->set_cs\n");

       printk("enable = %d\n",enable);

spi->master->set_cs(spi, !enable);

}

}

in spi->master-set_cs(spi, !enable) function, the second parameter is set to 1, it is meaning that in omap2_mcspi_set_cs function, enable=1, and FORCE bit will be set to 0.

if kernel running up without any message send by spi bus(spi_transfer_one_message() not run), the FORCE bit is 0.

but  my system has an spi slave device and this device driver will access the device register through spi bus, then the function spi_transfer_one_message() would run and set bit FORCE to 1(not set FORCE bit to 0), thus,  the SPIEN line becames to low when my system boot up.

when system boot up, the spi slave device driver only read one register of the slave device, when the read operation finished the SPIEN line need to recover to high, but it isn't recovery to high, there is my doubt.

I think in spi_transfer_one_message funciton not only  invoke spi_set_cs() function to set FORCE bit to 1, also need to invoke spi_set_cs() function to set FORCE bit to 0 while the message has been sent.

Longfei,

I agree with you, I overlooked spi->master-set_cs(spi, !enable). Thus we have the below flow:

1. spi_setup() -> spi_set_cs(spi, false) -> enable = 1 -> FORCE = 0
2. spi_transfer_one_message() -> spi_set_cs(spi, true) -> enable = 0 -> FORCE = 1

Thus you end up with FORCE=1, which do not match your custom board implementation. What I can suggest you is to enable flag SPI_CS_HIGH, thus you will have FORCE =0 for spi_transfer_one_message.

Regards,
Pavel

Hello Pavel

I think enable flag SPI_CS_HIGH can't resolve my problem.

spi driver send a message to spi slave device will run spi_transfer_one_message function, in the function spi_transfer_one_message, master->transfer_one(master, msg->spi, xfer) will real send the message to spi slave device, before send the message, the driver need to enable SPIEN line, which is  invoke spi_set_cs(spi, true)  before  master->transfer_one(master, msg->spi, xfer), if enable flag SPI_CS_HIFH, spi_set_cs(spi, true) will set FORCE bit to 0(SPIEN line to high, SPIEN line disable).

in spi_transfer_one_message function, there need to invoke spi_set_cs(spi, true) to enalbe SPIEN line before send message and invoke spi_set_cs(spi, false) to disable SPIEN line after the message sent, but there is not disable SPIEN line operation isn't it ?

transfer_one_message - The subsystem calls the driver to transfer a single message while queueing transfers that arrive in the meantime. When the driver is finished with this message, it must call spi_finalize_current_message() so the subsystem can issue the next message. This may sleep.

I do not think you should modify SPI drivers (spi-omap2-mcspi.c and spi.c), these drivers are generic. I would suggest you to align your slave device driver to spi.c/spi-omap2-mcspi.c and/or configure SPI parameters according to your custom board specifics. See the below pointers for more info:

linux-4.9.69/Documentation/spi/spi-summary
linux-4.9.69/Documentation/devicetree/bindings/spi/spi-bus.txt
inux-4.9.69/Documentation/devicetree/bindings/spi/omap-spi.txt

processors.wiki.ti.com/.../Linux_Core_SPI_User's_Guide

Regards,
Pavel