On Wed Apr 27 2022, Steven Rostedt wrote:
> I'm able to trigger this on x86 64bit too.

OK, reproduced it by using the function tracer (instead of events).

Anyway, with your patch applied [1] and the one below it looks way
better:

|            bash-4252    [003] ...1. 1651091299.936121: file_ra_state_init <-do_dentry_open
|            bash-4252    [003] ...1. 1651091299.936121: inode_to_bdi <-file_ra_state_init
|            bash-4252    [003] ...1. 1651091299.936121: do_truncate <-path_openat
|            bash-4252    [003] ...1. 1651091299.936122: dentry_needs_remove_privs <-do_truncate
|            bash-4252    [003] ...1. 1651091299.936122: should_remove_suid <-dentry_needs_remove_privs
|            bash-4252    [003] ...1. 1651091299.936122: security_inode_need_killpriv <-dentry_needs_remove_privs
|            bash-4252    [003] ...1. 1651091299.936122: cap_inode_need_killpriv <-security_inode_need_killpriv
|            bash-4252    [003] ...1. 1651091299.936123: __vfs_getxattr <-cap_inode_need_killpriv
|            bash-4252    [003] ...1. 1651091299.936123: xattr_resolve_name <-__vfs_getxattr
|            bash-4252    [003] ...1. 1651091299.936123: is_bad_inode <-xattr_resolve_name
|            bash-4252    [003] ...1. 1651091299.936123: down_write <-do_truncate
|            bash-4252    [003] ...1. 1651091299.936123: notify_change <-do_truncate
|            bash-4252    [003] ...1. 1651091299.936123: may_setattr <-notify_change
|            bash-4252    [003] ...1. 1651091299.936123: current_time <-notify_change
|            bash-4252    [003] ...1. 1651091299.936124: ktime_get_coarse_real_ts64 <-current_time
|            bash-4252    [003] ...1. 1651091299.936124: security_inode_setattr <-notify_change
|            bash-4252    [003] ...1. 1651091299.936124: selinux_inode_setattr <-security_inode_setattr
|            bash-4252    [003] ...1. 1651091299.936125: inode_has_perm <-selinux_inode_setattr
|/sys/kernel/debug/tracing # phc_ctl /dev/ptp0 get
|phc_ctl[760.604]: clock time is 1651091302.512977591 or Wed Apr 27 22:28:22 2022

Thanks for debugging it!

[1] - https://lore.kernel.org/all/20220427153339.16c33f75@gandalf.local.home/

Thanks,
Kurt

commit 81c4f2de420cc4ac08efc39e78ffd80e146bfbd7
Author: Kurt Kanzenbach <kurt@linutronix.de>
Date:   Wed Apr 27 21:59:58 2022 +0200

    timekeeping: Mark mono fast time accessors as notrace
    
    Mark the CLOCK_MONOTONIC fast time accessors as notrace. These functions are
    used in tracing to retrieve timestamps.
    
    Signed-off-by: Kurt Kanzenbach <kurt@linutronix.de>

diff --git a/kernel/time/timekeeping.c b/kernel/time/timekeeping.c
index 2c22023fbf5f..dddc37035215 100644
--- a/kernel/time/timekeeping.c
+++ b/kernel/time/timekeeping.c
@@ -482,7 +482,7 @@ static __always_inline u64 __ktime_get_fast_ns(struct tk_fast *tkf)
  * of the following timestamps. Callers need to be aware of that and
  * deal with it.
  */
-u64 ktime_get_mono_fast_ns(void)
+u64 notrace ktime_get_mono_fast_ns(void)
 {
        return __ktime_get_fast_ns(&tk_fast_mono);
 }
@@ -494,7 +494,7 @@ EXPORT_SYMBOL_GPL(ktime_get_mono_fast_ns);
  * Contrary to ktime_get_mono_fast_ns() this is always correct because the
  * conversion factor is not affected by NTP/PTP correction.
  */
-u64 ktime_get_raw_fast_ns(void)
+u64 notrace ktime_get_raw_fast_ns(void)
 {
        return __ktime_get_fast_ns(&tk_fast_raw);
 }