========= Debugging ========= `View slides `_ .. slideconf:: :autoslides: False :theme: single-level Lecture objectives: =================== One essential part of Linux kernel development is debugging. In user space we had the support of the kernel so we could easily stop processes and use gdb to inspect their behavior. In the kernel, in order to use gdb we need to use hypervisor like QEMU or JTAG based hardware interfaces which are not always available. The Linux kernel provides a set of tools and debug options useful for investigating abnormal behavior. In this lecture we will learn about: .. slide:: Debugging :inline-contents: True :level: 2 * decoding an oops/panic * list debugging * memory debugging * locking debugging * profiling Decoding an oops/panic ====================== An oops is an inconsistent state that the kernel detects inside itself. Upon detecting an oops the Linux kernel kills the offending process, prints information that can help debug the problem and continues execution but with limited reliability. Lets consider the following Linux kernel module: .. slide:: Oops module :inline-contents: True :level: 2 .. code-block:: c static noinline void do_oops(void) { *(int*)0x42 = 'a'; } static int so2_oops_init(void) { pr_info("oops_init\n"); do_oops(); return 0; } static void so2_oops_exit(void) { pr_info("oops exit\n"); } module_init(so2_oops_init); module_exit(so2_oops_exit); Notice that ''do_oops'' function tries to write at an invalid memory address. Because the kernel cannot find a suitable physical page were to write, it kills the insmod task in the context of which ''do_oops'' runs. Then it prints the following oops message: .. code-block:: bash root@qemux86:~/skels/debugging/oops# insmod oops.ko BUG: unable to handle kernel NULL pointer dereference at 00000042 IP: do_oops+0x8/0x10 [oops] *pde = 00000000 Oops: 0002 [#1] SMP Modules linked in: oops(O+) CPU: 0 PID: 234 Comm: insmod Tainted: G O 4.15.0+ #3 Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Ubuntu-1.8.2-1ubuntu1 04/01/2014 EIP: do_oops+0x8/0x10 [oops] EFLAGS: 00000292 CPU: 0 EAX: 00000061 EBX: 00000000 ECX: c7ed3584 EDX: c7ece8dc ESI: c716c908 EDI: c8816010 EBP: c7257df0 ESP: c7257df0 DS: 007b ES: 007b FS: 00d8 GS: 0033 SS: 0068 CR0: 80050033 CR2: 00000042 CR3: 0785f000 CR4: 00000690 Call Trace: so2_oops_init+0x17/0x20 [oops] do_one_initcall+0x37/0x170 ? cache_alloc_debugcheck_after.isra.19+0x15f/0x2f0 ? __might_sleep+0x32/0x90 ? trace_hardirqs_on_caller+0x11c/0x1a0 ? do_init_module+0x17/0x1c2 ? kmem_cache_alloc+0xa4/0x1e0 ? do_init_module+0x17/0x1c2 do_init_module+0x46/0x1c2 load_module+0x1f45/0x2380 SyS_init_module+0xe5/0x100 do_int80_syscall_32+0x61/0x190 entry_INT80_32+0x2f/0x2f EIP: 0x44902cc2 EFLAGS: 00000206 CPU: 0 EAX: ffffffda EBX: 08afb050 ECX: 0000eef4 EDX: 08afb008 ESI: 00000000 EDI: bf914dbc EBP: 00000000 ESP: bf914c1c DS: 007b ES: 007b FS: 0000 GS: 0033 SS: 007b Code: 42 00 00 00 5d c3 90 55 89 e5 83 ec 04 c7 04 24 24 70 81 c8 e8 EIP: do_oops+0x8/0x10 [oops] SS:ESP: 0068:c7257df0 CR2: 0000000000000042 ---[ end trace 011848be72f8bb42 ]--- Killed An oops contains information about the IP which caused the fault, register status, process, CPU on which the fault happend like below: .. slide:: Oops information :inline-contents: True :level: 2 .. code-block:: bash root@qemux86:~/skels/debugging/oops# insmod oops.ko BUG: unable to handle kernel NULL pointer dereference at 00000042 IP: do_oops+0x8/0x10 [oops] *pde = 00000000 Oops: 0002 [#1] SMP Modules linked in: oops(O+) CPU: 0 PID: 234 Comm: insmod Tainted: G O 4.15.0+ #3 Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Ubuntu-1.8.2-1ubuntu1 04/01/2014 EIP: do_oops+0x8/0x10 [oops] CR0: 80050033 CR2: 00000042 CR3: 0785f000 CR4: 00000690 EIP: 0x44902cc2 EFLAGS: 00000206 CPU: 0 EAX: ffffffda EBX: 08afb050 ECX: 0000eef4 EDX: 08afb008 ESI: 00000000 EDI: bf914dbc EBP: 00000000 ESP: bf914c1c DS: 007b ES: 007b FS: 0000 GS: 0033 SS: 007b Code: 42 00 00 00 5d c3 90 55 89 e5 83 ec 04 c7 04 24 24 70 81 c8 e8 Killed Another important thing that an oops can provide is the stack trace of functions called before the fault happend: .. slide:: Oops stacktrace :inline-contents: True :level: 2 .. code-block:: bash root@qemux86:~/skels/debugging/oops# insmod oops.ko BUG: unable to handle kernel NULL pointer dereference at 00000042 Call Trace: so2_oops_init+0x17/0x20 [oops] do_one_initcall+0x37/0x170 ? cache_alloc_debugcheck_after.isra.19+0x15f/0x2f0 ? __might_sleep+0x32/0x90 ? trace_hardirqs_on_caller+0x11c/0x1a0 ? do_init_module+0x17/0x1c2 ? kmem_cache_alloc+0xa4/0x1e0 ? do_init_module+0x17/0x1c2 do_init_module+0x46/0x1c2 load_module+0x1f45/0x2380 SyS_init_module+0xe5/0x100 do_int80_syscall_32+0x61/0x190 entry_INT80_32+0x2f/0x2f Killed Decoding an oops ---------------- .. slide:: Debugging :inline-contents: True :level: 2 * CONFIG_DEBUG_INFO * addr2line * gdb * objdump -dSr addr2line --------- *addr2line* translates addresses into file names and line numbers. Given an address in an executable it uses the debugging information to figure out which file name and line number are associated with it. Modules are loaded at dynamic addresses but are compiled starting with 0 as a base address. So, in order to find the line number for a given dynamic address we need to know module's load address. .. slide:: addr2line :inline-contents: True :level: 2 .. code-block:: bash $ addr2line -e oops.o 0x08 $ skels/debugging/oops/oops.c:5 $ # 0x08 is the offset of the offending instruction inside the oops.ko module objdump ------- Similar we can determine the offending line using objdump: .. slide:: objdump :inline-contents: True :level: 2 .. code-block:: bash $ cat /proc/modules oops 20480 1 - Loading 0xc8816000 (O+) $ objdump -dS --adjust-vma=0xc8816000 oops.ko c8816000: b8 61 00 00 00 mov $0x61,%eax static noinline void do_oops(void) { c8816005: 55 push %ebp c8816006: 89 e5 mov %esp,%ebp *(int*)0x42 = 'a'; c8816008: a3 42 00 00 00 mov %eax,0x42 gdb --- .. slide:: gdb :inline-contents: True :level: 2 .. code-block:: bash $ gdb ./vmlinux (gdb) list *(do_panic+0x8) 0xc1244138 is in do_panic (lib/test_panic.c:8). 3 4 static struct timer_list panic_timer; 5 6 static void do_panic(struct timer_list *unused) 7 { 8 *(int*)0x42 = 'a'; 9 } 10 11 static int so2_panic_init(void) Kernel panic ------------ A kernel panic is a special type of oops where the kernel cannot continue execution. For example if the function do_oops from above was called in the interrupt context, the kernel wouldn't know how to kill and it will decide that it is better to crash the kernel and stop execution. Here is a sample code that will generate a kernel panic: .. slide:: Kernel panic :inline-contents: True :level: 2 .. code-block:: c static struct timer_list panic_timer; static void do_panic(struct timer_list *unused) { *(int*)0x42 = 'a'; } static int so2_panic_init(void) { pr_info("panic_init\n"); timer_setup(&panic_timer, do_panic, 0); mod_timer(&panic_timer, jiffies + 2 * HZ); return 0; } Loading the module will generate the following kernel panic message: .. code-block:: bash root@qemux86:~/skels/debugging/panic# insmod panic.ko panic: loading out-of-tree module taints kernel. panic_init root@qemux86:~/skels/debugging/panic# BUG: unable to handle kernel NULL pointer dereference at 00000042 IP: do_panic+0x8/0x10 [panic] *pde = 00000000 Oops: 0002 [#1] SMP Modules linked in: panic(O) CPU: 0 PID: 0 Comm: swapper/0 Tainted: G O 4.15.0+ #19 Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Ubuntu-1.8.2-1ubuntu1 04/01/2014 EIP: do_panic+0x8/0x10 [panic] EFLAGS: 00010246 CPU: 0 EAX: 00000061 EBX: 00000101 ECX: 000002d8 EDX: 00000000 ESI: c8817000 EDI: c8819200 EBP: c780ff34 ESP: c780ff34 DS: 007b ES: 007b FS: 00d8 GS: 0000 SS: 0068 CR0: 80050033 CR2: 00000042 CR3: 0716b000 CR4: 00000690 Call Trace: call_timer_fn+0x63/0xf0 ? process_timeout+0x10/0x10 run_timer_softirq+0x14f/0x170 ? 0xc8817000 ? trace_hardirqs_on_caller+0x9b/0x1a0 __do_softirq+0xde/0x1f2 ? __irqentry_text_end+0x6/0x6 do_softirq_own_stack+0x57/0x70 irq_exit+0x7d/0x90 smp_apic_timer_interrupt+0x4f/0x90 ? trace_hardirqs_off_thunk+0xc/0x1d apic_timer_interrupt+0x3a/0x40 EIP: default_idle+0xa/0x10 EFLAGS: 00000246 CPU: 0 EAX: c15c97c0 EBX: 00000000 ECX: 00000000 EDX: 00000001 ESI: 00000000 EDI: 00000000 EBP: c15c3f48 ESP: c15c3f48 DS: 007b ES: 007b FS: 00d8 GS: 0000 SS: 0068 arch_cpu_idle+0x9/0x10 default_idle_call+0x19/0x30 do_idle+0x105/0x180 cpu_startup_entry+0x25/0x30 rest_init+0x1e3/0x1f0 start_kernel+0x305/0x30a i386_start_kernel+0x95/0x99 startup_32_smp+0x15f/0x164 Code: 42 00 00 00 5d c3 90 55 89 e5 83 ec 08 c7 04 24 24 80 81 c8 e8 EIP: do_panic+0x8/0x10 [panic] SS:ESP: 0068:c780ff34 CR2: 0000000000000042 ---[ end trace 77f49f83f2e42f91 ]--- Kernel panic - not syncing: Fatal exception in interrupt Kernel Offset: disabled ---[ end Kernel panic - not syncing: Fatal exception in interrupt List debugging ============== In order to catch access to uninitialized elements the kernel uses poison magic values. .. slide:: List debugging :inline-contents: True :level: 2 .. code-block:: bash static inline void list_del(struct list_head *entry) { __list_del(entry->prev, entry->next); entry->next = (struct list_head*)LIST_POISON1; entry->prev = (struct list_head*)LIST_POISON2; } BUG: unable to handle kernel NULL pointer dereference at 00000100 IP: crush+0x80/0xb0 [list] Memory debugging ================ There are several tools for memory debugging: .. slide:: Memory debugging :inline-contents: True :level: 2 * SLAB/SLUB debugging * KASAN * kmemcheck * DEBUG_PAGEALLOC Slab debugging --------------- Slab debugging uses a memory poison technique to detect several types of memory bugs in the SLAB/SUB allocators. The allocated buffers are guarded with memory that has been filled in with special markers. Any adjacent writes to the buffer will be detected at a later time when other memory management operations on that buffer are performed (e.g. when the buffer is freed). Upon allocation of the buffer, the buffer it is also filled in with a special value to potentially detect buffer access before initialization (e.g. if the buffer holds pointers). The value is selected in such a way that it is unlikely to be a valid address and as such to trigger kernel bugs at the access time. A similar technique is used when freeing the buffer: the buffer is filled with another special value that will cause kernel bugs if pointers are accessed after the memory is freed. In this case, the allocator also checks the next time the buffer is allocated that the buffer was not modified. The diagram bellow shows a summary of the way SLAB/SLUB poisoning works: .. slide:: Slab debugging :inline-contents: True :level: 2 * CONFIG_DEBUG_SLAB * poisoned based memory debuggers .. ditaa:: +--------------+-----------------------+--------------+ | cF88 | c8F8 | cF88 | | Buffer | Allocated buffer | Buffer | | Underflow | 0x5a5a5a5a | Overflow | | Poison | 0x5a5a5a5a | Poison | | | 0x5a5a5a5a | | +--------------+-----------------------+--------------+ +--------------+-----------------------+--------------+ | cF88 | c888 | cF88 | | Buffer | Freed buffer | Buffer | | Underflow | 0x6b6b6b6b | Overflow | | Poison | 0x6b6b6b6b | Poison | | | 0x6b6b6b6b | | +--------------+-----------------------+--------------+ Example of an use before initialize bug: .. slide:: Use before initialize bugs :inline-contents: True :level: 2 :: BUG: unable to handle kernel paging request at 5a5a5a5a IP: [] __list_del_entry+0x37/0x71 … Call Trace: [] list_del+0xb/0x1b [] use_before_init+0x31/0x38 [crusher] [] crush_it+0x38/0xa9 [crusher] [] init_module+0x8/0xa [crusher] [] do_one_initcall+0x72/0x119 [] ? crush_it+0xa9/0xa9 [crusher] [] sys_init_module+0xc8d/0xe77 [] syscall_call+0x7/0xb .. code-block:: c noinline void use_before_init(void) { struct list_m *m = kmalloc(sizeof(*m), GFP_KERNEL); printk("%s\n", __func__); list_del(&m->lh); } Example of an use after free bug: .. slide:: Use after free bug :inline-contents: True :level: 2 :: BUG: unable to handle kernel paging request at 6b6b6b6b IP: [] __list_del_entry+0x37/0x71 … Call Trace: [] list_del+0xb/0x1b [] use_after_free+0x38/0x3f [crusher] [] crush_it+0x52/0xa9 [crusher] [] init_module+0x8/0xa [crusher] [] do_one_initcall+0x72/0x119 [] ? crush_it+0xa9/0xa9 [crusher] [] sys_init_module+0xc8d/0xe77 [] syscall_call+0x7/0xb .. code-block:: c noinline void use_after_free(void) { struct list_m *m = kmalloc(sizeof(*m), GFP_KERNEL); printk("%s\n", __func__); kfree(m); list_del(&m->lh); } Another example of an use after free bug is shown below. Note that this time the bug is detected at the next allocation. .. slide:: Use after free bug :inline-contents: True :level: 2 :: # insmod /system/lib/modules/crusher.ko test=use_before_init Slab corruption: size-4096 start=ed612000, len=4096 000: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 010: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 6b 6b .. code-block:: c noinline void use_after_free2(void) { char *b = kmalloc(3000, GFP_KERNEL); kfree(b); memset(b, 0, 30); b = kmalloc(3000, GFP_KERNEL); kfree(b); } Finally this is an example of a buffer overflow bug: .. slide:: Buffer overflow bugs :inline-contents: True :level: 2 :: slab error in verify_redzone_free(): cache `dummy': memory outside object was overwritten Pid: 1282, comm: insmod Not tainted 3.0.16-mid10-00007-ga4a6b62-dirty #70 Call Trace: [] __slab_error+0x17/0x1c [] __cache_free+0x12c/0x317 [] kmem_cache_free+0x2b/0xaf [] buffer_overflow+0x4c/0x57 [crusher] [] crush_it+0x6c/0xa9 [crusher] [] init_module+0x8/0xd [crusher] [] do_one_initcall+0x72/0x119 [] sys_init_module+0xc8d/0xe77 [] syscall_call+0x7/0xb eb002bf8: redzone 1:0xd84156c5635688c0, redzone 2:0x0 .. code-block:: c noinline void buffer_overflow(void) { struct kmem_cache *km = kmem_cache_create("dummy", 3000, 0, 0, NULL); char *b = kmem_cache_alloc(km, GFP_KERNEL); printk("%s\n", __func__); memset(b, 0, 3016); kmem_cache_free(km, b); } DEBUG_PAGEALLOC --------------- .. slide:: DEBUG_PAGEALLOC :inline-contents: True :level: 2 * Memory debugger that works at a page level * Detects invalid accesses either by: * Filling pages with poison byte patterns and checking the pattern at reallocation * Unmapping the dellocated pages from kernel space (just a few architectures) KASan ----- KASan is a dynamic memory error detector designed to find use-after-free and out-of-bounds bugs. The main idea of KASAN is to use shadow memory to record whether each byte of memory is safe to access or not, and use compiler's instrumentation to check the shadow memory on each memory access. Address sanitizer uses 1 byte of shadow memory to track 8 bytes of kernel address space. It uses 0-7 to encode the number of consecutive bytes at the beginning of the eigh-byte region that are valid. See `The Kernel Address Sanitizer (KASAN)` for more information and have a look at lib/test_kasan.c for an example of problems that KASan can detect. .. slide:: KASan :inline-contents: True :level: 2 * dynamic memory error detector * finds user-after-free or out-of-bound bugs * uses shadow memory to track memory operations * lib/test_kasan.c KASan vs DEBUG_PAGEALLOC ~~~~~~~~~~~~~~~~~~~~~~~~ .. slide:: KASan vs DEBUG_PAGEALLOC :inline-contents: True :level: 2 KASan is slower than DEBUG_PAGEALLOC, but KASan works on sub-page granularity level, so it able to find more bugs. KASan vs SLUB_DEBUG ~~~~~~~~~~~~~~~~~~~ .. slide:: KASan vs SLUB_DEBUG :inline-contents: True :level: 2 * SLUB_DEBUG has lower overhead than KASan. * SLUB_DEBUG in most cases are not able to detect bad reads, KASan able to detect both reads and writes. * In some cases (e.g. redzone overwritten) SLUB_DEBUG detect bugs only on allocation/freeing of object. KASan catch bugs right before it will happen, so we always know exact place of first bad read/write. Kmemleak -------- Kmemleak provides a way of detecting kernel memory leaks in a way similar to a tracing garbage collector. Since tracing pointers is not possible in C, kmemleak scans the kernel stacks as well as dynamically and statically kernel memory for pointers to allocated buffers. A buffer for which there is no pointer is considered as leaked. The basic steps to use kmemleak are presented bellow, for more information see `Kernel Memory Leak Detector` .. slide:: Kmemleak :inline-contents: True :level: 2 * enable kernel config: `CONFIG_DEBUG_KMEMLEAK` * setup: `mount -t debugfs nodev /sys/kernel/debug` * trigger a memory scan: `echo scan > /sys/kernel/debug/kmemleak` * show memory leaks: `cat /sys/kernel/debug/kmemleak` * clear all possible leaks: `echo clear > /sys/kernel/debug/kmemleak` As an example, lets look at the following simple module: .. slide:: Kmemleak example :inline-contents: True :level: 2 .. code-block:: c static int leak_init(void) { pr_info("%s\n", __func__); (void)kmalloc(16, GFP_KERNEL); return 0; } MODULE_LICENSE("GPL v2"); module_init(leak_init); Loading the module and triggering a kmemleak scan will issue the following report: .. slide:: Kmemleak report :inline-contents: True :level: 2 :: root@qemux86:~# insmod skels/debugging/leak/leak.ko leak: loading out-of-tree module taints kernel. leak_init root@qemux86:~# echo scan > /sys/kernel/debug/kmemleak root@qemux86:~# echo scan > /sys/kernel/debug/kmemleak kmemleak: 1 new suspected memory leaks (see /sys/kernel/debug/kmemleak) root@qemux86:~# cat /sys/kernel/debug/kmemleak unreferenced object 0xd7871500 (size 32): comm "insmod", pid 237, jiffies 4294902108 (age 24.628s) hex dump (first 32 bytes): 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a ZZZZZZZZZZZZZZZZ 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a 5a a5 ZZZZZZZZZZZZZZZ. backtrace: [<(ptrval)>] kmem_cache_alloc_trace+0x163/0x310 [<(ptrval)>] leak_init+0x2f/0x1000 [leak] [<(ptrval)>] do_one_initcall+0x57/0x2e0 [<(ptrval)>] do_init_module+0x4b/0x1be [<(ptrval)>] load_module+0x201a/0x2590 [<(ptrval)>] sys_init_module+0xfd/0x120 [<(ptrval)>] do_int80_syscall_32+0x6a/0x1a0 .. note:: Notice that we did not had to unload the module to detect the memory leak since kmemleak detects that the allocated buffer is not reachable anymore. Lockdep checker =============== .. slide:: Lockdep checker :inline-contents: True :level: 2 * CONFIG_DEBUG_LOCKDEP * Detects lock inversio, circular dependencies, incorrect usage of locks (including interrupt context) * Maintains dependency between classes of locks not individual locks * Each scenario is only checked once and hashed Lets take for example the following kernel module that runs two kernel threads: .. slide:: AB BA Deadlock Example :inline-contents: True :level: 2 .. code-block:: c static noinline int thread_a(void *unused) { mutex_lock(&a); pr_info("%s acquired A\n", __func__); mutex_lock(&b); pr_info("%s acquired B\n", __func__); mutex_unlock(&b); mutex_unlock(&a); return 0; } .. code-block:: c static noinline int thread_b(void *unused) { mutex_lock(&b); pr_info("%s acquired B\n", __func__); mutex_lock(&a); pr_info("%s acquired A\n", __func__); mutex_unlock(&a); mutex_unlock(&b); return 0; } Loading this module with lockdep checker active will produce the following kernel log: .. slide:: AB BA Deadlock Report :inline-contents: True :level: 2 :: thread_a acquired A thread_a acquired B thread_b acquired B ====================================================== WARNING: possible circular locking dependency detected 4.19.0+ #4 Tainted: G O ------------------------------------------------------ thread_b/238 is trying to acquire lock: (ptrval) (a){+.+.}, at: thread_b+0x48/0x90 [locking] but task is already holding lock: (ptrval) (b){+.+.}, at: thread_b+0x27/0x90 [locking] which lock already depends on the new lock. As you can see, although the deadlock condition did not trigger (because thread A did not complete execution before thread B started execution) the lockdep checker identified a potential deadlock scenario. Lockdep checker will provide even more information to help determine what caused the deadlock, like the dependency chain: .. slide:: AB BA Deadlock Report (dependency chain) :inline-contents: True :level: 2 :: the existing dependency chain (in reverse order) is: -> #1 (b){+.+.}: __mutex_lock+0x60/0x830 mutex_lock_nested+0x20/0x30 thread_a+0x48/0x90 [locking] kthread+0xeb/0x100 ret_from_fork+0x2e/0x38 -> #0 (a){+.+.}: lock_acquire+0x93/0x190 __mutex_lock+0x60/0x830 mutex_lock_nested+0x20/0x30 thread_b+0x48/0x90 [locking] kthread+0xeb/0x100 ret_from_fork+0x2e/0x38 and even an unsafe locking scenario: .. slide:: AB BA Deadlock Report (unsafe locking scenario) :inline-contents: True :level: 2 :: other info that might help us debug this: Possible unsafe locking scenario: CPU0 CPU1 ---- ---- lock(b); lock(a); lock(b); lock(a); *** DEADLOCK *** Another example of unsafe locking issues that lockdep checker detects is unsafe locking from interrupt context. Lets consider the following kernel module: .. slide:: IRQ Deadlock Example :inline-contents: True :level: 2 .. code-block:: c static DEFINE_SPINLOCK(lock); static void timerfn(struct timer_list *unused) { pr_info("%s acquiring lock\n", __func__); spin_lock(&lock); pr_info("%s acquired lock\n", __func__); spin_unlock(&lock); pr_info("%s released lock\n", __func__); } static DEFINE_TIMER(timer, timerfn); int init_module(void) { mod_timer(&timer, jiffies); pr_info("%s acquiring lock\n", __func__); spin_lock(&lock); pr_info("%s acquired lock\n", __func__); spin_unlock(&lock); pr_info("%s released lock\n", __func__); return 0; } As in the previous case, loading the module will trigger a lockdep warning: .. slide:: IRQ Deadlock Report :inline-contents: True :level: 2 :: init_module acquiring lock init_module acquired lock init_module released lock timerfn acquiring lock ================================ WARNING: inconsistent lock state 4.19.0+ #4 Tainted: G O -------------------------------- inconsistent {SOFTIRQ-ON-W} -> {IN-SOFTIRQ-W} usage. ksoftirqd/0/9 [HC0[0]:SC1[1]:HE1:SE0] takes: (ptrval) (lock#4){+.?.}, at: timerfn+0x25/0x60 [locking2] {SOFTIRQ-ON-W} state was registered at: lock_acquire+0x93/0x190 _raw_spin_lock+0x39/0x50 init_module+0x35/0x70 [locking2] do_one_initcall+0x57/0x2e0 do_init_module+0x4b/0x1be load_module+0x201a/0x2590 sys_init_module+0xfd/0x120 do_int80_syscall_32+0x6a/0x1a0 restore_all+0x0/0x8d The warning will also provide additional information and a potential unsafe locking scenario: .. slide:: IRQ Deadlock Report :inline-contents: True :level: 2 :: Possible unsafe locking scenario: CPU0 ---- lock(lock#4); lock(lock#4); *** DEADLOCK *** 1 lock held by ksoftirqd/0/9: #0: (ptrval) (/home/tavi/src/linux/tools/labs/skels/./debugging/locking2/locking2.c:13){+.-.}, at: call_timer_f0 stack backtrace: CPU: 0 PID: 9 Comm: ksoftirqd/0 Tainted: G O 4.19.0+ #4 Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.10.2-1ubuntu1 04/01/2014 Call Trace: dump_stack+0x66/0x96 print_usage_bug.part.26+0x1ee/0x200 mark_lock+0x5ea/0x640 __lock_acquire+0x4b4/0x17a0 lock_acquire+0x93/0x190 _raw_spin_lock+0x39/0x50 timerfn+0x25/0x60 [locking2] perf ==== .. slide:: perf :inline-contents: True :level: 2 * performance counters, tracepoints, kprobes, uprobes * hardware events: CPU cycles, TLB misses, cache misses * software events: page faults , context switches * collects backtraces (user + kernel) Other tools =========== .. slide:: Other tools :inline-contents: True :level: 2 * ftrace * kprobes * sparse * coccinelle * checkpatch.pl * printk * dump_stack()