[<prev] [next>] [<thread-prev] [thread-next>] [day] [month] [year] [list]
Message-ID: <87pml2wasm.ffs@tglx>
Date: Wed, 27 Apr 2022 22:06:49 +0200
From: Thomas Gleixner <tglx@...utronix.de>
To: Steven Rostedt <rostedt@...dmis.org>,
Kurt Kanzenbach <kurt@...utronix.de>
Cc: John Stultz <john.stultz@...aro.org>,
Stephen Boyd <sboyd@...nel.org>,
Ingo Molnar <mingo@...hat.com>,
Jonathan Corbet <corbet@....net>,
Richard Cochran <richardcochran@...il.com>,
linux-doc@...r.kernel.org, linux-kernel@...r.kernel.org
Subject: Re: [PATCH v2 1/3] timekeeping: Introduce fast accessor to clock tai
On Wed, Apr 27 2022 at 11:27, Steven Rostedt wrote:
>> > 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
TAI offset after boot is somewhere in this region:
It's 16e9d5dca2e7ac57 here. Converted to ctime:
Wed Apr 27 20:58:02 2022
and that does not change after booting on the VM I'm testing. But then
ftrace suddenly throws this warning:
[ 456.444350] Delta way too big! 1152921504606861182
ts=1651087617720667106 before=498166113113805924
after=498166113113820130 write stamp=498166113113820130
I first set tai as trace clock and then enabled a trace point. It seems
the first hit on this trace point ended up there.
> That is, the last nibble either is 0 or 1, causing the change?
>
> 06e9c9df4afd3647
> 16e9c9df4afd3647
I added debug into ktime_get_tai_fast_ns() to emit a pr_warn() when
either the TAI offset or the result is less than 1 << 60.
That does not trigger, but ftrace still confuses itself....
There is some mumble about timestamps only requiring 59 bits and the
check which triggers the warning has:
if (unlikely(info->delta > (1ULL << 59))) {
So something cuts off bit 60 somewhere and then the whole thing goes
into confusion mode.
When I set wall time to something before 1985, it works.
ctime(0x06e9c9df4afd3647/1e9) = Mon Oct 14 16:19:54 1985
Haven't found where ftrace loses the upper bit, but it does so
somewhere.
Thanks,
tglx
Powered by blists - more mailing lists