Kernel Trace (UART terminal)

🚧 TRACER is under construction

⚠️ Out of date: for armv6m, the Trace has fewer features than described here.

Kernel Trace

The RK0 trace module provides an interactive UART console and snapshot APIs for inspecting kernel state at run time. It is intended for debugging task behaviour, kernel object state, timers, priority inheritance, and recent operations on synchronisation and message-passing objects.

Trace is optional. When it is disabled, most trace APIs compile to no-ops.

Enable Trace

Enable trace in core/inc/kconfig.h:

#define RK_CONF_TRACE (ON)

The trace configuration also controls RAM usage:

#define RK_CONF_TRACE_STACKSIZE
#define RK_CONF_TRACE_PRIO
#define RK_CONF_TRACE_MAX_OBJECTS
#define RK_CONF_TRACE_LINE_LEN
#define RK_CONF_TRACE_RECORD_DEPTH

ARMv6-M targets use smaller defaults than ARMv7-M targets. Increase RK_CONF_TRACE_MAX_OBJECTS if objects are missing from list kobjects, and increase RK_CONF_TRACE_RECORD_DEPTH if object history or task priority-change history overwrites useful events too quickly.

Minimal Setup

Initialise trace after creating and naming the objects you want to inspect:

static RK_SEMAPHORE sema;

VOID kApplicationInit(VOID)
{
    RK_ERR err;

    err = kSemaphoreInit(&sema, 0U, 1U);
    K_ASSERT(err == RK_ERR_SUCCESS);

    err = kTraceNameObject(&sema, "AppSem");
    K_ASSERT(err == RK_ERR_SUCCESS);

    err = kTraceInit();
    K_ASSERT(err == RK_ERR_SUCCESS);
}

Object names are limited by RK_NAME_SIZE. With the default size, keep names to 7 visible characters plus the terminating NUL.

UART Access

The trace console reads commands through this weak hook:

INT kTraceUartGetc(CHAR *chPtr);

The function must be non-blocking:

INT kTraceUartGetc(CHAR *chPtr)
{
    if (chPtr == NULL)
    {
        return 0;
    }

    if (uart_rx_empty())
    {
        return 0;
    }

    *chPtr = uart_read();
    return 1;
}

Return 1 when a character was read, and 0 when no character is available. Do not block inside this hook.

The trace task is intended to be event-driven by UART RX. A platform UART backend should enable receive interrupts with:

VOID kTraceUartRxEnable(VOID);

The UART ISR should buffer received characters and then signal the trace task:

kTraceInputSignalFromISR();

kTracePoll() remains public for applications that want to drain trace input from their own service loop, but the default trace task wakes from the UART RX task event instead of periodically polling.

On QEMU builds that provide the UART hook, run:

make ARCH=armv7m qemu

or:

make ARCH=armv6m qemu

With qemu-system-arm -nographic, the terminal stdin/stdout acts as the UART. When the prompt appears, type trace commands:

ktrace> top
ktrace> list kobjects
ktrace> hist TrQueue
ktrace> hist task/XrOwn

If the prompt does not appear, check that:

• RK_CONF_TRACE is ON.
• kTraceInit() is called.
• The board provides a non-blocking kTraceUartGetc().
• The board enables RX interrupts with kTraceUartRxEnable().
• The UART ISR calls kTraceInputSignalFromISR() after buffering RX data.
• The trace task has enough stack.
• The trace task priority allows it to run.

Naming Objects

Use one macro for all traceable kernel objects:

kTraceNameObject(&object, "Name");

Name objects after their kernel initialisation call succeeds:

kTraceNameObject(&traceSema, "TrSema");
kTraceNameObject(&traceMutex, "TrMutex");
kTraceNameObject(&traceQ, "TrQueue");
kTraceNameObject(&traceTimer, "TrTimer");
kTraceNameObject(&traceMem, "TrMem");
kTraceNameObject(&traceMrm, "TrMrm");

Unnamed objects are printed with a fallback type name such as mem, sema, or timer. If several rows appear as mem mem, those are unnamed memory pools. Name the owning object where possible so the trace output is easier to read.

Console Commands

help

Prints the supported commands:

top
list kobjects
list kmesg
list kipc
list ksema
list kmem
list ksleepq
list kmrm
list ktimers
list ktimerq
hist [object-name|task/name|task/pid]
history [object-name|task/name|task/pid]
dump [frames]
help

history is an alias for hist.

top

Lists tasks and scheduling-related state:

PID NAME     ST     PRIO NOM RUNS  PCHG CPU% TICKS OWNMTX STACK     FIRST    LAST     LOWSP    EVCUR    EVREQ    EVOP

Fields:

• PID: task id.
• NAME: task name.
• ST: task state.
• PRIO: current effective priority.
• NOM: nominal priority.
• RUNS: number of times the scheduler has dispatched the task.
• PCHG: number of effective-priority changes recorded for the task.
• CPU%: percentage of trace accounting ticks.
• TICKS: trace accounting ticks charged to the task.
• OWNMTX: number of mutexes owned by the task.
• STACK: free/total stack words.
• FIRST: first address in the task stack buffer.
• LAST: last address in the task stack buffer.
• LOWSP: lowest stack address reached, derived from the stack paint pattern.
• EVCUR: current task event register.
• EVREQ: requested event mask while waiting for events.
• EVOP: event wait mode, usually ANY, ALL, or -.

Use PCHG to find tasks affected by priority inheritance or priority adoption. Then use hist task/<name> or hist task/<pid> to inspect the individual priority transitions.

CPU% is trace accounting, not a cycle-accurate profiler. If the system has no ready work, IDLE can legitimately show close to 100%.

list kobjects

Lists all registered trace objects:

TYPE  NAME     EVENTS LASTOP

Fields:

• TYPE: object type, for example mem, sema, mutex, mesgq, timer, mrm, or sleepq.
• NAME: object name or fallback type name.
• EVENTS: number of retained history records for the object.
• LASTOP: most recent recorded operation.

Use this command first when deciding which object to inspect with hist.

list kmesg

Lists registered message queues:

TYPE  NAME     OWNER    BUF/CAP SEND RECV REQ ACTIVE

This includes message queues only. Channel and Rendezvous have no traceable kernel object; use list kipc for their task-backed state.

• OWNER: owner task for Port-style owned queues.
• BUF/CAP: current buffered messages over capacity.
• SEND: blocked senders.
• RECV: blocked receivers.
• REQ: blocked requesters, where applicable.
• ACTIVE: object-specific active state.

list kipc

Lists task-backed IPC state for Channel and Rendezvous:

PID TASK     ST     IPC       SERVER   SVEF SVNOM PEER     TPR TNOM STATE    BYTES CALLQ ACCQ SENDQ ACT

Fields:

• IPC: chan-call, chan-srv, rdvz-send, or rdvz-recv.
• SERVER: Channel server task or Rendezvous receiver task.
• SVEF: server effective priority at the time of the snapshot.
• SVNOM: server nominal priority.
• PEER: active or next waiting caller/sender, where applicable.
• TPR: row task effective priority.
• TNOM: row task nominal priority.
• STATE: IPC-specific state such as queued, active, accept, pending, recvwait, or idle.
• BYTES: request or Rendezvous payload size in bytes.
• CALLQ: queued Channel callers for the server.
• ACCQ: server tasks blocked in Channel accept.
• SENDQ: queued Rendezvous senders for the receiver.
• ACT: active call or pending Rendezvous sender flag.

Use list kipc when checking whether Channel priority adoption is active. For a Channel server row, SVEF is the server's current effective priority and SVNOM is the priority it will restore to after kChannelDone().

Port, Channel, and Rendezvous operations enforce the single-authority rule: a task that owns a mutex cannot enter those ownership-transfer paths. top shows OWNMTX, which helps diagnose rejections caused by this rule.

list ksema

Lists semaphores and mutexes:

TYPE  NAME     OWNER    LOCK VAL MAX PI WAIT

Fields:

• TYPE: sema or mutex.
• OWNER: owning task for a locked mutex.
• LOCK: mutex lock state.
• VAL: semaphore value.
• MAX: semaphore maximum value.
• PI: priority inheritance flag for mutexes.
• WAIT: number of waiting tasks.

list kmem

Lists memory partitions:

NAME     BLKSZ FREE/MAX POOL

Fields:

• BLKSZ: block size in bytes.
• FREE/MAX: free blocks over total blocks.
• POOL: backing pool pointer.

Some internal pools are named automatically, for example TCBPool and LogMem. MRM-related pools may appear with names derived from the parent MRM object.

list ksleepq

Lists sleep queues:

NAME     WAIT

WAIT is the number of tasks waiting on the sleep queue.

list kmrm

Lists MRM objects:

NAME     WORDS CUR BUF   DATA

Fields:

• WORDS: message size in words.
• CUR: whether a current published buffer exists.
• BUF: free/max state of the MRM buffer pool.
• DATA: free/max state of the MRM data pool.

list ktimers

Lists application timers:

NAME     ACT RLD PHASE PERIOD REMAIN ARGS

Fields:

• ACT: timer is active.
• RLD: timer reload flag.
• PHASE: initial phase value.
• PERIOD: reload period in ticks.
• REMAIN: ticks from now until the timer expires.
• ARGS: callback argument pointer.

Timer values are in kernel ticks. Use RK_MS_TO_TICKS(ms) when configuring timers from milliseconds.

list ktimerq

Prints the raw application timer delta list:

IDX NAME     DELTA ACCUM PHASE PERIOD NEXT (TICKS)

The timer queue is a delta list:

