Kernel Event Logger

The kernel event logger records the occurrence of certain types of kernel events, allowing them to be subsequently extracted and reviewed. This capability can be helpful in profiling the operation of an application, either for debugging purposes or for optimizing the performance the application.

Concepts

The kernel event logger does not exist unless it is configured for an application. The capacity of the kernel event logger is also configurable. By default, it has a ring buffer that can hold up to 128 32-bit words of event information.

The kernel event logger is capable of recording the following pre-defined event types:

  • Interrupts.
  • Context switching of threads.
  • Kernel sleep events (i.e. entering and exiting a low power state).

The kernel event logger only records the pre-defined event types it has been configured to record. Each event type can be enabled independently.

An application can also define and record custom event types. The information recorded for a custom event, and the times at which it is recorded, must be implemented by the application.

All events recorded by the kernel event logger remain in its ring buffer until they are retrieved by the application for review and analysis. The retrieval and analysis logic must be implemented by the application.

Important

An application must retrieve the events recorded by the kernel event logger in a timely manner, otherwise new events will be dropped once the event logger’s ring buffer becomes full. A recommended approach is to use a cooperative thread to retrieve the events, either on a periodic basis or as its sole responsibility.

By default, the kernel event logger records all occurrences of all event types that have been enabled. However, it can also be configured to allow an application to dynamically start or stop the recording of events at any time, and to control which event types are being recorded. This permits the application to capture only the events that occur during times of particular interest, thereby reducing the work needed to analyze them.

Note

The kernel event logger can also be instructed to ignore context switches involving a single specified thread. This can be used to avoid recording context switch events involving the thread that retrieves the events from the kernel event logger.

Event Formats

Each event recorded by the kernel event logger consists of one or more 32-bit words of data that describe the event.

An interrupt event has the following format:

struct {
    uint32_t timestamp;        /* time of interrupt */
    uint32_t interrupt_id;     /* ID of interrupt */
};

A context-switch event has the following format:

struct {
    uint32_t timestamp;        /* time of context switch */
    uint32_t context_id;       /* ID of thread that was switched out */
};

A sleep event has the following format:

struct {
    uint32_t sleep_timestamp;  /* time when CPU entered sleep mode */
    uint32_t wake_timestamp;   /* time when CPU exited sleep mode */
    uint32_t interrupt_id;     /* ID of interrupt that woke CPU */
};

A custom event must have a type ID that does not conflict with any existing pre-defined event type ID. The format of a custom event is application-defined, but must contain at least one 32-bit data word. A custom event may utilize a variable size, to allow different events of a single type to record differing amounts of information.

Timestamps

By default, the timestamp recorded with each pre-defined event is obtained from the kernel’s hardware clock. This 32-bit clock counts up extremely rapidly, which means the timestamp value wraps around frequently. (For example, the Lakemont APIC timer for Quark SE wraps every 134 seconds.) This wraparound must be accounted for when analyzing kernel event logger data. In addition, care must be taken when tickless idle is enabled, in case a sleep duration exceeds 2^32 clock cycles.

If desired, the kernel event logger can be configured to record a custom timestamp, rather than the default timestamp. The application registers the callback function that generates the custom 32-bit timestamp at run-time by calling sys_k_event_logger_set_timer().

Implementation

Retrieving An Event

An event can be retrieved from the kernel event logger in a blocking or non-blocking manner using the following APIs:

In each case, the API also returns the type and size of the event, as well as the event information itself. The API also indicates how many events were dropped between the occurrence of the previous event and the retrieved event.

The following code illustrates how a thread can retrieve the events recorded by the kernel event logger. A sample application that shows how to collect kernel event data can also be found at samples/kernel_event_logger.

uint16_t event_id;
uint8_t  dropped_count;
uint32_t data[3];
uint8_t  data_size;

