core: add core_mutex_debug to aid debugging deadlocks

Adding `USEMODULE += core_mutex_debug` to your `Makefile` results in
on log messages such as

    [mutex] waiting for thread 1 (pc = 0x800024d)

being added whenever `mutex_lock()` blocks. This makes tracing down
deadlocks easier.

core/Kconfig

@@ -39,6 +39,9 @@ config MODULE_CORE_MSG_BUS
     help
         Messaging Bus API for inter process message broadcast.
 
+config MODULE_CORE_MUTEX_DEBUG
+    bool "Aid debugging deadlocks by printing on whom mutex_lock() is waiting"
+
 config MODULE_CORE_MUTEX_PRIORITY_INHERITANCE
     bool "Use priority inheritance to mitigate priority inversion for mutexes"
 

core/include/mutex.h

@@ -97,6 +97,19 @@
  *       `MUTEX_LOCK`.
  *     - The scheduler is run, so that if the unblocked waiting thread can
  *       run now, in case it has a higher priority than the running thread.
+ *
+ * Debugging deadlocks
+ * -------------------
+ *
+ * The module `core_mutex_debug` can be used to print on whom `mutex_lock()`
+ * is waiting. This information includes the thread ID of the owner and the
+ * program counter (PC) from where `mutex_lock()` was called. Note that the
+ * information is only valid if:
+ *
+ * - The mutex was locked by a thread, and not e.g. by `MUTEX_INIT_LOCKED`
+ * - The function `cpu_get_acller_pc()` is implemented for the target
+ *   architecture. (The thread ID will remain valid, though.)
+ *
  * @{
  *
  * @file
@@ -112,6 +125,8 @@
 #include <stdint.h>
 #include <stdbool.h>
 
+#include "architecture.h"
+#include "cpu.h"
 #include "kernel_defines.h"
 #include "list.h"
 #include "thread.h"
@@ -130,7 +145,8 @@ typedef struct {
      * @internal
      */
     list_node_t queue;
-#if defined(DOXYGEN) || defined(MODULE_CORE_MUTEX_PRIORITY_INHERITANCE)
+#if defined(DOXYGEN) || defined(MODULE_CORE_MUTEX_PRIORITY_INHERITANCE) \
+    || defined(MODULE_CORE_MUTEX_DEBUG)
     /**
      * @brief   The current owner of the mutex or `NULL`
      * @note    Only available if module core_mutex_priority_inheritance
@@ -141,6 +157,18 @@ typedef struct {
      * this will have the value of `NULL`.
      */
     kernel_pid_t owner;
+#endif
+#if defined(DOXYGEN) || defined(MODULE_CORE_MUTEX_DEBUG)
+    /**
+     * @brief   Program counter of the call to @ref mutex_lock that most
+     *          recently acquired this mutex
+     *
+     * This is used when the module `core_mutex_debug` is used to debug
+     * deadlocks and is non-existing otherwise
+     */
+    uinttxtptr_t owner_calling_pc;
+#endif
+#if defined(DOXYGEN) || defined(MODULE_CORE_MUTEX_PRIORITY_INHERITANCE)
     /**
      * @brief   Original priority of the owner
      * @note    Only available if module core_mutex_priority_inheritance

core/mutex.c

@@ -50,6 +50,11 @@
 static inline __attribute__((always_inline)) void _block(mutex_t *mutex,
                                                          unsigned irq_state)
 {
+#if IS_USED(MODULE_CORE_MUTEX_DEBUG)
+    printf("[mutex] waiting for thread %" PRIkernel_pid " (pc = 0x%" PRIxTXTPTR
+           ")\n",
+           mutex->owner, mutex->owner_calling_pc);
+#endif
     thread_t *me = thread_get_active();
 
     /* Fail visibly even if a blocking action is called from somewhere where
@@ -80,6 +85,9 @@ static inline __attribute__((always_inline)) void _block(mutex_t *mutex,
     irq_restore(irq_state);
     thread_yield_higher();
     /* We were woken up by scheduler. Waker removed us from queue. */
+#if IS_USED(MODULE_CORE_MUTEX_DEBUG)
+    mutex->owner_calling_pc = cpu_get_caller_pc();
+#endif
 }
 
 bool mutex_lock_internal(mutex_t *mutex, bool block)
@@ -92,9 +100,15 @@ bool mutex_lock_internal(mutex_t *mutex, bool block)
     if (mutex->queue.next == NULL) {
         /* mutex is unlocked. */
         mutex->queue.next = MUTEX_LOCKED;
-#ifdef MODULE_CORE_MUTEX_PRIORITY_INHERITANCE
+#if IS_USED(MODULE_CORE_MUTEX_PRIORITY_INHERITANCE) \
+        || IS_USED(MODULE_CORE_MUTEX_DEBUG)
         thread_t *me = thread_get_active();
         mutex->owner = me->pid;
+#endif
+#if IS_USED(MODULE_CORE_MUTEX_DEBUG)
+        mutex->owner_calling_pc = cpu_get_caller_pc();
+#endif
+#if IS_USED(MODULE_CORE_MUTEX_PRIORITY_INHERITANCE)
         mutex->owner_original_priority = me->priority;
 #endif
         DEBUG("PID[%" PRIkernel_pid "] mutex_lock(): early out.\n",
@@ -131,9 +145,15 @@ int mutex_lock_cancelable(mutex_cancel_t *mc)
     if (mutex->queue.next == NULL) {
         /* mutex is unlocked. */
         mutex->queue.next = MUTEX_LOCKED;
-#ifdef MODULE_CORE_MUTEX_PRIORITY_INHERITANCE
+#if IS_USED(MODULE_CORE_MUTEX_PRIORITY_INHERITANCE) \
+        || IS_USED(MODULE_CORE_MUTEX_DEBUG)
         thread_t *me = thread_get_active();
         mutex->owner = me->pid;
+#endif
+#if IS_USED(MODULE_CORE_MUTEX_DEBUG)
+        mutex->owner_calling_pc = cpu_get_caller_pc();
+#endif
+#if IS_USED(MODULE_CORE_MUTEX_PRIORITY_INHERITANCE)
         mutex->owner_original_priority = me->priority;
 #endif
         DEBUG("PID[%" PRIkernel_pid "] mutex_lock_cancelable() early out.\n",
@@ -185,7 +205,7 @@ void mutex_unlock(mutex_t *mutex)
 
     uint16_t process_priority = process->priority;
 
-#ifdef MODULE_CORE_MUTEX_PRIORITY_INHERITANCE
+#if IS_USED(MODULE_CORE_MUTEX_PRIORITY_INHERITANCE)
     thread_t *owner = thread_get(mutex->owner);
     if ((owner) && (owner->priority != mutex->owner_original_priority)) {
         DEBUG("PID[%" PRIkernel_pid "] prio %u --> %u\n",
@@ -194,6 +214,9 @@ void mutex_unlock(mutex_t *mutex)
         sched_change_priority(owner, mutex->owner_original_priority);
     }
 #endif
+#if IS_USED(MODULE_CORE_MUTEX_DEBUG)
+    mutex->owner_calling_pc = 0;
+#endif
 
     irq_restore(irqstate);
     sched_switch(process_priority);