Do not use the debugging level logging over the UART interface with 115200 baud rate. This baud rate is too slow to correctly handle the data and logs. Use 1 Mhz, 8 Mhz for SPI or 1 Mbps for UART instead.
Because of their verbosity, use the debug-related logging features only during the development stage. Do not use them after the product has been released.
Extend the logging buffer to up to 32 kB to avoid losing logs.

Setup

The measurement test was performed only for the NCP architecture, as it is more complex than the RCP one and generates more logs. To enable the log transport option, the log output option was set to OPENTHREAD_CONFIG_LOG_OUTPUT_NCP_SPINEL.

The following devices were used for the test:

nRF52840 PCA10056 board (OpenThread CLI FTD) – acting as Thread Router.
Thread Border Router, consisting of:
- nRF52840 PCA10056 board (OpenThread NCP) – acting as Thread Border Router.
- Raspberry Pi connected over SPI, UART, or USB with the NCP board – acting as Thread Border Router Host.
  - Raspberry Pi can be replaced with other type of device.
Saleae Logic Analyzer – to calculate the bandwidth utilization for Border Router.

Figure 1. Border Router performance measurement setup.

Test conditions

Measurement methods

The following measurement methods were adopted because of the amount of logs they generate:

Commissioning measurement – The Border Router is commissioning the new joiner CLI device.
Ping measurement – The Border Router Host is periodically pinging the CLI device and expects to receive a ping in return.

Measurement

For both measurement methods, the following data was measured:

For SPI and UART interfaces: Utilization of communication medium – the bandwidth utilization was calculated using Saleae Logic Analyzer as follows:
- For SPI, the bandwidth calculation was measuring the time when CS (Chip Select) line was active during measurement.
- For UART, the bandwidth calculation was measuring the time when RX and TX lines are busy separately.
For SPI, UART, and USB interfaces: Rate of dropped logs. Additionally, the bandwidth utilization was calculated for SPI and UART interfaces using Saleae Logic Analyzer:

Additional log counters: To provide more accurate information about the dropped logs, sent logs, and transmitted Spinel frames, additional log counters were added to NCP. These log counters were increased when new data or a log frame was transmitted or rejected. New wpantund command line options were added to read and reset the NCP log counters.

Test log levels: The test was done for all log levels except the NONE one. The DEBG measurements were done for both measurement methods, with packet content dump enabled and disabled.

Interface speeds

The following interface speeds were used for the test:

UART: 115200 and 921600 baud rates.
SPI: 1 MHz and 8 MHz clock speed.

Test procedure

The measurement procedure comprised of the following steps:

Set up the Thread network (Host/NCP + CLI node).
Reset the NCP log counters from wpantund.
Start Saleae Logic Analyzer measurement.
Start the testing procedure for commissioning and ping measurement methods.
Stop the testing procedure.
Stop Saleae Logic Analyzer measurement.
Read the NCP log counters.

The procedure was identical for the different interfaces, interface speeds, and logging levels. The ping was sent for a total of 1 minute, with 100-ms and 250-ms intervals and with a payload of 64 bytes.

Test results

The tables in this section show the results for the utilization of communication medium for SPI and UART, and the dropped log rates for SPI, UART and USB, with various speeds and for different log levels.

The most significant takeaways are the following:

The log levels CRIT, WARN and NOTE are not introducing any significant load to the communication interface.
For the DEBG configuration, the debug configuration with the packet dump is consuming most of the bandwidth (up to 92% for the utilization of communication medium, 18 times more compared with a scenario with disabled logging).
The default buffer size of 512 bytes is too small to process all generated logs. The execution of the code is much faster than the throughput of the serial transport, which causes random logs packet drops because of insufficient space in the NCP buffer. After increasing the NCP log buffer size to 32 kB ((OPENTHREAD_CONFIG_NCP_TX_BUFFER_SIZE) in the openthread-core-default-config.h file, the number of dropped logs decreased to 0% for both the Ping and Commissioning methods.
- The only exception is the UART interface with 115200 baudrate and the DEBG log level with the packet dump.
During the Ping measurement every 100 ms with a payload of 64 B:
- For the dropped log rate for the DEBG log level, the UART interface returned 55.54%.
- For the utilization of communication medium for the DEBG log level, the UART interface was completely saturated and not able to handle more data efficiently.

Results for utilization of communication medium

Commissioning

SPI/UART settings	Log level CRIT	Log level WARN	Log level NOTE	Log level INFO	Log level DEBG	Log level DEBG (no packet dump)
SPI default (1 MHz)	0.06%	0.06%	0.06%	1.93%	8.87%	4.02%
SPI max (8 MHz)	0.02%	0.03%	0.03%	0.46%	2.47%	0.97%
UART default (115200 bps)	RX 0.05% TX 0.25%	RX 0.05% TX 0.25%	RX 0.05% TX 0.25%	RX 0.04% TX 8.40%	RX 0.04% TX 40.26%	RX 0.04% TX 19.21%
UART max (1 Mbps)	RX 0.01% TX 0.03%	RX 0.01% TX 0.04%	RX 0.01% TX 0.04%	RX 0.01% TX 1.24%	RX 0.01% TX 6.50%	RX 0.01% TX 2.68%

Ping - 250 ms

In this measurement, the ping was executed every 250 ms with 64 B of payload.

SPI/UART settings	Log level CRIT	Log level WARN	Log level NOTE	Log level INFO	Log level DEBG	Log level DEBG (no packet dump)
SPI default (1 MHz)	1.01%	1.05%	1.06%	4.21%	18.13%	7.89%
SPI max (8 MHz)	0.23%	0.23%	0.23%	0.99%	4.40%	2.09%
UART default (115200 bps)	RX 4.61% TX 4.19%	RX 4.65% TX 4.21%	RX 4.51% TX 4.15%	RX 4.72% TX 19.52%	RX 4.69% TX 92.25%	RX 4.65% TX 36.24%
UART max (1 Mbps)	RX 0.64% TX 0.58%	RX 0.64% TX 0.58%	RX 0.63% TX 0.58%	RX 0.62% TX 2.79%	RX 0.65% TX 13.03%	RX 0.65% TX 5.20%

Ping - 100 ms

In this measurement, the ping was executed every 100 ms with 64 B of payload.

SPI/UART settings	Log level CRIT	Log level WARN	Log level NOTE	Log level INFO	Log level DEBG	Log level DEBG (no packet dump)
SPI default (1 MHz)	2.63%	2.64%	2.65%	9.88%	42.95%	19.48%
SPI max (8 MHz)	0.57%	0.55%	0.56%	2.51%	10.69%	5.20%
UART default (115200 bps)	RX 11.13% TX 10.1%	RX 11.62% TX 10.52%	RX 11.43% TX 10.37%	RX 11.63% TX 47.76%	RX 10.93% TX 92.64%	RX 11.61% TX 90.54%
UART max (1 Mbps)	RX 1.60% TX 1.42%	RX 1.63% TX 1.48%	RX 1.58% TX 1.44%	RX 1.59% TX 6.96%	RX 1.62% TX 32.46%	RX 1.62% TX 12.87%

Results for dropped log rate

The SPI/UART settings and the log levels tested were identical to the communication medium result tables.

Commissioning: In this measurement, all log levels for both SPI and UART returned values equal to 0%.