On Wed, 27 Apr 2022 10:38:59 +0200 Kurt Kanzenbach <kurt@xxxxxxxxxxxxx> wrote: > Looking at the other functions used for tracing: > > - ktime_get_mono_fast_ns - no annotations > - ktime_get_raw_fast_ns - no annotations > - ktime_get_boot_fast_ns - notrace > - ktime_get_tai_fast_ns - notrace Yeah, all should be notrace. > > Seems a little bit inconsistent. > > > > > That said, I hit this too: > > > > less-5071 [000] d.h2. 498087876.351330: do_raw_spin_trylock <-_raw_spin_lock > > less-5071 [000] d.h4. 498087876.351334: ktime_get_mono_fast_ns <-ktime_get_tai_fast_ns > > less-5071 [000] d.h5. 498087876.351334: ktime_get_mono_fast_ns <-ktime_get_tai_fast_ns > > less-5071 [000] d.h3. 498087876.351334: rcu_read_lock_sched_held <-lock_acquired > > less-5071 [000] d.h5. 498087876.351337: ktime_get_mono_fast_ns <-ktime_get_tai_fast_ns > > kworker/u8:1-45 [003] d.h7. 1651009380.982749: ktime_get_mono_fast_ns <-ktime_get_tai_fast_ns > > kworker/u8:1-45 [003] d.h7. 1651009380.982749: ktime_get_mono_fast_ns <-ktime_get_tai_fast_ns > > kworker/u8:1-45 [003] d.h5. 1651009380.982749: rcu_read_lock_held_common <-rcu_read_lock_sched_held > > kworker/u8:1-45 [003] d.h7. 498087876.375905: ktime_get_mono_fast_ns <-ktime_get_tai_fast_ns > > kworker/u8:1-45 [003] d.h7. 498087876.375905: ktime_get_mono_fast_ns <-ktime_get_tai_fast_ns > > kworker/u8:1-45 [003] d.h5. 498087876.375905: update_cfs_group <-task_tick_fair > > kworker/u8:1-45 [003] d.h7. 498087876.375909: ktime_get_mono_fast_ns <-ktime_get_tai_fast_ns > > > > The clock seems to be toggling between 1651009380 and 498087876 causing the > > ftrace ring buffer to shutdown (it doesn't allow for time to go backwards). > > > > This is running on a 32 bit x86. > > Hm. The only problem is that the TAI offset may change. That should only > happen if the time is set or similar. For the TSN use case I've ran > ptp4l and phc2sys. phc2sys in the default configuration sets the offset > hard once and uses frequency adjustments from that point on. I didn't > observe any time jumps. Nevertheless, my test systems is based on > arm64. I'll do some testing on x86. I'm able to trigger this on x86 64bit too. One thing I noticed, is that the two numbers I have (from a different trace, but very similar to the above) $ printf "%llx\n" 498151194674148935 6e9c9df4afd3647 $ printf "%llx\n" 1651072699280995911 16e9c9df4afd3647 That is, the last nibble either is 0 or 1, causing the change? 06e9c9df4afd3647 16e9c9df4afd3647 The numbers are the same except for that last nibble. -- Steve
