Re: [RFC PATCH] kasan: Record and report more information

From: Juntong Deng
Date: Mon Nov 20 2023 - 11:43:26 EST

On 2023/11/20 19:06, Dmitry Vyukov wrote:
On Wed, 15 Nov 2023 at 22:53, Juntong Deng <juntong.deng@xxxxxxxxxxx> wrote:

On 2023/11/14 15:27, Dmitry Vyukov wrote:
On Mon, 13 Nov 2023 at 22:17, Juntong Deng <juntong.deng@xxxxxxxxxxx> wrote:

Record and report more information to help us find the cause of
the bug (for example, bugs caused by subtle race condition).

This patch adds recording and showing CPU number and timestamp at
allocation and free (controlled by CONFIG_KASAN_EXTRA_INFO), and
adds recording and showing timestamp at error occurrence (CPU number
is already shown by dump_stack_lvl). The timestamps in the report use
the same format and source as printk.

In order to record CPU number and timestamp at allocation and free,
corresponding members need to be added to the relevant data structures,
which may lead to increased memory consumption.

In Generic KASAN, members are added to struct kasan_track. Since in
most cases, alloc meta is stored in the redzone and free meta is
stored in the object or the redzone, memory consumption will not
increase much.

In SW_TAGS KASAN and HW_TAGS KASAN, members are added to
struct kasan_stack_ring_entry. Memory consumption increases as the
size of struct kasan_stack_ring_entry increases (this part of the
memory is allocated by memblock), but since this is configurable,
it is up to the user to choose.

Signed-off-by: Juntong Deng <juntong.deng@xxxxxxxxxxx>
---
lib/Kconfig.kasan | 11 +++++++++++
mm/kasan/common.c | 5 +++++
mm/kasan/kasan.h | 9 +++++++++
mm/kasan/report.c | 28 ++++++++++++++++++++++------
mm/kasan/report_tags.c | 18 ++++++++++++++++++
mm/kasan/tags.c | 15 +++++++++++++++
6 files changed, 80 insertions(+), 6 deletions(-)

diff --git a/lib/Kconfig.kasan b/lib/Kconfig.kasan
index fdca89c05745..d9611564b339 100644
--- a/lib/Kconfig.kasan
+++ b/lib/Kconfig.kasan
@@ -207,4 +207,15 @@ config KASAN_MODULE_TEST
A part of the KASAN test suite that is not integrated with KUnit.
Incompatible with Hardware Tag-Based KASAN.

+config KASAN_EXTRA_INFO
+ bool "Record and report more information"
+ depends on KASAN
+ help
+ Record and report more information to help us find the cause of
+ the bug. The trade-off is potentially increased memory consumption
+ (to record more information).
+
+ Currently the CPU number and timestamp are additionally recorded
+ at allocation and free.

Hi Juntong,

Thanks for working on this.



Thanks for your reply!


As a KASAN developer I understand what this is doing, but I am trying
to think from a position of a user that does not know details of KASAN
implementation. From this position it may be useful to say somewhere
that information is recorded "per heap allocation". Perhaps something
like:

"Currently the CPU number and timestamp are additionally recorded for
each heap block at allocation and free time".


Yes, I agree, that is a better expression.



Also it's unclear what the memory consumption increase is. You say
"potentially|, so may it not increase at all? If it increases, by how
much? I obviously want more information, if I can afford it, but I
can't understand if I can or not based on this description. I would
assume that this may be a problem only for small/embedded devices.
Can we provide some ballpark estimation of the memory consumption
increase? And somehow say that's probably not an issue for larger
machines?



How about this expression?

Currently, in order to record CPU number and timestamp, the data
structure to record allocation and free information will increase
by 12 bytes.

In Generic KASAN, this affects all allocations less than 32 bytes.
In SW_TAGS KASAN and HW_TAGS KASAN, depending on the stack_ring_size
boot parameter increases the memory consumption by
12 * stack_ring_size bytes.

Let's go with this version.


