LOG_MODE_MINIMAL do not work with USB_CDC for nRF52840

[DuMaM]

Describe the bug

I was trying to enable a log in console.
To do so, I played around with shell_module example, and I was trying to add another console driver to this example.
When I pick LOG_DEFFERED=y it works perfectly.
When I pick LOG_MINIMAL or LOG_MODE_IMMEDIATE then nothing works.

To Reproduce
Steps to reproduce the behavior:

1. Take a nRF52840 board
2. Change LOG_MODE_DEFFERED to LOG_MODE_MINIMAL and add zephyr,console = &cdc_acm_uart0; in usb.overlay file in shell_subsystem sample.
3. build sample with your changes together with prj_minimal.conf with usb_overlay.proj
4. See error

Expected behavior
Shell and console is working on usb port.

Impact
Huge for me. I need a solution which gives me fast output.
For others, I guess it will be not a big problem.

Environment (please complete the following information):

• OS: Windows
• Toolchain NRF SDK 2.2.0,
• Commit SHA commit c0689b1 (3.2.99)
• Board: Particle Xenon

[carlescufi]

cc @jfischer-no @desowin

[DuMaM]

Here is repo with my changes
https://github.com/DuMaM/nrf_submodule_shell_error/commits/master

[desowin]

I don't think going with LOG_MODE_MINIMAL will give you the desired fast output due to the very nature how USB works (host initiates every single transaction). The biggest limiting factor currently is that when CDC ACM is used as console, then every single character output to console tends to get transmitted in its own transfer. That is, on host you get 1 byte per URB which is seriously limiting the throughput.

The console uart driver writes the characters with uart_poll_out:

zephyr/drivers/console/uart_console.c

Lines 77 to 95 in 85a7d0c

	static int console_out(int c)
	{
	#ifdef CONFIG_UART_CONSOLE_DEBUG_SERVER_HOOKS
	int handled_by_debug_server = HANDLE_DEBUG_HOOK_OUT(c);
	if (handled_by_debug_server) {
	return c;
	}
	#endif /* CONFIG_UART_CONSOLE_DEBUG_SERVER_HOOKS */
	if ('\n' == c) {
	uart_poll_out(uart_console_dev, '\r');
	}
	uart_poll_out(uart_console_dev, c);
	return c;
	}

which calls cdc_acm_poll_out:

zephyr/subsys/usb/device/class/cdc_acm.c

Lines 988 to 1020 in 85a7d0c

	/*
	* @brief Output a character in polled mode.
	*
	* The poll function looks similar to cdc_acm_fifo_fill() and
	* tries to do the best to mimic behavior of a hardware UART controller
	* without flow control.
	* This function does not block, if the USB subsystem
	* is not ready, no data is transferred to the buffer, that is, c is dropped.
	* If the USB subsystem is ready and the buffer is full, the first character
	* from the tx_ringbuf is removed to make room for the new character.
	*/
	static void cdc_acm_poll_out(const struct device *dev, unsigned char c)
	{
	struct cdc_acm_dev_data_t * const dev_data = dev->data;
	if (!dev_data->configured || dev_data->suspended) {
	LOG_INF("USB device not ready, drop data");
	return;
	}
	dev_data->tx_ready = false;
	if (!ring_buf_put(dev_data->tx_ringbuf, &c, 1)) {
	LOG_INF("Ring buffer full, drain buffer");
	if (!ring_buf_get(dev_data->tx_ringbuf, NULL, 1) ||
	!ring_buf_put(dev_data->tx_ringbuf, &c, 1)) {
	LOG_ERR("Failed to drain buffer");
	return;
	}
	}
	k_work_submit_to_queue(&USB_WORK_Q, &dev_data->tx_work);
	}

USB_WORKQUEUE_PRIORITY Kconfig help mentions:

  By default, USB work queue priority is the lowest cooperative
  priority. This means that any work handler, once started, won't
  be preempted by any other thread until finished.

Therefore, if the console output happens in lower priority (i.e. any preemptive priority) then you'll essentially get one character at a time. You can get more characters at a time (which allows greater throughput, which is essentially what @DuMaM seems to want) by changing USB_WORKQUEUE_PRIORITY to lower priority (e.g. to 1; lowest cooperative priority is higher than any preemptive priority) but that might bring unforeseen issues.

@pfalcon Any idea how to handle it? I think the USB workqueue being cooperative is generally good, however it clearly messes up with the possibility to fill up console buffer.

[desowin]

@DuMaM Could you please check if #53003 gives you enough speedup when used with deferred logging?

[DuMaM]

I need to send a lot of data. Throughput is one problem, but the second one is a space amount i have.
I don't have possiblity to buffer this all and send it via deferred logs.
That's why i need a minimal logs to work. :(
But sure i will check it today.

[desowin]

Minimal logging is working just fine with CDC ACM console when I disable CDC ACM logging. I think the only way around that is to either remove the CDC ACM logging completely or to fail build if CDC ACM is used as console and CDC ACM log level is not Off (done in #53032).