SPIM Read fails when using Zephyr WorkQueue

[Miguel Ferreira]

Hi,

Im using an SPI device and also the SPIM NRF driver. This device is not always on, but the overall flow is:

1. Power On the device on boot and do basic info readings to check if the device is ok
2. Turn off the device
3. Start the delayable Zephyr work, for example 1 minute delay
4. The delayable Zephyr work triggers, power on the SPI device and tries to communicate with it
5. Writings to the device work, from the power profiller I can see the wave changes as I send commands to it - like a soft reset for example
6. Cant read from the device, value from reaing always return 0.

However using a flow without the wrok queue, just the main thread and the same function being used inside the work:

1. Power On the device on boot and do basic info readings to check if the device is ok
2. Turn off the device
3. Do a k_sleep(K_SECONDS(60))
4. Power on the SPI device and tries to communicate with it
5. Writings to the device work, from the power profiller I can see the wave changes as I send commands to it - like a soft reset for example
6. Can read correctly the data coming form the device

Do you have any clue for why this is happening ? Or what things I should try in order to debug this issue ? Havent attached a logical analyzer yet but I pretend to. Also, the work queue stack size is big enough for the function Im running, so I believe the issue is not there. Im also running a BLE advertising every 10 seconds, but even with the BLE stack and advertising disable the behavior is the same.

Thank you!

[Hung Bui]

Hi Miguel, 

Could you explain what do you mean by Turn off and Turn on the device ? Do you control VDD to the SPIS device ? Could you test without turn off and on the device ? 

As far as I know system work queue should have higher priority than main thread, by default. So it's quite strange that it worked in main thread but not in system work queue. 
But I know that BLE use system work queue to perform BLE task. So it may have some interference here. But you mentioned even without any BLE activity you still see the problem. Please check if the CONFIG_SYSTEM_WORKQUEUE_STACK_SIZE has enough. 
I think the logic analyzer trace will really help here. 

[Miguel Ferreira]

Hi Hung Bui 

By turn off I mean disabling the VDD signal. Another note on this, Im using NRF connect 2.4.3 and at this point sadly I can t upgrade it... Im also not using system workqueue, Im using my own workqueue (k_work_queue_init). 

I ran the logical analyzer and the data seems ok:

These signals are from the init of the device, in this situations the data is read correctly (see the logs) and it appears as expected in the MISO line.