endif # KASAN
diff --git a/mm/kasan/common.c b/mm/kasan/common.c
index 256930da578a..7a81566d9d66 100644
--- a/mm/kasan/common.c
+++ b/mm/kasan/common.c
@@ -20,6 +20,7 @@
#include <linux/module.h>
#include <linux/printk.h>
#include <linux/sched.h>
+#include <linux/sched/clock.h>
#include <linux/sched/task_stack.h>
#include <linux/slab.h>
#include <linux/stacktrace.h>
@@ -50,6 +51,10 @@ void kasan_set_track(struct kasan_track *track, gfp_t flags)
{
track->pid = current->pid;
track->stack = kasan_save_stack(flags, true);
+#ifdef CONFIG_KASAN_EXTRA_INFO
+ track->cpu = raw_smp_processor_id();
+ track->ts_nsec = local_clock();

What does "local_" mean? Is this clock value comparable across CPUs?



No, local_clock is the local CPU clock and cannot be used for comparison
across CPUs, I made a mistake here.

I delved into the clock subsystem of the Linux kernel today and I found
that we have two choices.

- sched_clock(): based on jiffies, high performance, but on some
hardware, it will drift between CPUs.

- ktime_get_boot_fast_ns(): based on clocksource, highly accurate,
can be compared between CPUs, but performance is worse (seqlock).

I tested 100000 calls respectively on my laptop, the average of
sched_clock() is 17ns and the average of ktime_get_boot_fast_ns()
is 25ns.

ktime_get_boot_fast_ns() takes about 1.5 times as long as sched_clock().

With Generic KASAN enabled, the average of one memory allocation is
3512ns on my laptop.

Personally, I prefer ktime_get_boot_fast_ns() because it is more
accurate and the extra time is insignificant for the time required for
one memory allocation with Generic KASAN enabled.

But maybe using ktime_get_boot_fast_ns() would have a more serious
impact on small/embedded devices.

Which do you think is the better choice?

I don't have a strong preference.

Re drift of sched_clock(), do you mean unsynchronized RDTSC on
different cores? I had the impression that RDTSC is synchronized
across cores on all recent CPUs/systems.



https://elixir.bootlin.com/linux/latest/source/kernel/trace/trace_clock.c#L27
https://docs.kernel.org/timers/timekeeping.html#sched-clock
https://lore.kernel.org/lkml/20100612023457.14850.50439.stgit@xxxxxxxxxxxxxxxxxxxxxxxxxx/
https://lkml.org/lkml/2020/3/16/902

All of the above seems to indicate that sched_clock() is not reliable
for comparison across CPUs.

Comparing time across CPUs, ktime is probably the only reliable option.



+#endif /* CONFIG_KASAN_EXTRA_INFO */
}

