lkml.org 
[lkml]   [2022]   [Apr]   [3]   [last100]   RSS Feed
Views: [wrap][no wrap]   [headers]  [forward] 
 
Messages in this thread
    Patch in this message
    /
    From
    SubjectRe: UML time-travel warning from __run_timers
    Date
    On Sun, Apr 03 2022 at 19:13, Johannes Berg wrote:
    > On Sun, 2022-04-03 at 18:18 +0200, Thomas Gleixner wrote:
    >> On Sat, Apr 02 2022 at 16:09, Johannes Berg wrote:
    > There was no timer. If there's ever a timer on this base (BASE_DEF) then
    > this doesn't happen.

    You said:

    >> > init_timer_cpu(0) base 0 clk=0xffff8ad0, next_expiry=0x13fff8acf
    >> > init_timer_cpu(0) base 1 clk=0xffff8ad0, next_expiry=0x13fff8acf

    which confused me. It's actually initialized to:

    base->clk + NEXT_TIMER_MAX_DELTA

    but that's fine and it is overwritten by every timer which is inserted
    to expire before that. So that's not an issue as the prandom timer is
    firing and rearmed.

    That would not happen if next_expiry would stay at 0x13fff8acf. The
    first one in your trace expires at 5339070200, i.e. 0x13e3bbef8, which
    is way before that.

    So that 0x13fff8acf thing is really a red herring.

    > Sure, but since we simulate ~50 days of uptime, that's a massive number
    > of events and lots of them are not there:

    Thanks for providing that. This does not give much of an hint. jiffies,
    base clock and clock monotonic advance as expected. The prandom timer
    seems to be the only timer which is armed here, but of course the trace
    does not go far enough back to be sure. OTOH, there is no timer canceled
    just before that which might trigger this. I suspect that's a base
    forward call missing and I have a nagging feeling where, but I'm not
    sure.

    Can you please apply the debug patch below and run with the same
    parameters as before?

    Thanks,

    tglx
    ---
    Hint: I tried to figure out how to use that time travel muck, but did
    not get to the point where I bothered to try myself. Might be
    either my incompetence or lack of documentation. Clearly the bug
    report lacks any hint how to reproduce that problem.
    ---

    --- a/include/trace/events/timer.h
    +++ b/include/trace/events/timer.h
    @@ -52,15 +52,19 @@ DEFINE_EVENT(timer_class, timer_init,
    TRACE_EVENT(timer_start,

    TP_PROTO(struct timer_list *timer,
    - unsigned long expires,
    - unsigned int flags),
    + unsigned long expires,
    + unsigned long bucket_expiry,
    + unsigned long next_expiry,
    + unsigned int flags),

    - TP_ARGS(timer, expires, flags),
    + TP_ARGS(timer, expires, bucket_expiry, next_expiry, flags),

    TP_STRUCT__entry(
    __field( void *, timer )
    __field( void *, function )
    __field( unsigned long, expires )
    + __field( unsigned long, bucket_expiry )
    + __field( unsigned long, next_expiry )
    __field( unsigned long, now )
    __field( unsigned int, flags )
    ),
    @@ -69,13 +73,16 @@ TRACE_EVENT(timer_start,
    __entry->timer = timer;
    __entry->function = timer->function;
    __entry->expires = expires;
    + __entry->bucket_expiry = bucket_expiry;
    + __entry->next_expiry = next_expiry;
    __entry->now = jiffies;
    __entry->flags = flags;
    ),

    - TP_printk("timer=%p function=%ps expires=%lu [timeout=%ld] cpu=%u idx=%u flags=%s",
    + TP_printk("timer=%p function=%ps expires=%lu [timeout=%ld] bucket_expiry=%lu next_expiry=%lu cpu=%u idx=%u flags=%s",
    __entry->timer, __entry->function, __entry->expires,
    (long)__entry->expires - __entry->now,
    + __entry->bucket_expiry, __entry->next_expiry,
    __entry->flags & TIMER_CPUMASK,
    __entry->flags >> TIMER_ARRAYSHIFT,
    decode_timer_flags(__entry->flags & TIMER_TRACE_FLAGMASK))
    --- a/kernel/time/timer.c
    +++ b/kernel/time/timer.c
    @@ -583,8 +583,6 @@ static void enqueue_timer(struct timer_b
    __set_bit(idx, base->pending_map);
    timer_set_idx(timer, idx);

    - trace_timer_start(timer, timer->expires, timer->flags);
    -
    /*
    * Check whether this is the new first expiring timer. The
    * effective expiry time of the timer is required here
    @@ -600,6 +598,7 @@ static void enqueue_timer(struct timer_b
    base->next_expiry_recalc = false;
    trigger_dyntick_cpu(base, timer);
    }
    + trace_timer_start(timer, timer->expires, bucket_expiry, base->next_expiry, timer->flags);
    }

    static void internal_add_timer(struct timer_base *base, struct timer_list *timer)
    @@ -893,6 +892,9 @@ static inline void forward_timer_base(st
    {
    unsigned long jnow = READ_ONCE(jiffies);

    + trace_printk("FWD: now=%lu clk=%lu next_expiry=%lu recalc=%d\n",
    + jnow, base->clk, base->next_expiry,
    + base->next_expiry_recalc);
    /*
    * No need to forward if we are close enough below jiffies.
    * Also while executing timers, base->clk is 1 offset ahead
    @@ -1710,6 +1712,7 @@ void timer_clear_idle(void)
    static inline void __run_timers(struct timer_base *base)
    {
    struct hlist_head heads[LVL_DEPTH];
    + bool confused = false;
    int levels;

    if (time_before(jiffies, base->next_expiry))
    @@ -1718,6 +1721,10 @@ static inline void __run_timers(struct t
    timer_base_lock_expiry(base);
    raw_spin_lock_irq(&base->lock);

    + trace_printk("RUN: now=%lu clk=%lu next_expiry=%lu recalc=%d\n",
    + jiffies, base->clk, base->next_expiry,
    + base->next_expiry_recalc);
    +
    while (time_after_eq(jiffies, base->clk) &&
    time_after_eq(jiffies, base->next_expiry)) {
    levels = collect_expired_timers(base, heads);
    @@ -1726,7 +1733,12 @@ static inline void __run_timers(struct t
    * timer at this clk is that all matching timers have been
    * dequeued.
    */
    - WARN_ON_ONCE(!levels && !base->next_expiry_recalc);
    + if (!levels && !base->next_expiry_recalc) {
    + trace_printk("WTH: now=%lu clk=%lu next_expiry=%lu recalc=%d\n",
    + jiffies, base->clk, base->next_expiry,
    + base->next_expiry_recalc);
    + confused = true;
    + }
    base->clk++;
    base->next_expiry = __next_timer_interrupt(base);

    @@ -1735,6 +1747,9 @@ static inline void __run_timers(struct t
    }
    raw_spin_unlock_irq(&base->lock);
    timer_base_unlock_expiry(base);
    +
    + if (confused)
    + panic("Confused");
    }

    /*


    \
     
     \ /
      Last update: 2022-04-03 21:51    [W:3.090 / U:0.492 seconds]
    ©2003-2020 Jasper Spaans|hosted at Digital Ocean and TransIP|Read the blog|Advertise on this site