while(1) {
    /* retrieve an event */
    data_size = SIZE32_OF(data);
    res = sys_k_event_logger_get_wait(&event_id, &dropped_count, data,
                                      &data_size);

    if (dropped_count > 0) {
        /* ... Process the dropped events count ... */
    }

    if (res > 0) {
        /* process the event */
        switch (event_id) {
        case KERNEL_EVENT_CONTEXT_SWITCH_EVENT_ID:
            /* ... Process the context switch event ... */
            break;
        case KERNEL_EVENT_INTERRUPT_EVENT_ID:
            /* ... Process the interrupt event ... */
            break;
        case KERNEL_EVENT_SLEEP_EVENT_ID:
            /* ... Process the sleep event ... */
            break;
        default:
            printf("unrecognized event id %d\n", event_id);
        }
    } else if (res == -EMSGSIZE) {
        /* ... Data array is too small to hold the event! ... */
    }
}

Adding a Custom Event Type

A custom event type must use an integer type ID that does not duplicate an existing type ID. The type IDs for the pre-defined events can be found in include/logging/kernel_event_logger.h. If dynamic recording of events is enabled, the event type ID must not exceed 32.

Custom events can be written to the kernel event logger using the following APIs:

Both of these APIs record an event as long as there is room in the kernel event logger’s ring buffer. To enable dynamic recording of a custom event type, the application must first call sys_k_must_log_event() to determine if event recording is currently active for that event type.

The following code illustrates how an application can write a custom event consisting of two 32-bit words to the kernel event logger.

#define MY_CUSTOM_EVENT_ID 8

/* record custom event only if recording is currently wanted */
if (sys_k_must_log_event(MY_CUSTOM_EVENT_ID)) {
    uint32_t data[2];

    data[0] = custom_data_1;
    data[1] = custom_data_2;

    sys_k_event_logger_put(MY_CUSTOM_EVENT_ID, data, ARRAY_SIZE(data));
}

The following code illustrates how an application can write a custom event that records just a timestamp using a single 32-bit word.

#define MY_CUSTOM_TIME_ONLY_EVENT_ID 9

if (sys_k_must_log_event(MY_CUSTOM_TIME_ONLY_EVENT_ID)) {
    sys_k_event_logger_put_timed(MY_CUSTOM_TIME_ONLY_EVENT_ID);
}

APIs

Event Logger

An event logger is an object that can record the occurrence of significant events, which can be subsequently extracted and reviewed.

void sys_event_logger_init(struct event_logger *logger, uint32_t *logger_buffer, uint32_t buffer_size)

Initialize the event logger.

This routine initializes the ring buffer.

Return
N/A
Parameters
  • logger: Logger to be initialized.
  • logger_buffer: Pointer to the buffer to be used by the logger.
  • buffer_size: Size of the buffer in 32-bit words.

void sys_event_logger_put(struct event_logger *logger, uint16_t event_id, uint32_t *event_data, uint8_t data_size)

Send an event message to the logger.

This routine adds an event message to the ring buffer and signals the sync semaphore to indicate that event messages are available.

Return
N/A
Parameters
  • logger: Pointer to the event logger used.
  • event_id: The profiler event’s ID.
  • event_data: Pointer to the data of the message.
  • data_size: Size of the buffer in 32-bit words.

int sys_event_logger_get(struct event_logger *logger, uint16_t *event_id, uint8_t *dropped_event_count, uint32_t *buffer, uint8_t *buffer_size)

Retrieve an event message from the logger.

This routine retrieves an event message from the ring buffer and copies it to the provided buffer. If the provided buffer is smaller than the message size the function returns -EMSGSIZE. Otherwise, it returns the number of 32-bit words copied. The function retrieves messages in FIFO order. If there is no message in the buffer the function returns immediately. It can only be called from a fiber.

Parameters
  • logger: Pointer to the event logger used.
  • event_id: Pointer to the id of the fetched event.
  • dropped_event_count: Pointer to the number of events dropped.
  • buffer: Pointer to the buffer for the copied message.
  • buffer_size: Size of the buffer in 32-bit words. Updated with the actual message’s size.
