SDK_LOG_ENABLED causes saadc channels to shift.

[_Scott_]

So we have the SAADC configured to read using timer attached to ppi. We read from 5 adc channels. If we set NRF_LOG_ENABLED to 1 in sdk_config.h all the channels read fine. However, if we set NRF_LOG_ENABLED to 0, the values in the adc channels shift by 2 channels, eg channel 1 is now the values of channel 4.

I've seen posts saying saadc channels can get shifted if the saadc isn't uninitialized properly between reads. However, when we first started using the saadc, we ran into that issue and fixed our uninitialization. The other strange part, is that with the NRF_LOG_ENABLED issue I'm seeing, the very first read from the saadc is shifted, implying it isn't an issue with uninitialization, but rather the initialization itself. 

What is strange is that the nrf logger would somehow be causing this issue. I can't seem to find any posts with the same issue, but it has such a strange cause I'm also having trouble phrasing my search in a way that brings up relevant results.

Any thoughts on what/why the logger module is shifting the saadc channels?

[Priyanka]

Hi Scott,

Could you tell me what version of SDK are you working on?

Regards,

Priyanka

[_Scott_]

We are using v17.0.2 on a nRF52832

[Priyanka]

Hi Scott,

Is it possible to attach some logs or errors that you see? Also, kindly expect some delay owing to the holiday season in Norway.

Regards,

Priyanka

[_Scott_]

Hi Priyanka,

I was also out for the holiday season so sorry for the delay on my part. We don't get an error, so I can't pass on an error message. Is there an SDK logging feature to give detailed updates on what the SAADC is doing?

Otherwise, I'll upload some screenshots showing the output of each of the SAADC channels with and without NRF_LOG_ENABLED so you can see what I mean by the values in each channel shifting.

[Priyanka]

Hi Scott,

Happy New Year!

The shift could possibly be due to calibration problem or a small halt to the CPU, i.e how did you verify your buffer when the log is disabled? In case you used a debug breakpoint, this can cause a halt to CPU (while PPI is still functioning) and this can cause a shift.

Also, you could take a look at the calibration errata. A offset can be observed if there is a change in the order of events, i.e. if calibration is done before starting the sampling.

The solutions here too can be fruitful.

Regards,

Priyanka

[_Scott_]

Happy New Year Priyanka, thanks for helping me sort through this.

I'm verifying the buffer contents using printf() statements to output the values for each channel. I am not using any debug breakpoints so it may not be a cpu halt. We are running nrf_drv_saadc_calibrate_offset() between each batch of reads, then running nrfx_saadc_disable() followed by nrfx_saadc_enable() to ensure the calibration is used. If this is order of calls is incorrect please let me know.

I looked at the calibration errata, and the symptom does not match what we are seeing. The first sample in the buffer is a correct value, however for the wrong sensor. With NRF_LOG_ENABLED 1, we see the expected channel order of {1,2,3,4,5}, but with NRF_LOG_ENABLED 0 we see the shift where the channel order is now {4,5,1,2,3} but all the values are correct.

I looked through the other post you linked as well. The explanation by Jorgen describing how a DMA transfer can get stuck as pending makes sense. However, I see the shift starting with the very first read from the adc. So if there wasn't a DMA transfer prior to the first read, a pending transfer finally executing doesn't make sense for us. I would like to try his proposed solution 1, "Use PPI to trigger START task on an END event" just to be sure, but I'm not sure how to trigger a start task like that using the soft device.

On top of all that, I still have yet to see how having the NRF logging module enabled prevents me from having the shift issue, but disabling the logging module makes the shift occur. I make no changes to the code expect for the line in sdk_config.h, and I know the code can work, so I don't see how logging causes the issue.

Thanks for help,

Scott

[_Scott_]

Ok, after further investigation, it does seem like my issue is related to the calibration errata. The first value in the buffer, while it does come from the expected sensor (accounting for the shift), is about double what it should be. That is to say the first value in the buffer is from sensor 4, and can be changed by affecting sensor 4, but is about twice what the rest of the samples from sensor 4 are. 

However, I found an interesting way to prevent the sensor shift and errata all together, which is to add a delay after calling nrf_drv_saadc_calibrate_offset(). I had added a print statement in our saadc_callback handler to see  which of the nrfx_saadc_evt_type_t are being called. Simply adding the print statement fixed the channel shifting issue. I replaced the print statement with an nrf_delay and it also fixed the issue. I figured it might be a problem with how we are running the calibration, so I checked this example.

https://github.com/NordicPlayground/nRF52-ADC-examples/blob/master/saadc_low_power/main.c

In that example, after calling nrf_drv_saadc_calibrate_offset() it ensures that NRF_DRV_SAADC_EVT_CALIBRATEDONE occurs before calling nrf_drv_saadc_buffer_convert to setup the buffers again. We were not doing this, so I thought the delay or print statement I had added was giving the device enough time to finish the calibration before we called nrf_drv_saadc_buffer_convert. 

