From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: X-Spam-Checker-Version: SpamAssassin 3.4.0 (2014-02-07) on aws-us-west-2-korg-lkml-1.web.codeaurora.org Received: from kanga.kvack.org (kanga.kvack.org [205.233.56.17]) by smtp.lore.kernel.org (Postfix) with ESMTP id 3EABDC4332F for ; Tue, 14 Nov 2023 07:28:05 +0000 (UTC) Received: by kanga.kvack.org (Postfix) id AB2246B02B4; Tue, 14 Nov 2023 02:28:04 -0500 (EST) Received: by kanga.kvack.org (Postfix, from userid 40) id A61636B02B5; Tue, 14 Nov 2023 02:28:04 -0500 (EST) X-Delivered-To: int-list-linux-mm@kvack.org Received: by kanga.kvack.org (Postfix, from userid 63042) id 92A1B6B02B6; Tue, 14 Nov 2023 02:28:04 -0500 (EST) X-Delivered-To: linux-mm@kvack.org Received: from relay.hostedemail.com (smtprelay0011.hostedemail.com [216.40.44.11]) by kanga.kvack.org (Postfix) with ESMTP id 7C9E66B02B4 for ; Tue, 14 Nov 2023 02:28:04 -0500 (EST) Received: from smtpin02.hostedemail.com (a10.router.float.18 [10.200.18.1]) by unirelay07.hostedemail.com (Postfix) with ESMTP id 598F716084A for ; Tue, 14 Nov 2023 07:28:04 +0000 (UTC) X-FDA: 81455730888.02.EB882AC Received: from mail-ed1-f53.google.com (mail-ed1-f53.google.com [209.85.208.53]) by imf11.hostedemail.com (Postfix) with ESMTP id 8F1D240008 for ; Tue, 14 Nov 2023 07:28:02 +0000 (UTC) Authentication-Results: imf11.hostedemail.com; dkim=pass header.d=google.com header.s=20230601 header.b=nTH0ltWf; dmarc=pass (policy=reject) header.from=google.com; spf=pass (imf11.hostedemail.com: domain of dvyukov@google.com designates 209.85.208.53 as permitted sender) smtp.mailfrom=dvyukov@google.com ARC-Message-Signature: i=1; a=rsa-sha256; c=relaxed/relaxed; d=hostedemail.com; s=arc-20220608; t=1699946882; h=from:from:sender:reply-to:subject:subject:date:date: message-id:message-id:to:to:cc:cc:mime-version:mime-version: content-type:content-type:content-transfer-encoding: in-reply-to:in-reply-to:references:references:dkim-signature; bh=j7k5QLsXr1VaePKPJwpckb69EbdmzQCB0DATBTJO1Js=; b=o9UV+dXRseS698qGnkgI0atlYjkHQhrSYrbJrBlV2yHyYZPwsC+EQygjPwY/AUhgcWeHbz j+LbMVtKHnJifJucvrJ9I9GWf+mYCmfiu95x5tdkfKOlwID3qXfKtqHmKc3ulHL4kvPaEY sbSBbiSGjel2nU02qt3SM7jbwzeqbpc= ARC-Authentication-Results: i=1; imf11.hostedemail.com; dkim=pass header.d=google.com header.s=20230601 header.b=nTH0ltWf; dmarc=pass (policy=reject) header.from=google.com; spf=pass (imf11.hostedemail.com: domain of dvyukov@google.com designates 209.85.208.53 as permitted sender) smtp.mailfrom=dvyukov@google.com ARC-Seal: i=1; s=arc-20220608; d=hostedemail.com; t=1699946882; a=rsa-sha256; cv=none; b=J6b/lb17QZmV/bpSkAmONpUKdnS72gM5yNHMW2XuYN43ujsAHESTpoauXuI7NJMNyPM58n /jIdqm8YyS4WceKZS52LVAFsdRbqa6MJb7lNyrciMhp65wVtz3DqWIi1kwuljUjkJvxcXU f2VdqrmV8sDEo64B0NV95aR3frcj2iU= Received: by mail-ed1-f53.google.com with SMTP id 4fb4d7f45d1cf-54366bb1c02so6144a12.1 for ; Mon, 13 Nov 2023 23:28:02 -0800 (PST) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=google.com; s=20230601; t=1699946881; x=1700551681; darn=kvack.org; h=cc:to:subject:message-id:date:from:in-reply-to:references :mime-version:from:to:cc:subject:date:message-id:reply-to; bh=j7k5QLsXr1VaePKPJwpckb69EbdmzQCB0DATBTJO1Js=; b=nTH0ltWf06qyvoSihH3VhsjFUqdu32xl3mwEqfzF/9tpk0RjJNlwpmcRl8Ejuvw8lt jSrmGH0apzpYCKA2qV/D5L1uRL5T2zzYR9ihJtXk5pMiwoVa5J50Y2B6U1eENcdRegwM mUrHWO1Yi5JmIBB0TnxsNsUnlww9yihVRe5sTaZpU1NBePbGBufNEgpKyxH2PrhxvPbM gFmQhourT2Hi3pfAwje/0d+B+PlfKwKKtEgYeT02GkoyAK8OlItY4IaSBsaXQHMAAERU 0YHvzNilBLgn3ewulNgBuh2jcaLrWJjbSPdDwe1w0NOxIQV4ywTcWEkeCjJITeZjb7MX JndA== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20230601; t=1699946881; x=1700551681; h=cc:to:subject:message-id:date:from:in-reply-to:references :mime-version:x-gm-message-state:from:to:cc:subject:date:message-id :reply-to; bh=j7k5QLsXr1VaePKPJwpckb69EbdmzQCB0DATBTJO1Js=; b=j0twnxaehGH3Tkst4qsYQAnOsH6bGeVdlhCyhA2lPvki3d9HQZ4gfh+yQn01I8IaFy NYNJW8q8dvbVEfl0wag/Nu9dqOVZ4IFAyPwEpPSlW+pP7/3bmx9OYlz+VhgF/ZS0kKcq KfWq0Qn8IB4x+z9rBFmQO2KobY0NPsdBJ2SSQJs7SQUBNQKO3kXhjUMf86oJWMwY5FP3 YoT2TR6YZzUgpcxdKjWeBoaEu4jyGQ015pSw/ymcExADLCZA99EnD/vIifd+nuijYRMH TusChUFZHjdIL6sBP8bGKvSjk2kBC8LdFixH0VUzRb2KIf4+nY9fNtlB4Z38nRe6vEY1 JUpg== X-Gm-Message-State: AOJu0YwsVmUp9Lru5CV/l1xIPRJvlMADsUPABLW7amx9D+Y3NirU54k0 3gI4t7QSXdvlUD3TFPCPZQE3fWunbgE0eDg8232YWg== X-Google-Smtp-Source: AGHT+IGznF9Y+y85mBjQGKheeKLj798TNkdqDfsd+3MX4sGPTet4hqMC5c91b5q2L6Q8B/5J04ZwNG9RIHgzWcPhIOE= X-Received: by 2002:aa7:dc0f:0:b0:545:94c:862e with SMTP id b15-20020aa7dc0f000000b00545094c862emr93008edu.2.1699946880793; Mon, 13 Nov 2023 23:28:00 -0800 (PST) MIME-Version: 1.0 References: In-Reply-To: From: Dmitry Vyukov Date: Tue, 14 Nov 2023 08:27:44 +0100 Message-ID: Subject: Re: [RFC PATCH] kasan: Record and report more information To: Juntong Deng Cc: ryabinin.a.a@gmail.com, glider@google.com, andreyknvl@gmail.com, vincenzo.frascino@arm.com, akpm@linux-foundation.org, kasan-dev@googlegroups.com, linux-mm@kvack.org, linux-kernel@vger.kernel.org, linux-kernel-mentees@lists.linuxfoundation.org Content-Type: text/plain; charset="UTF-8" X-Rspamd-Server: rspam09 X-Rspamd-Queue-Id: 8F1D240008 X-Stat-Signature: kyke9eda1yessn9t7x53phc656ie1iaw X-Rspam-User: X-HE-Tag: 1699946882-71312 X-HE-Meta: U2FsdGVkX1/pz185O0HPgUBMlJABl5pF1tREnjTcDLJEEvTaJYNrJTTmAMLriDZbUzcNWeg6dkgBr3uYmOlN0efdor0+J4IgLySnZra3bUPj9SSLg2Kskmniq/uPplPqev6HHFUaJpAUAqb2Frpin70VeiPqKmFxSg5g9uhSGEDMGbOE/EpLgHLka6Y/6boXKN2evGVfklP+U+uIR+oFnD/fg8y40OPh/fy1f4STVjxQ3GzsFgBbAWHS7PbbH4bFyzVPiFTgkfU822ZCw/bf+759r/Nc1h9AsaloLI7mhXbj8QTCOZH+MxFliGXqZBQxFYO4Ar6cCHzH/7vyXYmQBnub0lVygSY39g7zkfJyBBK3ybKD3KD9OeXk/NRRi24hMCuyXr1rE0LvRKxbTYFX7yumoDXZAC3rlRxwHdPRD8Lx8n/3j+0U8tpLbp9jgua69PASHdKENmwbeT2lo31vRIQwMpXgh25BJpJu1KpnFodrqJpIYSCL3JsqIMeK8kI2G053F5V1c27XMWwCwMtmtKR+X/B7fCtrNeSBpSFVBhlxe5NMEY/SzI4hHr03j/p9d35b3GekOYr75eVrAE0mXChM+Pj4XLpyxFdbSbcNjbab5ItcrABTsd0sxWuBhBhJSdj3kV/QvbzSB0GBp2Vke/fb7ReH9/YNRy+8TnWvO2mk0BsKx9SSRL0L6CUL3B9XjM9+e0AsGVZr2O9sHcV2MgKzcCFRJkx2eiqUc/GyEDTK+p2YGhom2nBWx977Ypaeo1WwJyQ72GGZ0Hw1QD3eHK2u5Lg/3zsjqftrUjyd9opWEyzNw384ys1J4LsZ2JRSOhJBv3A6LHFzverpZb53HphLcIdKqVPn8/0oTgJ/RMDW86ulakDGfxIAXDAVdGjxV65TVGgJ3iCj0oYfoQxVNVHKtcC+0+nu//w8ivfnB1Y60YP94I3FJkLIbr4o8oy3UhIkNag/sAztKB/+eU9 fS3b8ebJ cNG2CM1AdrPTFVJ6tAonN0ZR4XDTEsDm76qb9cH0HC5mzYq7jTMQrFnH5l3jLF+i7O4UmTeNH/NSoo4Dg9jH25rkV8Yv5eEmYo4ghYDVTrLhhZCIPb7/SMbK6TmQERB290QcLfA44OR/+tnjdPRTvl7/OSGpOSMExrsD9XPv/W1ADRsuyt4/7CjSjuwmQpDT9iAupSbirQKAjSrA+GVrifeW7kW8q6Iy4e6TugO0Mj9YAuMNxgrCpVBitqFSVXryNeYS/IrKNPiOOgSrkBDjSFioZ5oQ8VKlCovMeo/Y3Ho8zAmgFls1eHWzfOA5UH0DD6O+XhEp3LGpDtZUJzU907jJ/J7T7IjOJoeoPOw+FaLUK0oFu0EA2mIWUcxQCQSZld4sNDAYYyYeAbd0wXz4L4qHUj7mNzgtzPaE5BATUPCj26SN4Vy6sLFigWw== X-Bogosity: Ham, tests=bogofilter, spamicity=0.000000, version=1.2.4 Sender: owner-linux-mm@kvack.org Precedence: bulk X-Loop: owner-majordomo@kvack.org List-ID: List-Subscribe: List-Unsubscribe: On Mon, 13 Nov 2023 at 22:17, Juntong Deng 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 > --- > 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. 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". 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? > 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 > #include > #include > +#include > #include > #include > #include > @@ -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? > +#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. 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. > +#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 > #include > #include > +#include > #include > #include > #include > @@ -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 > #include > #include > +#include > #include > #include > #include > @@ -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 >