[PATCH v3 1/2] lib: stacklog_debug: Introduce helper tool for collecting and displaying stacktraces

[PATCH v3 1/2] lib: stacklog_debug: Introduce helper tool for collecting and displaying stacktraces

[John Stultz]

When debugging, its often useful to understand how a function is
called and the different paths taken to get there. Usually
dump_stack() can be used for this purpose. However there are a
number of cases where a function is called very frequently,
making dump_stack far too noisy to be useful.

This is a little debug tool that utilizes stackdepot to capture
unique stack traces and store them in a circular buffer.

In the code, the developer adds: stacklog_debug_save() calls
at points of interest (as they might with stack_dump()).

Then after running the kernel, the developer can dump the unique
stack traces from the buffer via:
   cat /sys/kernel/debug/stacklog_debug

This is pretty trivial, but I've had this hanging around for
awhile and recently hit another case where it was helpful, so I
figured it would be worth sending it out for feedback as to if
others thought it would be useful enough to merge upstream or to
possibly rework into stackdepot itself?

Cc: Steven Rostedt <rostedt@goodmis.org>
Cc: Alexander Potapenko <glider@google.com>
Cc: Andrey Konovalov <andreyknvl@gmail.com>
Cc: Andrew Morton <akpm@linux-foundation.org>
Cc: kernel-team@android.com
Signed-off-by: John Stultz <jstultz@google.com>
---
v2:
* Add dependency on STACKTRACE_SUPPORT as reported by
  kernel test robot <lkp@intel.com>
* Expand the Kconfig help to include basic usage
v3:
* Make globals static as Reported-by: kernel test robot <lkp@intel.com>
---
 include/linux/stacklog_debug.h |  13 ++++
 lib/Kconfig                    |  16 +++++
 lib/Makefile                   |   1 +
 lib/stacklog_debug.c           | 110 +++++++++++++++++++++++++++++++++
 4 files changed, 140 insertions(+)
 create mode 100644 include/linux/stacklog_debug.h
 create mode 100644 lib/stacklog_debug.c

diff --git a/include/linux/stacklog_debug.h b/include/linux/stacklog_debug.h
new file mode 100644
index 0000000000000..d88f05d7000a5
--- /dev/null
+++ b/include/linux/stacklog_debug.h
@@ -0,0 +1,13 @@
+/* SPDX-License-Identifier: GPL-2.0-or-later */
+
+#ifndef _LINUX_STACKLOG_DEBUG_H
+#define _LINUX_STACKLOG_DEBUG_H
+
+#ifdef CONFIG_STACKLOG_DEBUG
+void stacklog_debug_save(void);
+#else
+static inline void stacklog_debug_save(void)
+{
+}
+#endif
+#endif
diff --git a/lib/Kconfig b/lib/Kconfig
index 5a318f753b2f4..d0320329260b2 100644
--- a/lib/Kconfig
+++ b/lib/Kconfig
@@ -737,6 +737,22 @@ config REF_TRACKER
 	depends on STACKTRACE_SUPPORT
 	select STACKDEPOT
 
+config STACKLOG_DEBUG
+	bool "Debug tool for logging and later displaying stacktraces"
+	depends on STACKTRACE_SUPPORT
+	select STACKDEPOT
+	select STACKDEPOT_ALWAYS_INIT
+	help
+	  Enables debug infrastructure for logging unique stack traces at
+	  a specific point, which can be later displayed from userland.
+
+	  The developer adds: stacklog_debug_save() calls at points of
+	  interest (as they might with stack_dump()).
+
+	  Then after running the kernel, the developer can dump the unique
+	  stack traces from the buffer via:
+	    cat /sys/kernel/debug/stacklog_debug
+
 config SBITMAP
 	bool
 
diff --git a/lib/Makefile b/lib/Makefile
index a8155c972f028..931347245334e 100644
--- a/lib/Makefile
+++ b/lib/Makefile
@@ -268,6 +268,7 @@ obj-$(CONFIG_IRQ_POLL) += irq_poll.o
 
 obj-$(CONFIG_POLYNOMIAL) += polynomial.o
 
+obj-$(CONFIG_STACKLOG_DEBUG) += stacklog_debug.o
 # stackdepot.c should not be instrumented or call instrumented functions.
 # Prevent the compiler from calling builtins like memcmp() or bcmp() from this
 # file.
