[BUG][next-20170606][bisected 411fe24e6b] WARNING: CPU: 10 PID: 0 at kernel/time/tick-sched.c:791

classic Classic list List threaded Threaded
3 messages Options
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

[BUG][next-20170606][bisected 411fe24e6b] WARNING: CPU: 10 PID: 0 at kernel/time/tick-sched.c:791

Abdul Haleem
Hi,

Test: Trinity (https://github.com/kernelslacker/trinity)
Machine : Power 8 PowerVM LPAR
Kernel : 4.12.0-rc4-next-20170606
gcc : version 5.2.1
config : attached

With commit (411fe24e6b : nohz: Fix collision between tick and other
hrtimers), a WARNING is seen while running trinity syscall fuzzer

In file kernel/time/tick-sched.c at line 791, a WARN_ON_ONCE is being
triggered from tick_nohz_stop_sched_tick function.

    /* Skip reprogram of event if its not changed */
    if (ts->tick_stopped && (expires == ts->next_tick)) {
        /* Sanity check: make sure clockevent is actually programmed */
        if (likely(dev->next_event <= ts->next_tick))
            goto out;

        WARN_ON_ONCE(1);
        printk_once("basemono: %llu ts->next_tick: %llu dev->next_event: %llu timer->active: %d timer->expires: %llu\n",
                basemono, ts->next_tick, dev->next_event,
                hrtimer_active(&ts->sched_timer), hrtimer_get_expires(&ts->sched_timer));
    }

Trace logs:
[22934.302780] ------------[ cut here ]------------
[22934.302787] WARNING: CPU: 10 PID: 0 at kernel/time/tick-sched.c:791
__tick_nohz_idle_enter+0x2e8/0x570
[22934.302788] Modules linked in: pseries_rng(E) rtc_generic(E)
vmx_crypto(E) autofs4(E) [last unloaded: torture]
[22934.302796] CPU: 10 PID: 0 Comm: swapper/10 Tainted: G      D W   E
4.12.0-rc4-next-20170606-autotest #1
[22934.302798] task: c000000777ddb800 task.stack: c000000777e50000
[22934.302799] NIP: c0000000001ac628 LR: c0000000001ac4b8 CTR:
c000000000025030
[22934.302801] REGS: c000000777e53740 TRAP: 0700   Tainted: G      D W
E    (4.12.0-rc4-next-20170606-autotest)
[22934.302802] MSR: 8000000000029033 <SF,EE,ME,IR,DR,RI,LE>
[22934.302808]   CR: 28002428  XER: 00000000
[22934.302809] CFAR: c0000000001ac514 SOFTE: 0
               GPR00: c0000000001ac4b8 c000000777e539c0 c000000001536c00
7fffffffffffffff
               GPR04: 0000000000000000 0000000000000240 c000000001576c00
c000000001401e10
               GPR08: 0000000000632690 000014dbda7cb800 7fffeb2425c050ff
0000000000000000
               GPR12: c000000000025030 c00000000e746900 c000000777e53f90
c000000777e4c080
               GPR16: c000000000eecf00 c000000000ed83e8 c000000777e4c000
c000000777e4c000
               GPR20: c000000001429b10 0000000000000001 0000000000000002
000014dbda7cb933
               GPR24: c00000077fd80400 0000000000000001 000014dbda3faf00
000000000000000a
               GPR28: c000000001571db8 000014dbda7cb862 000014dbda7cb800
c00000077fd91a10
[22934.302835] NIP [c0000000001ac628] __tick_nohz_idle_enter+0x2e8/0x570
[22934.302837] LR [c0000000001ac4b8] __tick_nohz_idle_enter+0x178/0x570
[22934.302838] Call Trace:
[22934.302840] [c000000777e539c0] [c0000000001ac4b8]
__tick_nohz_idle_enter+0x178/0x570 (unreliable)
[22934.302844] [c000000777e53a80] [c0000000000fc274] irq_exit+0xf4/0x120
[22934.302847] [c000000777e53aa0] [c0000000000258b4] timer_interrupt
+0xa4/0xe0
[22934.302851] [c000000777e53ad0] [c000000000008f54] decrementer_common
+0x114/0x120
[22934.302855] --- interrupt: 901 at snooze_loop+0x1b0/0x1f0
                   LR = snooze_loop+0x54/0x1f0
[22934.302857] [c000000777e53df0] [c0000000009ed1b4] cpuidle_enter_state
+0x174/0x460
[22934.302860] [c000000777e53e50] [c000000000157bd0] call_cpuidle
+0x70/0xd0
[22934.302863] [c000000777e53e90] [c0000000001580d0] do_idle+0x2b0/0x310
[22934.302866] [c000000777e53f00] [c000000000158358] cpu_startup_entry
+0x38/0x40
[22934.302869] [c000000777e53f30] [c000000000047d60] start_secondary
+0x340/0x390
[22934.302872] [c000000777e53f90] [c00000000000a880]
start_secondary_resume+0x10/0x14
[22934.302873] Instruction dump:
[22934.302874] 409efef0 3860ffff 78630040 4bfffee4 60000000 60420000
e93f0058 7fbe4800
[22934.302879] 409eff30 eaf80018 7fbeb800 409cff58 <0fe00000> 3ce20004
8927b740 2f890000
[22934.302884] ---[ end trace aad28e52ad829bbd ]---
[22934.302887] basemono: 22934492000000 ts->next_tick: 22934496000000
dev->next_event: 22934496000307 timer->active: 1 timer->expires:
22934496000000

--
Regard's

Abdul Haleem
IBM Linux Technology Centre



Tul-vm-config (190K) Download Attachment
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: [BUG][next-20170606][bisected 411fe24e6b] WARNING: CPU: 10 PID: 0 at kernel/time/tick-sched.c:791

Frederic Weisbecker-3
On Wed, Jun 07, 2017 at 12:56:53PM +0530, Abdul Haleem wrote:

> Hi,
>
> Test: Trinity (https://github.com/kernelslacker/trinity)
> Machine : Power 8 PowerVM LPAR
> Kernel : 4.12.0-rc4-next-20170606
> gcc : version 5.2.1
> config : attached
>
> With commit (411fe24e6b : nohz: Fix collision between tick and other
> hrtimers), a WARNING is seen while running trinity syscall fuzzer
>
> In file kernel/time/tick-sched.c at line 791, a WARN_ON_ONCE is being
> triggered from tick_nohz_stop_sched_tick function.
>
>     /* Skip reprogram of event if its not changed */
>     if (ts->tick_stopped && (expires == ts->next_tick)) {
>         /* Sanity check: make sure clockevent is actually programmed */
>         if (likely(dev->next_event <= ts->next_tick))
>             goto out;
>
>         WARN_ON_ONCE(1);
>         printk_once("basemono: %llu ts->next_tick: %llu dev->next_event: %llu timer->active: %d timer->expires: %llu\n",
>                 basemono, ts->next_tick, dev->next_event,
>                 hrtimer_active(&ts->sched_timer), hrtimer_get_expires(&ts->sched_timer));
>     }
>
> Trace logs:
> [22934.302780] ------------[ cut here ]------------
> [22934.302787] WARNING: CPU: 10 PID: 0 at kernel/time/tick-sched.c:791
> __tick_nohz_idle_enter+0x2e8/0x570

Hi Abdul,

Thanks for reporting. I've cooked a fix, any chance you could test it?

--
From f80041b5209aaf9d02ac25a29a248d0f214ba19f Mon Sep 17 00:00:00 2001
From: Frederic Weisbecker <[hidden email]>
Date: Thu, 8 Jun 2017 16:32:58 +0200
Subject: [PATCH] nohz: Fix spurious warning when hrtimer and clocksource get
 out of sync

The sanity check ensuring that the tick expiry cache (ts->next_tick)
is actually in sync with the hardware clock (dev->next_event) makes the
wrong assumption that the clock can't be programmed later than the
hrtimer deadline.

In fact the clock hardware can be programmed later on some conditions
such as:

    * The hrtimer deadline is already in the past.
    * The hrtimer deadline is earlier than the minimum delay supported
      by the hardware.

Such conditions can be met when we program the tick, for example if the
last jiffies update hasn't been seen by the current CPU yet, we may
program the hrtimer to a deadline that is earlier than ktime_get()
because last_jiffies_update is our timestamp base to compute the next
tick.

As a result, we can randomly observe such warning:

        WARNING: CPU: 5 PID: 0 at kernel/time/tick-sched.c:794 tick_nohz_stop_sched_tick kernel/time/tick-sched.c:791 [inline]
        Call Trace:
         tick_nohz_irq_exit
         tick_irq_exit
         irq_exit
         exiting_irq
         smp_call_function_interrupt
         smp_call_function_single_interrupt
         call_function_single_interrupt

Therefore, let's rather make sure that the tick expiry cache is sync'ed
with the tick hrtimer deadline, against which it is not supposed to
drift away. The clock hardware instead has its own will and can't be
used as a reliable comparison point.

Reported-by: Sasha Levin <[hidden email]>
Cc: Thomas Gleixner <[hidden email]>
Cc: Ingo Molnar <[hidden email]>
Cc: Peter Zijlstra <[hidden email]>
Cc: Rik van Riel <[hidden email]>
Cc: James Hartsock <[hidden email]>
Cc: Tim Wright <[hidden email]>
Signed-off-by: Frederic Weisbecker <[hidden email]>
---
 kernel/time/tick-sched.c | 7 +++++--
 1 file changed, 5 insertions(+), 2 deletions(-)

diff --git a/kernel/time/tick-sched.c b/kernel/time/tick-sched.c
index 9d31f1e..83c788e 100644
--- a/kernel/time/tick-sched.c
+++ b/kernel/time/tick-sched.c
@@ -768,7 +768,8 @@ static ktime_t tick_nohz_stop_sched_tick(struct tick_sched *ts,
  /* Skip reprogram of event if its not changed */
  if (ts->tick_stopped && (expires == ts->next_tick)) {
  /* Sanity check: make sure clockevent is actually programmed */
- if (likely(dev->next_event <= ts->next_tick))
+ if (tick == KTIME_MAX ||
+    ts->next_tick == hrtimer_get_expires(&ts->sched_timer))
  goto out;
 
  WARN_ON_ONCE(1);
@@ -806,8 +807,10 @@ static ktime_t tick_nohz_stop_sched_tick(struct tick_sched *ts,
  goto out;
  }
 
+ hrtimer_set_expires(&ts->sched_timer, tick);
+
  if (ts->nohz_mode == NOHZ_MODE_HIGHRES)
- hrtimer_start(&ts->sched_timer, tick, HRTIMER_MODE_ABS_PINNED);
+ hrtimer_start_expires(&ts->sched_timer, HRTIMER_MODE_ABS_PINNED);
  else
  tick_program_event(tick, 1);
 out:
--
2.7.4

Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: [BUG][next-20170606][bisected 411fe24e6b] WARNING: CPU: 10 PID: 0 at kernel/time/tick-sched.c:791

Abdul Haleem
On Fri, 2017-06-09 at 15:09 +0200, Frederic Weisbecker wrote:

> On Wed, Jun 07, 2017 at 12:56:53PM +0530, Abdul Haleem wrote:
> > Hi,
> >
> > Test: Trinity (https://github.com/kernelslacker/trinity)
> > Machine : Power 8 PowerVM LPAR
> > Kernel : 4.12.0-rc4-next-20170606
> > gcc : version 5.2.1
> > config : attached
> >
> > With commit (411fe24e6b : nohz: Fix collision between tick and other
> > hrtimers), a WARNING is seen while running trinity syscall fuzzer
> >
> > In file kernel/time/tick-sched.c at line 791, a WARN_ON_ONCE is being
> > triggered from tick_nohz_stop_sched_tick function.
> >
> >     /* Skip reprogram of event if its not changed */
> >     if (ts->tick_stopped && (expires == ts->next_tick)) {
> >         /* Sanity check: make sure clockevent is actually programmed */
> >         if (likely(dev->next_event <= ts->next_tick))
> >             goto out;
> >
> >         WARN_ON_ONCE(1);
> >         printk_once("basemono: %llu ts->next_tick: %llu dev->next_event: %llu timer->active: %d timer->expires: %llu\n",
> >                 basemono, ts->next_tick, dev->next_event,
> >                 hrtimer_active(&ts->sched_timer), hrtimer_get_expires(&ts->sched_timer));
> >     }
> >
> > Trace logs:
> > [22934.302780] ------------[ cut here ]------------
> > [22934.302787] WARNING: CPU: 10 PID: 0 at kernel/time/tick-sched.c:791
> > __tick_nohz_idle_enter+0x2e8/0x570
>
> Hi Abdul,
>
> Thanks for reporting. I've cooked a fix, any chance you could test it?

Hi Frederic,

Thanks for the fix. With given patch on 4.12.0-rc4-next-20170609, test
completed with no WARNINGS.

Reported-and-tested-by : Abdul Haleem <[hidden email]>

> --
> From f80041b5209aaf9d02ac25a29a248d0f214ba19f Mon Sep 17 00:00:00 2001
> From: Frederic Weisbecker <[hidden email]>
> Date: Thu, 8 Jun 2017 16:32:58 +0200
> Subject: [PATCH] nohz: Fix spurious warning when hrtimer and clocksource get
>  out of sync
>
> The sanity check ensuring that the tick expiry cache (ts->next_tick)
> is actually in sync with the hardware clock (dev->next_event) makes the
> wrong assumption that the clock can't be programmed later than the
> hrtimer deadline.
>
> In fact the clock hardware can be programmed later on some conditions
> such as:
>
>     * The hrtimer deadline is already in the past.
>     * The hrtimer deadline is earlier than the minimum delay supported
>       by the hardware.
>
> Such conditions can be met when we program the tick, for example if the
> last jiffies update hasn't been seen by the current CPU yet, we may
> program the hrtimer to a deadline that is earlier than ktime_get()
> because last_jiffies_update is our timestamp base to compute the next
> tick.
>
> As a result, we can randomly observe such warning:
>
> WARNING: CPU: 5 PID: 0 at kernel/time/tick-sched.c:794 tick_nohz_stop_sched_tick kernel/time/tick-sched.c:791 [inline]
> Call Trace:
> tick_nohz_irq_exit
> tick_irq_exit
> irq_exit
> exiting_irq
> smp_call_function_interrupt
> smp_call_function_single_interrupt
> call_function_single_interrupt
>
> Therefore, let's rather make sure that the tick expiry cache is sync'ed
> with the tick hrtimer deadline, against which it is not supposed to
> drift away. The clock hardware instead has its own will and can't be
> used as a reliable comparison point.
>
> Reported-by: Sasha Levin <[hidden email]>
> Cc: Thomas Gleixner <[hidden email]>
> Cc: Ingo Molnar <[hidden email]>
> Cc: Peter Zijlstra <[hidden email]>
> Cc: Rik van Riel <[hidden email]>
> Cc: James Hartsock <[hidden email]>
> Cc: Tim Wright <[hidden email]>
> Signed-off-by: Frederic Weisbecker <[hidden email]>
> ---
>  kernel/time/tick-sched.c | 7 +++++--
>  1 file changed, 5 insertions(+), 2 deletions(-)
>
> diff --git a/kernel/time/tick-sched.c b/kernel/time/tick-sched.c
> index 9d31f1e..83c788e 100644
> --- a/kernel/time/tick-sched.c
> +++ b/kernel/time/tick-sched.c
> @@ -768,7 +768,8 @@ static ktime_t tick_nohz_stop_sched_tick(struct tick_sched *ts,
>   /* Skip reprogram of event if its not changed */
>   if (ts->tick_stopped && (expires == ts->next_tick)) {
>   /* Sanity check: make sure clockevent is actually programmed */
> - if (likely(dev->next_event <= ts->next_tick))
> + if (tick == KTIME_MAX ||
> +    ts->next_tick == hrtimer_get_expires(&ts->sched_timer))
>   goto out;
>
>   WARN_ON_ONCE(1);
> @@ -806,8 +807,10 @@ static ktime_t tick_nohz_stop_sched_tick(struct tick_sched *ts,
>   goto out;
>   }
>
> + hrtimer_set_expires(&ts->sched_timer, tick);
> +
>   if (ts->nohz_mode == NOHZ_MODE_HIGHRES)
> - hrtimer_start(&ts->sched_timer, tick, HRTIMER_MODE_ABS_PINNED);
> + hrtimer_start_expires(&ts->sched_timer, HRTIMER_MODE_ABS_PINNED);
>   else
>   tick_program_event(tick, 1);
>  out:


--
Regard's

Abdul Haleem
IBM Linux Technology Centre



Loading...