• DELTA: relative delay from the previous timer node.
• ACCUM: accumulated delay from now.
• PHASE: timer phase value.
• PERIOD: timer reload period.
• NEXT: timer next-time tick value.

Use ACCUM to answer "how many ticks from now will this timer expire?"

Example:

IDX NAME     DELTA ACCUM PHASE PERIOD NEXT (TICKS)
  0 TrTimer      8     8     0     25 4398

This means TrTimer is currently 8 ticks from expiry. If it is a reload timer with PERIOD 25, it should be reinserted with a 25 tick period after the callback runs.

hist [object-name]

Prints operation history. With no name, it prints history for all registered objects. With a name, it prints only that object:

ktrace> hist TrQueue

Output:

history mesgq/TrQueue
TICK     TASK     OP       RET VAL
   5880 TrTx     send       0 1
   5889 TrRx     recv       0 0

Fields:

• TICK: kernel tick when the operation was recorded.
• TASK: task that performed the operation, or - when no task was running.
• OP: operation name.
• RET: return code, usually 0 for success.
• VAL: operation-specific value.

Common operations include:

init name query alloc free send recv jam post pend block wake timeout reset
sendblk recvblk jamblk pendblk lockblk wait waitblk lock unlock call accept
done reserve publish get unget cancel reload expire

Operations ending in blk mean the named operation suspended the running task, for example recvblk means a receive operation blocked waiting for data.

VAL depends on the object and operation. Examples:

• Memory alloc or free: often the remaining free block count.
• Message queue send or recv: often queue occupancy.
• Semaphore post or pend: often semaphore value.
• Timer reload: usually the delay used to reinsert the timer.
• Timer expire: usually the timer active/reload state.

hist task/<name> and hist task/<pid>

Prints the retained effective-priority change history for one task:

ktrace> hist task/XrOwn

Output:

history task/XrOwn
TICK     ACTOR    REASON   OLD NEW NOM
       0 XrSend   prio       4   1   4
       0 XrOwn    prio       1   4   4

Fields:

• TICK: kernel tick when the priority change was recorded.
• ACTOR: running task at the time of the change.
• REASON: currently prio for effective-priority changes.
• OLD: previous effective priority.
• NEW: new effective priority.
• NOM: task nominal priority.

This view explains the PCHG count shown by top. It is especially useful when checking priority inheritance caused by mutexes and priority adoption caused by Ports, Channels, or Rendezvous paths.

Interpreting Common Output

IDLE shows 100% CPU

This means the scheduler mostly had no runnable application work during the trace accounting window. It is normal for an idle system. If a task should be running, inspect its state in top and check whether it is blocked on events, a semaphore, a queue, a delay, or a synchronous rendezvous.

A task has PCHG greater than zero

The task's effective priority changed at least once. Use:

hist task/<name>

or:

hist task/<pid>

to inspect the retained old/new transitions. For a low-priority Rendezvous owner, a typical pair is a boost to the sender priority followed by restoration to nominal priority after the receiver-side copy.

A task is waiting for events

Use top:

EVCUR    EVREQ    EVOP

EVCUR is the task's current event bits. EVREQ is the mask the task wants. EVOP tells whether any requested bit is enough (ANY) or all requested bits are required (ALL).

Timer expiry looks too frequent

Check both timer views:

list ktimers
list ktimerq
hist TrTimer

list ktimerq is the best view for delta-list behaviour. ACCUM is the actual remaining time from now. hist shows whether the timer is being reloaded with the expected tick count.

Several objects have the same name

If list kobjects shows repeated fallback names such as:

mem   mem
mem   mem

those objects were registered without explicit names. Add kTraceNameObject() calls for the owning objects, or increase naming coverage for internal pools if they need to be inspected directly.

Snapshot APIs

The UART console is built on snapshot APIs that can also be used by custom diagnostic code:

kTraceTaskSnapshot(...)
kTraceMesgSnapshot(...)
kTraceSemaSnapshot(...)
kTraceTimerSnapshot(...)
kTraceRecordSnapshot(...)
kTraceTaskPrioSnapshot(...)

These APIs copy trace state into caller-provided buffers so the caller can print or export the information in another format.

The lower-level hooks that register objects, count ticks, and record operations are kernel instrumentation points. Application code normally only needs:

kTraceInit();
kTraceNameObject(&object, "Name");

Cost And Limits

Trace consumes RAM for:

• The trace task stack.
• The registered object table.
• Per-object operation history.
• Per-task priority-change history.
• Temporary line buffers.

Trace also adds small run-time overhead:

• kTraceTick() accounts the running task.
• Instrumented kernel operations record circular history entries.
• Priority inheritance/adoption paths record task priority changes.
• The trace task is event-driven by UART RX interrupt.
• Console output uses printf.

Keep trace disabled in builds where this overhead or console output is not acceptable.