kernel: workq: introduce work timeout:

Introduce work timeout, which is an optional workqueue configuration
which enables monitoring for work items which take longer than
expected. This could be due to long running or deadlocked handlers.

Signed-off-by: Bjarki Arge Andreasen <[email protected]>

Author: bjarki-andreasen

include/zephyr/kernel.h

@@ -4168,6 +4168,14 @@ struct k_work_queue_config {
 	 * essential thread.
 	 */
 	bool essential;
+
+	/** Controls whether work queue monitors work timeouts.
+	 *
+	 * If set to a positive value, the work queue will monitor the
+	 * duration of each work item, and warn the user if the work
+	 * item handler takes longer than work_timeout to execute.
+	 */
+	uint32_t work_timeout_ms;
 };
 
 /** @brief A structure used to hold work until it can be processed. */
@@ -4190,6 +4198,15 @@ struct k_work_q {
 
 	/* Flags describing queue state. */
 	uint32_t flags;
+
+	/* Timeout which invokes sentinal */
+	struct _timeout workto;
+
+	/* Work monitored by sentinal */
+	struct k_work *work;
+
+	/* Maximum work duration */
+	k_timeout_t work_timeout;
 };
 
 /* Provide the implementation for inline functions declared above */

kernel/Kconfig

@@ -574,6 +574,9 @@ endmenu
 
 rsource "Kconfig.obj_core"
 
+config WORKQUEUE_WORK_TIMEOUT
+	bool "Support workqueue work timeout monitoring"
+
 menu "System Work Queue Options"
 config SYSTEM_WORKQUEUE_STACK_SIZE
 	int "System workqueue stack size"
@@ -600,6 +603,13 @@ config SYSTEM_WORKQUEUE_NO_YIELD
 	  cooperative and a sequence of work items is expected to complete
 	  without yielding.
 
+config SYSTEM_WORKQUEUE_WORK_TIMEOUT_MS
+	int "Select system work queue work timeout in milliseconds"
+	default 5000 if ASSERT
+	default 0
+	help
+	  Set to 0 to disable work timeout for system workqueue.
+
 endmenu
 
 menu "Barrier Operations"

kernel/system_work_q.c

@@ -25,6 +25,7 @@ static int k_sys_work_q_init(void)
 		.name = "sysworkq",
 		.no_yield = IS_ENABLED(CONFIG_SYSTEM_WORKQUEUE_NO_YIELD),
 		.essential = true,
+		.work_timeout_ms = CONFIG_SYSTEM_WORKQUEUE_WORK_TIMEOUT_MS,
 	};
 
 	k_work_queue_start(&k_sys_work_q,

kernel/work.c

@@ -17,6 +17,9 @@
 #include <errno.h>
 #include <ksched.h>
 #include <zephyr/sys/printk.h>
+#include <zephyr/logging/log.h>
+
+LOG_MODULE_DECLARE(os, CONFIG_KERNEL_LOG_LEVEL);
 
 static inline void flag_clear(uint32_t *flagp,
 			      uint32_t bit)
@@ -599,6 +602,52 @@ bool k_work_cancel_sync(struct k_work *work,
 	return pending;
 }
 
+#if defined(CONFIG_WORKQUEUE_WORK_TIMEOUT)
+static void workto_handler(struct _timeout *to)
+{
+	struct k_work_q *queue = CONTAINER_OF(to, struct k_work_q, workto);
+	k_spinlock_key_t key;
+	const char *name;
+	struct k_work *work;
+	k_work_handler_t handler;
+
+	key = k_spin_lock(&lock);
+
+	name = k_thread_name_get(&queue->thread);
+	work = queue->work;
+	handler = work->handler;
+
+	if (name != NULL) {
+		LOG_ERR("queue %s blocked by work %p with handler %p", name, work, handler);
+	} else {
+		LOG_ERR("queue %p blocked by work %p with handler %p", queue, work, handler);
+	}
+
+	k_spin_unlock(&lock, key);
+
+	k_oops();
+}
+
+static void work_timeout_start_locked(struct k_work_q *queue, struct k_work *work)
+{
+	if (K_TIMEOUT_EQ(queue->work_timeout, K_FOREVER)) {
+		return;
+	}
+
+	queue->work = work;
+	z_add_timeout(&queue->workto, workto_handler, queue->work_timeout);
+}
+
+static void work_timeout_stop_locked(struct k_work_q *queue)
+{
+	if (K_TIMEOUT_EQ(queue->work_timeout, K_FOREVER)) {
+		return;
+	}
+
+	z_abort_timeout(&queue->workto);
+}
+#endif /* defined(CONFIG_WORKQUEUE_WORK_TIMEOUT) */
+
 /* Loop executed by a work queue thread.
  *
  * @param workq_ptr pointer to the work queue structure
@@ -678,6 +727,10 @@ static void work_queue_main(void *workq_ptr, void *p2, void *p3)
 			continue;
 		}
 
+#if defined(CONFIG_WORKQUEUE_WORK_TIMEOUT)
+		work_timeout_start_locked(queue, work);
+#endif /* defined(CONFIG_WORKQUEUE_WORK_TIMEOUT) */
+
 		k_spin_unlock(&lock, key);
 
 		__ASSERT_NO_MSG(handler != NULL);
@@ -690,6 +743,10 @@ static void work_queue_main(void *workq_ptr, void *p2, void *p3)
 		 */
 		key = k_spin_lock(&lock);
 
+#if defined(CONFIG_WORKQUEUE_WORK_TIMEOUT)
+		work_timeout_stop_locked(queue);
+#endif /* defined(CONFIG_WORKQUEUE_WORK_TIMEOUT) */
+
 		flag_clear(&work->flags, K_WORK_RUNNING_BIT);
 		if (flag_test(&work->flags, K_WORK_FLUSHING_BIT)) {
 			finalize_flush_locked(work);
@@ -761,6 +818,14 @@ void k_work_queue_start(struct k_work_q *queue,
 		queue->thread.base.user_options |= K_ESSENTIAL;
 	}
 
+#if defined(CONFIG_WORKQUEUE_WORK_TIMEOUT)
+	if ((cfg != NULL) && (cfg->work_timeout_ms)) {
+		queue->work_timeout = K_MSEC(cfg->work_timeout_ms);
+	} else {
+		queue->work_timeout = K_FOREVER;
+	}
+#endif /* defined(CONFIG_WORKQUEUE_WORK_TIMEOUT) */
+
 	k_thread_start(&queue->thread);
 
 	SYS_PORT_TRACING_OBJ_FUNC_EXIT(k_work_queue, start, queue);