[00:00:02.000,701] <err> spi_nrfx_spim: Received content of rx buffer 00
[00:00:02.000,732] <err> spi_nrfx_spim: Received content of rx buffer 00
[00:00:02.000,793] <err> spi_nrfx_spim: Received content of rx buffer 22
[00:00:02.000,854] <err> spi_nrfx_spim: Received content of rx buffer 22
[00:00:02.000,885] <err> spi_nrfx_spim: Received content of rx buffer 22
[00:00:02.000,915] <err> spi_nrfx_spim: Received content of rx buffer 84
[00:00:02.001,007] <err> spi_nrfx_spim: Received content of rx buffer 84
[00:00:02.001,037] <err> spi_nrfx_spim: Received content of rx buffer 84
[00:00:02.001,098] <err> spi_nrfx_spim: Received content of rx buffer 17
[00:00:02.001,129] <err> spi_nrfx_spim: Received content of rx buffer 17
[00:00:02.001,190] <err> spi_nrfx_spim: Received content of rx buffer 17
[00:00:02.001,220] <err> spi_nrfx_spim: Received content of rx buffer 04
[00:00:02.001,281] <err> spi_nrfx_spim: Received content of rx buffer 04
[00:00:02.001,312] <err> spi_nrfx_spim: Received content of rx buffer 04
[00:00:02.001,373] <err> spi_nrfx_spim: Received content of rx buffer 0c
[00:00:02.001,434] <err> spi_nrfx_spim: Received content of rx buffer 0c
[00:00:02.001,464] <err> spi_nrfx_spim: Received content of rx buffer 0c
[00:00:02.001,495] <err> spi_nrfx_spim: Received content of rx buffer 20
[00:00:02.001,586] <err> spi_nrfx_spim: Received content of rx buffer 20
[00:00:02.001,617] <err> spi_nrfx_spim: Received content of rx buffer 20
[00:00:02.001,647] <err> spi_nrfx_spim: Received content of rx buffer 22
[00:00:02.001,800] <err> spi_nrfx_spim: Received content of rx buffer 22
[00:00:02.001,831] <err> spi_nrfx_spim: Received content of rx buffer 22
[00:00:02.001,861] <err> spi_nrfx_spim: Received content of rx buffer 21
[00:00:02.004,028] <err> spi_nrfx_spim: Received content of rx buffer 21
[00:00:02.004,058] <err> spi_nrfx_spim: Received content of rx buffer 21
[00:00:02.004,089] <err> spi_nrfx_spim: Received content of rx buffer 21
[00:00:02.006,256] <err> spi_nrfx_spim: Received content of rx buffer 21
[00:00:02.006,286] <err> spi_nrfx_spim: Received content of rx buffer 21
[00:00:02.006,347] <err> spi_nrfx_spim: Received content of rx buffer 21
[00:00:02.008,483] <err> spi_nrfx_spim: Received content of rx buffer 21
[00:00:02.008,514] <err> spi_nrfx_spim: Received content of rx buffer 21
[00:00:02.008,544] <err> spi_nrfx_spim: Received content of rx buffer 21
[00:00:02.010,711] <err> spi_nrfx_spim: Received content of rx buffer 21
[00:00:02.010,742] <err> spi_nrfx_spim: Received content of rx buffer 21
[00:00:02.010,772] <err> spi_nrfx_spim: Received content of rx buffer 22
[00:00:02.010,833] <err> spi_nrfx_spim: Received content of rx buffer 22
[00:00:02.010,864] <err> spi_nrfx_spim: Received content of rx buffer 22
[00:00:02.010,925] <err> spi_nrfx_spim: Received content of rx buffer 22
[00:00:02.011,047] <err> spi_nrfx_spim: Received content of rx buffer 22
[00:00:02.011,077] <err> spi_nrfx_spim: Received content of rx buffer 22
[00:00:02.011,138] <err> spi_nrfx_spim: Received content of rx buffer 21
[00:00:02.013,275] <err> spi_nrfx_spim: Received content of rx buffer 21
[00:00:02.013,305] <err> spi_nrfx_spim: Received content of rx buffer 21
[00:00:02.013,336] <err> spi_nrfx_spim: Received content of rx buffer 21
[00:00:02.015,502] <err> spi_nrfx_spim: Received content of rx buffer 21
[00:00:02.015,533] <err> spi_nrfx_spim: Received content of rx buffer 21
[00:00:02.015,563] <err> spi_nrfx_spim: Received content of rx buffer 21
[00:00:02.017,730] <err> spi_nrfx_spim: Received content of rx buffer 21
[00:00:02.017,761] <err> spi_nrfx_spim: Received content of rx buffer 21
[00:00:02.017,791] <err> spi_nrfx_spim: Received content of rx buffer 20
[00:00:02.019,958] <err> spi_nrfx_spim: Received content of rx buffer 21
[00:00:02.019,989] <err> spi_nrfx_spim: Received content of rx buffer 21
[00:00:02.020,019] <err> spi_nrfx_spim: Received content of rx buffer 21
[00:00:02.022,186] <err> spi_nrfx_spim: Received content of rx buffer 21
[00:00:02.022,216] <err> spi_nrfx_spim: Received content of rx buffer 21
[00:00:02.022,247] <err> spi_nrfx_spim: Received content of rx buffer 22

These signals are from the work, as we can see I have simillar data as the one received during the init. However, from the logs we only have 0s being read. 