Return Value
  • EMSGSIZE: If the buffer size is smaller than the message size.
  • Number: of 32-bit words copied.
  • 0: If no message was already available.

int sys_event_logger_get_wait(struct event_logger *logger, uint16_t *event_id, uint8_t *dropped_event_count, uint32_t *buffer, uint8_t *buffer_size)

Retrieve an event message from the logger, wait if empty.

This routine retrieves an event message from the ring buffer and copies it to the provided buffer. If the provided buffer is smaller than the message size the function returns -EMSGSIZE. Otherwise, it returns the number of 32-bit words copied.

The function retrieves messages in FIFO order. The caller pends if there is no message available in the buffer. It can only be called from a fiber.

Parameters
  • logger: Pointer to the event logger used.
  • event_id: Pointer to the ID of the fetched event.
  • dropped_event_count: Pointer to the number of dropped events.
  • buffer: Pointer to the buffer for the copied messages.
  • buffer_size: Size of the buffer in 32-bit words. Updated with the actual message’s size.
Return Value
  • EMSGSIZE: If the buffer size is smaller than the message size.
  • Number: of DWORDs copied, otherwise.

int sys_event_logger_get_wait_timeout(struct event_logger *logger, uint16_t *event_id, uint8_t *dropped_event_count, uint32_t *buffer, uint8_t *buffer_size, uint32_t timeout)

Retrieve an event message from the logger, wait with a timeout if empty.

This routine retrieves an event message from the ring buffer and copies it to the provided buffer. If the provided buffer is smaller than the message size the routine returns -EMSGSIZE. Otherwise, it returns the number of dwords copied. The function retrieves messages in FIFO order. If no message is available in the buffer, the caller pends until a new message is added or the timeout expires. This routine can only be called from a fiber.

Parameters
  • logger: Pointer to the event logger used.
  • event_id: Pointer to the ID of the event fetched.
  • dropped_event_count: Pointer to the number of dropped events.
  • buffer: Pointer to the buffer for the copied message.
  • buffer_size: Size of the buffer in 32-bit words. Updated with the actual message size.
  • timeout: Timeout in ticks.
Return Value
  • EMSGSIZE: if the buffer size is smaller than the message size.
  • Number: of 32-bit words copied.
  • 0: If the timeout expired and there was no message already available.

Kernel Event Logger

The kernel event logger records the occurrence of significant kernel events, which can be subsequently extracted and reviewed. (See Kernel Event Logger.)

typedef sys_k_timer_func_t

Event timestamp generator function type.

A timestamp generator function is executed when the kernel event logger generates an event containing a timestamp.

Return
Timestamp value (application-defined).

static void sys_k_event_logger_set_timer(sys_k_timer_func_t func)

Set kernel event logger timestamp function.

This routine instructs the kernel event logger to call func whenever it needs to generate an event timestamp. By default, the kernel’s hardware timer is used.

Note
On some boards the hardware timer is not a pure hardware up counter, which can lead to timestamp errors. For example, boards using the LOAPIC timer can run it in periodic mode, which requires software to update a count of accumulated cycles each time the timer hardware resets itself to zero. This can result in an incorrect timestamp being generated if it occurs after the timer hardware has reset but before the timer ISR has updated accumulated cycle count.
Return
N/A
Parameters
  • func: Address of timestamp function to be used.

static void sys_k_event_logger_set_mask(int value)

Set kernel event logger filtering mask.

This routine specifies which events are recorded by the kernel event logger. It can only be used when dynamic event logging has been configured.

Each mask bit corresponds to a kernel event type. The least significant mask bit corresponds to event type 1, the next bit to event type 2, and so on.

Return
N/A
Parameters
  • value: Bitmask indicating events to be recorded.