I went ahead and added a flag to our saadc_callback, and ensured that we do not call nrf_drv_saadc_buffer_convert until after NRF_DRV_SAADC_EVT_CALIBRATEDONE occurs. This did NOT fix the problem. Even if I wait until NRF_DRV_SAADC_EVT_CALIBRATEDONE occurs, the only thing that fixes the buffer shift issue is to add a delay between the call to nrf_drv_saadc_buffer_convert and nrf_drv_saadc_buffer_convert. essentially

while(nrf_drv_saadc_calibrate_offset() != NRF_SUCCESS);

nrf_delay_ms(1); // or a printf() statement

err_code = nrf_drv_saadc_buffer_convert(m_buffer[0], SAMPLE_COUNT);

APP_ERROR_CHECK(err_code);

I'm guessing that having logging enabled logs something when NRF_DRV_SAADC_EVT_CALIBRATEDONE occurs, which adds a short delay, and in the example I referenced nrf_drv_saadc_buffer_convert() is called by the saadc_callback which is on a timer, so there must be a delay after nrf_drv_saadc_calibrate_offset() is called and the timer fires.

I can't find anything documented saying there must be a delay of any sort between nrf_drv_saadc_calibrate_offset() and nrf_drv_saadc_buffer_convert(), or what event I must wait for before calling nrf_drv_saadc_buffer_convert(). Admittedly I could have missed something, but I've looked at a number of forum posts and examples and don't see any reference to anything of the sort.

So at this point I guess my question is what is the recommended way of calling nrf_drv_saadc_buffer_convert() after calling nrf_drv_saadc_calibrate_offset()? Place it in the saadc_callback which effectively adds a delay? Just explicitly call nrf_delay for some amount of time? Or look for a specific event to be completed?

Thanks,

Scott

[Priyanka]

Hi Scott,

How exactly are you implementing the NRF_DRV_SAADC_EVT_CALIBRATEDONE ? Is it exactly as shown in the example?

Regards,

Priyanka

[_Scott_]

Yes we are implementing it exactly like in the example. In our SAADC_callback we run

if (p_event->type == NRF_DRV_SAADC_EVT_CALIBRATEDONE) {
    err_code = nrf_drv_saadc_buffer_convert(m_buffer[0], SAMPLES_IN_BUFFER);
    APP_ERROR_CHECK(err_code);
    done_calibrating = true;
} 

And when we do the calibration call it looks like:

while(nrf_drv_saadc_calibrate_offset() != NRF_SUCCESS);
while (!done_calibrating);
done_calibrating = false;

The done_calibrating check I added is to ensure we don't start sampling until the calibration is complete. This method still results in the buffer shift issue. If I add nrf_delay_us(500) in the saadc_callback before nrf_drv_saadc_buffer_convert() then the buffer shift issue is avoided.

if (p_event->type == NRF_DRV_SAADC_EVT_CALIBRATEDONE) {
    nrf_delay_us(500);
    err_code = nrf_drv_saadc_buffer_convert(m_buffer[0], SAMPLES_IN_BUFFER);
    APP_ERROR_CHECK(err_code);
    done_calibrating = true;
} 

I suspect in the example the LEDS_INVERT(BSP_LED_2_MASK); line adds enough of a delay that the buffer shift issue is avoided.

else if (p_event->type == NRF_DRV_SAADC_EVT_CALIBRATEDONE)
{
    LEDS_INVERT(BSP_LED_2_MASK);                                                                    //Toggle LED3 to indicate SAADC calibration complete
    
    err_code = nrf_drv_saadc_buffer_convert(m_buffer_pool[0], SAADC_SAMPLES_IN_BUFFER);             //Set buffer so the SAADC can write to it again. 
    APP_ERROR_CHECK(err_code);

}

[_Scott_]

Ok I've managed to narrow the issue down, it stems from low_power_mode and I am able to replicate it in the saadc_low_power example. In the example, in saadc_init() if you set saadc_config.low_power_mode to false, the first value in the calibration event will be incorrect. If you add a short delay in the NRF_DRV_SAADC_EVT_CALIBRATEDONE in the callback before calling nrf_drv_saadc_buffer_convert() it fixes the issue, just like in my project.

The issue does not occur if you set low_power_mode to true. So my guess is that this relates to the calibration errata you linked above. Since low power mode turns the saadc off between samples, my guess is that after the calibration, the saadc gets turned off, allowing it to follow the pattern listed under the workaround. 

However, with low power mode disabled, why does a delay cause the calibration to follow the workaround pattern? Shouldn't the saadc stay on during a delay, meaning the STOP event never occurs after CALIBRATEDONE as needed by the workaround? Or does it all fall under the category of "it's an errata so  of course it will have weird behavior"?