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.
  • Ccontext 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/misc/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);
}