NRF_LOG timestamp resolution via UART

Question

I would like to do log timestamping using the UART backend with NRF_LOG.

As described in many devzone posts (e.g. here: https://devzone.nordicsemi.com/f/nordic-q-a/18707/timestamp-problem/72239#72239) , I added counter.h and counter.c (see also attachments to this post) configured NRF_LOG_USES_TIMESTAMP 1, NRF_LOG_TIMESTAMP_DEFAULT_FREQUENCE 0 and also have NRFX_RTC_DEFAULT_CONFIG_FREQUENCY=32768 and added the relevant changes to log_init()

static void log_init(void)
{
    #if NRF_LOG_USES_TIMESTAMP==1
    counter_init();
    counter_start();
    
    ret_code_t err_code = NRF_LOG_INIT(counter_get);
    #else
    ret_code_t err_code = NRF_LOG_INIT(NULL);
    #endif

    APP_ERROR_CHECK(err_code);

    NRF_LOG_DEFAULT_BACKENDS_INIT();
}

This basically does what it is supposed to - add timestamps but the timestamp itself looked totally off and not in 1s resp. 1000ms intervals.

[00:00:00.114,746] <info> app: Tick! 1/1000
[00:00:00.114,990] <info> calculations: prev_cumulative_crank_revs=0 - Should never happen after start!
[00:00:00.115,600] <info> calculations: prev_last_crank_event_time=0 - Very unlikely to happen!
[00:00:00.175,354] <info> app: Tick! 2/2000
[00:00:00.235,961] <info> app: Tick! 3/3000
[00:00:00.296,569] <info> app: Tick! 4/4000
[00:00:00.357,177] <info> app: Tick! 5/5000
[00:00:00.417,785] <info> app: Tick! 6/6000
[00:00:00.478,393] <info> app: Tick! 7/7000
[00:00:00.539,001] <info> app: Tick! 8/8000
[00:00:00.599,609] <info> app: Tick! 9/9000
[00:00:00.660,217] <info> app: Tick! 10/10000
[00:00:00.720,825] <info> app: Tick! 11/11000
[00:00:00.781,433] <info> app: Tick! 12/12000
[00:00:00.842,041] <info> app: Tick! 13/13000
[00:00:00.902,648] <info> app: Tick! 14/14000
[00:00:00.963,256] <info> app: Tick! 15/15000
[00:00:01.023,864] <info> app: Tick! 16/16000
[00:00:01.084,472] <info> app: Tick! 17/17000

I figured out, that when I set config.prescaler =1

void counter_init(void)
{
    ret_code_t err_code;

    // Initialize the RTC instance.
    nrfx_rtc_config_t config = NRFX_RTC_DEFAULT_CONFIG;

    // 1 ms interval.
    //config.prescaler = 32;
    config.prescaler = 1; // prescaler = 1 gives proper timestamps

    err_code = nrfx_rtc_init(&m_rtc, &config, rtc_handler);
    APP_ERROR_CHECK(err_code);

    nrfx_rtc_tick_disable(&m_rtc);
}

The log cleanly logs in the right time intervals.

For example I have a 1000ms tick I log and this is printed in the log as:

[00:00:46.117,126] <info> app: Found 0 services on conn_handle: 0
[00:00:46.123,474] <info> app: Disconnected due to sec failure. Deleting peers.
[00:00:46.130,920] <info> app: Erase bonds!
[00:00:46.889,770] <info> app: Tick! 46/46000
[00:00:47.889,770] <info> app: Tick! 47/47000
[00:00:48.889,831] <info> app: Tick! 48/48000
[00:00:49.889,831] <info> app: Tick! 49/49000
[00:00:50.646,179] <info> oled: Start OLED redraw()

However I am worried about the info at https://infocenter.nordicsemi.com/index.jsp?topic=%2Fcom.nordic.infocenter.sdk5.v15.0.0%2Fgroup__nrfx__rtc.html stating that a rollover at prescaler=1 will occur very soon.

How do I need to adapt the counter.h/RTC config in order to keep the proper timebase but allow the system to log for a much longer time than a couple of hundred seconds? I don't care so much about the actual ms resolution in the log, it is more important to me to see whether the log message was logged about 5s, 5min or 20min

Fullscreen counter.c Download

/**
 * Copyright (c) 2016 - 2020, Nordic Semiconductor ASA
 *
 * All rights reserved.
 *
 * Redistribution and use in source and binary forms, with or without modification,
 * are permitted provided that the following conditions are met:
 *
 * 1. Redistributions of source code must retain the above copyright notice, this
 *    list of conditions and the following disclaimer.
 *
 * 2. Redistributions in binary form, except as embedded into a Nordic
 *    Semiconductor ASA integrated circuit in a product or a software update for
 *    such product, must reproduce the above copyright notice, this list of
 *    conditions and the following disclaimer in the documentation and/or other
 *    materials provided with the distribution.
 *
 * 3. Neither the name of Nordic Semiconductor ASA nor the names of its
 *    contributors may be used to endorse or promote products derived from this
 *    software without specific prior written permission.
 *
 * 4. This software, with or without modification, must only be used with a
 *    Nordic Semiconductor ASA integrated circuit.
 *
 * 5. Any software provided in binary form under this license must not be reverse
 *    engineered, decompiled, modified and/or disassembled.
 *
 * THIS SOFTWARE IS PROVIDED BY NORDIC SEMICONDUCTOR ASA "AS IS" AND ANY EXPRESS
 * OR IMPLIED WARRANTIES, INCLUDING, BUT NOT LIMITED TO, THE IMPLIED WARRANTIES
 * OF MERCHANTABILITY, NONINFRINGEMENT, AND FITNESS FOR A PARTICULAR PURPOSE ARE
 * DISCLAIMED. IN NO EVENT SHALL NORDIC SEMICONDUCTOR ASA OR CONTRIBUTORS BE
 * LIABLE FOR ANY DIRECT, INDIRECT, INCIDENTAL, SPECIAL, EXEMPLARY, OR
 * CONSEQUENTIAL DAMAGES (INCLUDING, BUT NOT LIMITED TO, PROCUREMENT OF SUBSTITUTE
 * GOODS OR SERVICES; LOSS OF USE, DATA, OR PROFITS; OR BUSINESS INTERRUPTION)
 * HOWEVER CAUSED AND ON ANY THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT
 * LIABILITY, OR TORT (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY OUT
 * OF THE USE OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE.
 *
 */
/**@cond To Make Doxygen skip documentation generation for this file.
 * @{
 */

#include "counter.h"
#include "nrfx_rtc.h"


// RTC driver instance using RTC2.
// RTC0 is used by the SoftDevice, and RTC1 by the app_timer library.
static const nrfx_rtc_t m_rtc = NRFX_RTC_INSTANCE(2);


static void rtc_handler(nrfx_rtc_int_type_t int_type)
{
    // Likely a counter overflow.
    APP_ERROR_CHECK(0xFFFFFFFF);
}


void counter_init(void)
{
    ret_code_t err_code;

    // Initialize the RTC instance.
    nrfx_rtc_config_t config = NRFX_RTC_DEFAULT_CONFIG;

    // 1 ms interval.
    //config.prescaler = 32;
    config.prescaler = 1;

    err_code = nrfx_rtc_init(&m_rtc, &config, rtc_handler);
    APP_ERROR_CHECK(err_code);

    nrfx_rtc_tick_disable(&m_rtc);
}


void counter_start(void)
{
    nrfx_rtc_counter_clear(&m_rtc);

    // Power on!
    nrfx_rtc_enable(&m_rtc);
}


void counter_stop(void)
{
    nrfx_rtc_disable(&m_rtc);
}


uint32_t counter_get(void)
{
    uint32_t cnt = nrfx_rtc_counter_get(&m_rtc);
    return cnt;
}

/** @}
 *  @endcond
 */

counter.h

Marjeris Romero · Accepted Answer

Hi Markus, 
 Sorry for the late reply. We are on summer vacation staffing so responses may be a bit slower than usual. You can handle the rollover using an external variable you increment each time RTC overflows. Something like this: 
 uint32_t counter_get(void)
{
 uint32_t cnt = nrfx_rtc_counter_get(&m_rtc);
 cnt |= overflow_counter << 24;
 return cnt;
} 
 This way you could increase the counter to 256 instead of only having the RTC 24-bit counter. It will give you 72 hours before the RTC overflows instead of 17 minutes. I don't know if this would be OK for your implementation? 
 Best regards, 
 Marjeris

NRF_LOG timestamp resolution via UART

Top Replies