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 C656CC5AD4C for ; Thu, 23 Nov 2023 09:43:29 +0000 (UTC) Received: by kanga.kvack.org (Postfix) id 0D8AE8D0019; Thu, 23 Nov 2023 04:43:29 -0500 (EST) Received: by kanga.kvack.org (Postfix, from userid 40) id 06A928D0002; Thu, 23 Nov 2023 04:43:28 -0500 (EST) X-Delivered-To: int-list-linux-mm@kvack.org Received: by kanga.kvack.org (Postfix, from userid 63042) id E6B3F8D0019; Thu, 23 Nov 2023 04:43:28 -0500 (EST) X-Delivered-To: linux-mm@kvack.org Received: from relay.hostedemail.com (smtprelay0010.hostedemail.com [216.40.44.10]) by kanga.kvack.org (Postfix) with ESMTP id D502B8D0002 for ; Thu, 23 Nov 2023 04:43:28 -0500 (EST) Received: from smtpin10.hostedemail.com (a10.router.float.18 [10.200.18.1]) by unirelay01.hostedemail.com (Postfix) with ESMTP id A80191CBED0 for ; Thu, 23 Nov 2023 09:43:28 +0000 (UTC) X-FDA: 81488731296.10.551D8ED Received: from mail-vs1-f47.google.com (mail-vs1-f47.google.com [209.85.217.47]) by imf07.hostedemail.com (Postfix) with ESMTP id E8ACA40004 for ; Thu, 23 Nov 2023 09:43:26 +0000 (UTC) Authentication-Results: imf07.hostedemail.com; dkim=pass header.d=google.com header.s=20230601 header.b=f58ccZAw; spf=pass (imf07.hostedemail.com: domain of elver@google.com designates 209.85.217.47 as permitted sender) smtp.mailfrom=elver@google.com; dmarc=pass (policy=reject) header.from=google.com ARC-Message-Signature: i=1; a=rsa-sha256; c=relaxed/relaxed; d=hostedemail.com; s=arc-20220608; t=1700732607; 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=lryrEVp0pcZo60SdyGtopQxDXDiRzsB0TNAuuSGzQ+0=; b=sLFbvoMZ9qVfLs4JDKC4hSqnPO//TCtr6aD97clerXIF2itkYUwi3hFYidOPI6vXBEFkVE I8jZ3wVa+7L+IsuOglsfX4NCXsvYWiX2bDa0syPE7IPtnIzWPA8MxH+VvKVGnP0qO8VZDK mEnc1U+MDsXjPjfs4L/kO0oLvN9mV5A= ARC-Authentication-Results: i=1; imf07.hostedemail.com; dkim=pass header.d=google.com header.s=20230601 header.b=f58ccZAw; spf=pass (imf07.hostedemail.com: domain of elver@google.com designates 209.85.217.47 as permitted sender) smtp.mailfrom=elver@google.com; dmarc=pass (policy=reject) header.from=google.com ARC-Seal: i=1; s=arc-20220608; d=hostedemail.com; t=1700732607; a=rsa-sha256; cv=none; b=VDzSght3RLIX522+mDy9wiDaiyl4CIvrTRhqtt92OvgXQBJMI7Ocz09FWtFL4eyD0CbYng iOHVGUvZJwJlgefiG6lRps4S8mYl6Wp3ErkSX7hyPsS1acDdMKr4YzYtEODvWlOrrMoXFk gH5w/awOIlsE08e1Ixo1oiwouoCek5s= Received: by mail-vs1-f47.google.com with SMTP id ada2fe7eead31-45dadc5bf51so226915137.2 for ; Thu, 23 Nov 2023 01:43:26 -0800 (PST) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=google.com; s=20230601; t=1700732606; x=1701337406; 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=lryrEVp0pcZo60SdyGtopQxDXDiRzsB0TNAuuSGzQ+0=; b=f58ccZAwmI+RuKEUT1ZMtODyyJI8ISzQUmiC05DUhSNcVldFwmy4ownVS0UpPk+B7o x7vJrFk5eTLJVq5kXxBh2R/4OH5Yj2zQqO0Nx3RQ3GJDk7qno/JxOkAyw6k38xpfpzra 5X2VvKVil0WIrggKLs9LV8G4L0RGbVoIvd210TcVh2njuPKraIoXTknnnJJSoBeKlFuR GbrTwX5r7o9QoCisCQsnW3BJhswtNFec507jO/V9n4veMeCuOviSp/q9p2mNKi7wJdpx +5Gj8DvN0Trt1uWiEI/BDhLv5uUsTIMZ3hDynH5Bh7fMZOKBNuS2ltvJKnZxCnjIMkD6 CaNA== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20230601; t=1700732606; x=1701337406; 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=lryrEVp0pcZo60SdyGtopQxDXDiRzsB0TNAuuSGzQ+0=; b=xCCk6w3CmC1yaTBXcddYGHrfI3jULOaFZnY53MJ5p43LwlB0sxYoLj4MU4oGQ0D2RS EPkuZtflaJDG5WK6K/9v0/bGRfCV+XSGnoFoP6XEjAkgkT5yICwFT7ZllFgRqUozACCE PSaT6yborf/OQ5hoWT++Btequ+xaeY7UXpGXFOJ03w5oI0U9MVjLw+BtiCuEGh51VQ4m UM0sH8P0qzsbvvC4RfC5QL+/2kU6BiHkoVYHn199eojZ4bxEXLRw9r4HNaMSeOMPNpHg 2WMMcmbIq0bJNQOmgejU3PoVE71LO1sF6UqdjNNiMVGQkiZ/imF0rhIDjiGqWXf9XUMU l83A== X-Gm-Message-State: AOJu0YwaU+R5QU3QwDlczkqZWjBUzp0MihxGWrTMmZhkw3KEOL+jWvJX 0bLgyZVaGVEf90JJ7mG/uOqYyop5mNm8RsXlekKN1A== X-Google-Smtp-Source: AGHT+IFqBeOIaHKyrXq881wDBVRDXzgnV4q21QPK5FmdAqeYGDfmK15LNRbrY0A1mdpRtly2i/6RSHFK1Xb0kdQGGL8= X-Received: by 2002:a05:6102:1004:b0:45d:aa3e:a78 with SMTP id q4-20020a056102100400b0045daa3e0a78mr5613596vsp.10.1700732605928; Thu, 23 Nov 2023 01:43:25 -0800 (PST) MIME-Version: 1.0 References: In-Reply-To: From: Marco Elver Date: Thu, 23 Nov 2023 10:42:48 +0100 Message-ID: Subject: Re: [PATCH] kfence: Replace local_clock() with ktime_get_boot_fast_ns() To: Juntong Deng Cc: glider@google.com, dvyukov@google.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-Queue-Id: E8ACA40004 X-Rspam-User: X-Stat-Signature: nnacgwngyojenbgzmwdefq7nn7zjomba X-Rspamd-Server: rspam01 X-HE-Tag: 1700732606-941145 X-HE-Meta: U2FsdGVkX199eqaNdXZQnWiasi21JVfFig+XI/MQqMMalU6ir8QNU1nem1xQQUdzTAY/2Fv8jm/ZnoYEDcZXYngpr5exjoMjXUQTcPZuZqUatFh5vzlGmP2MxfX1ggmWd9G//AVY05onlssIQgBanWOE0JmX1qJycqxgla2QhQtzMY5tCqKJQu0F5aabumUI+J9wDpyyFLnCJ1nZC3GBwhy85nUGj2NSbm18P/gCJVupE6vUn1P8SsAVwEiwpNfCgkFpBYe+x5N5KLMmWmd/F+UdstpUvZPCzAj/uiHXPlNNrRFEpPPRchYvOZgT6NNh8EuYZsQsq2KXiWIEjaOt+XVnD693a+LejGSiVLftScrktK+HUDsWiNf7X1ck6JOa/fvvl/cPyvcqtjZq/0XxxIAKsQVvaIdWZmB/Lh81R9ylO8Fu6unXMSdtzAagzds21AtXCPlUMBg3wRrYQltrOzXFOpgfi1Y5JA7lhCKyIhXN4LT+q88zNPBSihotRQ4ES0H2GFKJfCO33NywvtooH3szhAhTT3AynlccMyVTdbdBRrTL7qwhgJ9QhCpvKifAGeEV9GNGfs4VMQo8H2CaWXfi4+Xh90JbCzNGWvOfgn31O0KCB+NQHsdq9cdfGV+jOux/5+uiG6arI8eLGcMc4y4q0FN4l+2sVfYjTCAXaD8qHgL1VrEfDgnq01QeNRPcRcXR+suJw5/NuntEgVSmpq/8chSQtUR4CvlPd1uyMtoR6Nb0KAYYZ1xckZ9gOOpemHOIqm53AMDrKum+PEvSaOtzpBHZq4ePg173R1Nj0SSmMnIlfcuS5gOqinoo4kIahYQSlPPWcbkxuorm+RwttqJEgzn12V5LRcaeELSihiHh44DSNI61jh8j0nViYv3YfxjT6lNQqxQlKXuQhVgrLoqzuPiy4sLsHQarDv5J8+Ak4KrUpvnAcx9kMcIvu+6VdgMTxVn46/DGzI01EFt KGVlGP0O jKUcweD1Y73k0SVQLhu088HeGfaeKXsY7ua+hy+t1uQMuvQlrFnvuW/p00Gv9EtCjgThRZPItnXdKgPoCSSrq+Es2WgQMR8DLka9QUt4w6uNbE5NxOKBOVHYoZzNYCHMiR8vvj46kL9cNJG4bXPV7OOQ6/GHC/wZ12xLyaQwkgniO0BUz5GDJqIDFuCsDEt1r9hHDNHHQbRMtMqFhMNHVM+KO4ar+/+Vfpw3kgqv3HwDt8iUYZ67aaEATJ45mqcH99uiFIJXHL2GFsSBo3T5sdjSLqJ0YGkQui8XOTKtl1aTb90s= X-Bogosity: Ham, tests=bogofilter, spamicity=0.000014, 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 Thu, 23 Nov 2023 at 10:29, Juntong Deng wrote: > > On 2023/11/23 6:19, Marco Elver wrote: > > On Wed, 22 Nov 2023 at 22:36, Juntong Deng wrote: > >> > >> On 2023/11/23 4:35, Marco Elver wrote: > >>> On Wed, 22 Nov 2023 at 21:01, Juntong Deng wrote: > >>>> > >>>> The time obtained by local_clock() is the local CPU time, which may > >>>> drift between CPUs and is not suitable for comparison across CPUs. > >>>> > >>>> It is possible for allocation and free to occur on different CPUs, > >>>> and using local_clock() to record timestamps may cause confusion. > >>> > >>> The same problem exists with printk logging. > >>> > >>>> ktime_get_boot_fast_ns() is based on clock sources and can be used > >>>> reliably and accurately for comparison across CPUs. > >>> > >>> You may be right here, however, the choice of local_clock() was > >>> deliberate: it's the same timestamp source that printk uses. > >>> > >>> Also, on systems where there is drift, the arch selects > >>> CONFIG_HAVE_UNSTABLE_SCHED_CLOCK (like on x86) and the drift is > >>> generally bounded. > >>> > >>>> Signed-off-by: Juntong Deng > >>>> --- > >>>> mm/kfence/core.c | 2 +- > >>>> 1 file changed, 1 insertion(+), 1 deletion(-) > >>>> > >>>> diff --git a/mm/kfence/core.c b/mm/kfence/core.c > >>>> index 3872528d0963..041c03394193 100644 > >>>> --- a/mm/kfence/core.c > >>>> +++ b/mm/kfence/core.c > >>>> @@ -295,7 +295,7 @@ metadata_update_state(struct kfence_metadata *meta, enum kfence_object_state nex > >>>> track->num_stack_entries = num_stack_entries; > >>>> track->pid = task_pid_nr(current); > >>>> track->cpu = raw_smp_processor_id(); > >>>> - track->ts_nsec = local_clock(); /* Same source as printk timestamps. */ > >>>> + track->ts_nsec = ktime_get_boot_fast_ns(); > >>> > >>> You have ignored the comment placed here - now it's no longer the same > >>> source as printk timestamps. I think not being able to correlate > >>> information from KFENCE reports with timestamps in lines from printk > >>> is worse. > >>> > >>> For now, I have to Nack: Unless you can prove that > >>> ktime_get_boot_fast_ns() can still be correlated with timestamps from > >>> printk timestamps, I think this change only trades one problem for > >>> another. > >>> > >>> Thanks, > >>> -- Marco > >> > >> Honestly, the possibility of accurately matching a message in the printk > >> log by the timestamp in the kfence report is very low, since allocation > >> and free do not directly correspond to a certain event. > > > > It's about being able to compare the timestamps. I don't want to match > > an exact event, but be able to figure out which event happened > > before/after an allocation or free, i.e. the logical ordering of > > events. > > > > With CONFIG_PRINTK_CALLER we can see the CPU ID in printk lines and > > are therefore able to accurately compare printk lines with information > > given by KFENCE alloc/free info. > > > > > That makes sense. > > > >> Since time drifts across CPUs, timestamps may be different even if > >> allocation and free can correspond to a certain event. > > > > This is not a problem with CONFIG_PRINTK_CALLER. > > > >> If we really need to find the relevant printk logs by the timestamps in > >> the kfence report, all we can do is to look for messages that are within > >> a certain time range. > >> > >> If we are looking for messages in a certain time range, there is not > >> much difference between local_clock() and ktime_get_boot_fast_ns(). > >> > >> Also, this patch is in preparation for my next patch. > >> > >> My next patch is to show the PID, CPU number, and timestamp when the > >> error occurred, in this case time drift from different CPUs can > >> cause confusion. > > > > It's not quite clear how there's a dependency between this patch and a > > later patch, but generally it's good practice to send related patches > > as a patch series. That way it's easier to see what the overall > > changes are and provide feedback as a whole - as is, it's difficult to > > provide feedback. > > > > However, from what you say this information is already given. > > dump_stack_print_info() shows this - e.g this bit here is printed by > > where the error occurred: > > > > | 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.14.0-2 > > 04/01/2014 > > > > And if the printk log has timestamps, then these lines are prefixed > > with the timestamp where the error occurred. > > > > > Thanks, I found that information. > > Since this information is at the bottom of the report, I had previously > ignored them. > > I would suggest considering moving this information to the top of > the report, for example > > BUG: KFENCE: out-of-bounds read in test_out_of_bounds_read+0xa6/0x234 > > 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.14.0-2 > 04/01/2014 > > Out-of-bounds read at 0xffff8c3f2e291fff (1B left of kfence-#72): > ... > > This more clearly correlates this information with the occurrence of > the error. Most kernel warnings/bugs/etc. show this information at the bottom of the report, hence KFENCE also showing it there. If you look at kfence_report_error() where it prints this info, there is a mode where KFENCE also dumps all registers via show_regs(). show_regs() itself displays this information at the bottom as well, but showing a dump of registers at the start of the KFENCE report is pretty distracting and looks ugly. The placement of this information is not the best, but at the same time I found it to be the least bad compromise (when also considering the mode where it dumps registers). We could of course untangle some of these functions and e.g. have a show_regs() version that doesn't show that info, but I find that to add more interfaces to the kernel with unclear gains - overall probably not worth the time effort. At least that's the reasoning for why things are the way they are today. If there is an easier way I missed, any clear improvements are of course welcome. Thanks, -- Marco