log

Application:

• every call to NRF_LOG_sth puts a log entry into ringbuffer.
• NOT DEFERRED: NRF_LOG_FLUSH() is enforced: calls nrf_log_frontend_dequeue() in loop until ringbuffer empty.

Frontend:

• DEFERRED: Application calls nrf_log_frontend_dequeue() and:
• nrf_log_frontend_dequeue():
  • one entry is pop-ed from ringbuffer
  • new memobj is allocated from log_mempool to fit log entry.
  • all registered backends are iterated:
    • check if backend is enabled nrf_log_backend_is_enabled(p_backend)
    • filters: check if module log level and log entry severity level matches
    • if log entry should be send to backend - call nrf_log_backend_put
    • BACKEND: process log entry and do really printf-like processing and sending / TX-ing / storing for background processing (NRF_CLI_LOG_BACKEND)
• nrf_log_frontend_dequeue() return false if ringbuffer is empty

<uml> participant Application as APP queue “Circular Buffer\nNRF_LOG_BUFSIZE” as CB queue “log_mempool\ndynamic memory pool” as MEM control “nrf_log_frontend_dequeue()” as DE note over MEM NRF_LOG_MSGPOOL_ELEMENT_SIZE

• *x**

NRF_LOG_MSGPOOL_ELEMENT_COUNT endnote control “backend RTT” as B1 control “backend UART” as B2 control “backend x” as B3

APP → CB: NRF_LOG_INFO() activate CB APP → CB: NRF_LOG_DEBUG() activate CB APP → CB: NRF_LOG_HEXDUMP() activate CB … APP → DE: NRF_LOG_PROCESS() activate DE DE ←- MEM: nrf_memobj_alloc() activate MEM activate DE CB –> DE: pop one entry deactivate CB DE –> DE: copy entry to allocated\nmempool object DE ←- DE: backend1:\ncheck filters and status DE –> B1: mempool object DE ←- DE: backend2:\ncheck filters and status DE –> B2: mempool object DE ←- DE: backend3:\ncheck filters and status DE –> B3: mempool object MEM ←- DE: nrf_memobj_put() deactivate MEM DE –> APP: return “circular buffer is empty” deactivate DE deactivate DE </uml>

• Circular buffer of NRF_LOG_BUFSIZE (1024):
  • Its aim is to store log entry from app as fast as possible without further processing.
  • DEFERRED: should be big enough to store all log entries until apps calls log to be processed.
• Dynamic memory pool:
  • size is NRF_LOG_MSGPOOL_ELEMENT_SIZE (20) x NRF_LOG_MSGPOOL_ELEMENT_COUNT (8)
  • provides dynamic memory access, even to fragmented memory.
  • provides storage for log entry qualified to be passed to backends.
  • provides get/put counting semaphore locking mechanism, so one log entry can be passed to multiple log backends at time.
  • It looks like to be designed for background backends. Counting semaphore will keep object locked until all backends finish.
  • Background backends:
    • NRF_CLI_LOG_BACKEND
• Backends are using temporary string buffers - this is the real place where printf-like function writes generated strings.
  • NRF_LOG_BACKEND_UART_TEMP_BUFFER_SIZE 64

typedef struct
{
    void (*put)(nrf_log_backend_t const * p_backend, nrf_log_entry_t * p_entry);
    void (*panic_set)(nrf_log_backend_t const * p_backend);
    void (*flush)(nrf_log_backend_t const * p_backend);
} nrf_log_backend_api_t;

• put
  • UART/RTT:
    • printf-like processing
    • memobj with log entry is released (put() - counting semaphore decremented)
  • CLI:
    • memobj is not released. get() is called to lock it. And entry is pushed to own queue.
    • own queue size is defined by NRF_CLI_DEF
    • nrf_cli_process() –> cli_log_entry_process() gets entries from queue. It makes memobj free by put() after processing.
• panic_set:
  • RTT: empty
  • UART: uninit uart driver
• flush - empty function in most backends
  • CLI: (void)cli_log_entry_process(p_cli, true);

• nrf_cli_process()
  • cli_log_entry_process()
    • do { } while loop until no log entries in CLI internal queue. So all entries are processed at once.
    • result of processing is passed to printf-like writer p_cli→p_fprintf_ctx == nrf_cli_print_stream
      • cli_write which maps to nrf_cli_uart_transport_api.write == cli_uart_write
      • cli_uart_write puts data to UART TX ringbuffer defined by macro NRF_CLI_UART_DEF

SUMMARY:

• app logs data and metadata to ringbuffer: NRF_LOG_BUFSIZE - so must be big enough to handle all entries until log process
• app idle calls: NRF_LOG_PROCESS()
  • if dynamic log levels enabled it filter what to log
  • it copies entries from ringbuffer to memobj (dynamic memory of size NRF_LOG_MSGPOOL_ELEMENT_SIZE (20) x NRF_LOG_MSGPOOL_ELEMENT_COUNT (8))
  • each one memobj log entry is passed to all active backends (multiple reference locking possible by counting semaphore)
    • UART backend: it process log entry (printf-like formatting) and put it in UART TX buffer. Memobj log entry is released.
    • RTT backend: it process log entry (printf-like formatting) and put it in RTT buffer. Memobj log entry is released.
    • CLI backend: it puts log entry into own queue. Memobj log entry is NOT released.
      • conclusion: dynamic memory pool size NRF_LOG_MSGPOOL_ELEMENT_SIZE (20) x NRF_LOG_MSGPOOL_ELEMENT_COUNT (8) should be the same as NRF_LOG_BUFSIZE.
      • conclusion: CLI LOG queue sized defined by macro NRF_CLI_DEF should be big enough to track all memobj log entries.
• app idle calls: nrf_cli_process()
  • whole queue is processed in loop
    • each memobj log entry is processed (printf-like formatting) and put into UART TX ring buffer (size defined by NRF_CLI_UART_DEF).