Received-SPF: softfail (google.com: domain of transitioning linux-kernel-owner@vger.kernel.org does not designate 23.128.96.19 as permitted sender) client-ip=23.128.96.19;
Date:   Wed, 27 Apr 2022 11:27:59 -0400
From:   Steven Rostedt <rostedt@goodmis.org>
To:     Kurt Kanzenbach <kurt@linutronix.de>
Cc:     John Stultz <john.stultz@linaro.org>,
        Thomas Gleixner <tglx@linutronix.de>,
        Stephen Boyd <sboyd@kernel.org>,
        Ingo Molnar <mingo@redhat.com>,
        Jonathan Corbet <corbet@lwn.net>,
        Richard Cochran <richardcochran@gmail.com>,
        linux-doc@vger.kernel.org, linux-kernel@vger.kernel.org
Subject: Re: [PATCH v2 1/3] timekeeping: Introduce fast accessor to clock
 tai
Message-ID: <20220427112759.1cedda69@gandalf.local.home>
In-Reply-To: <87r15i9azg.fsf@kurt>
References: <20220414091805.89667-1-kurt@linutronix.de>
        <20220414091805.89667-2-kurt@linutronix.de>
        <20220426175338.3807ca4f@gandalf.local.home>
        <87r15i9azg.fsf@kurt>
MIME-Version: 1.0
Content-Type: text/plain; charset=US-ASCII
Content-Transfer-Encoding: 7bit
Precedence: bulk

On Wed, 27 Apr 2022 10:38:59 +0200
Kurt Kanzenbach <kurt@linutronix.de> 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