nRFSDK v17 libuarte cli example and logging float numbers

[Franz]

Dear all,

The forum is full of questions around printing floating point numbers, however, I have a rather strange issue where maybe someone can help.

I have a project based on the libuarte cli example (set up in VisualGDB using v17 of the SDK). cli with libuarte was chosen because the forum suggests that libuarte is the proper choice for exchanging rather big amounts of data.

I do some code profiling and for this, I have to print out floating point numbers (with as many digits "as possible") via the uart.

Since the logging backend uses libuarte cli as setup in the example, i have to send floats as strings, because sending "raw" data via cli is not possible. I could use a second UART to do so, but it is much easier to control the program and get debug data over the same interface.

Now, since NRF_LOG_FLOAT with the respective float markers is very limited in the number of digits, i use an approach like:

void write_out(float* float_array_p)
{
	char floatchar[15];
	
	for (int ii = 0; ii < 1024; ii++)
	{
		memset(floatchar, 0, sizeof(floatchar));
		sprintf(floatchar, "%14.9f", (float_array_p[ii]));
		NRF_LOG_RAW_INFO("%s,", NRF_LOG_PUSH(floatchar));
		while(NRF_LOG_PROCESS());
		cli_process();
	}
}

The code runs in the main context. While not elegant, it should work fine.

Now, I trigger the function and receive the data on the PC side where i interpret the numbers as floats again. This essentially works, but not all numbers receive with the specified number of digits. It seems that NRF_LOG_RAW_INFO does not always dela correctly with the (as it seems correct) string provided by sprintf.

For example, I receive something like

['0.261669427', '0.25', '0.251542121', '0.247047648', '0.242788866', '0.238817886', '0.235065147', '0.231475547', '0.228071377', '0.224838212', '0.22', '0.208597437', '0.199891493', '0.193471178', '0.188196659', '0.183472663']

 You can see the second number and in this case the 11th one just show 2 digits after the comma.

As far as I can tell (it is hard to debug, because even using the very same numbers as input, not always the same numbers are truncated in the received data!), the strings passed to the NRF_LOG_RAW functions are correct.

Any idea?

[Einar Thorsrud]

Hi,

You convert the floating point to string yourself, so that should not be related. Also, you write that all the strings passed to NRF_LOG_RAW is correct. If that is the case, then the issue could be related to buffer overflows so that strings are cropped, either on the nRF side or the receiving end.

Do you see the same behavior of you logg less or with a lower frequency? What happens if you set NRF_LOG_ALLOW_OVERFLOW to 0 in sdk_config.h (assuming it is not already)?

[Franz]

Hi Einar,

NRF_LOG_ALLOW_OVERFLOW is already at 0

If I look at the requested data directly in putty (i.e. in the terminal", i do not get any "logs dropped" messages.

Since I write the data from the uC to the PC in the loop as shown above, the uC should never run into a buffer overflow because in each iteration it has time to process the logs, right?

Also, since in the example I have shown above, the second value is already corrupted and the firmware has nothing else to do, this also does not seem like a buffer overflow. What else could I check?

//EDIT: Is it possible, that the cli module somehow "overwrites" data before inserting the "terminal style escape sequences"?

A snapshot of the raw string received on the PC side is e.g.

 

 0.025194759,cli:~$\x1b[6D\x1b[J   0.025259649,cli:~$\x1b[6D\x1b[J   0.025324948,cli:~$\x1b[6D\x1b[J   0.02,cli:~$\x1b[6D\x1b[J   0.025456227,cli:~$\x1b[6D\x1b[J

//EDIT 2:
It seems like the issues can be "solved" with a ridiculously big buffer for NRF_LOG_STR_PUSH_BUFFER_SIZE of 2048 and slight modification of the code to every time call log and cli process, i.e.

		NRF_LOG_RAW_INFO("%s,", NRF_LOG_PUSH(floatchar));
		while (NRF_LOG_PROCESS())
		{
			cli_process();
		}

Can you maybe tell me how (i.e. how often) I have to cavv NRF_LOG_PROCESS() and or cli_process per loop iteration? In my code portion I posted initially, It seems that the string cannot be processed by a single call to NRF_LOG_PROCESS() and that NRF_LOG_PROCESS does "more work" than a single call of cli_process can handle. Still, I would not suspect that I have to increase NRF_LOG_STR_PUSH_BUFFER_SIZE , because the doc says that NRF_LOG_PUSH just overwrites the existing string in the buffer, so I should get garbage values but the buffer should not increase. Instead It looks like something is filling up anf then starts overwriting data in the buffer.

Maybe you can give me some more insights on how to fix that problem. I suspect I have to add some kind of delay in the loop since cli somhow makes use of APP_TIMER for log processing?

[Einar Thorsrud]

Hi,

Regarding NRF_LOG_PROCESS() that only processes one entry at a time. And so it also makes sense to call cli_process() for every call, like you do now. I do not have full overview of the CLI module though, but I have asked one of the authors to look at it.

[Krzysztof Chruscinski]

Unfortunately, what you see is the limitation of string pushing. They are copied into ring buffer and when next allocation lands at the end of the buffer string is trimmed. See comment in nrf_log_push() (in nrf_log_frontend.c).

What i could recommend is to not use pushing but statically allocated array on your side and logging strings directly from that array. You can tune array size so logs are processed faster than strings update. I know it is not perfect but should work better.

[Franz]

Hi Krzysztof,

Thanks for the reply. So that I understand better:

1.) NRF_LOG_PUSH pushes the string into a ringbuffer and what I see is that the loop is pushing strings to the buffer faster than the strings are taken from the ringbuffer (by the uart backend), right? That means the NRF_LOG_PROCESS() and nrf_cli_process() commands are non-blocking and just pass the message to the backend?

2.) If so, is there a way to make NRF_LOG_PROCESS and cli_process blocking so that I can trade off the blocking behaviour against a small buffer size?

3.) Can you shortly explain how NRF_LOG_PROCESS() and nrf_cli_process() work together?

3.1) For one string pushed to the ringbuffer, Is ONE call of NRF_LOG_PROCESS() and ONE call to nrf_cli() sufficient? Or does that depend on the length of the string? (does the logger backend somehow cut the string into a fixed chunk size during processing)

3.2) As far as I understand the libuart_cli example, the cli module is used as a backend for the logger, so I am not sure why I have to call both processing functions. Should´nt the logger itself trigger the processing of all the enabled backends?

Thanks!

[Krzysztof Chruscinski]

Hi Franz,

you can delay NRF_LOG_PROCESS() by adding a delay or sleep to while loop. When NRF_LOG_PROCESS() is called it takes one message from the queue and passes it to all active backends. CLI is one of the active backends. CLI takes this message and queues. When cli_process() is called it handles cli pending actions, it will find pending log message and will process it.

Logger passes whole message to the cli, cli is the one who formats the string and sends it to transport layer (uart, rtt).

Regarding 3.1 one call to LOG_PROCESS() and one to nrf_cli_process() will process (print) one log message.

3.2 Logger passes the message to all backends. It is up to the backend to react. Simple backend like uart may print immediately but more complex may require more operations. CLI is that example, logger only enqueues the message so cli process must be explicitly called by the user.