diff --git a/lib/stacklog_debug.c b/lib/stacklog_debug.c
new file mode 100644
index 0000000000000..70d2e203b36c6
--- /dev/null
+++ b/lib/stacklog_debug.c
@@ -0,0 +1,110 @@
+// SPDX-License-Identifier: GPL-2.0-only
+/*
+ * Copyright (c) 2014, The Linux Foundation. All rights reserved.
+ */
+#include <linux/kernel.h>
+#include <linux/mm.h>
+#include <linux/slab.h>
+#include <linux/module.h>
+#include <linux/sched.h>
+#include <linux/vmalloc.h>
+#include <linux/stackdepot.h>
+#include <linux/debugfs.h>
+#include <linux/stacklog_debug.h>
+
+#define STACKDEPTH 32
+#define BUFSZ 4096
+
+#define LIST_ENTRIES 512
+static DEFINE_SPINLOCK(stack_lock);
+static depot_stack_handle_t stack_list[LIST_ENTRIES];
+static int head, tail;
+
+void stacklog_debug_save(void)
+{
+	unsigned long entries[STACKDEPTH];
+	depot_stack_handle_t stack_hash;
+	unsigned long flags;
+	unsigned int n;
+	int i;
+
+	n = stack_trace_save(entries, ARRAY_SIZE(entries), 1);
+	stack_hash = stack_depot_save(entries, n, GFP_NOWAIT);
+	if (!stack_hash)
+		return;
+
+	spin_lock_irqsave(&stack_lock, flags);
+	for (i = head; i < tail; i++)
+		if (stack_list[i % LIST_ENTRIES] == stack_hash)
+			goto out;
+
+	stack_list[(tail++ % LIST_ENTRIES)] = stack_hash;
+
+	if (tail % LIST_ENTRIES == head % LIST_ENTRIES)
+		head++;
+
+	if (tail >= 2 * LIST_ENTRIES) {
+		head %= LIST_ENTRIES;
+		tail %= LIST_ENTRIES;
+		if (tail < head)
+			tail += LIST_ENTRIES;
+	}
+out:
+	spin_unlock_irqrestore(&stack_lock, flags);
+}
+
+#ifdef CONFIG_DEBUG_FS
+static int stacklog_stats_show(struct seq_file *s, void *unused)
+{
+	char *buf = kmalloc(BUFSZ, GFP_NOWAIT);
+	unsigned int nr_entries;
+	unsigned long flags;
+	int i, start, stop;
+
+	if (!buf)
+		return -ENOMEM;
+
+	spin_lock_irqsave(&stack_lock, flags);
+	start = head;
+	stop = tail;
+	spin_unlock_irqrestore(&stack_lock, flags);
+
+	if (start == stop)
+		goto out;
+
+	for (i = start; i < stop; i++) {
+		unsigned long *ent;
+		u32 hash;
+
+		/*
+		 * We avoid holdings the lock over the entire loop
+		 * just to be careful as we don't want to trip a
+		 * call path that calls back into stacklog_debug_save
+		 * which would deadlock, so hold the lock minimally
+		 * (and be ok with the data changing between loop
+		 * iterations).
+		 */
+		spin_lock_irqsave(&stack_lock, flags);
+		hash = stack_list[i % LIST_ENTRIES];
+		spin_unlock_irqrestore(&stack_lock, flags);
+
+		nr_entries = stack_depot_fetch(hash, &ent);
+		stack_trace_snprint(buf, BUFSZ, ent, nr_entries, 0);
+		seq_printf(s, "[idx: %i hash: %ld]====================\n%s\n\n",
+			   i - start, (long)hash, buf);
+	}
+out:
+	kfree(buf);
+	return 0;
+}
+DEFINE_SHOW_ATTRIBUTE(stacklog_stats);
+
+static int __init stacklog_debug_init(void)
+{
+	debugfs_create_file("stacklog_debug", 0400, NULL, NULL,
+			    &stacklog_stats_fops);
+	return 0;
+}
+
+late_initcall(stacklog_debug_init);
+#endif
-- 
2.47.1.613.gc27f4b7a9f-goog

[PATCH v3 2/2] lib: stackdepot: Avoid null pointer if stack_depot_save is called too early

[John Stultz]

If stack_depot_save is called before stackdepot has initialized
a null reference to the stack_table might be used, crashing the
system.

Instead, check stack_table has been initialized before going
further.

Cc: Steven Rostedt <rostedt@goodmis.org>
Cc: Alexander Potapenko <glider@google.com>
Cc: Andrey Konovalov <andreyknvl@gmail.com>
Cc: Andrew Morton <akpm@linux-foundation.org>
Cc: kernel-team@android.com
Signed-off-by: John Stultz <jstultz@google.com>
---
 lib/stackdepot.c | 3 +++
 1 file changed, 3 insertions(+)