static int sys_k_event_logger_get_mask(void)

Get kernel event logger filtering mask.

This routine indicates which events are currently being recorded by the kernel event logger. It can only be used when dynamic event logging has been configured. By default, no events are recorded.

Return
Bitmask indicating events that are being recorded.

static int sys_k_must_log_event(int event_type)

Indicate if an event type is currently being recorded.

This routine indicates if event type event_type should be recorded by the kernel event logger when the event occurs. The routine should be used by code that writes an event to the kernel event logger to ensure that only events of interest to the application are recorded.

Return
1 if event should be recorded, or 0 if not.
Parameters
  • event_type: Event ID.

static void sys_k_event_logger_put(uint16_t event_id, uint32_t *event_data, uint8_t data_size)

Write an event to the kernel event logger.

This routine writes an event message to the kernel event logger.

Return
N/A
Parameters
  • event_id: Event ID.
  • event_data: Address of event data.
  • data_size: Size of event data (number of 32-bit words).

void sys_k_event_logger_put_timed(uint16_t event_id)

Write an event to the kernel event logger (with timestamp only).

This routine writes an event message to the kernel event logger. The event records a single 32-bit word containing a timestamp.

Return
N/A
Parameters
  • event_id: Event ID.

static int sys_k_event_logger_get(uint16_t *event_id, uint8_t *dropped, uint32_t *event_data, uint8_t *data_size)

Retrieves a kernel event message, or returns without waiting.

This routine retrieves the next recorded event from the kernel event logger, or returns immediately if no such event exists.

Parameters
  • event_id: Area to store event type ID.
  • dropped: Area to store number of events that were dropped between the previous event and the retrieved event.
  • event_data: Buffer to store event data.
  • data_size: Size of event data buffer (number of 32-bit words).
Return Value
  • positive_integer: Number of event data words retrieved; event_id, dropped, and buffer have been updated.
  • 0: Returned without waiting; no event was retrieved.
  • -EMSGSIZE: Buffer too small; data_size now indicates the size of the event to be retrieved.

static int sys_k_event_logger_get_wait(uint16_t *event_id, uint8_t *dropped, uint32_t *event_data, uint8_t *data_size)

Retrieves a kernel event message.

This routine retrieves the next recorded event from the kernel event logger. If there is no such event the caller pends until it is available.

Parameters
  • event_id: Area to store event type ID.
  • dropped: Area to store number of events that were dropped between the previous event and the retrieved event.
  • event_data: Buffer to store event data.
  • data_size: Size of event data buffer (number of 32-bit words).
Return Value
  • positive_integer: Number of event data words retrieved; event_id, dropped, and buffer have been updated.
  • -EMSGSIZE: Buffer too small; data_size now indicates the size of the event to be retrieved.

static int sys_k_event_logger_get_wait_timeout(uint16_t *event_id, uint8_t *dropped, uint32_t *event_data, uint8_t *data_size, uint32_t timeout)

Retrieves a kernel event message, or waits for a specified time.

This routine retrieves the next recorded event from the kernel event logger. If there is no such event the caller pends until it is available or until the specified timeout expires.

Parameters
  • event_id: Area to store event type ID.
  • dropped: Area to store number of events that were dropped between the previous event and the retrieved event.
  • event_data: Buffer to store event data.
  • data_size: Size of event data buffer (number of 32-bit words).
  • timeout: Timeout in system clock ticks.
Return Value
  • positive_integer: Number of event data words retrieved; event_id, dropped, and buffer have been updated.
  • 0: Waiting period timed out; no event was retrieved.
  • -EMSGSIZE: Buffer too small; data_size now indicates the size of the event to be retrieved.

static void sys_k_event_logger_register_as_collector(void)

Register thread that retrieves kernel events.

This routine instructs the kernel event logger not to record context switch events for the calling thread. It is typically called by the thread that retrieves events from the kernel event logger.

Return
N/A