On Tue Apr 26 2022, Steven Rostedt wrote:
> On Thu, 14 Apr 2022 11:18:03 +0200
> Kurt Kanzenbach <kurt@linutronix.de> wrote:
>
> I finally ran this series through my tests, and it has some issues.

Thanks!

[snip]

>> +/**
>> + * ktime_get_tai_fast_ns - NMI safe and fast access to tai clock.
>> + *
>> + * The same limitations as described for ktime_get_boot_fast_ns() apply. The
>> + * mono time and the TAI offset are not read atomically which may yield wrong
>> + * readouts. However, an update of the TAI offset is an rare event e.g., caused
>> + * by settime or adjtimex with an offset. The user of this function has to deal
>> + * with the possibility of wrong timestamps in post processing.
>> + */
>> +u64 notrace ktime_get_tai_fast_ns(void)
>> +{
>> +	struct timekeeper *tk = &tk_core.timekeeper;
>> +
>> +	return (ktime_get_mono_fast_ns() + ktime_to_ns(data_race(tk->offs_tai)));
>
> As you are using this for tracing, can you open code the
> ktime_get_mono_fast_ns(), otherwise we need to mark that function as
> notrace. Not to mention, this is a fast path and using the noinline of
> __ktime_get_fast_ns() should be less overhead.

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

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.

Thanks,
Kurt