#if defined(CONFIG_KASAN_GENERIC) || defined(CONFIG_KASAN_SW_TAGS)
diff --git a/mm/kasan/kasan.h b/mm/kasan/kasan.h
index 8b06bab5c406..b3899a255aca 100644
--- a/mm/kasan/kasan.h
+++ b/mm/kasan/kasan.h
@@ -187,6 +187,10 @@ static inline bool kasan_requires_meta(void)
struct kasan_track {
u32 pid;
depot_stack_handle_t stack;
+#ifdef CONFIG_KASAN_EXTRA_INFO
+ u32 cpu;
+ u64 ts_nsec;

This increases the size of meta from 8 to 24 bytes.
Can we somehow store the timestamp as 32 bits? Maybe compress the CPU
number (it shouldn't be larger than 20 bits?)?
I see below we report on microseconds, so we don't low bits of the
timestamp as well.



Maybe we can use bit field.

struct kasan_track {
u32 pid;
depot_stack_handle_t stack;
#ifdef CONFIG_KASAN_EXTRA_INFO
u64 cpu:20;
u64 ts_sec:22;
u64 ts_usec:22;
#endif /* CONFIG_KASAN_EXTRA_INFO */
};

For example, 20-bit cpu, 22-bit ts_sec, 22-bit ts_usec, 64 bits
(8 bytes), and the data structure is 16 bytes in total.

This looks better.
Can't we have a single field for time instead of ts_sec/usec?
Both sched_clock() and ktime_get_boot_fast_ns() return just u64.

If the data structure becomes 16 bytes, it will not affect objects
larger than 16 bytes.

But the bit field can only be used in struct kasan_track (Generic),
and cannot be used in struct kasan_stack_ring_entry (SW_TAGS KASAN
and HW_TAGS KASAN).

Because we need to use READ_ONCE and WRITE_ONCE to read and write
struct kasan_stack_ring_entry, but READ_ONCE and WRITE_ONCE cannot
read or write bit field.

If that's necessary, we could store both values as a single u64 and
the manually pack/unpack.



I will try to store the CPU and timestamp in a u64, unpack it
when reporting, and send PATCH V2.



I see there is a deficiency in kasan_cache_create():
https://elixir.bootlin.com/linux/latest/source/mm/kasan/generic.c#L412

If free_meta does not fit into the object, we add it after the object.
But we could overlap it with the object.
For example if the object size is 16 bytes and free_meta size is 24
bytes, we could increase object size to 24, while currently we
increase it to 16+24 = 40.
We need to place it after the object only if we have these other cases
"(cache->flags & SLAB_TYPESAFE_BY_RCU) || cache->ctor".

Currently it affects only kmalloc-8 slab.
But with this change it will affect at least kmalloc-16 slab as well.



I completely agree that we can use both object space and redzone
space to store free meta, thereby further reducing the extra memory
consumption caused by KASAN.

Of course, in this case we need to readjust the offset of the
alloc meta.

If you agree I can make this change in a separate patch.

This would be good. Thanks.



I have sent a patch for this.

[PATCH] kasan: Improve free meta storage in Generic KASAN


+#endif /* CONFIG_KASAN_EXTRA_INFO */
};

enum kasan_report_type {
@@ -202,6 +206,7 @@ struct kasan_report_info {
size_t access_size;
bool is_write;
unsigned long ip;
+ u64 ts_nsec;

/* Filled in by the common reporting code. */
const void *first_bad_addr;
@@ -278,6 +283,10 @@ struct kasan_stack_ring_entry {
u32 pid;
depot_stack_handle_t stack;
bool is_free;
+#ifdef CONFIG_KASAN_EXTRA_INFO
+ u32 cpu;
+ u64 ts_nsec;
+#endif /* CONFIG_KASAN_EXTRA_INFO */
};

struct kasan_stack_ring {
diff --git a/mm/kasan/report.c b/mm/kasan/report.c
index e77facb62900..b6feaf807c08 100644
--- a/mm/kasan/report.c
+++ b/mm/kasan/report.c
@@ -25,6 +25,7 @@
#include <linux/types.h>
#include <linux/kasan.h>
#include <linux/module.h>
+#include <linux/sched/clock.h>
#include <linux/sched/task_stack.h>
#include <linux/uaccess.h>
#include <trace/events/error_report.h>
@@ -242,27 +243,40 @@ static void end_report(unsigned long *flags, const void *addr, bool is_write)

static void print_error_description(struct kasan_report_info *info)
{
+ unsigned long rem_usec = do_div(info->ts_nsec, NSEC_PER_SEC) / 1000;
+
pr_err("BUG: KASAN: %s in %pS\n", info->bug_type, (void *)info->ip);

if (info->type != KASAN_REPORT_ACCESS) {
- pr_err("Free of addr %px by task %s/%d\n",
- info->access_addr, current->comm, task_pid_nr(current));
+ pr_err("Free of addr %px by task %s/%d at %lu.%06lus\n",
+ info->access_addr, current->comm, task_pid_nr(current),
+ (unsigned long)info->ts_nsec, rem_usec);
return;
}

if (info->access_size)
- pr_err("%s of size %zu at addr %px by task %s/%d\n",
+ pr_err("%s of size %zu at addr %px by task %s/%d at %lu.%06lus\n",
info->is_write ? "Write" : "Read", info->access_size,
- info->access_addr, current->comm, task_pid_nr(current));
+ info->access_addr, current->comm, task_pid_nr(current),
+ (unsigned long)info->ts_nsec, rem_usec);
else
- pr_err("%s at addr %px by task %s/%d\n",
+ pr_err("%s at addr %px by task %s/%d at %lu.%06lus\n",
info->is_write ? "Write" : "Read",
- info->access_addr, current->comm, task_pid_nr(current));
+ info->access_addr, current->comm, task_pid_nr(current),
+ (unsigned long)info->ts_nsec, rem_usec);
}

static void print_track(struct kasan_track *track, const char *prefix)
{
+#ifdef CONFIG_KASAN_EXTRA_INFO
+ unsigned long rem_usec = do_div(track->ts_nsec, NSEC_PER_SEC) / 1000;
+
+ pr_err("%s by task %u on cpu %d at %lu.%06lus:\n",
+ prefix, track->pid, track->cpu,
+ (unsigned long)track->ts_nsec, rem_usec);
+#else
pr_err("%s by task %u:\n", prefix, track->pid);
+#endif /* CONFIG_KASAN_EXTRA_INFO */
if (track->stack)
stack_depot_print(track->stack);
else
@@ -544,6 +558,7 @@ void kasan_report_invalid_free(void *ptr, unsigned long ip, enum kasan_report_ty
info.access_size = 0;
info.is_write = false;
info.ip = ip;
+ info.ts_nsec = local_clock();

complete_report_info(&info);

@@ -582,6 +597,7 @@ bool kasan_report(const void *addr, size_t size, bool is_write,
info.access_size = size;
info.is_write = is_write;
info.ip = ip;
+ info.ts_nsec = local_clock();

complete_report_info(&info);

diff --git a/mm/kasan/report_tags.c b/mm/kasan/report_tags.c
index 8b8bfdb3cfdb..4d62f1b3e11d 100644
--- a/mm/kasan/report_tags.c
+++ b/mm/kasan/report_tags.c
@@ -26,6 +26,18 @@ static const char *get_common_bug_type(struct kasan_report_info *info)
return "invalid-access";
}

+#ifdef CONFIG_KASAN_EXTRA_INFO
+static void kasan_complete_extra_report_info(struct kasan_track *track,
+ struct kasan_stack_ring_entry *entry)
+{
+ u32 cpu = READ_ONCE(entry->cpu);
+ u64 ts_nsec = READ_ONCE(entry->ts_nsec);
+
+ track->cpu = cpu;
+ track->ts_nsec = ts_nsec;
+}
+#endif /* CONFIG_KASAN_EXTRA_INFO */
+
void kasan_complete_mode_report_info(struct kasan_report_info *info)
{
unsigned long flags;
@@ -82,6 +94,9 @@ void kasan_complete_mode_report_info(struct kasan_report_info *info)

info->free_track.pid = pid;
info->free_track.stack = stack;
+#ifdef CONFIG_KASAN_EXTRA_INFO
+ kasan_complete_extra_report_info(&info->free_track, entry);
+#endif /* CONFIG_KASAN_EXTRA_INFO */
free_found = true;

/*
@@ -97,6 +112,9 @@ void kasan_complete_mode_report_info(struct kasan_report_info *info)

info->alloc_track.pid = pid;
info->alloc_track.stack = stack;
+#ifdef CONFIG_KASAN_EXTRA_INFO
+ kasan_complete_extra_report_info(&info->alloc_track, entry);
+#endif /* CONFIG_KASAN_EXTRA_INFO */
alloc_found = true;

/*
diff --git a/mm/kasan/tags.c b/mm/kasan/tags.c
index 7dcfe341d48e..474ce7e8be8b 100644
--- a/mm/kasan/tags.c
+++ b/mm/kasan/tags.c
@@ -13,6 +13,7 @@
#include <linux/memblock.h>
#include <linux/memory.h>
#include <linux/mm.h>
+#include <linux/sched/clock.h>
#include <linux/static_key.h>
#include <linux/string.h>
#include <linux/types.h>
@@ -92,6 +93,17 @@ void __init kasan_init_tags(void)
}
}

+#ifdef CONFIG_KASAN_EXTRA_INFO
+static void save_extra_info(struct kasan_stack_ring_entry *entry)
+{
+ u32 cpu = raw_smp_processor_id();
+ u64 ts_nsec = local_clock();
+
+ WRITE_ONCE(entry->cpu, cpu);
+ WRITE_ONCE(entry->ts_nsec, ts_nsec);
+}
+#endif /* CONFIG_KASAN_EXTRA_INFO */
+
static void save_stack_info(struct kmem_cache *cache, void *object,
gfp_t gfp_flags, bool is_free)
{
@@ -124,6 +136,9 @@ static void save_stack_info(struct kmem_cache *cache, void *object,
WRITE_ONCE(entry->pid, current->pid);
WRITE_ONCE(entry->stack, stack);
WRITE_ONCE(entry->is_free, is_free);
+#ifdef CONFIG_KASAN_EXTRA_INFO
+ save_extra_info(entry);
+#endif /* CONFIG_KASAN_EXTRA_INFO */

/*
* Paired with smp_load_acquire() in kasan_complete_mode_report_info().
--
2.39.2