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 96EA3C433EF for ; Mon, 6 Dec 2021 17:18:09 +0000 (UTC) Received: by kanga.kvack.org (Postfix) id ECB7C6B0071; Mon, 6 Dec 2021 12:17:58 -0500 (EST) Received: by kanga.kvack.org (Postfix, from userid 40) id E7A3A6B0072; Mon, 6 Dec 2021 12:17:58 -0500 (EST) X-Delivered-To: int-list-linux-mm@kvack.org Received: by kanga.kvack.org (Postfix, from userid 63042) id D1AC16B007E; Mon, 6 Dec 2021 12:17:58 -0500 (EST) X-Delivered-To: linux-mm@kvack.org Received: from forelay.hostedemail.com (smtprelay0074.hostedemail.com [216.40.44.74]) by kanga.kvack.org (Postfix) with ESMTP id BFFAD6B0071 for ; Mon, 6 Dec 2021 12:17:58 -0500 (EST) Received: from smtpin25.hostedemail.com (10.5.19.251.rfc1918.com [10.5.19.251]) by forelay01.hostedemail.com (Postfix) with ESMTP id 830E118397646 for ; Mon, 6 Dec 2021 17:17:48 +0000 (UTC) X-FDA: 78888026616.25.F9AB170 Received: from mail-io1-f45.google.com (mail-io1-f45.google.com [209.85.166.45]) by imf21.hostedemail.com (Postfix) with ESMTP id EFA6BD0369C8 for ; Mon, 6 Dec 2021 17:17:47 +0000 (UTC) Received: by mail-io1-f45.google.com with SMTP id c3so13815681iob.6 for ; Mon, 06 Dec 2021 09:17:47 -0800 (PST) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=20210112; h=date:from:to:cc:subject:message-id:references:mime-version :content-disposition:in-reply-to; bh=aNz3Q2mlKF711FA8wRX14koPJl39WuNweWYokTQs3qU=; b=AwTjbe4JskmjdVEHzHOR1FdY/bm5eSzHzio26QFOYCc4QTlRRzGcpZNWTOmwvHCWUv DiqrMq/laf0baqEnExZnhGWJKVAglgQlB5NsUUWLKUwqb2iV/QKTGcmMGoD9vU/9feFA quH5Q1HK3vDzFEBvRHE/9Eivv+9WOGhA8iHL3DvHJ9lDL8Jos11pIxhEIxw6WdgW0Yqg QkFnXjVRfF7DHU4l7BLLaLBGCLmt4SfnIAXjFGMxZaXGDMH3CWALYiBYrk5Z64efPGYB vFzg5dlqju1UrQ0pHToAb5NTDBE+tw9NU3sswbWCeRDeiQYpFCJz7YLYwDCnqA+0uVyA xu8g== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20210112; h=x-gm-message-state:date:from:to:cc:subject:message-id:references :mime-version:content-disposition:in-reply-to; bh=aNz3Q2mlKF711FA8wRX14koPJl39WuNweWYokTQs3qU=; b=HH8e9HuXIQsRuj7qDvuOZ9+WJVkFjEqCReE0eaV7aMi0WiJwtC0wCBMaRBaxMiMmui gWXmgLhTKpfWQf0VQdOPicqV0DNV4TcMio0JIi/qfc0W5eR2FFP/rqYTLDeJXLRcceKa x6/7/kANDZmPjl8lZKAKWPiRrmWYeJy14jN40J7kkyt5YB3kR3U/7CLuxgaXGLLw/17a 3V5BQLaicVg96EhZmf90/Ra9A14ZT7Nyp+CgvzWxtTy2v4EhKCwamFYtyRnjn0h/mqqY ghnV552D37LwIFVNjrISVdRni6spmaKLFPQ00ebfKvhioOpZ5Saw/ssWVuS7qbgWbDSs en9A== X-Gm-Message-State: AOAM532hRVka26fJPmHJmLY7w8Ix31rzVH1jeFZsWGw5LGr1bbJylYLd 4DkvYHdojo6phNkdY8e3HeQ= X-Google-Smtp-Source: ABdhPJyv3jGlqSSJnIRJD424hIOvjpgEoXREUM7M0+VcqmqFV24bQgbl0uhMJAoKJXaUpVwvcHznpA== X-Received: by 2002:a05:6602:1609:: with SMTP id x9mr34726304iow.6.1638811067376; Mon, 06 Dec 2021 09:17:47 -0800 (PST) Received: from auth2-smtp.messagingengine.com (auth2-smtp.messagingengine.com. [66.111.4.228]) by smtp.gmail.com with ESMTPSA id r3sm7030982iob.0.2021.12.06.09.17.45 (version=TLS1_3 cipher=TLS_AES_256_GCM_SHA384 bits=256/256); Mon, 06 Dec 2021 09:17:46 -0800 (PST) Received: from compute1.internal (compute1.nyi.internal [10.202.2.41]) by mailauth.nyi.internal (Postfix) with ESMTP id 25CDA27C0064; Mon, 6 Dec 2021 12:17:45 -0500 (EST) Received: from mailfrontend1 ([10.202.2.162]) by compute1.internal (MEProxy); Mon, 06 Dec 2021 12:17:45 -0500 X-ME-Sender: X-ME-Received: X-ME-Proxy-Cause: gggruggvucftvghtrhhoucdtuddrgedvuddrjeefgdellecutefuodetggdotefrodftvf curfhrohhfihhlvgemucfhrghsthforghilhdpqfgfvfdpuffrtefokffrpgfnqfghnecu uegrihhlohhuthemuceftddtnecusecvtfgvtghiphhivghnthhsucdlqddutddtmdenuc fjughrpeffhffvuffkfhggtggujgesthdtredttddtvdenucfhrhhomhepuehoqhhunhcu hfgvnhhguceosghoqhhunhdrfhgvnhhgsehgmhgrihhlrdgtohhmqeenucggtffrrghtth gvrhhnpedvleeigedugfegveejhfejveeuveeiteejieekvdfgjeefudehfefhgfegvdeg jeenucevlhhushhtvghrufhiiigvpedtnecurfgrrhgrmhepmhgrihhlfhhrohhmpegsoh hquhhnodhmvghsmhhtphgruhhthhhpvghrshhonhgrlhhithihqdeiledvgeehtdeigedq udejjeekheehhedvqdgsohhquhhnrdhfvghngheppehgmhgrihhlrdgtohhmsehfihigmh gvrdhnrghmvg X-ME-Proxy: Received: by mail.messagingengine.com (Postfix) with ESMTPA; Mon, 6 Dec 2021 12:17:44 -0500 (EST) Date: Tue, 7 Dec 2021 01:16:25 +0800 From: Boqun Feng To: Marco Elver Cc: "Paul E. McKenney" , Alexander Potapenko , Borislav Petkov , Dmitry Vyukov , Ingo Molnar , Mark Rutland , Peter Zijlstra , Thomas Gleixner , Waiman Long , Will Deacon , kasan-dev@googlegroups.com, linux-arch@vger.kernel.org, linux-doc@vger.kernel.org, linux-kbuild@vger.kernel.org, linux-kernel@vger.kernel.org, linux-mm@kvack.org, llvm@lists.linux.dev, x86@kernel.org Subject: Re: [PATCH v3 08/25] kcsan: Show location access was reordered to Message-ID: References: <20211130114433.2580590-1-elver@google.com> <20211130114433.2580590-9-elver@google.com> MIME-Version: 1.0 Content-Type: text/plain; charset=us-ascii Content-Disposition: inline In-Reply-To: X-Stat-Signature: dj783ztd7rkhr5sfed6wnksf4w13aokq Authentication-Results: imf21.hostedemail.com; dkim=pass header.d=gmail.com header.s=20210112 header.b=AwTjbe4J; dmarc=pass (policy=none) header.from=gmail.com; spf=pass (imf21.hostedemail.com: domain of boqun.feng@gmail.com designates 209.85.166.45 as permitted sender) smtp.mailfrom=boqun.feng@gmail.com X-Rspamd-Server: rspam06 X-Rspamd-Queue-Id: EFA6BD0369C8 X-HE-Tag: 1638811067-424617 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: On Mon, Dec 06, 2021 at 05:04:20PM +0100, Marco Elver wrote: > On Mon, Dec 06, 2021 at 10:31PM +0800, Boqun Feng wrote: > [...] > > Thanks for the explanation, I was missing the swap here. However... > > > > > So in your above example you need to swap "reordered to" and the top > > > frame of the stack trace. > > > > > Apologies, I wasn't entirely precise ... what you say below is correct. > > > IIUC, the report for my above example will be: > > > > | write (reordered) to 0xaaaa of ...: > > | foo+0x... // address of the write to A > > | ... > > | | > > | +-> reordered to: foo+0x... // address of the callsite to bar() in foo() > > > > , right? Because in replace_stack_entry(), it's not the top frame where > > the race occurred that gets swapped, it's the frame which belongs to the > > same function as the original access that gets swapped. In other words, > > when KCSAN finds the problem, top entries of the calling stack are: > > > > [0] bar+0x.. // address of the write to B > > [1] foo+0x.. // address of the callsite to bar() in foo() > > > > after replace_stack_entry(), they changes to: > > > > [0] bar+0x.. // address of the write to B > > skip ->[1] foo+0x.. // address of the write to A > > > > , as a result the report won't mention bar() at all. > > Correct. > > > And I think a better report will be: > > > > | write (reordered) to 0xaaaa of ...: > > | foo+0x... // address of the write to A > > | ... > > | | > > | +-> reordered to: bar+0x... // address of the write to B in bar() > > > > because it tells users the exact place the accesses get reordered. That > > means maybe we want something as below? Not completely tested, but I > > play with scope checking a bit, seems it gives what I want. Thoughts? > > This is problematic because it makes it much harder to actually figure > out what's going on, given "reordered to" isn't a full stack trace. So > if you're deep in some call hierarchy, seeing a random "reordered to" > line is quite useless. What I want to see, at the very least, is the ip > to the same function where the original access happened. > > We could of course try and generate a full stack trace at "reordered > to", but this would entail > > a) allocating 2x unsigned long[64] on the stack (or moving to > static storage), > b) further increasing the report length, > c) an even larger number of possibly distinct reports for the > same issue; this makes deduplication even harder. > > The reason I couldn't justify all that is that when I looked through > several dozen "reordered to" reports, I never found anything other than > the ip in the function frame of the original access useful. That, and in > most cases the "reordered to" location was in the same function or in an > inlined function. > > The below patch would do what you'd want I think. > > My opinion is to err on the side of simplicity until there is evidence > we need it. Of course, if you have a compelling reason that we need it > from the beginning, happy to send it as a separate patch on top. > > What do you think? > Totally agreed. It's better to keep it simple until people report that they want to see more information to resolve the issues. And thanks for looking into the "double stack traces", that looks good to me too. For the original patch, feel free to add: Reviewed-by: Boqun Feng Regards, Boqun > Thanks, > -- Marco > > ------ >8 ------ > > From: Marco Elver > Date: Mon, 6 Dec 2021 16:35:02 +0100 > Subject: [PATCH] kcsan: Show full stack trace of reordered-to accesses > > Change reports involving reordered accesses to show the full stack trace > of "reordered to" accesses. For example: > > | ================================================================== > | BUG: KCSAN: data-race in test_kernel_wrong_memorder / test_kernel_wrong_memorder > | > | read-write to 0xffffffffc02d01e8 of 8 bytes by task 2481 on cpu 2: > | test_kernel_wrong_memorder+0x57/0x90 > | access_thread+0xb7/0x100 > | kthread+0x2ed/0x320 > | ret_from_fork+0x22/0x30 > | > | read-write (reordered) to 0xffffffffc02d01e8 of 8 bytes by task 2480 on cpu 0: > | test_kernel_wrong_memorder+0x57/0x90 > | access_thread+0xb7/0x100 > | kthread+0x2ed/0x320 > | ret_from_fork+0x22/0x30 > | | > | +-> reordered to: test_delay+0x31/0x110 > | test_kernel_wrong_memorder+0x80/0x90 > | > | Reported by Kernel Concurrency Sanitizer on: > | CPU: 0 PID: 2480 Comm: access_thread Not tainted 5.16.0-rc1+ #2 > | Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.14.0-2 04/01/2014 > | ================================================================== > > Signed-off-by: Marco Elver > --- > kernel/kcsan/report.c | 33 +++++++++++++++++++++++---------- > 1 file changed, 23 insertions(+), 10 deletions(-) > > diff --git a/kernel/kcsan/report.c b/kernel/kcsan/report.c > index 67794404042a..a8317d5f5123 100644 > --- a/kernel/kcsan/report.c > +++ b/kernel/kcsan/report.c > @@ -317,22 +317,29 @@ replace_stack_entry(unsigned long stack_entries[], int num_entries, unsigned lon > { > unsigned long symbolsize, offset; > unsigned long target_func; > - int skip; > + int skip, i; > > if (kallsyms_lookup_size_offset(ip, &symbolsize, &offset)) > target_func = ip - offset; > else > goto fallback; > > - for (skip = 0; skip < num_entries; ++skip) { > + skip = get_stack_skipnr(stack_entries, num_entries); > + for (i = 0; skip < num_entries; ++skip, ++i) { > unsigned long func = stack_entries[skip]; > > if (!kallsyms_lookup_size_offset(func, &symbolsize, &offset)) > goto fallback; > func -= offset; > > + replaced[i] = stack_entries[skip]; > if (func == target_func) { > - *replaced = stack_entries[skip]; > + /* > + * There must be at least 1 entry left in the original > + * @stack_entries, so we know that we will never occupy > + * more than @num_entries - 1 of @replaced. > + */ > + replaced[i + 1] = 0; > stack_entries[skip] = ip; > return skip; > } > @@ -341,6 +348,7 @@ replace_stack_entry(unsigned long stack_entries[], int num_entries, unsigned lon > fallback: > /* Should not happen; the resulting stack trace is likely misleading. */ > WARN_ONCE(1, "Cannot find frame for %pS in stack trace", (void *)ip); > + replaced[0] = 0; > return get_stack_skipnr(stack_entries, num_entries); > } > > @@ -365,11 +373,16 @@ static int sym_strcmp(void *addr1, void *addr2) > } > > static void > -print_stack_trace(unsigned long stack_entries[], int num_entries, unsigned long reordered_to) > +print_stack_trace(unsigned long stack_entries[], int num_entries, unsigned long *reordered_to) > { > stack_trace_print(stack_entries, num_entries, 0); > - if (reordered_to) > - pr_err(" |\n +-> reordered to: %pS\n", (void *)reordered_to); > + if (reordered_to[0]) { > + int i; > + > + pr_err(" |\n +-> reordered to: %pS\n", (void *)reordered_to[0]); > + for (i = 1; i < NUM_STACK_ENTRIES && reordered_to[i]; ++i) > + pr_err(" %pS\n", (void *)reordered_to[i]); > + } > } > > static void print_verbose_info(struct task_struct *task) > @@ -390,12 +403,12 @@ static void print_report(enum kcsan_value_change value_change, > struct other_info *other_info, > u64 old, u64 new, u64 mask) > { > - unsigned long reordered_to = 0; > + unsigned long reordered_to[NUM_STACK_ENTRIES] = { 0 }; > unsigned long stack_entries[NUM_STACK_ENTRIES] = { 0 }; > int num_stack_entries = stack_trace_save(stack_entries, NUM_STACK_ENTRIES, 1); > - int skipnr = sanitize_stack_entries(stack_entries, num_stack_entries, ai->ip, &reordered_to); > + int skipnr = sanitize_stack_entries(stack_entries, num_stack_entries, ai->ip, reordered_to); > unsigned long this_frame = stack_entries[skipnr]; > - unsigned long other_reordered_to = 0; > + unsigned long other_reordered_to[NUM_STACK_ENTRIES] = { 0 }; > unsigned long other_frame = 0; > int other_skipnr = 0; /* silence uninit warnings */ > > @@ -408,7 +421,7 @@ static void print_report(enum kcsan_value_change value_change, > if (other_info) { > other_skipnr = sanitize_stack_entries(other_info->stack_entries, > other_info->num_stack_entries, > - other_info->ai.ip, &other_reordered_to); > + other_info->ai.ip, other_reordered_to); > other_frame = other_info->stack_entries[other_skipnr]; > > /* @value_change is only known for the other thread */ > -- > 2.34.1.400.ga245620fadb-goog >