Flushing the LTE modem trace buffer

[Peter Murphy]

Dear Nordic,

We’ve developed an application which runs on an nRF9151 DK using NCS 2.8.2. The device is running modem fw nrf91x1_2.0.2. Our application has enabled modem traces using the following Kconfig settings:

• CONFIG_NRF_MODEM_LIB_TRACE_BACKEND_UART=y
• CONFIG_NRF_MODEM_LIB_TRACE_BACKEND_UART_CHUNK_SZ=8191
• CONFIG_NRF_MODEM_LIB_TRACE_STACK_SIZE=768
• CONFIG_NRF_MODEM_LIB_TRACE_LEVEL_OVERRIDE=y
• CONFIG_NRF_MODEM_LIB_TRACE_LEVEL_FULL=y
• CONFIG_NRF_MODEM_LIB_TRACE_LEVEL=2
• CONFIG_NRF_MODEM_LIB_TRACE_BACKEND_SUSPEND_DELAY_MS=5000

The nRF9151 is connected to a linux machine via a USB cable. The linux machine is running Ubuntu 22.04. On the linux machine the nRF9151 presents two serial ports (/dev/ttyACM0 and /dev/ttyACM1). The first serial port allows us to connect to the console port of our application. The second port allows us to read the modem traces. To capture and decode the LTE modem traces we are running the command nrfutil trace lte --input-serialport port=/dev/ttyACM1,flow_control=flow_control_type --output-pcapng pcap_file.pcap. The version information for nrfutil is the following:

• nrfutil -V
• nrfutil 8.0.0 (54d8087 2025-01-07)
• commit-hash: 54d8087a38b73b6e56942fb1b024b62365f06731
• commit-date: 2025-01-07
• host: x86_64-unknown-linux-gnu
• build-timestamp: 2025-01-07T14:26:42.070728557Z
• classification: nrf-external

• nrfutil trace -V
• nrfutil-trace 4.0.1 (4c291c5 2025-04-29)
• commit-hash: 4c291c53eb3b9a9aa0a4dc9c080ed6e274e6a31d
• commit-date: 2025-04-29
• host: x86_64-unknown-linux-gnu
• build-timestamp: 2025-04-30T13:29:07.326959894Z
• classification: nrf-external

We’ve developed some test code which controls the application over the /dev/ttyACM0 port. Within the test code we have a for loop which contains the following pseudo code:

• #flow_control = ‘none’
• #flow_control = ‘software’
• flow_control = ‘hardware’
• for ii 0:N-1
  • Start modem trace using the command nrfutil trace lte --input-serialport port=/dev/ttyACM1,flow_control=flow_control_type --output-pcapng pcap_file_{ii}.pcap
  • Upload data to our cloud service
    • Device goes into RRC connected
    • Upload data
    • Wait for the device to go into RRC idle
  • sleep 10 (10 seconds)
  • Stop the modem trace

The issue we’re running into is that about 20% of the time the pcap_file_{ii}.pcap files generated are empty. We tried the different flow control values (i.e., ‘none’,’software’,’hardware’) but that didn’t help. We’ve also tried prepending the following linux commands to the nrfutil command but this didn’t help either:

• stdbuf -o0 
• stdbuf -oL
• stdbuf -i0 -o0 -e0

Our current thinking is that either the application or the modem itself is buffering the modem traces.

Can you offer some guidance on how to resolve this issue?

Thank you.

Peter

[JONATHAN LL]

Hi Peter, 

Looking in to this and have forwarded the question to our devz, will update. 

But the documentation says that the modem buffers the data. 

The trace backend needs to handle trace data at ~1 Mbps to avoid filling up the buffer in the modem. If the modem buffer is full, the modem drops modem traces until the buffer has space available again.

Ref: https://docs.nordicsemi.com/bundle/ncs-latest/page/nrf/libraries/modem/nrf_modem_lib/nrf_modem_lib_trace.html#modem_trace_flash_backend 


Regards,
Jonathan

[JONATHAN LL]

Update from devz:

Do they have the Device Tree overlay as given in the nrf91-modem-trace-uart snippet?

/* Enable uart1 for tracing. */
&uart1 {
status = "okay";
current-speed = < 1000000 >;
};

/ {
chosen {
nordic,modem-trace-uart = &uart1;
};
};

If not, modem will likely drop a lot of trace messages because of the uart baud rate. Not sure if that can explain the PCAP being completely blank though. Enabling HWFC would help on loosing traces in the board controller if RTT is enabled, as RTT has priority.

Regards,
Jonathan

[Neal Riedel]

Hi Jonathan,

I'm the guy writing the software. ;)

We use the nrf91-modem-trace-uart snippet in the build.  Double-checking the  generated zephyr.dts file, it has this:

        chosen {
                zephyr,entropy = &psa_rng;
                zephyr,flash-controller = &flash_controller;
                zephyr,console = &uart0;
                zephyr,shell-uart = &uart0;
                zephyr,uart-mcumgr = &uart0;
                zephyr,flash = &flash0;
                zephyr,sram = &sram0_ns_app;
                zephyr,code-partition = &slot0_ns_partition;
                nordic,pm-ext-flash = &gd25wb256;
                nordic,modem-trace-uart = &uart1;
        };

And also this:

                        uart1: arduino_serial: uart@9000 {
                                compatible = "nordic,nrf-uarte";
                                reg = < 0x9000 0x1000 >;
                                interrupts = < 0x9 0x1 >;
                                status = "okay";
                                current-speed = < 0xf4240 >;
                                pinctrl-0 = < &uart1_default >;
                                pinctrl-1 = < &uart1_sleep >;
                                pinctrl-names = "default", "sleep";
                                hw-flow-control;
                        };

So I think it is correct.  We do have HW flow control set on this port.  Could that be the issue?

Thanks,

Neal Riedel

[JONATHAN LL]

Hi Neal, 

This looks ok. 

Neal Riedel said:

We do have HW flow control set on this port.  Could that be the issue?

Still checking with the devz and discussing here what could be the reason. 

Regards,
Jonathan

[Neal Riedel]

Thanks, Jonathan.

I tried disabling the HW flow control on uart1, but it had no effect on this problem.

I also connected a scope to the uart1 TXD pin and monitoring the activity when the problem occurs.  The nrfutil trace command displays this:

Saving trace to trace_log3.pcapng (0 bytes)

However I can clearly see activity on the TXD pin, indicating that the 9151 is sending data to the nrfutil application.  So I wonder if the trace data is actually being queue in the linux PC?

[JONATHAN LL]

The HWFC is not the issue, enabled or not the difference would be if the trace data is silently dropped or that the dropped data is registered as a dropped event. But the trace data is gone either way.

This happens if RTT is used and since RTT holdes priority it will take over while the buffer is filled up, if the buffer is full the trace data will be dropped


Having HWFC enabled does not enable a greater risk of missing traces if RTT is on, though it would be more visible in the binary trace than if HWFC is disabled.


An alterative route is to use other pins for for UART and use UART to serial and get the data that way. But there can be issues here as baudrate used is 1 000 000. 

Regards,
Jonathan