From 6511616f76e6bedb6e559fdf16cabbf6f0c9a559 Mon Sep 17 00:00:00 2001 From: Savinay Dharmappa Date: Tue, 24 Oct 2017 01:32:39 +0530 Subject: [PATCH 1/2] subsys: logging: event_logger: Fix CPU fault A CPU fault occurs when sys_k_event_logger_get_wait() api invoked with config KERNEL_EVENT_LOGGER_THREAD enabled. sys_k_event_logger_get_wait() supposed to pend on a semaphore when all the events from kernel event logger are read.But when sys_k_event_logger_get_wait() inovked with config KERNEL_EVENT_LOGGER_THREAD(i.e captures thread events) subsquent call inside this function will write to kernel event log buffer to capture pend event.This will release the semaphore on which sys_k_event_logger_get_wait() was pending hence thread gets unpend before swap gets called. Which in other words a thread which is invoking sys_k_event_logger_get_wait()(i. e sem_count = 0) get pends and unpends in single function flow when KERNEL_EVENT_LOGGER_THREAD enabled. This would cause overlapping of the stack address where return address of "_pend_current_thread" stored with esp of callee saved(i. e thread->callee_saved.esp). Thus return adrress of "_pend_current_thread" would be overwitten with zero. Which in turn causes CPU fault. The thread invoking sys_k_event_logger_get_wait() supposed to only read the events of the threads which logged to kernel event logger buffer. But it should not write to kernel event logger buffer. Otherwise it would cause the race condition explained above. Signed-off-by: Savinay Dharmappa --- subsys/logging/event_logger.c | 29 ++++++++++++++++++++++++++--- 1 file changed, 26 insertions(+), 3 deletions(-) diff --git a/subsys/logging/event_logger.c b/subsys/logging/event_logger.c index 0ea9ebad483e..d1bb10f31535 100644 --- a/subsys/logging/event_logger.c +++ b/subsys/logging/event_logger.c @@ -11,6 +11,7 @@ #include #include +#include void sys_event_logger_init(struct event_logger *logger, u32_t *logger_buffer, u32_t buffer_size) @@ -44,7 +45,18 @@ static void event_logger_put(struct event_logger *logger, u16_t event_id, void sys_event_logger_put(struct event_logger *logger, u16_t event_id, u32_t *event_data, u8_t data_size) { - event_logger_put(logger, event_id, event_data, data_size, k_sem_give); + /* The thread invoking sys_k_event_logger_get_wait() supposed + * to only read the events of the threads which logged to kernel event + * logger buffer. But it should not write to kernel event logger + * buffer. Otherwise it would cause the race condition. + */ + + struct k_thread *event_logger_thread = + (struct k_thread *)sys_dlist_peek_head(&(logger->sync_sema.wait_q)); + if (_current != event_logger_thread) { + event_logger_put(logger, event_id, event_data, + data_size, k_sem_give); + } } @@ -71,8 +83,19 @@ void _sys_event_logger_put_non_preemptible(struct event_logger *logger, { extern void _sem_give_non_preemptible(struct k_sem *sem); - event_logger_put(logger, event_id, event_data, data_size, - _sem_give_non_preemptible); + /* The thread invoking sys_k_event_logger_get_wait() supposed + * to only read the events of the threads which logged to kernel event + * logger buffer. But it should not write to kernel event logger + * buffer. Otherwise it would cause the race condition. + */ + + struct k_thread *event_logger_thread = + (struct k_thread *)sys_dlist_peek_head(&(logger->sync_sema.wait_q)); + + if (_current != event_logger_thread) { + event_logger_put(logger, event_id, event_data, data_size, + _sem_give_non_preemptible); + } } From 8a8bd0d6e453c4cfc1db89aeb0820f8b1ea7ba46 Mon Sep 17 00:00:00 2001 From: Savinay Dharmappa Date: Wed, 25 Oct 2017 23:34:15 +0530 Subject: [PATCH 2/2] sample: subsys: logging: kernel_event_logger: Add sample application patch adds a sample application to demonstrate use of kernel event logger feature. Signed-off-by: Savinay Dharmappa --- .../logging/kernel_event_logger/Makefile | 4 + .../logging/kernel_event_logger/README.rst | 39 +++++++ .../logging/kernel_event_logger/prj.conf | 9 ++ .../logging/kernel_event_logger/sample.yaml | 9 ++ .../logging/kernel_event_logger/src/Makefile | 1 + .../logging/kernel_event_logger/src/main.c | 101 ++++++++++++++++++ samples/subsys/logging/logging.rst | 10 ++ 7 files changed, 173 insertions(+) create mode 100644 samples/subsys/logging/kernel_event_logger/Makefile create mode 100644 samples/subsys/logging/kernel_event_logger/README.rst create mode 100644 samples/subsys/logging/kernel_event_logger/prj.conf create mode 100644 samples/subsys/logging/kernel_event_logger/sample.yaml create mode 100644 samples/subsys/logging/kernel_event_logger/src/Makefile create mode 100644 samples/subsys/logging/kernel_event_logger/src/main.c create mode 100644 samples/subsys/logging/logging.rst diff --git a/samples/subsys/logging/kernel_event_logger/Makefile b/samples/subsys/logging/kernel_event_logger/Makefile new file mode 100644 index 000000000000..4de50f93d4d3 --- /dev/null +++ b/samples/subsys/logging/kernel_event_logger/Makefile @@ -0,0 +1,4 @@ +BOARD ?= qemu_x86 +CONF_FILE = prj.conf + +include ${ZEPHYR_BASE}/Makefile.inc diff --git a/samples/subsys/logging/kernel_event_logger/README.rst b/samples/subsys/logging/kernel_event_logger/README.rst new file mode 100644 index 000000000000..2787e673e870 --- /dev/null +++ b/samples/subsys/logging/kernel_event_logger/README.rst @@ -0,0 +1,39 @@ +.. _kerneleventlogger_sample: + +Kernel Event Logger Sample +################################ + +Overview +******** + +A simple application that demonstrates use of kernel event +logger feature. Two threads (A and B) of the same priority +are created and main thread is configured to have low priority, +which reads the events from kernel event logger's buffer and +prints to the console. When thread 'A' gets scheduled it will +sleep for 1 second. Similarly when thread 'B' gets scheduled +it will sleep for 0.5 seconds. When both A and B are sleeping, +the main thread gets scheduled and retrieves the events captured +from kernel event logger's buffer and prints to the console. + +Building and Running +******************** + +This project outputs to the console. It can be built and executed +on QEMU as follows: + +.. code-block:: console + + $ cd samples/subsys/kernel_event_logger + $ make run + +Sample Output +============= + +.. code-block:: console + + tid of context switched thread = 400080 at time = 96538 + tid of context switched thread = 4000c0 at time = 98047 + thread = 400080, is moved to = REDAY_Q , at time = 51019657 + thread = 400040, is moved to = REDAY_Q , at time = 51024998 + diff --git a/samples/subsys/logging/kernel_event_logger/prj.conf b/samples/subsys/logging/kernel_event_logger/prj.conf new file mode 100644 index 000000000000..aa0462054456 --- /dev/null +++ b/samples/subsys/logging/kernel_event_logger/prj.conf @@ -0,0 +1,9 @@ +CONFIG_BOOT_BANNER=y + +CONFIG_MAIN_THREAD_PRIORITY=3 +CONFIG_RING_BUFFER=y +CONFIG_KERNEL_EVENT_LOGGER=y +CONFIG_KERNEL_EVENT_LOGGER_CONTEXT_SWITCH=y +CONFIG_KERNEL_EVENT_LOGGER_INTERRUPT=n +CONFIG_KERNEL_EVENT_LOGGER_THREAD=y +CONFIG_USERSPACE=n diff --git a/samples/subsys/logging/kernel_event_logger/sample.yaml b/samples/subsys/logging/kernel_event_logger/sample.yaml new file mode 100644 index 000000000000..c493fd332223 --- /dev/null +++ b/samples/subsys/logging/kernel_event_logger/sample.yaml @@ -0,0 +1,9 @@ +sample: + description: A simple application that demonstrate use of + kernel event logging feature. + name: Kernel event logger Sample +tests: +- test: + build_only: true + tags: apps + platform_whitelist: qemu_x86 diff --git a/samples/subsys/logging/kernel_event_logger/src/Makefile b/samples/subsys/logging/kernel_event_logger/src/Makefile new file mode 100644 index 000000000000..b666967fd570 --- /dev/null +++ b/samples/subsys/logging/kernel_event_logger/src/Makefile @@ -0,0 +1 @@ +obj-y += main.o diff --git a/samples/subsys/logging/kernel_event_logger/src/main.c b/samples/subsys/logging/kernel_event_logger/src/main.c new file mode 100644 index 000000000000..56f5949ece0a --- /dev/null +++ b/samples/subsys/logging/kernel_event_logger/src/main.c @@ -0,0 +1,101 @@ +/* + * Copyright (c) 2017 Intel Corporation + * + * SPDX-License-Identifier: Apache-2.0 + */ + +#include +#include +#include +#include +#include +#include + +K_THREAD_STACK_DEFINE(threadA_stack, 1024); +K_THREAD_STACK_DEFINE(threadB_stack, 1024); +K_THREAD_STACK_DEFINE(event_logger_stack, 4096); + +K_SEM_DEFINE(sem_sync, 0, 1); /* starts off "not available" */ + +static struct k_thread threadA_data; +static struct k_thread threadB_data; +static u32_t timestamp; +char event_type[][12] = {"REDAY_Q", "PEND_STATE", "EXIT_STATE"}; + +static void event_logger(void) +{ + u32_t event_data[4]; + u16_t event_id; + u8_t dropped; + u8_t event_data_size = (u8_t)ARRAY_SIZE(event_data); + int ret; + + for (;;) { + + ret = sys_k_event_logger_get_wait(&event_id, + &dropped, + event_data, + &event_data_size); + if (ret < 0) { + continue; + } + + timestamp = event_data[0]; + + switch (event_id) { + case KERNEL_EVENT_LOGGER_CONTEXT_SWITCH_EVENT_ID: + printk("tid of context switched thread = %x at " + "time = %d\n", event_data[1], timestamp); + break; + case KERNEL_EVENT_LOGGER_INTERRUPT_EVENT_ID: + break; + case KERNEL_EVENT_LOGGER_SLEEP_EVENT_ID: + break; + case KERNEL_EVENT_LOGGER_THREAD_EVENT_ID: + printk("thread = %x, is moved to = %s ,at time = %d\n" + , event_data[1], event_type[event_data[2]], timestamp); + break; + default: + break; + } + + } +} + +static void threadB(void) +{ + unsigned int i = 10; + + for (; i ; i--) { + k_sleep(MSEC_PER_SEC / 2); + } + + k_sem_take(&sem_sync, K_FOREVER); +} + +static void threadA(void) +{ + unsigned int j = 10; + + for (; j ; j--) { + + k_sleep(MSEC_PER_SEC); + } + + k_sem_give(&sem_sync); +} + +void main(void) +{ + k_thread_create(&threadB_data, threadB_stack, + K_THREAD_STACK_SIZEOF(threadB_stack), + (k_thread_entry_t)threadB, + NULL, NULL, NULL, K_PRIO_PREEMPT(2), 0, 0); + + k_thread_create(&threadA_data, threadA_stack, + K_THREAD_STACK_SIZEOF(threadA_stack), + (k_thread_entry_t)threadA, + NULL, NULL, NULL, K_PRIO_PREEMPT(2), 0, 0); + + event_logger(); +} diff --git a/samples/subsys/logging/logging.rst b/samples/subsys/logging/logging.rst new file mode 100644 index 000000000000..6b43a116f28a --- /dev/null +++ b/samples/subsys/logging/logging.rst @@ -0,0 +1,10 @@ +.. _logging-samples: + +Logging Sample +################ + +.. toctree:: + :maxdepth: 1 + :glob: + + **/*