On Wed, 22 Nov 2023 at 22:36, Juntong Deng <juntong.deng@xxxxxxxxxxx> wrote: > > On 2023/11/23 4:35, Marco Elver wrote: > > On Wed, 22 Nov 2023 at 21:01, Juntong Deng <juntong.deng@xxxxxxxxxxx> 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 <juntong.deng@xxxxxxxxxxx> > >> --- > >> 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. > 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. > For example, use-after-free caused by a subtle race condition, in which > the time between the free and the error occur will be very close. > > Time drift from different CPUs may cause it to appear in the report that > the error timestamp precedes the free timestamp. That doesn't matter. I recommend that you go through a hypothetical debugging scenario: 1. We are not interested in the absolute timings of events, but the logical ordering between them. 2. The logical ordering of events is inherent from how KFENCE operates: an error _always_ follows an allocation and/or free. From a debugging point of view, the timestamps do not have any value here. 3. The timestamps _do_ add value when trying to figure out the logical ordering between allocation, free, or the erroneous access _with other_ events in the system. A stream of other events is always shown in the kernel log (printk). Other streams of events can be obtained via e.g. ftrace (which also uses local_clock(), see kernel/trace/trace_clock.c). So, the timestamp that KFENCE should show is the one that most likely allows us to deduce the logical ordering with other events in the system.