[00:01:22.975,738] <err> spi_nrfx_spim: Received content of rx buffer 00
[00:01:22.975,799] <err> spi_nrfx_spim: Received content of rx buffer 00
[00:01:22.977,966] <err> spi_nrfx_spim: Received content of rx buffer 00
[00:01:22.977,996] <err> spi_nrfx_spim: Received content of rx buffer 00
[00:01:22.978,027] <err> spi_nrfx_spim: Received content of rx buffer 00
[00:01:22.980,194] <err> spi_nrfx_spim: Received content of rx buffer 00
[00:01:22.980,224] <err> spi_nrfx_spim: Received content of rx buffer 00
[00:01:22.980,255] <err> spi_nrfx_spim: Received content of rx buffer 00
[00:01:22.982,421] <err> spi_nrfx_spim: Received content of rx buffer 00
[00:01:22.982,452] <err> spi_nrfx_spim: Received content of rx buffer 00
[00:01:22.982,513] <err> spi_nrfx_spim: Received content of rx buffer 00
[00:01:22.982,666] <err> spi_nrfx_spim: Received content of rx buffer 00
[00:01:22.982,696] <err> spi_nrfx_spim: Received content of rx buffer 00
[00:01:22.982,727] <err> spi_nrfx_spim: Received content of rx buffer 00
[00:01:22.984,893] <err> spi_nrfx_spim: Received content of rx buffer 00
[00:01:22.984,924] <err> spi_nrfx_spim: Received content of rx buffer 00
[00:01:22.984,985] <err> spi_nrfx_spim: Received content of rx buffer 00
[00:01:22.987,121] <err> spi_nrfx_spim: Received content of rx buffer 00
[00:01:22.987,152] <err> spi_nrfx_spim: Received content of rx buffer 00
[00:01:22.987,182] <err> spi_nrfx_spim: Received content of rx buffer 00
[00:01:22.989,349] <err> spi_nrfx_spim: Received content of rx buffer 00
[00:01:22.989,379] <err> spi_nrfx_spim: Received content of rx buffer 00
[00:01:22.989,410] <err> spi_nrfx_spim: Received content of rx buffer 00
[00:01:22.991,577] <err> spi_nrfx_spim: Received content of rx buffer 00
[00:01:22.991,607] <err> spi_nrfx_spim: Received content of rx buffer 00
[00:01:22.991,638] <err> spi_nrfx_spim: Received content of rx buffer 00
[00:01:22.993,804] <err> spi_nrfx_spim: Received content of rx buffer 00
[00:01:22.993,835] <err> spi_nrfx_spim: Received content of rx buffer 00
[00:01:22.993,896] <err> spi_nrfx_spim: Received content of rx buffer 00
[00:01:22.996,032] <err> spi_nrfx_spim: Received content of rx buffer 00
[00:01:22.996,063] <err> spi_nrfx_spim: Received content of rx buffer 00
[00:01:22.996,093] <err> spi_nrfx_spim: Received content of rx buffer 00
[00:01:22.998,260] <err> spi_nrfx_spim: Received content of rx buffer 00
[00:01:22.998,291] <err> spi_nrfx_spim: Received content of rx buffer 00
[00:01:22.998,321] <err> spi_nrfx_spim: Received content of rx buffer 00
[00:01:23.000,488] <err> spi_nrfx_spim: Received content of rx buffer 00
[00:01:23.000,518] <err> spi_nrfx_spim: Received content of rx buffer 00
[00:01:23.000,579] <err> spi_nrfx_spim: Received content of rx buffer 00
[00:01:23.002,716] <err> spi_nrfx_spim: Received content of rx buffer 00
[00:01:23.002,746] <err> spi_nrfx_spim: Received content of rx buffer 00
[00:01:23.002,777] <err> spi_nrfx_spim: Received content of rx buffer 00
[00:01:23.004,943] <err> spi_nrfx_spim: Received content of rx buffer 00
[00:01:23.004,974] <err> spi_nrfx_spim: Received content of rx buffer 00
[00:01:23.005,004] <err> spi_nrfx_spim: Received content of rx buffer 00
[00:01:23.007,171] <err> spi_nrfx_spim: Received content of rx buffer 00
[00:01:23.007,202] <err> spi_nrfx_spim: Received content of rx buffer 00
[00:01:23.007,263] <err> spi_nrfx_spim: Received content of rx buffer 00
[00:01:23.009,399] <err> spi_nrfx_spim: Received content of rx buffer 00
[00:01:23.009,429] <err> spi_nrfx_spim: Received content of rx buffer 00
[00:01:23.009,490] <err> spi_nrfx_spim: Received content of rx buffer 00
[00:01:23.011,657] <err> spi_nrfx_spim: Received content of rx buffer 00

At first glance seems to me that the signals are ok. Do you have any clue if modifications were done to the SPIM driver to be used in multithread scenarios ? 

Thanks again!

[Hung Bui]

Hi Miguel, 

Could you tell what priority you run your workqueue on ? 

At Step 1 Power On the device on boot and do basic info readings to check if the device is ok, do you read from the SPIS device ? Do you have the correct reading ?If after 1 minute of sleeping, you do the same thing , do you see the same result or just 0x00 ? 

My understanding is that on the MISO line you still see correct data output from the SPIS but the reading from the SPIM result 0 ? 
Could you add some breakpoint/log in SPIM library and check why it's returned 0 ? Please check if any issue with the RX buffer. 

[Miguel Ferreira]

Hi,

Sorry I figure out the issue, in recent updates to the project the ADC channel on the DTS change to AIN2 and AIN2 is the MISO of the SPI device. Thanks for the help again!