Skip to content

L
linux
Commit 4bbf04aa authored by Marco Elver's avatar Marco Elver Committed by Linus Torvalds
Browse files
Options

kfence: show cpu and timestamp in alloc/free info 

Record cpu and timestamp on allocations and frees, and show them in
reports.  Upon an error, this can help correlate earlier messages in the
kernel log via allocation and free timestamps.

Link: https://lkml.kernel.org/r/20210714175312.2947941-1-elver@google.comSuggested-by: default avatarJoern Engel <joern@purestorage.com>
Signed-off-by: default avatarMarco Elver <elver@google.com>
Acked-by: default avatarAlexander Potapenko <glider@google.com>
Acked-by: default avatarJoern Engel <joern@purestorage.com>
Cc: Yuanyuan Zhong <yzhong@purestorage.com>
Signed-off-by: default avatarAndrew Morton <akpm@linux-foundation.org>
Signed-off-by: default avatarLinus Torvalds <torvalds@linux-foundation.org>
parent 11086054
Hide whitespace changes
Inline Side-by-side
Showing with 71 additions and 51 deletions
Documentation/dev-tools/kfence.rst
View file @ 4bbf04aa
...@@ -65,25 +65,27 @@ Error reports ...@@ -65,25 +65,27 @@ Error reports
A typical out-of-bounds access looks like this:: A typical out-of-bounds access looks like this::
================================================================== ==================================================================
BUG: KFENCE: out-of-bounds read in test_out_of_bounds_read+0xa3/0x22b BUG: KFENCE: out-of-bounds read in test_out_of_bounds_read+0xa6/0x234
Out-of-bounds read at 0xffffffffb672efff (1B left of kfence-#17): Out-of-bounds read at 0xffff8c3f2e291fff (1B left of kfence-#72):
test_out_of_bounds_read+0xa3/0x22b test_out_of_bounds_read+0xa6/0x234
kunit_try_run_case+0x51/0x85 kunit_try_run_case+0x61/0xa0
kunit_generic_run_threadfn_adapter+0x16/0x30 kunit_generic_run_threadfn_adapter+0x16/0x30
kthread+0x137/0x160 kthread+0x176/0x1b0
ret_from_fork+0x22/0x30 ret_from_fork+0x22/0x30
kfence-#17 [0xffffffffb672f000-0xffffffffb672f01f, size=32, cache=kmalloc-32] allocated by task 507: kfence-#72: 0xffff8c3f2e292000-0xffff8c3f2e29201f, size=32, cache=kmalloc-32
test_alloc+0xf3/0x25b
test_out_of_bounds_read+0x98/0x22b allocated by task 484 on cpu 0 at 32.919330s:
kunit_try_run_case+0x51/0x85 test_alloc+0xfe/0x738
test_out_of_bounds_read+0x9b/0x234
kunit_try_run_case+0x61/0xa0
kunit_generic_run_threadfn_adapter+0x16/0x30 kunit_generic_run_threadfn_adapter+0x16/0x30
kthread+0x137/0x160 kthread+0x176/0x1b0
ret_from_fork+0x22/0x30 ret_from_fork+0x22/0x30
CPU: 4 PID: 107 Comm: kunit_try_catch Not tainted 5.8.0-rc6+ #7 CPU: 0 PID: 484 Comm: kunit_try_catch Not tainted 5.13.0-rc3+ #7
Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.13.0-1 04/01/2014 Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.14.0-2 04/01/2014
================================================================== ==================================================================
The header of the report provides a short summary of the function involved in The header of the report provides a short summary of the function involved in
...@@ -96,30 +98,32 @@ Use-after-free accesses are reported as:: ...@@ -96,30 +98,32 @@ Use-after-free accesses are reported as::
================================================================== ==================================================================
BUG: KFENCE: use-after-free read in test_use_after_free_read+0xb3/0x143 BUG: KFENCE: use-after-free read in test_use_after_free_read+0xb3/0x143
Use-after-free read at 0xffffffffb673dfe0 (in kfence-#24): Use-after-free read at 0xffff8c3f2e2a0000 (in kfence-#79):
test_use_after_free_read+0xb3/0x143 test_use_after_free_read+0xb3/0x143
kunit_try_run_case+0x51/0x85 kunit_try_run_case+0x61/0xa0
kunit_generic_run_threadfn_adapter+0x16/0x30 kunit_generic_run_threadfn_adapter+0x16/0x30
kthread+0x137/0x160 kthread+0x176/0x1b0
ret_from_fork+0x22/0x30 ret_from_fork+0x22/0x30
kfence-#24 [0xffffffffb673dfe0-0xffffffffb673dfff, size=32, cache=kmalloc-32] allocated by task 507: kfence-#79: 0xffff8c3f2e2a0000-0xffff8c3f2e2a001f, size=32, cache=kmalloc-32
test_alloc+0xf3/0x25b
allocated by task 488 on cpu 2 at 33.871326s:
test_alloc+0xfe/0x738
test_use_after_free_read+0x76/0x143 test_use_after_free_read+0x76/0x143
kunit_try_run_case+0x51/0x85 kunit_try_run_case+0x61/0xa0
kunit_generic_run_threadfn_adapter+0x16/0x30 kunit_generic_run_threadfn_adapter+0x16/0x30
kthread+0x137/0x160 kthread+0x176/0x1b0
ret_from_fork+0x22/0x30 ret_from_fork+0x22/0x30
freed by task 507: freed by task 488 on cpu 2 at 33.871358s:
test_use_after_free_read+0xa8/0x143 test_use_after_free_read+0xa8/0x143
kunit_try_run_case+0x51/0x85 kunit_try_run_case+0x61/0xa0
kunit_generic_run_threadfn_adapter+0x16/0x30 kunit_generic_run_threadfn_adapter+0x16/0x30
kthread+0x137/0x160 kthread+0x176/0x1b0
ret_from_fork+0x22/0x30 ret_from_fork+0x22/0x30
CPU: 4 PID: 109 Comm: kunit_try_catch Tainted: G W 5.8.0-rc6+ #7 CPU: 2 PID: 488 Comm: kunit_try_catch Tainted: G B 5.13.0-rc3+ #7
Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.13.0-1 04/01/2014 Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.14.0-2 04/01/2014
================================================================== ==================================================================
KFENCE also reports on invalid frees, such as double-frees:: KFENCE also reports on invalid frees, such as double-frees::
...@@ -127,30 +131,32 @@ KFENCE also reports on invalid frees, such as double-frees:: ...@@ -127,30 +131,32 @@ KFENCE also reports on invalid frees, such as double-frees::
================================================================== ==================================================================
BUG: KFENCE: invalid free in test_double_free+0xdc/0x171 BUG: KFENCE: invalid free in test_double_free+0xdc/0x171
Invalid free of 0xffffffffb6741000: Invalid free of 0xffff8c3f2e2a4000 (in kfence-#81):
test_double_free+0xdc/0x171 test_double_free+0xdc/0x171
kunit_try_run_case+0x51/0x85 kunit_try_run_case+0x61/0xa0
kunit_generic_run_threadfn_adapter+0x16/0x30 kunit_generic_run_threadfn_adapter+0x16/0x30
kthread+0x137/0x160 kthread+0x176/0x1b0
ret_from_fork+0x22/0x30 ret_from_fork+0x22/0x30
kfence-#26 [0xffffffffb6741000-0xffffffffb674101f, size=32, cache=kmalloc-32] allocated by task 507: kfence-#81: 0xffff8c3f2e2a4000-0xffff8c3f2e2a401f, size=32, cache=kmalloc-32
test_alloc+0xf3/0x25b
allocated by task 490 on cpu 1 at 34.175321s:
test_alloc+0xfe/0x738
test_double_free+0x76/0x171 test_double_free+0x76/0x171
kunit_try_run_case+0x51/0x85 kunit_try_run_case+0x61/0xa0
kunit_generic_run_threadfn_adapter+0x16/0x30 kunit_generic_run_threadfn_adapter+0x16/0x30
kthread+0x137/0x160 kthread+0x176/0x1b0
ret_from_fork+0x22/0x30 ret_from_fork+0x22/0x30
freed by task 507: freed by task 490 on cpu 1 at 34.175348s:
test_double_free+0xa8/0x171 test_double_free+0xa8/0x171
kunit_try_run_case+0x51/0x85 kunit_try_run_case+0x61/0xa0
kunit_generic_run_threadfn_adapter+0x16/0x30 kunit_generic_run_threadfn_adapter+0x16/0x30
kthread+0x137/0x160 kthread+0x176/0x1b0
ret_from_fork+0x22/0x30 ret_from_fork+0x22/0x30
CPU: 4 PID: 111 Comm: kunit_try_catch Tainted: G W 5.8.0-rc6+ #7 CPU: 1 PID: 490 Comm: kunit_try_catch Tainted: G B 5.13.0-rc3+ #7
Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.13.0-1 04/01/2014 Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.14.0-2 04/01/2014
================================================================== ==================================================================
KFENCE also uses pattern-based redzones on the other side of an object's guard KFENCE also uses pattern-based redzones on the other side of an object's guard
...@@ -160,23 +166,25 @@ These are reported on frees:: ...@@ -160,23 +166,25 @@ These are reported on frees::
================================================================== ==================================================================
BUG: KFENCE: memory corruption in test_kmalloc_aligned_oob_write+0xef/0x184 BUG: KFENCE: memory corruption in test_kmalloc_aligned_oob_write+0xef/0x184
Corrupted memory at 0xffffffffb6797ff9 [ 0xac . . . . . . ] (in kfence-#69): Corrupted memory at 0xffff8c3f2e33aff9 [ 0xac . . . . . . ] (in kfence-#156):
test_kmalloc_aligned_oob_write+0xef/0x184 test_kmalloc_aligned_oob_write+0xef/0x184
kunit_try_run_case+0x51/0x85 kunit_try_run_case+0x61/0xa0
kunit_generic_run_threadfn_adapter+0x16/0x30 kunit_generic_run_threadfn_adapter+0x16/0x30
kthread+0x137/0x160 kthread+0x176/0x1b0
ret_from_fork+0x22/0x30 ret_from_fork+0x22/0x30
kfence-#69 [0xffffffffb6797fb0-0xffffffffb6797ff8, size=73, cache=kmalloc-96] allocated by task 507: kfence-#156: 0xffff8c3f2e33afb0-0xffff8c3f2e33aff8, size=73, cache=kmalloc-96
test_alloc+0xf3/0x25b
allocated by task 502 on cpu 7 at 42.159302s:
test_alloc+0xfe/0x738
test_kmalloc_aligned_oob_write+0x57/0x184 test_kmalloc_aligned_oob_write+0x57/0x184
kunit_try_run_case+0x51/0x85 kunit_try_run_case+0x61/0xa0
kunit_generic_run_threadfn_adapter+0x16/0x30 kunit_generic_run_threadfn_adapter+0x16/0x30
kthread+0x137/0x160 kthread+0x176/0x1b0
ret_from_fork+0x22/0x30 ret_from_fork+0x22/0x30
CPU: 4 PID: 120 Comm: kunit_try_catch Tainted: G W 5.8.0-rc6+ #7 CPU: 7 PID: 502 Comm: kunit_try_catch Tainted: G B 5.13.0-rc3+ #7
Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.13.0-1 04/01/2014 Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.14.0-2 04/01/2014
================================================================== ==================================================================
For such errors, the address where the corruption occurred as well as the For such errors, the address where the corruption occurred as well as the
......
mm/kfence/core.c
View file @ 4bbf04aa
...@@ -20,6 +20,7 @@ ...@@ -20,6 +20,7 @@
#include <linux/moduleparam.h> #include <linux/moduleparam.h>
#include <linux/random.h> #include <linux/random.h>
#include <linux/rcupdate.h> #include <linux/rcupdate.h>
#include <linux/sched/clock.h>
#include <linux/sched/sysctl.h> #include <linux/sched/sysctl.h>
#include <linux/seq_file.h> #include <linux/seq_file.h>
#include <linux/slab.h> #include <linux/slab.h>
...@@ -196,6 +197,8 @@ static noinline void metadata_update_state(struct kfence_metadata *meta, ...@@ -196,6 +197,8 @@ static noinline void metadata_update_state(struct kfence_metadata *meta,
*/ */
track->num_stack_entries = stack_trace_save(track->stack_entries, KFENCE_STACK_DEPTH, 1); track->num_stack_entries = stack_trace_save(track->stack_entries, KFENCE_STACK_DEPTH, 1);
track->pid = task_pid_nr(current); track->pid = task_pid_nr(current);
track->cpu = raw_smp_processor_id();
track->ts_nsec = local_clock(); /* Same source as printk timestamps. */
/* /*
* Pairs with READ_ONCE() in * Pairs with READ_ONCE() in
......
mm/kfence/kfence.h
View file @ 4bbf04aa
...@@ -36,6 +36,8 @@ enum kfence_object_state { ...@@ -36,6 +36,8 @@ enum kfence_object_state {
/* Alloc/free tracking information. */ /* Alloc/free tracking information. */
struct kfence_track { struct kfence_track {
pid_t pid; pid_t pid;
int cpu;
u64 ts_nsec;
int num_stack_entries; int num_stack_entries;
unsigned long stack_entries[KFENCE_STACK_DEPTH]; unsigned long stack_entries[KFENCE_STACK_DEPTH];
}; };
......
mm/kfence/report.c
View file @ 4bbf04aa
...@@ -9,6 +9,7 @@ ...@@ -9,6 +9,7 @@
#include <linux/kernel.h> #include <linux/kernel.h>
#include <linux/lockdep.h> #include <linux/lockdep.h>
#include <linux/math.h>
#include <linux/printk.h> #include <linux/printk.h>
#include <linux/sched/debug.h> #include <linux/sched/debug.h>
#include <linux/seq_file.h> #include <linux/seq_file.h>
...@@ -100,6 +101,13 @@ static void kfence_print_stack(struct seq_file *seq, const struct kfence_metadat ...@@ -100,6 +101,13 @@ static void kfence_print_stack(struct seq_file *seq, const struct kfence_metadat
bool show_alloc) bool show_alloc)
{ {
const struct kfence_track *track = show_alloc ? &meta->alloc_track : &meta->free_track; const struct kfence_track *track = show_alloc ? &meta->alloc_track : &meta->free_track;
u64 ts_sec = track->ts_nsec;
unsigned long rem_nsec = do_div(ts_sec, NSEC_PER_SEC);
/* Timestamp matches printk timestamp format. */
seq_con_printf(seq, "%s by task %d on cpu %d at %lu.%06lus:\n",
show_alloc ? "allocated" : "freed", track->pid,
track->cpu, (unsigned long)ts_sec, rem_nsec / 1000);
if (track->num_stack_entries) { if (track->num_stack_entries) {
/* Skip allocation/free internals stack. */ /* Skip allocation/free internals stack. */
...@@ -126,15 +134,14 @@ void kfence_print_object(struct seq_file *seq, const struct kfence_metadata *met ...@@ -126,15 +134,14 @@ void kfence_print_object(struct seq_file *seq, const struct kfence_metadata *met
return; return;
} }
seq_con_printf(seq, seq_con_printf(seq, "kfence-#%td: 0x%p-0x%p, size=%d, cache=%s\n\n",
"kfence-#%td [0x%p-0x%p" meta - kfence_metadata, (void *)start, (void *)(start + size - 1),
", size=%d, cache=%s] allocated by task %d:\n", size, (cache && cache->name) ? cache->name : "<destroyed>");
meta - kfence_metadata, (void *)start, (void *)(start + size - 1), size,
(cache && cache->name) ? cache->name : "<destroyed>", meta->alloc_track.pid);
kfence_print_stack(seq, meta, true); kfence_print_stack(seq, meta, true);
if (meta->state == KFENCE_OBJECT_FREED) { if (meta->state == KFENCE_OBJECT_FREED) {
seq_con_printf(seq, "\nfreed by task %d:\n", meta->free_track.pid); seq_con_printf(seq, "\n");
kfence_print_stack(seq, meta, false); kfence_print_stack(seq, meta, false);
} }
} }
......
Markdown is supported
0% or
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment
GitLab Nexedi Edition | About GitLab | About Nexedi | 沪ICP备2021021310号-2 | 沪ICP备2021021310号-7