diff --git a/lib/stackdepot.c b/lib/stackdepot.c
index 245d5b4166999..1fe627584535d 100644
--- a/lib/stackdepot.c
+++ b/lib/stackdepot.c
@@ -611,6 +611,9 @@ depot_stack_handle_t stack_depot_save_flags(unsigned long *entries,
 	if (unlikely(nr_entries == 0) || stack_depot_disabled)
 		return 0;
 
+	if (!stack_table)
+		return 0;
+
 	hash = hash_stack(entries, nr_entries);
 	bucket = &stack_table[hash & stack_hash_mask];
 
-- 
2.47.1.613.gc27f4b7a9f-goog

Re: [PATCH v3 1/2] lib: stacklog_debug: Introduce helper tool for collecting and displaying stacktraces

[Steven Rostedt]

On Wed, 18 Dec 2024 22:06:05 -0800
John Stultz <jstultz@google.com> wrote:

> When debugging, its often useful to understand how a function is
> called and the different paths taken to get there. Usually
> dump_stack() can be used for this purpose. However there are a
> number of cases where a function is called very frequently,
> making dump_stack far too noisy to be useful.
> 
> This is a little debug tool that utilizes stackdepot to capture
> unique stack traces and store them in a circular buffer.
> 
> In the code, the developer adds: stacklog_debug_save() calls
> at points of interest (as they might with stack_dump()).
> 
> Then after running the kernel, the developer can dump the unique
> stack traces from the buffer via:
>    cat /sys/kernel/debug/stacklog_debug
> 
> This is pretty trivial, but I've had this hanging around for
> awhile and recently hit another case where it was helpful, so I
> figured it would be worth sending it out for feedback as to if
> others thought it would be useful enough to merge upstream or to
> possibly rework into stackdepot itself?

Have you looked at using ftrace?

You can even do histograms of stack traces from tracepoints (including
kprobe events).

Let's say we want to see all the calls to kmalloc:

 # echo 'hist:keys=common_stacktrace' > /sys/kernel/tracing/events/kmem/kmalloc/trigger
 # cat /sys/kernel/tracing/events/kmem/kmalloc/hist
# event histogram
#
# trigger info: hist:keys=common_stacktrace:vals=hitcount:sort=hitcount:size=2048 [active]
#

{ common_stacktrace:
         kmalloc_reserve+0xb3/0x100
         __alloc_skb+0xb1/0x160
         alloc_skb_with_frags+0x58/0x1d0
         sock_alloc_send_pskb+0x1db/0x250
         __ip_append_data+0x50d/0xf20
         ip_make_skb+0x142/0x200
         udp_sendmsg+0xaa5/0xc20
         __sock_sendmsg+0x6c/0xb0
         __sys_sendto+0x282/0x2f0
         __x64_sys_sendto+0x26/0x30
         do_syscall_64+0x8f/0x110
         entry_SYSCALL_64_after_hwframe+0x71/0x79
} hitcount:          1
{ common_stacktrace:
         __kvmalloc_node_noprof+0x45/0xd0
         file_tty_write+0xfb/0x340
         vfs_write+0x2fc/0x350
         ksys_write+0x8c/0x100
         do_syscall_64+0x8f/0x110
         entry_SYSCALL_64_after_hwframe+0x71/0x79
} hitcount:          1
{ common_stacktrace:
         __kmalloc_node_noprof+0x255/0x370
         __kvmalloc_node_noprof+0x45/0xd0
         seq_read_iter+0x21b/0x440
         seq_read+0x13e/0x170
         vfs_read+0xc2/0x310
         ksys_read+0x8c/0x100
         do_syscall_64+0x8f/0x110
         entry_SYSCALL_64_after_hwframe+0x71/0x79
} hitcount:          1
{ common_stacktrace:
         virtqueue_add+0x215/0xde0
         virtqueue_add_outbuf+0x3a/0x60
         start_xmit+0x45d/0x7f0
         dev_hard_start_xmit+0xcd/0x260
         sch_direct_xmit+0xdf/0x260
         __dev_queue_xmit+0xc91/0x1100
         ip_finish_output2+0x481/0x4f0
         __ip_queue_xmit+0x664/0x6f0
         __tcp_transmit_skb+0x899/0xa70
         tcp_write_xmit+0x885/0x11a0
         tcp_tsq_handler+0x97/0xc0
         tcp_tasklet_func+0xc9/0x130
         tasklet_action_common+0x136/0x410
         handle_softirqs+0x11e/0x3b0
         __irq_exit_rcu+0x69/0x110
         irq_exit_rcu+0xe/0x20
} hitcount:          1
{ common_stacktrace:
[..]
{ common_stacktrace:
         alloc_pipe_info+0x6a/0x220
         create_pipe_files+0x4a/0x200
         __do_pipe_flags+0x31/0xd0
         do_pipe2+0x4f/0xe0
         __x64_sys_pipe2+0x18/0x20
         do_syscall_64+0x8f/0x110
         entry_SYSCALL_64_after_hwframe+0x71/0x79
} hitcount:          4
{ common_stacktrace:
         __vmalloc_node_range_noprof+0x2a4/0x710
         vmalloc_noprof+0x45/0x50
         tracing_map_sort_entries+0x2b/0x3f0
         hist_show+0x18d/0x810
         seq_read_iter+0x1a6/0x440
         seq_read+0x13e/0x170
         vfs_read+0xc2/0x310
         ksys_read+0x8c/0x100
         do_syscall_64+0x8f/0x110
         entry_SYSCALL_64_after_hwframe+0x71/0x79
} hitcount:          4
{ common_stacktrace:
         tracing_map_sort_entries+0xa5/0x3f0
         hist_show+0x18d/0x810
         seq_read_iter+0x1a6/0x440
         seq_read+0x13e/0x170
         vfs_read+0xc2/0x310
         ksys_read+0x8c/0x100
         do_syscall_64+0x8f/0x110
         entry_SYSCALL_64_after_hwframe+0x71/0x79
} hitcount:         83
{ common_stacktrace:
         virtqueue_add+0x215/0xde0
         virtqueue_add_outbuf+0x3a/0x60
         start_xmit+0x45d/0x7f0
         dev_hard_start_xmit+0xcd/0x260
         sch_direct_xmit+0xdf/0x260
         __dev_queue_xmit+0xc91/0x1100
         ip_finish_output2+0x481/0x4f0
         __ip_queue_xmit+0x664/0x6f0
         __tcp_transmit_skb+0x899/0xa70
         tcp_write_xmit+0x885/0x11a0
         __tcp_push_pending_frames+0x32/0xc0
         tcp_sendmsg_locked+0xdbe/0x1040
         tcp_sendmsg+0x2c/0x50
         __sock_sendmsg+0x6c/0xb0
         sock_write_iter+0x110/0x160
         vfs_write+0x2fc/0x350
} hitcount:        392

Totals:
    Hits: 524
    Entries: 22
    Dropped: 0


-- Steve

Re: [PATCH v3 1/2] lib: stacklog_debug: Introduce helper tool for collecting and displaying stacktraces

[John Stultz]

On Thu, Dec 19, 2024 at 6:21 AM Steven Rostedt <rostedt@goodmis.org> wrote:
>
> On Wed, 18 Dec 2024 22:06:05 -0800
> John Stultz <jstultz@google.com> wrote:
>
> > When debugging, its often useful to understand how a function is
> > called and the different paths taken to get there. Usually
> > dump_stack() can be used for this purpose. However there are a
> > number of cases where a function is called very frequently,
> > making dump_stack far too noisy to be useful.
> >
> > This is a little debug tool that utilizes stackdepot to capture
> > unique stack traces and store them in a circular buffer.
> >
> > In the code, the developer adds: stacklog_debug_save() calls
> > at points of interest (as they might with stack_dump()).
> >
> > Then after running the kernel, the developer can dump the unique
> > stack traces from the buffer via:
> >    cat /sys/kernel/debug/stacklog_debug
> >
> > This is pretty trivial, but I've had this hanging around for
> > awhile and recently hit another case where it was helpful, so I
> > figured it would be worth sending it out for feedback as to if
> > others thought it would be useful enough to merge upstream or to
> > possibly rework into stackdepot itself?
>
> Have you looked at using ftrace?
>
> You can even do histograms of stack traces from tracepoints (including
> kprobe events).
>
> Let's say we want to see all the calls to kmalloc:
>
>  # echo 'hist:keys=common_stacktrace' > /sys/kernel/tracing/events/kmem/kmalloc/trigger
>  # cat /sys/kernel/tracing/events/kmem/kmalloc/hist

Cool!  I guess it does depend on the trace-event being there (or added
via kprobe), but it indeed does overlap with my tool, so I'll probably
abandon efforts to upstream mine.

That said, for not-so-bright printk debugging focused developers like
myself, adding tracepoints (explicitly or via kprobes) to the points
we are interested in (along with remembering the advanced ftrace
commands) feels a like a bit more work than adding a dump_stack-like
one-liner, but maybe that's a better thing to try to improve on the
ftrace side instead of adding my new tool.  I'll think about that a
bit.

thanks
-john