lkml.org 
[lkml]   [2023]   [Nov]   [20]   [last100]   RSS Feed
Views: [wrap][no wrap]   [headers]  [forward] 
 
Messages in this thread
/
Date
SubjectRe: [RFC PATCH] kasan: Record and report more information
From
On 2023/11/20 19:06, Dmitry Vyukov wrote:
> On Wed, 15 Nov 2023 at 22:53, Juntong Deng <juntong.deng@outlook.com> wrote:
>>
>> On 2023/11/14 15:27, Dmitry Vyukov wrote:
>>> On Mon, 13 Nov 2023 at 22:17, Juntong Deng <juntong.deng@outlook.com> 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@outlook.com>
>>>> ---
>>>> 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@austin.mtv.corp.google.com/
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
>>>>
>>

\
 
 \ /
  Last update: 2023-11-20 17:45    [W:0.204 / U:0.028 seconds]
©2003-2020 Jasper Spaans|hosted at Digital Ocean and TransIP|Read the blog|Advertise on this site