283 lines
8.2 KiB
ReStructuredText
283 lines
8.2 KiB
ReStructuredText
.. _event_logger_v2:
|
|
|
|
Kernel Event Logger [TBD]
|
|
#########################
|
|
|
|
Definition
|
|
**********
|
|
|
|
The kernel event logger is a standardized mechanism to record events within the
|
|
Kernel while providing a single interface for the user to collect the data.
|
|
This mechanism is currently used to log the following events:
|
|
|
|
* Sleep events (entering and exiting low power conditions).
|
|
* Context switch events.
|
|
* Interrupt events.
|
|
|
|
Kernel Event Logger Configuration
|
|
*********************************
|
|
|
|
Kconfig provides the ability to enable and disable the collection of events and
|
|
to configure the size of the buffer used by the event logger.
|
|
|
|
These options can be found in the following path :file:`kernel/Kconfig`.
|
|
|
|
General kernel event logger configuration:
|
|
|
|
* :option:`CONFIG_KERNEL_EVENT_LOGGER_BUFFER_SIZE`
|
|
|
|
Default size: 128 words, 32-bit length.
|
|
|
|
Profiling points configuration:
|
|
|
|
* :option:`CONFIG_KERNEL_EVENT_LOGGER_DYNAMIC`
|
|
|
|
Allows modifying at runtime the events to record. At boot no event is
|
|
recorded if enabled This flag adds functions allowing to enable/disable
|
|
recording of kernel event logger.
|
|
|
|
* :option:`CONFIG_KERNEL_EVENT_LOGGER_CUSTOM_TIMESTAMP`
|
|
|
|
Enables the possibility to set the timer function to be used to populate
|
|
kernel event logger timestamp. This has to be done at runtime by calling
|
|
sys_k_event_logger_set_timer and providing the function callback.
|
|
|
|
Adding a Kernel Event Logging Point
|
|
***********************************
|
|
|
|
Custom trace points can be added with the following API:
|
|
|
|
* :c:func:`sys_k_event_logger_put()`
|
|
|
|
Adds the profile of a new event with custom data.
|
|
|
|
* :cpp:func:`sys_k_event_logger_put_timed()`
|
|
|
|
Adds timestamped profile of a new event.
|
|
|
|
.. important::
|
|
|
|
The data must be in 32-bit sized blocks.
|
|
|
|
Retrieving Kernel Event Data
|
|
****************************
|
|
|
|
Applications are required to implement a cooperative thread for accessing the
|
|
recorded event messages. Developers can use the provided API to retrieve the
|
|
data, or may write their own routines using the ring buffer provided by the
|
|
event logger.
|
|
|
|
The API functions provided are:
|
|
|
|
* :c:func:`sys_k_event_logger_get()`
|
|
* :c:func:`sys_k_event_logger_get_wait()`
|
|
* :c:func:`sys_k_event_logger_get_wait_timeout()`
|
|
|
|
The above functions specify various ways to retrieve a event message and to
|
|
copy it to the provided buffer. When the buffer size is smaller than the
|
|
message, the function will return an error. All three functions retrieve
|
|
messages via a FIFO method. The :literal:`wait` and :literal:`wait_timeout`
|
|
functions allow the caller to pend until a new message is logged, or until the
|
|
timeout expires.
|
|
|
|
Enabling/disabling event recording
|
|
**********************************
|
|
|
|
If KERNEL_EVENT_LOGGER_DYNAMIC is enabled, following functions must be checked
|
|
for dynamically enabling/disabling event recording at runtime:
|
|
|
|
* :cpp:func:`sys_k_event_logger_set_mask()`
|
|
* :cpp:func:`sys_k_event_logger_get_mask()`
|
|
|
|
Each mask bit corresponds to the corresponding event ID (mask is starting at
|
|
bit 1 not bit 0).
|
|
|
|
More details are provided in function description.
|
|
|
|
Timestamp
|
|
*********
|
|
|
|
The timestamp used by the kernel event logger is 32-bit LSB of platform HW
|
|
timer (for example Lakemont APIC timer for Quark SE). This timer period is very
|
|
small and leads to timestamp wraparound happening quite often (e.g. every 134s
|
|
for Quark SE).
|
|
|
|
see :option:`CONFIG_SYS_CLOCK_HW_CYCLES_PER_SEC`
|
|
|
|
This wraparound must be considered when analyzing kernel event logger data and
|
|
care must be taken when tickless idle is enabled and sleep duration can exceed
|
|
maximum HW timer value.
|
|
|
|
Timestamp used by the kernel event logger can be customized by enabling
|
|
following option: :option:`CONFIG_KERNEL_EVENT_LOGGER_CUSTOM_TIMESTAMP`
|
|
|
|
In case this option is enabled, a callback function returning a 32-bit
|
|
timestamp must be provided to the kernel event logger by calling the following
|
|
function at runtime: :cpp:func:`sys_k_event_logger_set_timer()`
|
|
|
|
Message Formats
|
|
***************
|
|
|
|
Interrupt-driven Event Messaging
|
|
--------------------------------
|
|
|
|
The data of the interrupt-driven event message comes in two block of 32 bits:
|
|
|
|
* The first block contains the timestamp occurrence of the interrupt event.
|
|
* The second block contains the Id of the interrupt.
|
|
|
|
Example:
|
|
|
|
.. code-block:: c
|
|
|
|
uint32_t data[2];
|
|
data[0] = timestamp_event;
|
|
data[1] = interrupt_id;
|
|
|
|
Context-switch Event Messaging
|
|
------------------------------
|
|
|
|
The data of the context-switch event message comes in two block of 32 bits:
|
|
|
|
* The first block contains the timestamp occurrence of the context-switch event.
|
|
* The second block contains the thread id of the context involved.
|
|
|
|
Example:
|
|
|
|
.. code-block:: c
|
|
|
|
uint32_t data[2];
|
|
data[0] = timestamp_event;
|
|
data[1] = context_id;
|
|
|
|
Sleep Event Messaging
|
|
---------------------
|
|
|
|
The data of the sleep event message comes in three block of 32 bits:
|
|
|
|
* The first block contains the timestamp when the CPU went to sleep mode.
|
|
* The second block contains the timestamp when the CPU woke up.
|
|
* The third block contains the interrupt Id that woke the CPU up.
|
|
|
|
Example:
|
|
|
|
.. code-block:: c
|
|
|
|
uint32_t data[3];
|
|
data[0] = timestamp_went_sleep;
|
|
data[1] = timestamp woke_up.
|
|
data[2] = interrupt_id.
|
|
|
|
|
|
Example: Retrieving Profiling Messages
|
|
======================================
|
|
|
|
.. code-block:: c
|
|
|
|
uint32_t data[3];
|
|
uint8_t data_length = SIZE32_OF(data);
|
|
uint8_t dropped_count;
|
|
|
|
while(1) {
|
|
/* collect the data */
|
|
res = sys_k_event_logger_get_wait(&event_id, &dropped_count, data,
|
|
&data_length);
|
|
|
|
if (dropped_count > 0) {
|
|
/* process the message dropped count */
|
|
}
|
|
|
|
if (res > 0) {
|
|
/* process the data */
|
|
switch (event_id) {
|
|
case KERNEL_EVENT_CONTEXT_SWITCH_EVENT_ID:
|
|
/* ... Process the context switch event data ... */
|
|
break;
|
|
case KERNEL_EVENT_INTERRUPT_EVENT_ID:
|
|
/* ... Process the interrupt event data ... */
|
|
break;
|
|
case KERNEL_EVENT_SLEEP_EVENT_ID:
|
|
/* ... Process the data for a sleep event ... */
|
|
break;
|
|
default:
|
|
printf("unrecognized event id %d\n", event_id);
|
|
}
|
|
} else {
|
|
if (res == -EMSGSIZE) {
|
|
/* ERROR - The buffer provided to collect the
|
|
* profiling events is too small.
|
|
*/
|
|
} else if (ret == -EAGAIN) {
|
|
/* There is no message available in the buffer */
|
|
}
|
|
}
|
|
}
|
|
|
|
.. note::
|
|
|
|
To see an example that shows how to collect the kernel event data, check the
|
|
project :file:`samples/kernel_event_logger`.
|
|
|
|
Example: Adding a Kernel Event Logging Point
|
|
============================================
|
|
|
|
.. code-block:: c
|
|
|
|
uint32_t data[2];
|
|
|
|
if (sys_k_must_log_event(KERNEL_EVENT_LOGGER_CUSTOM_ID)) {
|
|
data[0] = custom_data_1;
|
|
data[1] = custom_data_2;
|
|
|
|
sys_k_event_logger_put(KERNEL_EVENT_LOGGER_CUSTOM_ID, data,
|
|
ARRAY_SIZE(data));
|
|
}
|
|
|
|
Use the following function to register only the time of an event.
|
|
|
|
.. code-block:: c
|
|
|
|
if (sys_k_must_log_event(KERNEL_EVENT_LOGGER_CUSTOM_ID)) {
|
|
sys_k_event_logger_put_timed(KERNEL_EVENT_LOGGER_CUSTOM_ID);
|
|
}
|
|
|
|
APIs
|
|
****
|
|
|
|
The following APIs are provided by the :file:`k_event_logger.h` file:
|
|
|
|
:cpp:func:`sys_k_event_logger_register_as_collector()`
|
|
Register the current cooperative thread as the collector thread.
|
|
|
|
:c:func:`sys_k_event_logger_put()`
|
|
Enqueue a kernel event logger message with custom data.
|
|
|
|
:cpp:func:`sys_k_event_logger_put_timed()`
|
|
Enqueue a kernel event logger message with the current time.
|
|
|
|
:c:func:`sys_k_event_logger_get()`
|
|
De-queue a kernel event logger message.
|
|
|
|
:c:func:`sys_k_event_logger_get_wait()`
|
|
De-queue a kernel event logger message. Wait if the buffer is empty.
|
|
|
|
:c:func:`sys_k_event_logger_get_wait_timeout()`
|
|
De-queue a kernel event logger message. Wait if the buffer is empty until
|
|
the timeout expires.
|
|
|
|
:cpp:func:`sys_k_must_log_event()`
|
|
Check if an event type has to be logged or not
|
|
|
|
In case KERNEL_EVENT_LOGGER_DYNAMIC is enabled:
|
|
|
|
:cpp:func:`sys_k_event_logger_set_mask()`
|
|
Set kernel event logger event mask
|
|
|
|
:cpp:func:`sys_k_event_logger_get_mask()`
|
|
Get kernel event logger event mask
|
|
|
|
In case KERNEL_EVENT_LOGGER_CUSTOM_TIMESTAMP is enabled:
|
|
|
|
:cpp:func:`sys_k_event_logger_set_timer()`
|
|
Set kernel event logger timestamp function
|