New logging subsystem's timestamps wrap a little before the 3-minute mark

[jhedberg]

The log format implies that it can show up many hours, however it seems to be wrapping back to zero a little bit before the three minute mark.

[nordic-krch]

@jhedberg logger is using k_cycle_get_32() by default. So maybe it is wrapping that often? You can try disabling timestmap formatting (LOG_BACKEND_UART_FORMAT_TIMESTAMP) then timestamp is printed in raw format. If it still wraps it's on k_cycle_get_32().

[pizi-nordic]

I have verified the k_cycle_get_32() and I did not noticed any wrapping around there minutes.

Code snipped which I used for verification:

        for (int i = 0; i < 60*60; i++) {
                u32_t c = k_cycle_get_32();

                printk("%04u => %02u:%02u (0x%08X)\n",
                        i,
                        (c / sys_clock_hw_cycles_per_sec) / 60,
                        (c / sys_clock_hw_cycles_per_sec) % 60,
                        c);

                k_sleep(1000);
        }

Result:

0148 => 02:31 (0x004ba5cf)
0149 => 02:32 (0x004c26d2)
0150 => 02:33 (0x004ca7d5)
(...)
0176 => 02:59 (0x0059c223)
0177 => 03:00 (0x005a4326)
0178 => 03:01 (0x005ac429)
(...)
0205 => 03:28 (0x00685f7a)
0206 => 03:29 (0x0068e07d)
0207 => 03:30 (0x00696180)

I also verified if wrapping of RTC hardware counter (which has only 24-bits) is handled correctly:

0500 => 08:26 (0x00fd09ef)
0501 => 08:27 (0x00fd8af2)
0502 => 08:28 (0x00fe0bf5)
0503 => 08:29 (0x00fe8cf8)
0504 => 08:30 (0x00ff0dfb)
0505 => 08:31 (0x00ff8efe)
0506 => 08:32 (0x01001001)
0507 => 08:33 (0x01009104)
0508 => 08:34 (0x01011207)
0509 => 08:35 (0x0101930a)
0510 => 08:36 (0x0102140d)

@nordic-krch: Could you please check logger if it is handling time obtained from k_cycle_get_32*() correctly?

[jhedberg]

Update: it appears the issue only occurs in qemu (I only tested qemu_x86). I cannot reproduce this e.g. on an nRF target.

[aurel32]

I got the same issue on an Atmel SAM E70 board, it wraps every 14 seconds. The CPU runs at 300MHz, and k_cycle_get_32() returns a 32-bit value. And 2**32/300e6 = 14.3 seconds. So k_cycle_get_32 does not seem a good time source for timestamping.

[nordic-krch]

@aurel32 by default logger uses k_cycle_get_32() but it can be changed runtime using log_set_timestamp_func (log_ctrl.h).

[pizi-nordic]

Could we close this?
It looks that whole thing is caused by high frequency of hardware timer on some architectures. There is a way to mitigate this in the logger (just provide other clock reference).

[jhedberg]

@pizi-nordic sure, though applications shouldn't be required to fix this, rather the commonly used boards that have this issue (e.g. qemu_x86) should come with a solution built-in and enabled by default.

[aurel32]

I think the issue is present on all ARM boards except the nRF52 based ones. The standard timer on ARM board is the ARM systick one, which usually runs in the range 10-500MHz.

[jukkar]

In frdm-k64f the counter wraps after 35 sec. I agree with @jhedberg here, there should be no need to application to "fix" this. In a way this is not really a logging subsystem issue but it is easy to see the problem when looking the logging output.

[pizi-nordic]

So the only generic solution I see is introduction of k_cycle_get_64(). Otherwise every soc will have to provide some custom clock source for logging only.

[pabigot]

see also #6498

[nordic-krch]

i'm not sure about using k_cycle_get_64(). Takes more precious cycles and more memory in log message (current log message is pretty with 32 bytes). What about applying compile time known, power-of-2 divisor (shift) to k_cycle_get_32().

Based on SYS_CLOCK_HW_CYCLES_PER_SEC logger kconfig can derive hidden config like:

config LOG_SYS_CLOCK_DIV
   int
   default 1024 if SYS_CLOCK_HW_CYCLES_PER_SEC>16000000
  ...

then timestamp function would be: return k_cycle_get_32() / CONFIG_LOG_SYS_CLOCK_DIV.

Practically, no performance penalty and period is extended.

[aurel32]

That won't help, given k_cycle_get_32() is actually the one wrapping very quickly in less than a minute on board with a fast CPU clock. If we want to keep e 32-bit value for the logs, what about using k_uptime_get_32() instead? It only has a millisecond granularity, but wraps only in 49 days, which is probably acceptable for the logs.

[nordic-krch]

@aurel32 it's clear now that i've probably returned from sick leave too early :)

[jhedberg]

If we want to keep e 32-bit value for the logs, what about using k_uptime_get_32() instead? It only has a millisecond granularity, but wraps only in 49 days, which is probably acceptable for the logs.

Wouldn't it be possible to use a combination of those two, i.e. k_uptime_get_32() to get the milliseconds and k_cycle_get_32() to get the microseconds?

[aurel32]

@jhedberg, I am not sure there is an easy relation between k_uptime_get_32() and k_cycle_get_32(). In addition to that, if the logger is limited to a 32-bit timestamp value, there is a trade-off to do between maximum time before wrapping and accuracy. A 32-bit value with microsecond resolution wraps in a bit more than 1 hour.

[jhedberg]

@aurel32 right, that's indeed an issue. I was thinking microseconds would always be wanted since the logger renders them in the output by default. Probably this all needs to be configurable, i.e. does the user want microsecond accuracy but is willing to accept a wrap-around in a bit more than an hour, or is millisecond accuracy sufficient.

[carlescufi]

@nordic-krch and @pizi-nordic. Is there a possible workaround for this issue as it stands, or do we need additional functionality in the logging subsystem?

[nordic-krch]

@carlescufi k_uptime_get_32 could be used instead. It's in milliseconds so resolution would be smaller. I would prefer to keep k_cycle_get_32 as long as CONFIG_SYS_CLOCK_HW_CYCLES_PER_SEC gives accepted resolution (like 32k in nrf) as this will be faster.

[carlescufi]

@nordic-krch Thanks for the reply. What you propose is reasonable. Since we are trying to close the open bugs that are important to users for 1.14, would you mind sending a PR that does what you describe?

[nordic-krch]

@carlescufi sure, we'll do that.