next-20130627 breaks i.MX6 sabre sd UART console

next-20130627 breaks i.MX6 sabre sd UART console

[Stehle Vincent-B46079]

Hi,

FYI I remark that today's Linux next 'next-20130627' breaks i.MX6 sabre sd UART console with ARM config imx_v6_v7_defconfig.

This was working fine yesterday with 'next-20130626'.

Bisecting gave me this commit:

  064706514ec3fea740c2656e03c4f01f6a551ac4  clocksource: Add generic dummy timer driver

If I revert it I do indeed get the boot messages on the UART console again, but the kernel then crashes in wm8962_probe(). So there is more to find out...

Best regards,

V.

Re: next-20130627 breaks i.MX6 sabre sd UART console

[Thomas Gleixner]

On Thu, 27 Jun 2013, Stehle Vincent-B46079 wrote:

Cc'ed Mark and Stephen.

> FYI I remark that today's Linux next 'next-20130627' breaks i.MX6
> sabre sd UART console with ARM config imx_v6_v7_defconfig.
> This was working fine yesterday with 'next-20130626'.
> 
> Bisecting gave me this commit:
> 
>   064706514ec3fea740c2656e03c4f01f6a551ac4 clocksource: Add generic
> dummy timer driver
> 
> If I revert it I do indeed get the boot messages on the UART console
> again, but the kernel then crashes in wm8962_probe(). So there is
> more to find out...

Re: next-20130627 breaks i.MX6 sabre sd UART console

[Stephen Boyd]

On 06/28/13 05:09, Thomas Gleixner wrote:
> On Thu, 27 Jun 2013, Stehle Vincent-B46079 wrote:
>
> Cc'ed Mark and Stephen.
>
>> FYI I remark that today's Linux next 'next-20130627' breaks i.MX6
>> sabre sd UART console with ARM config imx_v6_v7_defconfig.
>> This was working fine yesterday with 'next-20130626'.
>>
>> Bisecting gave me this commit:
>>
>>   064706514ec3fea740c2656e03c4f01f6a551ac4 clocksource: Add generic
>> dummy timer driver
>>
>> If I revert it I do indeed get the boot messages on the UART console
>> again, but the kernel then crashes in wm8962_probe(). So there is
>> more to find out...



Do you have debug_ll support to get some serial logs? Also could you try
booting with maxcpus=1 on the kernel commandline? And it would be useful
to have the output of /proc/timer_list if you have it from a working
device. I believe you have a per-cpu TWD timer and a global imx-gpt? Can
you try this patch? (sorry about the whitespace damage)

----8<-----

diff --git a/arch/arm/mach-imx/time.c b/arch/arm/mach-imx/time.c
index fea9131..f05f1f1 100644
--- a/arch/arm/mach-imx/time.c
+++ b/arch/arm/mach-imx/time.c
@@ -267,7 +267,7 @@ static int __init mxc_clockevent_init(struct clk *timer_clk)
        if (timer_is_v2())
                clockevent_mxc.set_next_event = v2_set_next_event;
 
-       clockevent_mxc.cpumask = cpumask_of(0);
+       clockevent_mxc.cpumask = cpu_all_mask;
        clockevents_config_and_register(&clockevent_mxc,
                                        clk_get_rate(timer_clk),
                                        0xff, 0xfffffffe);

-- 
Qualcomm Innovation Center, Inc. is a member of Code Aurora Forum,
hosted by The Linux Foundation

RE: next-20130627 breaks i.MX6 sabre sd UART console

[Stehle Vincent-B46079]

From: linux-next-owner@vger.kernel.org [mailto:linux-next-owner@vger.kernel.org] On Behalf Of Stephen Boyd
(..)
> Do you have debug_ll support to get some serial logs?

Hi,

Thanks for your concern on the matter. You are right, there is debug_ll support for i.MX6. If I activate it for next-20130628 imx_v6_v7_defconfig, that only "buys" me one additional line, though:

  Uncompressing Linux... done, booting the kernel.

> Also could you try booting with maxcpus=1 on the kernel commandline?

Good idea; it goes much further with this one (until it crashes in wm8962_probe(), which is as far as I go when I revert 064706514ec3fea740c2656e03c4f01f6a551ac4).

> And it would be useful to have the output of /proc/timer_list if you have it from a working device.

Sure; I pasted it below.

> I believe you have a per-cpu TWD timer and a global imx-gpt?

I think you are right from what I see in /proc/interrupts.

> Can you try this patch? (sorry about the whitespace damage)

Sorry, this patch had no visible effect.

Best regards,

V.

--- /proc/timer_list ---
Timer List Version: v0.7
HRTIMER_MAX_CLOCK_BASES: 4
now at 104544862569 nsecs

cpu: 0
 clock 0:
  .base:       80fcc5a0
  .index:      0
  .resolution: 1 nsecs
  .get_time:   ktime_get
  .offset:     0 nsecs
active timers:
 #0: <80fcc720>, tick_sched_timer, S:01
 # expires at 104550000000-104550000000 nsecs [in 5138067 to 5138067 nsecs]
 #1: <bf869a98>, hrtimer_wakeup, S:01
 # expires at 108088808660-108093808657 nsecs [in 3543946727 to 3548946724 nsecs]
 #2: <bf27df28>, hrtimer_wakeup, S:01
 # expires at 152209022299-152209072299 nsecs [in 47664160366 to 47664210366 nsecs]
 #3: <bfb91910>, it_real_fn, S:01
 # expires at 389697029617-389697029617 nsecs [in 285152167684 to 285152167684 nsecs]
 #4: <bf305a98>, hrtimer_wakeup, S:01
 # expires at 86489728463860-86489828463860 nsecs [in 86385183601927 to 86385283601927 nsecs]
 clock 1:
  .base:       80fcc5d8
  .index:      1
  .resolution: 1 nsecs
  .get_time:   ktime_get_real
  .offset:     31109466222080 nsecs
active timers:
 clock 2:
  .base:       80fcc610
  .index:      2
  .resolution: 1 nsecs
  .get_time:   ktime_get_boottime
  .offset:     0 nsecs
active timers:
 clock 3:
  .base:       80fcc648
  .index:      3
  .resolution: 1 nsecs
  .get_time:   ktime_get_clocktai
  .offset:     31109466222080 nsecs
active timers:
  .expires_next   : 104550000000 nsecs
  .hres_active    : 1
  .nr_events      : 4632
  .nr_retries     : 0
  .nr_hangs       : 0
  .max_hang_time  : 0 nsecs
  .nohz_mode      : 2
  .last_tick      : 104530000000 nsecs
  .tick_stopped   : 0
  .idle_jiffies   : 4294947748
  .idle_calls     : 12180
  .idle_sleeps    : 1193
  .idle_entrytime : 104542811418 nsecs
  .idle_waketime  : 104531758281 nsecs
  .idle_exittime  : 104531841675 nsecs
  .idle_sleeptime : 81643279539 nsecs
  .iowait_sleeptime: 5577955342 nsecs
  .last_jiffies   : 4294947750
  .next_jiffies   : 4294947751
  .idle_expires   : 104560000000 nsecs
jiffies: 4294947750

Tick Device: mode:     1
Broadcast device
Clock Event Device: <NULL>
tick_broadcast_mask: 00000000
tick_broadcast_oneshot_mask: 00000000

Tick Device: mode:     1
Per CPU device: 0
Clock Event Device: mxc_timer1
 max_delta_ns:   65075261923
 min_delta_ns:   3863
 mult:           141733921
 shift:          31
 mode:           3
 next_event:     104550000000 nsecs
 set_next_event: v2_set_next_event
 set_mode:       mxc_set_mode
 event_handler:  hrtimer_interrupt
 retries:        0

Re: next-20130627 breaks i.MX6 sabre sd UART console

[Stephen Boyd]

On 06/28/13 09:58, Stehle Vincent-B46079 wrote:
> From: linux-next-owner@vger.kernel.org [mailto:linux-next-owner@vger.kernel.org] On Behalf Of Stephen Boyd
> (..)
>> Do you have debug_ll support to get some serial logs?
> Hi,
>
> Thanks for your concern on the matter. You are right, there is debug_ll support for i.MX6. If I activate it for next-20130628 imx_v6_v7_defconfig, that only "buys" me one additional line, though:
>
>   Uncompressing Linux... done, booting the kernel.

Oh and also add earlyprintk to the command line and enable the
earlyprintk config. It should buy you some more lines.

>
>> Also could you try booting with maxcpus=1 on the kernel commandline?
> Good idea; it goes much further with this one (until it crashes in wm8962_probe(), which is as far as I go when I revert 064706514ec3fea740c2656e03c4f01f6a551ac4).

Interesting. Thanks for the test.

>
>> And it would be useful to have the output of /proc/timer_list if you have it from a working device.
> Sure; I pasted it below.

Is this an SMP capable device? What devicetree blob are you using?

>
>> I believe you have a per-cpu TWD timer and a global imx-gpt?
> I think you are right from what I see in /proc/interrupts.

Well oddly I don't see any twd in the timer list but that may be because
you're not running more than one CPU? It would be good to get the output
when you run SMP if it has that support.

-- 
Qualcomm Innovation Center, Inc. is a member of Code Aurora Forum,
hosted by The Linux Foundation

Re: next-20130627 breaks i.MX6 sabre sd UART console

[Stephen Boyd]

On 06/28, Stephen Boyd wrote:
> On 06/28/13 09:58, Stehle Vincent-B46079 wrote:
> > From: linux-next-owner@vger.kernel.org [mailto:linux-next-owner@vger.kernel.org] On Behalf Of Stephen Boyd
> > (..)
> >> Do you have debug_ll support to get some serial logs?
> > Hi,
> >
> > Thanks for your concern on the matter. You are right, there is debug_ll support for i.MX6. If I activate it for next-20130628 imx_v6_v7_defconfig, that only "buys" me one additional line, though:
> >
> >   Uncompressing Linux... done, booting the kernel.
> 
> Oh and also add earlyprintk to the command line and enable the
> earlyprintk config. It should buy you some more lines.
> 
> >
> >> Also could you try booting with maxcpus=1 on the kernel commandline?
> > Good idea; it goes much further with this one (until it crashes in wm8962_probe(), which is as far as I go when I revert 064706514ec3fea740c2656e03c4f01f6a551ac4).
> 
> Interesting. Thanks for the test.
> 
> >
> >> And it would be useful to have the output of /proc/timer_list if you have it from a working device.
> > Sure; I pasted it below.
> 
> Is this an SMP capable device? What devicetree blob are you using?
> 
> >
> >> I believe you have a per-cpu TWD timer and a global imx-gpt?
> > I think you are right from what I see in /proc/interrupts.
> 
> Well oddly I don't see any twd in the timer list but that may be because
> you're not running more than one CPU? It would be good to get the output
> when you run SMP if it has that support.
> 

I tried to recreate this probelm an an smp vexpress qemu and I
couldn't do it. This is with next-20130628. If you can get
debug_ll and earlyprinkt working it would be useful if you can
apply the attached patch and give back the logs. I'm confused how
the dummy timers are causing problems.

diff --git a/kernel/time/tick-broadcast.c b/kernel/time/tick-broadcast.c
index 9d96a54..3795c9c 100644
--- a/kernel/time/tick-broadcast.c
+++ b/kernel/time/tick-broadcast.c
@@ -92,6 +92,8 @@ void tick_install_broadcast_device(struct clock_event_device *dev)
 	if (!try_module_get(dev->owner))
 		return;
 
+	pr_info("%s is now the broadcast\n", dev->name);
+
 	clockevents_exchange_device(cur, dev);
 	if (cur)
 		cur->event_handler = clockevents_handle_noop;
diff --git a/kernel/time/tick-common.c b/kernel/time/tick-common.c
index edd45f6..24548aa 100644
--- a/kernel/time/tick-common.c
+++ b/kernel/time/tick-common.c
@@ -275,6 +275,8 @@ void tick_check_new_device(struct clock_event_device *newdev)
 	struct tick_device *td;
 	int cpu;
 
+	pr_info("Checking %s\n", newdev->name);
+
 	cpu = smp_processor_id();
 	if (!cpumask_test_cpu(cpu, newdev->cpumask))
 		goto out_bc;
@@ -286,10 +288,14 @@ void tick_check_new_device(struct clock_event_device *newdev)
 	if (!tick_check_percpu(curdev, newdev, cpu))
 		goto out_bc;
 
+	pr_info("%d: %s is per-cpu\n", cpu, newdev->name);
+
 	/* Preference decision */
 	if (!tick_check_preferred(curdev, newdev))
 		goto out_bc;
 
+	pr_info("%d: %s is preferred\n", cpu, newdev->name);
+
 	if (!try_module_get(newdev->owner))
 		return;
 
@@ -312,6 +318,7 @@ out_bc:
 	/*
 	 * Can the new device be used as a broadcast device ?
 	 */
+	pr_info("%d: %s is trying broadcast\n", cpu, newdev->name);
 	tick_install_broadcast_device(newdev);
 }
 

-- 
Qualcomm Innovation Center, Inc. is a member of Code Aurora Forum,
hosted by The Linux Foundation

Re: next-20130627 breaks i.MX6 sabre sd UART console

[Mark Rutland]

On Sat, Jun 29, 2013 at 03:07:38AM +0100, Stephen Boyd wrote:
> On 06/28, Stephen Boyd wrote:
> > On 06/28/13 09:58, Stehle Vincent-B46079 wrote:
> > > From: linux-next-owner@vger.kernel.org [mailto:linux-next-owner@vger.kernel.org] On Behalf Of Stephen Boyd
> > > (..)
> > >> Do you have debug_ll support to get some serial logs?
> > > Hi,
> > >
> > > Thanks for your concern on the matter. You are right, there is debug_ll support for i.MX6. If I activate it for next-20130628 imx_v6_v7_defconfig, that only "buys" me one additional line, though:
> > >
> > >   Uncompressing Linux... done, booting the kernel.
> > 
> > Oh and also add earlyprintk to the command line and enable the
> > earlyprintk config. It should buy you some more lines.
> > 
> > >
> > >> Also could you try booting with maxcpus=1 on the kernel commandline?
> > > Good idea; it goes much further with this one (until it crashes in wm8962_probe(), which is as far as I go when I revert 064706514ec3fea740c2656e03c4f01f6a551ac4).
> > 
> > Interesting. Thanks for the test.
> > 
> > >
> > >> And it would be useful to have the output of /proc/timer_list if you have it from a working device.
> > > Sure; I pasted it below.
> > 
> > Is this an SMP capable device? What devicetree blob are you using?
> > 
> > >
> > >> I believe you have a per-cpu TWD timer and a global imx-gpt?
> > > I think you are right from what I see in /proc/interrupts.
> > 
> > Well oddly I don't see any twd in the timer list but that may be because
> > you're not running more than one CPU? It would be good to get the output
> > when you run SMP if it has that support.
> > 
> 
> I tried to recreate this probelm an an smp vexpress qemu and I
> couldn't do it. This is with next-20130628. If you can get
> debug_ll and earlyprinkt working it would be useful if you can
> apply the attached patch and give back the logs. I'm confused how
> the dummy timers are causing problems.

Similarly I couldn't reproduce the issue on a physical A9x4 coretile
with next-20130627. In case there's some weird interaction with the
imx-gpt registration, I tried dropping the rating on the sp804 down to
200 to match, and also removed CLOCKEVT_FEAT_PERIODIC from its features,
but was still able to get to userspace.

If I've followed the code correctly, I see mxc_timer_init is called from
the imx6q_clocks_init, which is marked with CLK_OF_DECLARE. I had a
suspicion that there was an ordering issue that we were somehow
irritating, but given booting with one CPU worked, that doesn't seem to
be the case. On me A9x4. I can't move the sp804 to CLK_OF_INIT to check
as I cannot guarantee I'll have the requisite clocks.

I'm also left scratching my head on this one. A dmesg and timer list
from a working SMP boot would be useful.

Thanks,
Mark.

> 
> diff --git a/kernel/time/tick-broadcast.c b/kernel/time/tick-broadcast.c
> index 9d96a54..3795c9c 100644
> --- a/kernel/time/tick-broadcast.c
> +++ b/kernel/time/tick-broadcast.c
> @@ -92,6 +92,8 @@ void tick_install_broadcast_device(struct clock_event_device *dev)
>  	if (!try_module_get(dev->owner))
>  		return;
>  
> +	pr_info("%s is now the broadcast\n", dev->name);
> +
>  	clockevents_exchange_device(cur, dev);
>  	if (cur)
>  		cur->event_handler = clockevents_handle_noop;
> diff --git a/kernel/time/tick-common.c b/kernel/time/tick-common.c
> index edd45f6..24548aa 100644
> --- a/kernel/time/tick-common.c
> +++ b/kernel/time/tick-common.c
> @@ -275,6 +275,8 @@ void tick_check_new_device(struct clock_event_device *newdev)
>  	struct tick_device *td;
>  	int cpu;
>  
> +	pr_info("Checking %s\n", newdev->name);
> +
>  	cpu = smp_processor_id();
>  	if (!cpumask_test_cpu(cpu, newdev->cpumask))
>  		goto out_bc;
> @@ -286,10 +288,14 @@ void tick_check_new_device(struct clock_event_device *newdev)
>  	if (!tick_check_percpu(curdev, newdev, cpu))
>  		goto out_bc;
>  
> +	pr_info("%d: %s is per-cpu\n", cpu, newdev->name);
> +
>  	/* Preference decision */
>  	if (!tick_check_preferred(curdev, newdev))
>  		goto out_bc;
>  
> +	pr_info("%d: %s is preferred\n", cpu, newdev->name);
> +
>  	if (!try_module_get(newdev->owner))
>  		return;
>  
> @@ -312,6 +318,7 @@ out_bc:
>  	/*
>  	 * Can the new device be used as a broadcast device ?
>  	 */
> +	pr_info("%d: %s is trying broadcast\n", cpu, newdev->name);
>  	tick_install_broadcast_device(newdev);
>  }
>  
> 
> -- 
> Qualcomm Innovation Center, Inc. is a member of Code Aurora Forum,
> hosted by The Linux Foundation
> 

RE: next-20130627 breaks i.MX6 sabre sd UART console

[Stehle Vincent-B46079]

From: Stephen Boyd [mailto:sboyd@codeaurora.org] 
> (..) Is this an SMP capable device? What devicetree blob are you using?

Yes, this is an i.MX6 quad. I boot with imx6q-sabresd.dtb

> (..) Well oddly I don't see any twd in the timer list
> but that may be because you're not running more than one CPU?
> It would be good to get the output when you run SMP if it has that support.

Now that you mention it I see that mainline v3.10 boots with only one CPU. So I took next-20130625 instead, which does boot in SMP, and I captured /proc/timer_list and /proc/interrupts below.

> (..) If you can get debug_ll and earlyprinkt working it would be useful
> if you can apply the attached patch and give back the logs.

Sure; it worked, thanks. I pasted the full boot log below. There are messages about clockevents_program_event(), it seems.

Best regards,

V.

--- /proc/timer_list ---

Timer List Version: v0.7
HRTIMER_MAX_CLOCK_BASES: 4
now at 67484354137 nsecs

cpu: 0
 clock 0:
  .base:       80fa6620
  .index:      0
  .resolution: 1 nsecs
  .get_time:   ktime_get
  .offset:     0 nsecs
active timers:
 #0: <80fa68f8>, tick_sched_timer, S:01
 # expires at 67490000000-67490000000 nsecs [in 5646514 to 5646514 nsecs]
 #1: <bf875a90>, hrtimer_wakeup, S:01
 # expires at 68540821093-68545821090 nsecs [in 1056467607 to 1061467604 nsecs]
 #2: <bef37f28>, hrtimer_wakeup, S:01
 # expires at 70726814442-70726864442 nsecs [in 3242460956 to 3242510956 nsecs]
 #3: <bf0dff28>, hrtimer_wakeup, S:01
 # expires at 90990432538-90990482538 nsecs [in 23506079052 to 23506129052 nsecs]
 #4: <bed49a90>, hrtimer_wakeup, S:01
 # expires at 86430225655326-86430325655326 nsecs [in 86362741301840 to 86362841301840 nsecs]
 clock 1:
  .base:       80fa6658
  .index:      1
  .resolution: 1 nsecs
  .get_time:   ktime_get_real
  .offset:     9030273192973 nsecs
active timers:
 clock 2:
  .base:       80fa6690
  .index:      2
  .resolution: 1 nsecs
  .get_time:   ktime_get_boottime
  .offset:     0 nsecs
active timers:
 clock 3:
  .base:       80fa66c8
  .index:      3
  .resolution: 1 nsecs
  .get_time:   ktime_get_clocktai
  .offset:     9030273192973 nsecs
active timers:
  .expires_next   : 67490000000 nsecs
  .hres_active    : 1
  .nr_events      : 2441
  .nr_retries     : 0
  .nr_hangs       : 0
  .max_hang_time  : 0 nsecs
  .nohz_mode      : 2
  .last_tick      : 67480000000 nsecs
  .tick_stopped   : 0
  .idle_jiffies   : 4294944043
  .idle_calls     : 13840
  .idle_sleeps    : 1049
  .idle_entrytime : 67482221744 nsecs
  .idle_waketime  : 67474377895 nsecs
  .idle_exittime  : 67474461274 nsecs
  .idle_sleeptime : 52815293619 nsecs
  .iowait_sleeptime: 2416282884 nsecs
  .last_jiffies   : 4294944044
  .next_jiffies   : 4294944045
  .idle_expires   : 67510000000 nsecs
jiffies: 4294944044

cpu: 1
 clock 0:
  .base:       80fae620
  .index:      0
  .resolution: 1 nsecs
  .get_time:   ktime_get
  .offset:     0 nsecs
active timers:
 #0: <80fae8f8>, tick_sched_timer, S:01
 # expires at 67490000000-67490000000 nsecs [in 5646514 to 5646514 nsecs]
 clock 1:
  .base:       80fae658
  .index:      1
  .resolution: 1 nsecs
  .get_time:   ktime_get_real
  .offset:     9030273192973 nsecs
active timers:
 clock 2:
  .base:       80fae690
  .index:      2
  .resolution: 1 nsecs
  .get_time:   ktime_get_boottime
  .offset:     0 nsecs
active timers:
 clock 3:
  .base:       80fae6c8
  .index:      3
  .resolution: 1 nsecs
  .get_time:   ktime_get_clocktai
  .offset:     9030273192973 nsecs
active timers:
  .expires_next   : 67490000000 nsecs
  .hres_active    : 1
  .nr_events      : 1297
  .nr_retries     : 0
  .nr_hangs       : 0
  .max_hang_time  : 0 nsecs
  .nohz_mode      : 2
  .last_tick      : 67480000000 nsecs
  .tick_stopped   : 0
  .idle_jiffies   : 4294944043
  .idle_calls     : 4804
  .idle_sleeps    : 956
  .idle_entrytime : 67480050107 nsecs
  .idle_waketime  : 67475562153 nsecs
  .idle_exittime  : 67475569865 nsecs
  .idle_sleeptime : 63549212250 nsecs
  .iowait_sleeptime: 152457798 nsecs
  .last_jiffies   : 4294944044
  .next_jiffies   : 4294944045
  .idle_expires   : 92808680164 nsecs
jiffies: 4294944044

cpu: 2
 clock 0:
  .base:       80fb6620
  .index:      0
  .resolution: 1 nsecs
  .get_time:   ktime_get
  .offset:     0 nsecs
active timers:
 #0: <80fb68f8>, tick_sched_timer, S:01
 # expires at 67640000000-67640000000 nsecs [in 155646514 to 155646514 nsecs]
 clock 1:
  .base:       80fb6658
  .index:      1
  .resolution: 1 nsecs
  .get_time:   ktime_get_real
  .offset:     9030273192973 nsecs
active timers:
 clock 2:
  .base:       80fb6690
  .index:      2
  .resolution: 1 nsecs
  .get_time:   ktime_get_boottime
  .offset:     0 nsecs
active timers:
 clock 3:
  .base:       80fb66c8
  .index:      3
  .resolution: 1 nsecs
  .get_time:   ktime_get_clocktai
  .offset:     9030273192973 nsecs
active timers:
  .expires_next   : 67640000000 nsecs
  .hres_active    : 1
  .nr_events      : 1350
  .nr_retries     : 0
  .nr_hangs       : 0
  .max_hang_time  : 0 nsecs
  .nohz_mode      : 2
  .last_tick      : 67450000000 nsecs
  .tick_stopped   : 1
  .idle_jiffies   : 4294944040
  .idle_calls     : 2712
  .idle_sleeps    : 446
  .idle_entrytime : 67440072774 nsecs
  .idle_waketime  : 67440003456 nsecs
  .idle_exittime  : 67440042425 nsecs
  .idle_sleeptime : 64448445338 nsecs
  .iowait_sleeptime: 201545335 nsecs
  .last_jiffies   : 4294944040
  .next_jiffies   : 4294944060
  .idle_expires   : 67640000000 nsecs
jiffies: 4294944044

cpu: 3
 clock 0:
  .base:       80fbe620
  .index:      0
  .resolution: 1 nsecs
  .get_time:   ktime_get
  .offset:     0 nsecs
active timers:
 #0: <80fbe8f8>, tick_sched_timer, S:01
 # expires at 67870000000-67870000000 nsecs [in 385646514 to 385646514 nsecs]
 clock 1:
  .base:       80fbe658
  .index:      1
  .resolution: 1 nsecs
  .get_time:   ktime_get_real
  .offset:     9030273192973 nsecs
active timers:
 clock 2:
  .base:       80fbe690
  .index:      2
  .resolution: 1 nsecs
  .get_time:   ktime_get_boottime
  .offset:     0 nsecs
active timers:
 clock 3:
  .base:       80fbe6c8
  .index:      3
  .resolution: 1 nsecs
  .get_time:   ktime_get_clocktai
  .offset:     9030273192973 nsecs
active timers:
  .expires_next   : 67870000000 nsecs
  .hres_active    : 1
  .nr_events      : 928
  .nr_retries     : 0
  .nr_hangs       : 0
  .max_hang_time  : 0 nsecs
  .nohz_mode      : 2
  .last_tick      : 66880000000 nsecs
  .tick_stopped   : 1
  .idle_jiffies   : 4294943983
  .idle_calls     : 2050
  .idle_sleeps    : 176
  .idle_entrytime : 66870068456 nsecs
  .idle_waketime  : 66870003047 nsecs
  .idle_exittime  : 66870041956 nsecs
  .idle_sleeptime : 64340076917 nsecs
  .iowait_sleeptime: 67903365 nsecs
  .last_jiffies   : 4294943983
  .next_jiffies   : 4294944083
  .idle_expires   : 67870000000 nsecs
jiffies: 4294944044

Tick Device: mode:     1
Broadcast device
Clock Event Device: mxc_timer1
 max_delta_ns:   65075261923
 min_delta_ns:   3863
 mult:           141733921
 shift:          31
 mode:           1
 next_event:     9223372036854775807 nsecs
 set_next_event: v2_set_next_event
 set_mode:       mxc_set_mode
 event_handler:  tick_handle_oneshot_broadcast
 retries:        0

tick_broadcast_mask: 00000000
tick_broadcast_oneshot_mask: 00000000

Tick Device: mode:     1
Per CPU device: 0
Clock Event Device: local_timer
 max_delta_ns:   10845877002
 min_delta_ns:   1000
 mult:           850403525
 shift:          31
 mode:           3
 next_event:     67490000000 nsecs
 set_next_event: twd_set_next_event
 set_mode:       twd_set_mode
 event_handler:  hrtimer_interrupt
 retries:        0

Tick Device: mode:     1
Per CPU device: 1
Clock Event Device: local_timer
 max_delta_ns:   10845877002
 min_delta_ns:   1000
 mult:           850403525
 shift:          31
 mode:           3
 next_event:     67490000000 nsecs
 set_next_event: twd_set_next_event
 set_mode:       twd_set_mode
 event_handler:  hrtimer_interrupt
 retries:        0

Tick Device: mode:     1
Per CPU device: 2
Clock Event Device: local_timer
 max_delta_ns:   10845877002
 min_delta_ns:   1000
 mult:           850403525
 shift:          31
 mode:           3
 next_event:     67840000000 nsecs
 set_next_event: twd_set_next_event
 set_mode:       twd_set_mode
 event_handler:  hrtimer_interrupt
 retries:        0

Tick Device: mode:     1
Per CPU device: 3
Clock Event Device: local_timer
 max_delta_ns:   10845877002
 min_delta_ns:   1000
 mult:           850403525
 shift:          31
 mode:           3
 next_event:     67870000000 nsecs
 set_next_event: twd_set_next_event
 set_mode:       twd_set_mode
 event_handler:  hrtimer_interrupt
 retries:        0

--- /proc/interrupts ---

           CPU0       CPU1       CPU2       CPU3
 29:       2667       1326       1719       1004       GIC  29  twd
 34:          0          0          0          0       GIC  34  sdma
 51:          0          0          0          0       GIC  51  rtc alarm
 55:          0          0          0          0       GIC  55  mmc0
 56:        769          0          0          0       GIC  56  mmc1
 58:        647          0          0          0       GIC  58  IMX-uart
 63:          2          0          0          0       GIC  63  spi_imx
 68:          0          0          0          0       GIC  68  21a0000.i2c
 72:          0          0          0          0       GIC  72  ci_hdrc_imx
 75:          0          0          0          0       GIC  75  ci_hdrc_imx
 87:          9          0          0          0       GIC  87  i.MX Timer Tick
150:      33007          0          0          0       GIC 150  2188000.ethernet
151:          0          0          0          0       GIC 151  2188000.ethernet
164:          0          0          0          0  gpio-mxc   4  Volume Up
165:          0          0          0          0  gpio-mxc   5  Volume Down
192:          0          0          0          0  gpio-mxc   0  2198000.usdhc cd
194:          0          0          0          0  gpio-mxc   2  2194000.usdhc cd
384:          0          0          0          0       IPU  23  imx_drm
385:          0          0          0          0       IPU  28  imx_drm
386:          0          0          0          0       IPU  23  imx_drm
387:          0          0          0          0       IPU  28  imx_drm
IPI0:          0          0          0          0  CPU wakeup interrupts
IPI1:          0          0          0          0  Timer broadcast interrupts
IPI2:       1566       4556       2282       1940  Rescheduling interrupts
IPI3:          3          5          2          5  Function call interrupts
IPI4:          0          0          0          0  Single function call interrupts
IPI5:          0          0          0          0  CPU stop interrupts
Err:          0

--- Boot log with debug_ll, earlyprintk and patch 2 ---

U-Boot 2013.07-rc1-00209-g35186c8 (Jun 28 2013 - 18:22:00)

CPU:   Freescale i.MX6Q rev1.2 at 792 MHz
Reset cause: POR
Board: MX6Q-SabreSD
DRAM:  1 GiB
MMC:   FSL_SDHC: 0, FSL_SDHC: 1, FSL_SDHC: 2
In:    serial
Out:   serial
Err:   serial
Net:   FEC [PRIME]
Hit any key to stop autoboot:  0
Booting from net ...
FEC Waiting for PHY auto negotiation to complete.... done
BOOTP broadcast 1
DHCP client bound to address 192.168.111.121
Using FEC device
TFTP from server 192.168.111.1; our IP address is 192.168.111.121
Filename 'uImage'.
Load address: 0x12000000
Loading: #################################################################
         #################################################################
         #################################################################
         #################################################################
         #####################################
         4.2 MiB/s
done
Bytes transferred = 4359040 (428380 hex)
BOOTP broadcast 1
DHCP client bound to address 192.168.111.121
Using FEC device
TFTP from server 192.168.111.1; our IP address is 192.168.111.121
Filename 'imx6q-sabresd.dtb'.
Load address: 0x11000000
Loading: ##
         2.8 MiB/s
done
Bytes transferred = 26879 (68ff hex)
## Booting kernel from Legacy Image at 12000000 ...
   Image Name:   Linux-3.10.0-next-20130701+
   Image Type:   ARM Linux Kernel Image (uncompressed)
   Data Size:    4358976 Bytes = 4.2 MiB
   Load Address: 10008000
   Entry Point:  10008000
   Verifying Checksum ... OK
## Flattened Device Tree blob at 11000000
   Booting using the fdt blob at 0x11000000
   Loading Kernel Image ... OK
OK
   Using Device Tree in place at 11000000, end 110098fe

Starting kernel ...

Uncompressing Linux... done, booting the kernel.
Booting Linux on physical CPU 0x0
Linux version 3.10.0-next-20130701+ (vstehle@debian) (gcc version 4.7.2 (Debian 4.7.2-5) ) #1 SMP Mon Jul 1 11:52:44 CEST 2013
CPU: ARMv7 Processor [412fc09a] revision 10 (ARMv7), cr=10c53c7d
CPU: PIPT / VIPT nonaliasing data cache, VIPT aliasing instruction cache
Machine: Freescale i.MX6 Quad/DualLite (Device Tree), model: Freescale i.MX6 Quad SABRE Smart Device Board
bootconsole [earlycon0] enabled
Memory policy: ECC disabled, Data cache writealloc
On node 0 totalpages: 262144
free_area_init_node: node 0, pgdat 8078bd00, node_mem_map 807ea000
  Normal zone: 2048 pages used for memmap
  Normal zone: 0 pages reserved
  Normal zone: 262144 pages, LIFO batch:31
PERCPU: Embedded 7 pages/cpu @81007000 s7680 r8192 d12800 u32768
pcpu-alloc: s7680 r8192 d12800 u32768 alloc=8*4096
pcpu-alloc: [0] 0 [0] 1 [0] 2 [0] 3
Built 1 zonelists in Zone order, mobility grouping on.  Total pages: 260096
Kernel command line: console=ttymxc0,115200 root=/dev/nfs ip=dhcp nfsroot=192.168.111.1:/tftpboot/debian,v3,tcp rw earlyprintk debug
PID hash table entries: 4096 (order: 2, 16384 bytes)
Dentry cache hash table entries: 131072 (order: 7, 524288 bytes)
Inode-cache hash table entries: 65536 (order: 6, 262144 bytes)
Memory: 1031272K/1048576K available (5380K kernel code, 273K rwdata, 1736K rodata, 303K init, 373K bss, 17304K reserved)
Virtual kernel memory layout:
    vector  : 0xffff0000 - 0xffff1000   (   4 kB)
    fixmap  : 0xfff00000 - 0xfffe0000   ( 896 kB)
    vmalloc : 0xc0800000 - 0xff000000   (1000 MB)
    lowmem  : 0x80000000 - 0xc0000000   (1024 MB)
    modules : 0x7f000000 - 0x80000000   (  16 MB)
      .text : 0x80008000 - 0x806fb4e4   (7118 kB)
      .init : 0x806fc000 - 0x80747e00   ( 304 kB)
      .data : 0x80748000 - 0x8078c540   ( 274 kB)
       .bss : 0x8078c540 - 0x807e9bb4   ( 374 kB)
SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1
Hierarchical RCU implementation.
NR_IRQS:16 nr_irqs:16 16
sched_clock: 32 bits at 66MHz, resolution 15ns, wraps every 65075ms
Checking mxc_timer1
0: mxc_timer1 is per-cpu
0: mxc_timer1 is preferred
CPU identified as i.MX6Q, silicon rev 1.2
Console: colour dummy device 80x30
Calibrating delay loop... 1581.05 BogoMIPS (lpj=7905280)
pid_max: default: 32768 minimum: 301
Mount-cache hash table entries: 512
CPU: Testing write buffer coherency: ok
CPU0: thread -1, cpu 0, socket 0, mpidr 80000000
Checking local_timer
0: local_timer is per-cpu
0: local_timer is preferred
Checking mxc_timer1
0: mxc_timer1 is per-cpu
0: mxc_timer1 is trying broadcast
mxc_timer1 is now the broadcast
Setting up static identity map for 0x8051be70 - 0x8051bee0
Checking dummy_timer
0: dummy_timer is per-cpu
0: dummy_timer is trying broadcast
CPU1: Booted secondary processor
Checking dummy_timer
1: dummy_timer is per-cpu
1: dummy_timer is preferred
CPU1: thread -1, cpu 1, socket 0, mpidr 80000001
Checking local_timer
CPU2: Booted secondary processor
1: local_timer is per-cpu
1: local_timer is preferred
Checking dummy_timer
1: dummy_timer is per-cpu
1: dummy_timer is trying broadcast
Checking dummy_timer
2: dummy_timer is per-cpu
2: dummy_timer is preferred
CPU2: thread -1, cpu 2, socket 0, mpidr 80000002
Checking local_timer
CPU3: Booted secondary processor
2: local_timer is per-cpu
2: local_timer is preferred
Checking dummy_timer
2: dummy_timer is per-cpu
2: dummy_timer is trying broadcast
Checking dummy_timer
3: dummy_timer is per-cpu
3: dummy_timer is preferred
CPU3: thread -1, cpu 3, socket 0, mpidr 80000003
Checking local_timer
Brought up 4 CPUs
SMP: Total of 4 processors activated (6324.22 BogoMIPS).
CPU: All CPU(s) started in SVC mode.
devtmpfs: initialized
pinctrl core: initialized pinctrl subsystem
regulator-dummy: no parameters
NET: Registered protocol family 16
DMA: preallocated 256 KiB pool for atomic coherent allocations
syscon 20c8000.anatop: regmap [mem 0x020c8000-0x020c8fff] registered
vdd1p1: 800 <--> 1375 mV at 1100 mV
vdd3p0: 2800 <--> 3150 mV at 3000 mV
vdd2p5: 2000 <--> 2750 mV at 2400 mV
cpu: 725 <--> 1450 mV at 1150 mV
vddpu: 725 <--> 1450 mV at 1150 mV
vddsoc: 725 <--> 1450 mV at 1200 mV
syscon 20e0000.iomuxc-gpr: regmap [mem 0x020e0000-0x020e0037] registered
3: local_timer is per-cpu
3: local_timer is preferred
Checking dummy_timer
3: dummy_timer is per-cpu
3: dummy_timer is trying broadcast
hw-breakpoint: found 5 (+1 reserved) breakpoint and 1 watchpoint registers.
hw-breakpoint: maximum watchpoint size is 4 bytes.
imx6q-pinctrl 20e0000.iomuxc: initialized IMX pinctrl driver
bio: create slab <bio-0> at 0
mxs-dma 110000.dma-apbh: initialized
usb_otg_vbus: 5000 mV
wm8962-supply: no parameters
SCSI subsystem initialized
libata version 3.00 loaded.
usbcore: registered new interface driver usbfs
usbcore: registered new interface driver hub
usbcore: registered new device driver usb
i2c i2c-0: IMX I2C adapter registered
Linux video capture interface: v2.00
pps_core: LinuxPPS API ver. 1 registered
pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti <giometti@linux.it>
PTP clock support registered
Advanced Linux Sound Architecture Driver Initialized.
Switched to clocksource mxc_timer1
------------[ cut here ]------------
------------[ cut here ]------------
WARNING: CPU: 2 PID: 0 at kernel/time/clockevents.c:212 clockevents_program_event+0x134/0x148()
Modules linked in:
CPU: 2 PID: 0 Comm: swapper/2 Not tainted 3.10.0-next-20130701+ #1
[<800147d4>] (unwind_backtrace+0x0/0xf0) from [<80011538>] (show_stack+0x10/0x14)
[<80011538>] (show_stack+0x10/0x14) from [<805176a0>] (dump_stack+0x78/0x94)
[<805176a0>] (dump_stack+0x78/0x94) from [<8002407c>] (warn_slowpath_common+0x64/0x88)
[<8002407c>] (warn_slowpath_common+0x64/0x88) from [<800240bc>] (warn_slowpath_null+0x1c/0x24)
[<800240bc>] (warn_slowpath_null+0x1c/0x24) from [<800613f4>] (clockevents_program_event+0x134/0x148)
[<800613f4>] (clockevents_program_event+0x134/0x148) from [<80061900>] (tick_handle_periodic+0x64/0x88)
[<80061900>] (tick_handle_periodic+0x64/0x88) from [<80013f48>] (twd_handler+0x2c/0x40)
[<80013f48>] (twd_handler+0x2c/0x40) from [<800774e8>] (handle_percpu_devid_irq+0x80/0xa0)
[<800774e8>] (handle_percpu_devid_irq+0x80/0xa0) from [<80073d40>] (generic_handle_irq+0x20/0x30)
[<80073d40>] (generic_handle_irq+0x20/0x30) from [<8000edb8>] (handle_IRQ+0x4c/0xb0)
[<8000edb8>] (handle_IRQ+0x4c/0xb0) from [<800086d4>] (gic_handle_irq+0x28/0x5c)
[<800086d4>] (gic_handle_irq+0x28/0x5c) from [<80012080>] (__irq_svc+0x40/0x54)
Exception stack(0xbf899f98 to 0xbf899fe0)
9f80:                                                       00000000 00003ecc
9fa0: 00000000 8001cf60 bf898000 8078c428 00000001 8078c428 807508e8 80750894
9fc0: 8051e3ac 00000000 80750894 bf899fe0 8000f0cc 8000f0d0 60000113 ffffffff
[<80012080>] (__irq_svc+0x40/0x54) from [<8000f0d0>] (arch_cpu_idle+0x30/0x3c)
[<8000f0d0>] (arch_cpu_idle+0x30/0x3c) from [<80059f74>] (cpu_startup_entry+0x64/0x138)
[<80059f74>] (cpu_startup_entry+0x64/0x138) from [<100081ec>] (0x100081ec)
---[ end trace f6330182bcabb113 ]---
NET: Registered protocol family 2
TCP established hash table entries: 8192 (order: 4, 65536 bytes)
TCP bind hash table entries: 8192 (order: 4, 65536 bytes)
TCP: Hash tables configured (established 8192 bind 8192)
TCP: reno registered
UDP hash table entries: 512 (order: 2, 16384 bytes)
UDP-Lite hash table entries: 512 (order: 2, 16384 bytes)
NET: Registered protocol family 1
RPC: Registered named UNIX socket transport module.
RPC: Registered udp transport module.
RPC: Registered tcp transport module.
RPC: Registered tcp NFSv4.1 backchannel transport module.
WARNING: CPU: 3 PID: 0 at kernel/time/clockevents.c:212 clockevents_program_event+0x134/0x148()
Modules linked in:
CPU: 3 PID: 0 Comm: swapper/3 Tainted: G        W    3.10.0-next-20130701+ #1
[<800147d4>] (unwind_backtrace+0x0/0xf0) from [<80011538>] (show_stack+0x10/0x14)
[<80011538>] (show_stack+0x10/0x14) from [<805176a0>] (dump_stack+0x78/0x94)
[<805176a0>] (dump_stack+0x78/0x94) from [<8002407c>] (warn_slowpath_common+0x64/0x88)
[<8002407c>] (warn_slowpath_common+0x64/0x88) from [<800240bc>] (warn_slowpath_null+0x1c/0x24)
[<800240bc>] (warn_slowpath_null+0x1c/0x24) from [<800613f4>] (clockevents_program_event+0x134/0x148)
[<800613f4>] (clockevents_program_event+0x134/0x148) from [<80061900>] (tick_handle_periodic+0x64/0x88)
[<80061900>] (tick_handle_periodic+0x64/0x88) from [<80013f48>] (twd_handler+0x2c/0x40)
[<80013f48>] (twd_handler+0x2c/0x40) from [<800774e8>] (handle_percpu_devid_irq+0x80/0xa0)
[<800774e8>] (handle_percpu_devid_irq+0x80/0xa0) from [<80073d40>] (generic_handle_irq+0x20/0x30)
[<80073d40>] (generic_handle_irq+0x20/0x30) from [<8000edb8>] (handle_IRQ+0x4c/0xb0)
[<8000edb8>] (handle_IRQ+0x4c/0xb0) from [<800086d4>] (gic_handle_irq+0x28/0x5c)
[<800086d4>] (gic_handle_irq+0x28/0x5c) from [<80012080>] (__irq_svc+0x40/0x54)
Exception stack(0xbf89bf98 to 0xbf89bfe0)
bf80:                                                       00000000 00000052
bfa0: 00000000 8001cf60 bf89a000 8078c428 00000001 8078c428 807508e8 80750894
bfc0: 8051e3ac 00000000 80750894 bf89bfe0 8000f0cc 8000f0d0 60000113 ffffffff
[<80012080>] (__irq_svc+0x40/0x54) from [<8000f0d0>] (arch_cpu_idle+0x30/0x3c)
[<8000f0d0>] (arch_cpu_idle+0x30/0x3c) from [<80059f74>] (cpu_startup_entry+0x64/0x138)
[<80059f74>] (cpu_startup_entry+0x64/0x138) from [<100081ec>] (0x100081ec)
---[ end trace f6330182bcabb114 ]---
INFO: rcu_sched self-detected stall on CPU
INFO: rcu_sched self-detected stall on CPU { 2}  (t=2100 jiffies g=4294966998 c=4294966997 q=8)
CPU: 2 PID: 0 Comm: swapper/2 Tainted: G        W    3.10.0-next-20130701+ #1
[<800147d4>] (unwind_backtrace+0x0/0xf0) from [<80011538>] (show_stack+0x10/0x14)
[<80011538>] (show_stack+0x10/0x14) from [<805176a0>] (dump_stack+0x78/0x94)
[<805176a0>] (dump_stack+0x78/0x94) from [<8007ccf8>] (rcu_check_callbacks+0x2a8/0x700)
[<8007ccf8>] (rcu_check_callbacks+0x2a8/0x700) from [<80031ac4>] (update_process_times+0x38/0x64)
[<80031ac4>] (update_process_times+0x38/0x64) from [<8006191c>] (tick_handle_periodic+0x80/0x88)
[<8006191c>] (tick_handle_periodic+0x80/0x88) from [<80013f48>] (twd_handler+0x2c/0x40)
[<80013f48>] (twd_handler+0x2c/0x40) from [<800774e8>] (handle_percpu_devid_irq+0x80/0xa0)
[<800774e8>] (handle_percpu_devid_irq+0x80/0xa0) from [<80073d40>] (generic_handle_irq+0x20/0x30)
[<80073d40>] (generic_handle_irq+0x20/0x30) from [<8000edb8>] (handle_IRQ+0x4c/0xb0)
[<8000edb8>] (handle_IRQ+0x4c/0xb0) from [<800086d4>] (gic_handle_irq+0x28/0x5c)
[<800086d4>] (gic_handle_irq+0x28/0x5c) from [<80012080>] (__irq_svc+0x40/0x54)
Exception stack(0xbf899f98 to 0xbf899fe0)
9f80:                                                       00000000 00003ecc
9fa0: 00000000 8001cf60 bf898000 8078c428 00000001 8078c428 807508e8 80750894
9fc0: 8051e3ac 00000000 80750894 bf899fe0 8000f0cc 8000f0d0 60000113 ffffffff
[<80012080>] (__irq_svc+0x40/0x54) from [<8000f0d0>] (arch_cpu_idle+0x30/0x3c)
[<8000f0d0>] (arch_cpu_idle+0x30/0x3c) from [<80059f74>] (cpu_startup_entry+0x64/0x138)
[<80059f74>] (cpu_startup_entry+0x64/0x138) from [<100081ec>] (0x100081ec)
 { 3}  (t=2115 jiffies g=4294966998 c=4294966997 q=8)
CPU: 3 PID: 0 Comm: swapper/3 Tainted: G        W    3.10.0-next-20130701+ #1
[<800147d4>] (unwind_backtrace+0x0/0xf0) from [<80011538>] (show_stack+0x10/0x14)
[<80011538>] (show_stack+0x10/0x14) from [<805176a0>] (dump_stack+0x78/0x94)
[<805176a0>] (dump_stack+0x78/0x94) from [<8007ccf8>] (rcu_check_callbacks+0x2a8/0x700)
[<8007ccf8>] (rcu_check_callbacks+0x2a8/0x700) from [<80031ac4>] (update_process_times+0x38/0x64)
[<80031ac4>] (update_process_times+0x38/0x64) from [<8006191c>] (tick_handle_periodic+0x80/0x88)
[<8006191c>] (tick_handle_periodic+0x80/0x88) from [<80013f48>] (twd_handler+0x2c/0x40)
[<80013f48>] (twd_handler+0x2c/0x40) from [<800774e8>] (handle_percpu_devid_irq+0x80/0xa0)
[<800774e8>] (handle_percpu_devid_irq+0x80/0xa0) from [<80073d40>] (generic_handle_irq+0x20/0x30)
[<80073d40>] (generic_handle_irq+0x20/0x30) from [<8000edb8>] (handle_IRQ+0x4c/0xb0)
[<8000edb8>] (handle_IRQ+0x4c/0xb0) from [<800086d4>] (gic_handle_irq+0x28/0x5c)
[<800086d4>] (gic_handle_irq+0x28/0x5c) from [<80012080>] (__irq_svc+0x40/0x54)
Exception stack(0xbf89bf98 to 0xbf89bfe0)
bf80:                                                       00000000 00000052
bfa0: 00000000 8001cf60 bf89a000 8078c428 00000001 8078c428 807508e8 80750894
bfc0: 8051e3ac 00000000 80750894 bf89bfe0 8000f0cc 8000f0d0 60000113 ffffffff
[<80012080>] (__irq_svc+0x40/0x54) from [<8000f0d0>] (arch_cpu_idle+0x30/0x3c)
[<8000f0d0>] (arch_cpu_idle+0x30/0x3c) from [<80059f74>] (cpu_startup_entry+0x64/0x138)
[<80059f74>] (cpu_startup_entry+0x64/0x138) from [<100081ec>] (0x100081ec)

RE: next-20130627 breaks i.MX6 sabre sd UART console

[Thomas Gleixner]

On Mon, 1 Jul 2013, Stehle Vincent-B46079 wrote:

So up to this point everything looks ok. mxc timer is the broadcast
and the local timer is preferred over the dummy timer.

But after switching the clocksource:

> Switched to clocksource mxc_timer1
> ------------[ cut here ]------------
> WARNING: CPU: 2 PID: 0 at kernel/time/clockevents.c:212 clockevents_program_event+0x134/0x148()

That's when clockevents_program_event() is called with a negative
expiry time.

And its called from:

[<800613f4>] (clockevents_program_event+0x134/0x148) from [<80061900>]
(tick_handle_periodic+0x64/0x88)

Which calculates the expiry value via:
      
      next = ktime_add(dev->next_event, tick_period);

So something is hosed there.

Can you please apply the patch below and provide the output?

Thanks,

	tglx
---
diff --git a/kernel/time/tick-common.c b/kernel/time/tick-common.c
index edd45f6..5617628 100644
--- a/kernel/time/tick-common.c
+++ b/kernel/time/tick-common.c
@@ -94,6 +94,13 @@ void tick_handle_periodic(struct clock_event_device *dev)
 	 */
 	next = ktime_add(dev->next_event, tick_period);
 	for (;;) {
+		if (next.tv64 < 0) {
+			pr_err("next %llx nevt %llx per %llx nxtp %llx now %llx\n",
+			       next.tv64, dev->next_event.tv64,
+			       tick_period.tv64, tick_next_period.tv64,
+			       ktime_get().tv64);
+		}
+
 		if (!clockevents_program_event(dev, next, false))
 			return;
 		/*

RE: next-20130627 breaks i.MX6 sabre sd UART console

[Stehle Vincent-B46079]

From: Thomas Gleixner [mailto:tglx@linutronix.de] 
> (..) Can you please apply the patch below and provide the output?

Sure; thanks for the patch. The kernel seems to be in a loop, as it prints many messages and never stops. I copy only the first ones:

...
Switched to clocksource mxc_timer1
next 800000000098967f nevt 7fffffffffffffff per 989680 nxtp 1c03a180 now 1c553a59
next 800000000098967f nevt 7fffffffffffffff per 989680 nxtp 1c9c3800 now 1c71e40f
------------[ cut here ]------------
WARNING: CPU: 2 PID: 0 at kernel/time/clockevents.c:212 clockevents_program_event+0x134/0x148()
next 80000000e01d0bff nevt 7fffffffffffffff per 989680 nxtp 1d34ce80 now 1ca4a301
next 80000002c250a67f nevt 7fffffffffffffff per 989680 nxtp 1d34ce80 now 1d05af1c
next 80000004a64e047f nevt 7fffffffffffffff per 989680 nxtp 1dcd6500 now 1d729c96
next 800000068cadbc7f nevt 7fffffffffffffff per 989680 nxtp 1e65fb80 now 1de16ecb
next 80000008730d747f nevt 7fffffffffffffff per 989680 nxtp 1e65fb80 now 1e5173b3
next 8000000a583bff7f nevt 7fffffffffffffff per 989680 nxtp 1efe9200 now 1ec10b4a
next 8000000c3c395d7f nevt 7fffffffffffffff per 989680 nxtp 1f972880 now 1f306de8
next 8000000e2167e87f nevt 7fffffffffffffff per 989680 nxtp 202fbf00 now 1f9fe9db
next 800000100565467f nevt 7fffffffffffffff per 989680 nxtp 202fbf00 now 200f2ff3
next 80000011e831777f nevt 7fffffffffffffff per 989680 nxtp 20c85580 now 207e6fc4
next 80000013cc2ed57f nevt 7fffffffffffffff per 989680 nxtp 2160ec00 now 20edf2c2
next 80000015aefb067f nevt 7fffffffffffffff per 989680 nxtp 2160ec00 now 215d58fd
next 80000017925fcdff nevt 7fffffffffffffff per 989680 nxtp 21f98280 now 21ccfde5
...

Best regards,

V.

RE: next-20130627 breaks i.MX6 sabre sd UART console

[Thomas Gleixner]

On Mon, 1 Jul 2013, Stehle Vincent-B46079 wrote:

> From: Thomas Gleixner [mailto:tglx@linutronix.de] 
> > (..) Can you please apply the patch below and provide the output?
> 
> Sure; thanks for the patch. The kernel seems to be in a loop, as it prints many messages and never stops. I copy only the first ones:
> 
> ...
> Switched to clocksource mxc_timer1
> next 800000000098967f nevt 7fffffffffffffff per 989680 nxtp 1c03a180 now 1c553a59

Yuck. nevt (dev->next_event) is KTIME_MAX. No surprise, that we end up
in an endless loop.

Now the question is how we did end up with that and how is that
related to the dummy timer.

>From your debug output we see that the dummy timer is installed before
the local timer. The dummytimer is disfunctional, so it requires
broadcast in the first place.

Now when we install the local timer the broadcast is not disabled,
because the local timer is affected by C3STOP. Now the CPU is not in a
power state which makes the broadcasting necessary, but the broadcast
code has no way to distinguish whether the broadcast bit is set due to
power state or due to a dummy timer.

That's clearly wrong as we end up with two periodic events for that
cpu (broadcast and local timer) as long as nothing calls into the
broadcast control code. That's fixable with some surgery.

Though that does not explain why dev->next_event is set to KTIME_MAX
after we installed the mxc_timer1 as the system clocksource. And we
really need to know why that happens. 

Here is some more debugging which should shine some light on that.

Thanks,

	tglx

diff --git a/kernel/hrtimer.c b/kernel/hrtimer.c
index e86827e..b94aaf9 100644
--- a/kernel/hrtimer.c
+++ b/kernel/hrtimer.c
@@ -717,6 +717,7 @@ static int hrtimer_switch_to_hres(void)
 	tick_setup_sched_timer();
 	/* "Retrigger" the interrupt to get things going */
 	retrigger_next_event(NULL);
+	pr_err("Switched to highres mode %d\n", cpu);
 	local_irq_restore(flags);
 	return 1;
 }
@@ -1290,6 +1291,8 @@ void hrtimer_interrupt(struct clock_event_device *dev)
 	cpu_base->nr_events++;
 	dev->next_event.tv64 = KTIME_MAX;
 
+	pr_err("hrtimer_interrupt %d %p\n", smp_processor_id(), dev);
+
 	raw_spin_lock(&cpu_base->lock);
 	entry_time = now = hrtimer_update_base(cpu_base);
 retry:
diff --git a/kernel/time/clockevents.c b/kernel/time/clockevents.c
index 38959c8..331a30f 100644
--- a/kernel/time/clockevents.c
+++ b/kernel/time/clockevents.c
@@ -94,6 +94,8 @@ void clockevents_shutdown(struct clock_event_device *dev)
 {
 	clockevents_set_mode(dev, CLOCK_EVT_MODE_SHUTDOWN);
 	dev->next_event.tv64 = KTIME_MAX;
+	pr_err("clockevents_shutdown %d %p\n", smp_processor_id(), dev);
+	WARN_ON(1);
 }
 
 #ifdef CONFIG_GENERIC_CLOCKEVENTS_MIN_ADJUST
diff --git a/kernel/time/tick-broadcast.c b/kernel/time/tick-broadcast.c
index 9d96a54..e3456d3 100644
--- a/kernel/time/tick-broadcast.c
+++ b/kernel/time/tick-broadcast.c
@@ -508,6 +508,7 @@ static void tick_handle_oneshot_broadcast(struct clock_event_device *dev)
 	raw_spin_lock(&tick_broadcast_lock);
 again:
 	dev->next_event.tv64 = KTIME_MAX;
+	pr_err("oneshot_broadcast %d %p\n", smp_processor_id(), dev);
 	next_event.tv64 = KTIME_MAX;
 	cpumask_clear(tmpmask);
 	now = ktime_get();
@@ -736,6 +737,7 @@ void tick_broadcast_setup_oneshot(struct clock_event_device *bc)
 			tick_broadcast_set_event(bc, cpu, tick_next_period, 1);
 		} else
 			bc->next_event.tv64 = KTIME_MAX;
+		pr_err("bc_setup_oneshot %d %p\n", smp_processor_id(), bc);
 	} else {
 		/*
 		 * The first cpu which switches to oneshot mode sets
diff --git a/kernel/time/tick-common.c b/kernel/time/tick-common.c
index edd45f6..9606abb 100644
--- a/kernel/time/tick-common.c
+++ b/kernel/time/tick-common.c
@@ -28,6 +28,7 @@
  * Tick devices
  */
 DEFINE_PER_CPU(struct tick_device, tick_cpu_device);
+static DEFINE_PER_CPU(int, ticks_handled);
 /*
  * Tick next event: keeps track of the tick time
  */
@@ -82,8 +83,10 @@ static void tick_periodic(int cpu)
 void tick_handle_periodic(struct clock_event_device *dev)
 {
 	int cpu = smp_processor_id();
+	int handled = __this_cpu_read(ticks_handled);
 	ktime_t next;
 
+	__this_cpu_inc(ticks_handled);
 	tick_periodic(cpu);
 
 	if (dev->mode != CLOCK_EVT_MODE_ONESHOT)
@@ -94,6 +97,13 @@ void tick_handle_periodic(struct clock_event_device *dev)
 	 */
 	next = ktime_add(dev->next_event, tick_period);
 	for (;;) {
+		if (next.tv64 < 0) {
+			pr_err("next %llx nevt %llx per %llx nxtp %llx now %llx %d %p %d\n",
+			       next.tv64, dev->next_event.tv64,
+			       tick_period.tv64, tick_next_period.tv64,
+			       ktime_get().tv64, cpu, dev, handled);
+		}
+
 		if (!clockevents_program_event(dev, next, false))
 			return;
 		/*
diff --git a/kernel/time/tick-sched.c b/kernel/time/tick-sched.c
index 0cf1c14..1531837 100644
--- a/kernel/time/tick-sched.c
+++ b/kernel/time/tick-sched.c
@@ -969,6 +969,7 @@ static void tick_nohz_handler(struct clock_event_device *dev)
 	ktime_t now = ktime_get();
 
 	dev->next_event.tv64 = KTIME_MAX;
+	pr_err("nohz_handler %d %p\n", smp_processor_id(), dev);
 
 	tick_sched_do_timer(now);
 	tick_sched_handle(ts, regs);
@@ -1012,6 +1013,7 @@ static void tick_nohz_switch_to_nohz(void)
 			break;
 		next = ktime_add(next, tick_period);
 	}
+	pr_err("Switched to nohz mode %d\n", smp_processor_id());
 	local_irq_enable();
 }
 
@@ -1180,6 +1182,8 @@ void tick_clock_notify(void)
 {
 	int cpu;
 
+	pr_err("tick_clock_notify\n");
+
 	for_each_possible_cpu(cpu)
 		set_bit(0, &per_cpu(tick_cpu_sched, cpu).check_clocks);
 }

RE: next-20130627 breaks i.MX6 sabre sd UART console

[Stehle Vincent-B46079]

From: Thomas Gleixner [mailto:tglx@linutronix.de]
(..)
> Though that does not explain why dev->next_event is set to KTIME_MAX
> after we installed the mxc_timer1 as the system clocksource. And we
> really need to know why that happens.
> 
> Here is some more debugging which should shine some light on that.

...and here is your log :)

Best regards,

V.

Uncompressing Linux... done, booting the kernel.
Booting Linux on physical CPU 0x0
Linux version 3.10.0-next-20130701+ (vstehle@debian) (gcc version 4.7.2 (Debian 4.7.2-5) ) #2 SMP Mon Jul 1 21:36:54 CEST 2013
CPU: ARMv7 Processor [412fc09a] revision 10 (ARMv7), cr=10c53c7d
CPU: PIPT / VIPT nonaliasing data cache, VIPT aliasing instruction cache
Machine: Freescale i.MX6 Quad/DualLite (Device Tree), model: Freescale i.MX6 Quad SABRE Smart Device Board
bootconsole [earlycon0] enabled
Memory policy: ECC disabled, Data cache writealloc
On node 0 totalpages: 262144
free_area_init_node: node 0, pgdat 8078bd00, node_mem_map 807ea000
  Normal zone: 2048 pages used for memmap
  Normal zone: 0 pages reserved
  Normal zone: 262144 pages, LIFO batch:31
PERCPU: Embedded 7 pages/cpu @81007000 s7680 r8192 d12800 u32768
pcpu-alloc: s7680 r8192 d12800 u32768 alloc=8*4096
pcpu-alloc: [0] 0 [0] 1 [0] 2 [0] 3 
Built 1 zonelists in Zone order, mobility grouping on.  Total pages: 260096
Kernel command line: console=ttymxc0,115200 root=/dev/nfs ip=dhcp nfsroot=192.168.111.1:/tftpboot/debian,v3,tcp rw earlyprintk debug
PID hash table entries: 4096 (order: 2, 16384 bytes)
Dentry cache hash table entries: 131072 (order: 7, 524288 bytes)
Inode-cache hash table entries: 65536 (order: 6, 262144 bytes)
Memory: 1031272K/1048576K available (5380K kernel code, 273K rwdata, 1736K rodata, 303K init, 373K bss, 17304K reserved)
Virtual kernel memory layout:
    vector  : 0xffff0000 - 0xffff1000   (   4 kB)
    fixmap  : 0xfff00000 - 0xfffe0000   ( 896 kB)
    vmalloc : 0xc0800000 - 0xff000000   (1000 MB)
    lowmem  : 0x80000000 - 0xc0000000   (1024 MB)
    modules : 0x7f000000 - 0x80000000   (  16 MB)
      .text : 0x80008000 - 0x806fb4dc   (7118 kB)
      .init : 0x806fc000 - 0x80747e00   ( 304 kB)
      .data : 0x80748000 - 0x8078c540   ( 274 kB)
       .bss : 0x8078c540 - 0x807e9bb4   ( 374 kB)
SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1
Hierarchical RCU implementation.
NR_IRQS:16 nr_irqs:16 16
sched_clock: 32 bits at 66MHz, resolution 15ns, wraps every 65075ms
Checking mxc_timer1
0: mxc_timer1 is per-cpu
0: mxc_timer1 is preferred
clockevents_shutdown 0 80755900
------------[ cut here ]------------
WARNING: CPU: 0 PID: 0 at kernel/time/clockevents.c:98 clockevents_exchange_device+0x7c/0x8c()
Modules linked in:
CPU: 0 PID: 0 Comm: swapper/0 Not tainted 3.10.0-next-20130701+ #2
[<800147d4>] (unwind_backtrace+0x0/0xf0) from [<80011538>] (show_stack+0x10/0x14)
[<80011538>] (show_stack+0x10/0x14) from [<80517800>] (dump_stack+0x78/0x94)
[<80517800>] (dump_stack+0x78/0x94) from [<8002407c>] (warn_slowpath_common+0x64/0x88)
[<8002407c>] (warn_slowpath_common+0x64/0x88) from [<800240bc>] (warn_slowpath_null+0x1c/0x24)
[<800240bc>] (warn_slowpath_null+0x1c/0x24) from [<800615f0>] (clockevents_exchange_device+0x7c/0x8c)
[<800615f0>] (clockevents_exchange_device+0x7c/0x8c) from [<80061d90>] (tick_check_new_device+0xf4/0x158)
[<80061d90>] (tick_check_new_device+0xf4/0x158) from [<80060eb0>] (clockevents_register_device+0x58/0x128)
[<80060eb0>] (clockevents_register_device+0x58/0x128) from [<807032b4>] (mxc_timer_init+0x134/0x178)
[<807032b4>] (mxc_timer_init+0x134/0x178) from [<80728358>] (of_clk_init+0x38/0x64)
[<80728358>] (of_clk_init+0x38/0x64) from [<8070f06c>] (imx6q_timer_init+0xc/0x4c)
[<8070f06c>] (imx6q_timer_init+0xc/0x4c) from [<806ffbf4>] (time_init+0x1c/0x2c)
[<806ffbf4>] (time_init+0x1c/0x2c) from [<806fc768>] (start_kernel+0x1a8/0x308)
[<806fc768>] (start_kernel+0x1a8/0x308) from [<10008074>] (0x10008074)
---[ end trace 1b75b31a2719ed1c ]---
CPU identified as i.MX6Q, silicon rev 1.2
Console: colour dummy device 80x30
Calibrating delay loop... 1581.05 BogoMIPS (lpj=7905280)
pid_max: default: 32768 minimum: 301
Mount-cache hash table entries: 512
CPU: Testing write buffer coherency: ok
CPU0: thread -1, cpu 0, socket 0, mpidr 80000000
Checking local_timer
0: local_timer is per-cpu
0: local_timer is preferred
clockevents_shutdown 0 810071c0
------------[ cut here ]------------
WARNING: CPU: 0 PID: 1 at kernel/time/clockevents.c:98 clockevents_exchange_device+0x7c/0x8c()
Modules linked in:
CPU: 0 PID: 1 Comm: swapper/0 Tainted: G        W    3.10.0-next-20130701+ #2
[<800147d4>] (unwind_backtrace+0x0/0xf0) from [<80011538>] (show_stack+0x10/0x14)
[<80011538>] (show_stack+0x10/0x14) from [<80517800>] (dump_stack+0x78/0x94)
[<80517800>] (dump_stack+0x78/0x94) from [<8002407c>] (warn_slowpath_common+0x64/0x88)
[<8002407c>] (warn_slowpath_common+0x64/0x88) from [<800240bc>] (warn_slowpath_null+0x1c/0x24)
[<800240bc>] (warn_slowpath_null+0x1c/0x24) from [<800615f0>] (clockevents_exchange_device+0x7c/0x8c)
[<800615f0>] (clockevents_exchange_device+0x7c/0x8c) from [<80061d90>] (tick_check_new_device+0xf4/0x158)
[<80061d90>] (tick_check_new_device+0xf4/0x158) from [<80060eb0>] (clockevents_register_device+0x58/0x128)
[<80060eb0>] (clockevents_register_device+0x58/0x128) from [<80014024>] (twd_timer_setup+0xac/0x20c)
[<80014024>] (twd_timer_setup+0xac/0x20c) from [<80013004>] (percpu_timer_setup+0x5c/0xb4)
[<80013004>] (percpu_timer_setup+0x5c/0xb4) from [<80700518>] (smp_prepare_cpus+0x50/0x7c)
[<80700518>] (smp_prepare_cpus+0x50/0x7c) from [<806fc920>] (kernel_init_freeable+0x58/0x1c4)
[<806fc920>] (kernel_init_freeable+0x58/0x1c4) from [<80513c28>] (kernel_init+0x8/0xe4)
[<80513c28>] (kernel_init+0x8/0xe4) from [<8000e578>] (ret_from_fork+0x14/0x3c)
---[ end trace 1b75b31a2719ed1d ]---
Checking mxc_timer1
0: mxc_timer1 is per-cpu
0: mxc_timer1 is trying broadcast
mxc_timer1 is now the broadcast
clockevents_shutdown 0 80755900
------------[ cut here ]------------
WARNING: CPU: 0 PID: 1 at kernel/time/clockevents.c:98 clockevents_exchange_device+0x7c/0x8c()
Modules linked in:
CPU: 0 PID: 1 Comm: swapper/0 Tainted: G        W    3.10.0-next-20130701+ #2
[<800147d4>] (unwind_backtrace+0x0/0xf0) from [<80011538>] (show_stack+0x10/0x14)
[<80011538>] (show_stack+0x10/0x14) from [<80517800>] (dump_stack+0x78/0x94)
[<80517800>] (dump_stack+0x78/0x94) from [<8002407c>] (warn_slowpath_common+0x64/0x88)
[<8002407c>] (warn_slowpath_common+0x64/0x88) from [<800240bc>] (warn_slowpath_null+0x1c/0x24)
[<800240bc>] (warn_slowpath_null+0x1c/0x24) from [<800615f0>] (clockevents_exchange_device+0x7c/0x8c)
[<800615f0>] (clockevents_exchange_device+0x7c/0x8c) from [<80062390>] (tick_install_broadcast_device+0x68/0xbc)
[<80062390>] (tick_install_broadcast_device+0x68/0xbc) from [<80060ee8>] (clockevents_register_device+0x90/0x128)
[<80060ee8>] (clockevents_register_device+0x90/0x128) from [<80014024>] (twd_timer_setup+0xac/0x20c)
[<80014024>] (twd_timer_setup+0xac/0x20c) from [<80013004>] (percpu_timer_setup+0x5c/0xb4)
[<80013004>] (percpu_timer_setup+0x5c/0xb4) from [<80700518>] (smp_prepare_cpus+0x50/0x7c)
[<80700518>] (smp_prepare_cpus+0x50/0x7c) from [<806fc920>] (kernel_init_freeable+0x58/0x1c4)
[<806fc920>] (kernel_init_freeable+0x58/0x1c4) from [<80513c28>] (kernel_init+0x8/0xe4)
[<80513c28>] (kernel_init+0x8/0xe4) from [<8000e578>] (ret_from_fork+0x14/0x3c)
---[ end trace 1b75b31a2719ed1e ]---
tick_clock_notify
Setting up static identity map for 0x8051bfd0 - 0x8051c040
Checking dummy_timer
0: dummy_timer is per-cpu
0: dummy_timer is trying broadcast
CPU1: Booted secondary processor
Checking dummy_timer
1: dummy_timer is per-cpu
1: dummy_timer is preferred
clockevents_shutdown 1 8100ff00
------------[ cut here ]------------
WARNING: CPU: 1 PID: 0 at kernel/time/clockevents.c:98 clockevents_exchange_device+0x7c/0x8c()
Modules linked in:
CPU: 1 PID: 0 Comm: swapper/1 Tainted: G        W    3.10.0-next-20130701+ #2
[<800147d4>] (unwind_backtrace+0x0/0xf0) from [<80011538>] (show_stack+0x10/0x14)
[<80011538>] (show_stack+0x10/0x14) from [<80517800>] (dump_stack+0x78/0x94)
[<80517800>] (dump_stack+0x78/0x94) from [<8002407c>] (warn_slowpath_common+0x64/0x88)
[<8002407c>] (warn_slowpath_common+0x64/0x88) from [<800240bc>] (warn_slowpath_null+0x1c/0x24)
[<800240bc>] (warn_slowpath_null+0x1c/0x24) from [<800615f0>] (clockevents_exchange_device+0x7c/0x8c)
[<800615f0>] (clockevents_exchange_device+0x7c/0x8c) from [<80061d90>] (tick_check_new_device+0xf4/0x158)
[<80061d90>] (tick_check_new_device+0xf4/0x158) from [<80060eb0>] (clockevents_register_device+0x58/0x128)
[<80060eb0>] (clockevents_register_device+0x58/0x128) from [<803e9c44>] (dummy_timer_cpu_notify+0x1c/0x24)
[<803e9c44>] (dummy_timer_cpu_notify+0x1c/0x24) from [<800471fc>] (notifier_call_chain+0x44/0x84)
[<800471fc>] (notifier_call_chain+0x44/0x84) from [<80027628>] (__cpu_notify+0x2c/0x48)
[<80027628>] (__cpu_notify+0x2c/0x48) from [<800133e0>] (secondary_start_kernel+0xdc/0x140)
[<800133e0>] (secondary_start_kernel+0xdc/0x140) from [<100081ec>] (0x100081ec)
---[ end trace 1b75b31a2719ed1f ]---
CPU1: thread -1, cpu 1, socket 0, mpidr 80000001
Checking local_timer
CPU2: Booted secondary processor
1: local_timer is per-cpu
1: local_timer is preferred
clockevents_shutdown 1 8100f1c0
------------[ cut here ]------------
WARNING: CPU: 1 PID: 0 at kernel/time/clockevents.c:98 clockevents_exchange_device+0x7c/0x8c()
Modules linked in:
CPU: 1 PID: 0 Comm: swapper/1 Tainted: G        W    3.10.0-next-20130701+ #2
[<800147d4>] (unwind_backtrace+0x0/0xf0) from [<80011538>] (show_stack+0x10/0x14)
[<80011538>] (show_stack+0x10/0x14) from [<80517800>] (dump_stack+0x78/0x94)
[<80517800>] (dump_stack+0x78/0x94) from [<8002407c>] (warn_slowpath_common+0x64/0x88)
[<8002407c>] (warn_slowpath_common+0x64/0x88) from [<800240bc>] (warn_slowpath_null+0x1c/0x24)
[<800240bc>] (warn_slowpath_null+0x1c/0x24) from [<800615f0>] (clockevents_exchange_device+0x7c/0x8c)
[<800615f0>] (clockevents_exchange_device+0x7c/0x8c) from [<80061d90>] (tick_check_new_device+0xf4/0x158)
[<80061d90>] (tick_check_new_device+0xf4/0x158) from [<80060eb0>] (clockevents_register_device+0x58/0x128)
[<80060eb0>] (clockevents_register_device+0x58/0x128) from [<80014024>] (twd_timer_setup+0xac/0x20c)
[<80014024>] (twd_timer_setup+0xac/0x20c) from [<80013004>] (percpu_timer_setup+0x5c/0xb4)
[<80013004>] (percpu_timer_setup+0x5c/0xb4) from [<80013404>] (secondary_start_kernel+0x100/0x140)
[<80013404>] (secondary_start_kernel+0x100/0x140) from [<100081ec>] (0x100081ec)
---[ end trace 1b75b31a2719ed20 ]---
Checking dummy_timer
1: dummy_timer is per-cpu
1: dummy_timer is trying broadcast
Checking dummy_timer
2: dummy_timer is per-cpu
2: dummy_timer is preferred
clockevents_shutdown 2 81017f00
------------[ cut here ]------------
WARNING: CPU: 2 PID: 0 at kernel/time/clockevents.c:98 clockevents_exchange_device+0x7c/0x8c()
Modules linked in:
CPU: 2 PID: 0 Comm: swapper/2 Tainted: G        W    3.10.0-next-20130701+ #2
[<800147d4>] (unwind_backtrace+0x0/0xf0) from [<80011538>] (show_stack+0x10/0x14)
[<80011538>] (show_stack+0x10/0x14) from [<80517800>] (dump_stack+0x78/0x94)
[<80517800>] (dump_stack+0x78/0x94) from [<8002407c>] (warn_slowpath_common+0x64/0x88)
[<8002407c>] (warn_slowpath_common+0x64/0x88) from [<800240bc>] (warn_slowpath_null+0x1c/0x24)
[<800240bc>] (warn_slowpath_null+0x1c/0x24) from [<800615f0>] (clockevents_exchange_device+0x7c/0x8c)
[<800615f0>] (clockevents_exchange_device+0x7c/0x8c) from [<80061d90>] (tick_check_new_device+0xf4/0x158)
[<80061d90>] (tick_check_new_device+0xf4/0x158) from [<80060eb0>] (clockevents_register_device+0x58/0x128)
[<80060eb0>] (clockevents_register_device+0x58/0x128) from [<803e9c44>] (dummy_timer_cpu_notify+0x1c/0x24)
[<803e9c44>] (dummy_timer_cpu_notify+0x1c/0x24) from [<800471fc>] (notifier_call_chain+0x44/0x84)
[<800471fc>] (notifier_call_chain+0x44/0x84) from [<80027628>] (__cpu_notify+0x2c/0x48)
[<80027628>] (__cpu_notify+0x2c/0x48) from [<800133e0>] (secondary_start_kernel+0xdc/0x140)
[<800133e0>] (secondary_start_kernel+0xdc/0x140) from [<100081ec>] (0x100081ec)
---[ end trace 1b75b31a2719ed21 ]---
CPU2: thread -1, cpu 2, socket 0, mpidr 80000002
Checking local_timer
CPU3: Booted secondary processor
2: local_timer is per-cpu
2: local_timer is preferred
clockevents_shutdown 2 810171c0
------------[ cut here ]------------
WARNING: CPU: 2 PID: 0 at kernel/time/clockevents.c:98 clockevents_exchange_device+0x7c/0x8c()
Modules linked in:
CPU: 2 PID: 0 Comm: swapper/2 Tainted: G        W    3.10.0-next-20130701+ #2
[<800147d4>] (unwind_backtrace+0x0/0xf0) from [<80011538>] (show_stack+0x10/0x14)
[<80011538>] (show_stack+0x10/0x14) from [<80517800>] (dump_stack+0x78/0x94)
[<80517800>] (dump_stack+0x78/0x94) from [<8002407c>] (warn_slowpath_common+0x64/0x88)
[<8002407c>] (warn_slowpath_common+0x64/0x88) from [<800240bc>] (warn_slowpath_null+0x1c/0x24)
[<800240bc>] (warn_slowpath_null+0x1c/0x24) from [<800615f0>] (clockevents_exchange_device+0x7c/0x8c)
[<800615f0>] (clockevents_exchange_device+0x7c/0x8c) from [<80061d90>] (tick_check_new_device+0xf4/0x158)
[<80061d90>] (tick_check_new_device+0xf4/0x158) from [<80060eb0>] (clockevents_register_device+0x58/0x128)
[<80060eb0>] (clockevents_register_device+0x58/0x128) from [<80014024>] (twd_timer_setup+0xac/0x20c)
[<80014024>] (twd_timer_setup+0xac/0x20c) from [<80013004>] (percpu_timer_setup+0x5c/0xb4)
[<80013004>] (percpu_timer_setup+0x5c/0xb4) from [<80013404>] (secondary_start_kernel+0x100/0x140)
[<80013404>] (secondary_start_kernel+0x100/0x140) from [<100081ec>] (0x100081ec)
---[ end trace 1b75b31a2719ed22 ]---
Checking dummy_timer
2: dummy_timer is per-cpu
2: dummy_timer is trying broadcast
Checking dummy_timer
3: dummy_timer is per-cpu
3: dummy_timer is preferred
clockevents_shutdown 3 8101ff00
------------[ cut here ]------------
WARNING: CPU: 3 PID: 0 at kernel/time/clockevents.c:98 clockevents_exchange_device+0x7c/0x8c()
Modules linked in:
CPU: 3 PID: 0 Comm: swapper/3 Tainted: G        W    3.10.0-next-20130701+ #2
[<800147d4>] (unwind_backtrace+0x0/0xf0) from [<80011538>] (show_stack+0x10/0x14)
[<80011538>] (show_stack+0x10/0x14) from [<80517800>] (dump_stack+0x78/0x94)
[<80517800>] (dump_stack+0x78/0x94) from [<8002407c>] (warn_slowpath_common+0x64/0x88)
[<8002407c>] (warn_slowpath_common+0x64/0x88) from [<800240bc>] (warn_slowpath_null+0x1c/0x24)
[<800240bc>] (warn_slowpath_null+0x1c/0x24) from [<800615f0>] (clockevents_exchange_device+0x7c/0x8c)
[<800615f0>] (clockevents_exchange_device+0x7c/0x8c) from [<80061d90>] (tick_check_new_device+0xf4/0x158)
[<80061d90>] (tick_check_new_device+0xf4/0x158) from [<80060eb0>] (clockevents_register_device+0x58/0x128)
[<80060eb0>] (clockevents_register_device+0x58/0x128) from [<803e9c44>] (dummy_timer_cpu_notify+0x1c/0x24)
[<803e9c44>] (dummy_timer_cpu_notify+0x1c/0x24) from [<800471fc>] (notifier_call_chain+0x44/0x84)
[<800471fc>] (notifier_call_chain+0x44/0x84) from [<80027628>] (__cpu_notify+0x2c/0x48)
[<80027628>] (__cpu_notify+0x2c/0x48) from [<800133e0>] (secondary_start_kernel+0xdc/0x140)
[<800133e0>] (secondary_start_kernel+0xdc/0x140) from [<100081ec>] (0x100081ec)
---[ end trace 1b75b31a2719ed23 ]---
CPU3: thread -1, cpu 3, socket 0, mpidr 80000003
Checking local_timer
Brought up 4 CPUs
SMP: Total of 4 processors activated (6324.22 BogoMIPS).
CPU: All CPU(s) started in SVC mode.
devtmpfs: initialized
pinctrl core: initialized pinctrl subsystem
regulator-dummy: no parameters
NET: Registered protocol family 16
DMA: preallocated 256 KiB pool for atomic coherent allocations
syscon 20c8000.anatop: regmap [mem 0x020c8000-0x020c8fff] registered
vdd1p1: 800 <--> 1375 mV at 1100 mV 
vdd3p0: 2800 <--> 3150 mV at 3000 mV 
vdd2p5: 2000 <--> 2750 mV at 2400 mV 
cpu: 725 <--> 1450 mV at 1150 mV 
vddpu: 725 <--> 1450 mV at 1150 mV 
vddsoc: 725 <--> 1450 mV at 1200 mV 
syscon 20e0000.iomuxc-gpr: regmap [mem 0x020e0000-0x020e0037] registered
3: local_timer is per-cpu
3: local_timer is preferred
clockevents_shutdown 3 8101f1c0
------------[ cut here ]------------
WARNING: CPU: 3 PID: 0 at kernel/time/clockevents.c:98 clockevents_exchange_device+0x7c/0x8c()
Modules linked in:
CPU: 3 PID: 0 Comm: swapper/3 Tainted: G        W    3.10.0-next-20130701+ #2
[<800147d4>] (unwind_backtrace+0x0/0xf0) from [<80011538>] (show_stack+0x10/0x14)
[<80011538>] (show_stack+0x10/0x14) from [<80517800>] (dump_stack+0x78/0x94)
[<80517800>] (dump_stack+0x78/0x94) from [<8002407c>] (warn_slowpath_common+0x64/0x88)
[<8002407c>] (warn_slowpath_common+0x64/0x88) from [<800240bc>] (warn_slowpath_null+0x1c/0x24)
[<800240bc>] (warn_slowpath_null+0x1c/0x24) from [<800615f0>] (clockevents_exchange_device+0x7c/0x8c)
[<800615f0>] (clockevents_exchange_device+0x7c/0x8c) from [<80061d90>] (tick_check_new_device+0xf4/0x158)
[<80061d90>] (tick_check_new_device+0xf4/0x158) from [<80060eb0>] (clockevents_register_device+0x58/0x128)
[<80060eb0>] (clockevents_register_device+0x58/0x128) from [<80014024>] (twd_timer_setup+0xac/0x20c)
[<80014024>] (twd_timer_setup+0xac/0x20c) from [<80013004>] (percpu_timer_setup+0x5c/0xb4)
[<80013004>] (percpu_timer_setup+0x5c/0xb4) from [<80013404>] (secondary_start_kernel+0x100/0x140)
[<80013404>] (secondary_start_kernel+0x100/0x140) from [<100081ec>] (0x100081ec)
---[ end trace 1b75b31a2719ed24 ]---
Checking dummy_timer
3: dummy_timer is per-cpu
3: dummy_timer is trying broadcast
hw-breakpoint: found 5 (+1 reserved) breakpoint and 1 watchpoint registers.
hw-breakpoint: maximum watchpoint size is 4 bytes.
imx6q-pinctrl 20e0000.iomuxc: initialized IMX pinctrl driver
bio: create slab <bio-0> at 0
mxs-dma 110000.dma-apbh: initialized
usb_otg_vbus: 5000 mV 
wm8962-supply: no parameters
SCSI subsystem initialized
libata version 3.00 loaded.
usbcore: registered new interface driver usbfs
usbcore: registered new interface driver hub
usbcore: registered new device driver usb
i2c i2c-0: IMX I2C adapter registered
Linux video capture interface: v2.00
pps_core: LinuxPPS API ver. 1 registered
pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti <giometti@linux.it>
PTP clock support registered
Advanced Linux Sound Architecture Driver Initialized.
tick_clock_notify
Switched to clocksource mxc_timer1
bc_setup_oneshot 3 80755900
next 800000000098967f nevt 7fffffffffffffff per 989680 nxtp 48b7b900 now 4890a0f3 2 810171c0 93
------------[ cut here ]------------
WARNING: CPU: 2 PID: 0 at kernel/time/clockevents.c:214 clockevents_program_event+0x134/0x148()
Modules linked in:
next 800000001d34ce7f nevt 7fffffffffffffff per 989680 nxtp 48b7b900 now 489c4ed4 2 810171c0 93
next 8000000226bf35ff nevt 7fffffffffffffff per 989680 nxtp 49504f80 now 49193e51 2 810171c0 93
next 8000000430e233ff nevt 7fffffffffffffff per 989680 nxtp 49504f80 now 49995518 2 810171c0 93
next 800000063b0531ff nevt 7fffffffffffffff per 989680 nxtp 49504f80 now 4a1b13ff 2 810171c0 93
next 8000000845c0c67f nevt 7fffffffffffffff per 989680 nxtp 49504f80 now 4a9d8aca 2 810171c0 93
...

Re: next-20130627 breaks i.MX6 sabre sd UART console

[Stephen Boyd]

On 07/01/13 10:49, Thomas Gleixner wrote:
> On Mon, 1 Jul 2013, Stehle Vincent-B46079 wrote:
>
>> From: Thomas Gleixner [mailto:tglx@linutronix.de] 
>>> (..) Can you please apply the patch below and provide the output?
>> Sure; thanks for the patch. The kernel seems to be in a loop, as it prints many messages and never stops. I copy only the first ones:
>>
>> ...
>> Switched to clocksource mxc_timer1
>> next 800000000098967f nevt 7fffffffffffffff per 989680 nxtp 1c03a180 now 1c553a59
> Yuck. nevt (dev->next_event) is KTIME_MAX. No surprise, that we end up
> in an endless loop.
>
> Now the question is how we did end up with that and how is that
> related to the dummy timer.
>
> From your debug output we see that the dummy timer is installed before
> the local timer. The dummytimer is disfunctional, so it requires
> broadcast in the first place.
>
> Now when we install the local timer the broadcast is not disabled,
> because the local timer is affected by C3STOP. Now the CPU is not in a
> power state which makes the broadcasting necessary, but the broadcast
> code has no way to distinguish whether the broadcast bit is set due to
> power state or due to a dummy timer.
>
> That's clearly wrong as we end up with two periodic events for that
> cpu (broadcast and local timer) as long as nothing calls into the
> broadcast control code. That's fixable with some surgery.

Yes, that sounds like the problem. Before this change the dummy would
never have been installed first and so the broadcast timer wouldn't be
running during boot.

>
> Though that does not explain why dev->next_event is set to KTIME_MAX
> after we installed the mxc_timer1 as the system clocksource. And we
> really need to know why that happens. 
>
> Here is some more debugging which should shine some light on that.

Each local_timer clockevent should have their next_event set for
KTIME_MAX when they're registered because they get "shutdown" initially.
twd timers support both periodic and oneshot, so we won't emulate
periodic mode with oneshot mode. Looking at tick_setup_periodic() it
looks like the next_event member is ignored and we just set the mode to
periodic. KTIME_MAX should still be there. That should be fine though as
long as we don't switch the tick device into oneshot mode.

It seems that someone is switching the tick device into oneshot mode
without changing the event handler away from tick_handle_periodic(). Is
that supposed to happen? Most clockevents_set_mode(ONESHOT) calls are
prefaced with a handler change or they're operating on the broadcast
device. I suspect that tick_check_oneshot_broadcast() is the bad one.
That one changes the mode and then tick_handle_periodic() probably runs
past that if check and starts trying to emulate periodic mode when
next_event is still KTIME_MAX.

-- 
Qualcomm Innovation Center, Inc. is a member of Code Aurora Forum,
hosted by The Linux Foundation

Re: next-20130627 breaks i.MX6 sabre sd UART console

[Thomas Gleixner]

On Mon, 1 Jul 2013, Stephen Boyd wrote:
> On 07/01/13 10:49, Thomas Gleixner wrote:
> >
> > Though that does not explain why dev->next_event is set to KTIME_MAX
> > after we installed the mxc_timer1 as the system clocksource. And we
> > really need to know why that happens. 
> >
> > Here is some more debugging which should shine some light on that.
> 
> Each local_timer clockevent should have their next_event set for
> KTIME_MAX when they're registered because they get "shutdown" initially.

Yes.

> twd timers support both periodic and oneshot, so we won't emulate
> periodic mode with oneshot mode. Looking at tick_setup_periodic() it
> looks like the next_event member is ignored and we just set the mode to
> periodic. KTIME_MAX should still be there. That should be fine though as
> long as we don't switch the tick device into oneshot mode.

Correct.
 
> It seems that someone is switching the tick device into oneshot mode
> without changing the event handler away from tick_handle_periodic(). Is
> that supposed to happen? Most clockevents_set_mode(ONESHOT) calls are
> prefaced with a handler change or they're operating on the broadcast
> device. I suspect that tick_check_oneshot_broadcast() is the bad one.
> That one changes the mode and then tick_handle_periodic() probably runs
> past that if check and starts trying to emulate periodic mode when
> next_event is still KTIME_MAX.

The issue is very subtle. What happens is:

CPU0						CPU1

Switch to oneshot mode

 Copy the bits from tick_broadcast_mask to
 tick_broadcast_oneshot_mask. We need to do
 that so the other cpus reach the timer irq
 and the softirq which switches them to
 oneshot.

 Kick the broadcast device into oneshot.

						Timer interrupt fires
						
						irq_enter sees the cpu in
						tick_broadcast_oneshot_mask and
						sets the device to oneshot mode
						
						handle_periodic:
						 Sees oneshot mode and adds
						 period to
						 dev->next_event(KTIME_MAX)
						 
So we need two fixes:

1) The replacement of the dummy timer and the effect on the broadcast
   mask/device

2) tick_check_oneshot_broadcast needs a sanity check

Patch below.

Thanks,

	tglx
---
diff --git a/kernel/time/tick-broadcast.c b/kernel/time/tick-broadcast.c
index 9d96a54..58d69eb 100644
--- a/kernel/time/tick-broadcast.c
+++ b/kernel/time/tick-broadcast.c
@@ -30,6 +30,7 @@
 
 static struct tick_device tick_broadcast_device;
 static cpumask_var_t tick_broadcast_mask;
+static cpumask_var_t tick_broadcast_on;
 static cpumask_var_t tmpmask;
 static DEFINE_RAW_SPINLOCK(tick_broadcast_lock);
 static int tick_broadcast_force;
@@ -140,8 +141,9 @@ static void tick_device_setup_broadcast_func(struct clock_event_device *dev)
  */
 int tick_device_uses_broadcast(struct clock_event_device *dev, int cpu)
 {
+	struct clock_event_device *bc = tick_broadcast_device.evtdev;
 	unsigned long flags;
-	int ret = 0;
+	int ret;
 
 	raw_spin_lock_irqsave(&tick_broadcast_lock, flags);
 
@@ -155,22 +157,65 @@ int tick_device_uses_broadcast(struct clock_event_device *dev, int cpu)
 		dev->event_handler = tick_handle_periodic;
 		tick_device_setup_broadcast_func(dev);
 		cpumask_set_cpu(cpu, tick_broadcast_mask);
-		tick_broadcast_start_periodic(tick_broadcast_device.evtdev);
+		tick_broadcast_start_periodic(bc);
 		ret = 1;
 	} else {
+		int cpubc = cpumask_test_cpu(cpu, tick_broadcast_on);
+		int devc3 = dev->features & CLOCK_EVT_FEAT_C3STOP;
+
+		if (devc3)
+			tick_device_setup_broadcast_func(dev);
 		/*
-		 * When the new device is not affected by the stop
-		 * feature and the cpu is marked in the broadcast mask
-		 * then clear the broadcast bit.
+		 * If broadcast mode is enforced, leave the broadcast
+		 * mask alone.
 		 */
-		if (!(dev->features & CLOCK_EVT_FEAT_C3STOP)) {
-			int cpu = smp_processor_id();
-			cpumask_clear_cpu(cpu, tick_broadcast_mask);
+		if (!tick_broadcast_force) {
+			/*
+			 * Clear the broadcast bit for this cpu if the
+			 * device is not powerstate affected or the
+			 * cpu is not in the broadcast ON mode
+			 */
+			if (!devc3 || !cpubc)
+				cpumask_clear_cpu(cpu, tick_broadcast_mask);
+		}
+
+		switch (tick_broadcast_device.mode) {
+		case TICKDEV_MODE_ONESHOT:
+			/*
+			 * If the system is in oneshot mode we can
+			 * unconditionally clear the oneshot mask,
+			 * because the CPU is running and therefor not
+			 * in an idle state which causes the C3
+			 * affected device to stop. Let the caller
+			 * initialize the device.
+			 */
 			tick_broadcast_clear_oneshot(cpu);
-		} else {
-			tick_device_setup_broadcast_func(dev);
+			ret = 0;
+			break;
+
+		case TICKDEV_MODE_PERIODIC:
+			/*
+			 * If the system is in periodic mode, check
+			 * whether the broadcast device can be
+			 * switched off now.
+			 */
+			if (cpumask_empty(tick_broadcast_mask) && bc)
+				clockevents_shutdown(bc);
+			/*
+			 * If we kept the cpu in the broadcast mask,
+			 * tell the core code to leave it alone and
+			 * leave the per cpu device in shutdown
+			 * state.
+			 */
+			ret = cpumask_test_cpu(cpu, tick_broadcast_mask);
+			break;
+		default:
+			/* Nothing to do */
+			ret = 0;
+			break;
 		}
 	}
+
 	raw_spin_unlock_irqrestore(&tick_broadcast_lock, flags);
 	return ret;
 }
@@ -298,6 +343,7 @@ static void tick_do_broadcast_on_off(unsigned long *reason)
 	switch (*reason) {
 	case CLOCK_EVT_NOTIFY_BROADCAST_ON:
 	case CLOCK_EVT_NOTIFY_BROADCAST_FORCE:
+		cpumask_set_cpu(cpu, tick_broadcast_on);
 		if (!cpumask_test_and_set_cpu(cpu, tick_broadcast_mask)) {
 			if (tick_broadcast_device.mode ==
 			    TICKDEV_MODE_PERIODIC)
@@ -307,8 +353,12 @@ static void tick_do_broadcast_on_off(unsigned long *reason)
 			tick_broadcast_force = 1;
 		break;
 	case CLOCK_EVT_NOTIFY_BROADCAST_OFF:
-		if (!tick_broadcast_force &&
-		    cpumask_test_and_clear_cpu(cpu, tick_broadcast_mask)) {
+		if (tick_broadcast_force)
+			break;
+		cpumask_clear_cpu(cpu, tick_broadcast_on);
+		if (!tick_device_is_functional(dev))
+			break;
+		if (cpumask_test_and_clear_cpu(cpu, tick_broadcast_mask)) {
 			if (tick_broadcast_device.mode ==
 			    TICKDEV_MODE_PERIODIC)
 				tick_setup_periodic(dev, 0);
@@ -366,6 +416,7 @@ void tick_shutdown_broadcast(unsigned int *cpup)
 
 	bc = tick_broadcast_device.evtdev;
 	cpumask_clear_cpu(cpu, tick_broadcast_mask);
+	cpumask_clear_cpu(cpu, tick_broadcast_on);
 
 	if (tick_broadcast_device.mode == TICKDEV_MODE_PERIODIC) {
 		if (bc && cpumask_empty(tick_broadcast_mask))
@@ -492,7 +543,15 @@ void tick_check_oneshot_broadcast(int cpu)
 	if (cpumask_test_cpu(cpu, tick_broadcast_oneshot_mask)) {
 		struct tick_device *td = &per_cpu(tick_cpu_device, cpu);
 
-		clockevents_set_mode(td->evtdev, CLOCK_EVT_MODE_ONESHOT);
+		/*
+		 * We might be in the middle of switching over from
+		 * periodic to oneshot. If the CPU has not yet
+		 * switched over, leave the device alone.
+		 */
+		if (td->mode == TICKDEV_MODE_ONESHOT) {
+			clockevents_set_mode(td->evtdev,
+					     CLOCK_EVT_MODE_ONESHOT);
+		}
 	}
 }
 
@@ -809,6 +868,7 @@ bool tick_broadcast_oneshot_available(void)
 void __init tick_broadcast_init(void)
 {
 	zalloc_cpumask_var(&tick_broadcast_mask, GFP_NOWAIT);
+	zalloc_cpumask_var(&tick_broadcast_on, GFP_NOWAIT);
 	zalloc_cpumask_var(&tmpmask, GFP_NOWAIT);
 #ifdef CONFIG_TICK_ONESHOT
 	zalloc_cpumask_var(&tick_broadcast_oneshot_mask, GFP_NOWAIT);
diff --git a/kernel/time/tick-common.c b/kernel/time/tick-common.c
index edd45f6..5e3ed78 100644
--- a/kernel/time/tick-common.c
+++ b/kernel/time/tick-common.c
@@ -194,7 +194,8 @@ static void tick_setup_device(struct tick_device *td,
 	 * When global broadcasting is active, check if the current
 	 * device is registered as a placeholder for broadcast mode.
 	 * This allows us to handle this x86 misfeature in a generic
-	 * way.
+	 * way. This function also returns !=0 when we keep the
+	 * current active broadcast state.
 	 */
 	if (tick_device_uses_broadcast(newdev, cpu))
 		return;

Re: next-20130627 breaks i.MX6 sabre sd UART console

[Stephen Boyd]

On 07/01/13 13:14, Thomas Gleixner wrote:
> The issue is very subtle. What happens is:
>
> CPU0						CPU1
>
> Switch to oneshot mode
>
>  Copy the bits from tick_broadcast_mask to
>  tick_broadcast_oneshot_mask. We need to do
>  that so the other cpus reach the timer irq
>  and the softirq which switches them to
>  oneshot.
>
>  Kick the broadcast device into oneshot.
>
> 						Timer interrupt fires
> 						
> 						irq_enter sees the cpu in
> 						tick_broadcast_oneshot_mask and
> 						sets the device to oneshot mode
> 						
> 						handle_periodic:
> 						 Sees oneshot mode and adds
> 						 period to
> 						 dev->next_event(KTIME_MAX)
> 			

Yep. It is also racing with the timer interrupt so having more than two
CPUs must help widen the window (which is why we see it on the higher
numbered CPUs).

> 			 
> So we need two fixes:
>
> 1) The replacement of the dummy timer and the effect on the broadcast
>    mask/device
>
> 2) tick_check_oneshot_broadcast needs a sanity check
>
> Patch below.

Looks good.

Reviewed-by: Stephen Boyd <sboyd@codeaurora.org>

One minor typo in the comment below.

> +		switch (tick_broadcast_device.mode) {
> +		case TICKDEV_MODE_ONESHOT:
> +			/*
> +			 * If the system is in oneshot mode we can
> +			 * unconditionally clear the oneshot mask,
> +			 * because the CPU is running and therefor not

s/therefor/therefore/

-- 
Qualcomm Innovation Center, Inc. is a member of Code Aurora Forum,
hosted by The Linux Foundation

Re: next-20130627 breaks i.MX6 sabre sd UART console

[Thomas Gleixner]

On Mon, 1 Jul 2013, Stephen Boyd wrote:
> On 07/01/13 13:14, Thomas Gleixner wrote:
> > The issue is very subtle. What happens is:
> >
> > CPU0						CPU1
> >
> > Switch to oneshot mode
> >
> >  Copy the bits from tick_broadcast_mask to
> >  tick_broadcast_oneshot_mask. We need to do
> >  that so the other cpus reach the timer irq
> >  and the softirq which switches them to
> >  oneshot.
> >
> >  Kick the broadcast device into oneshot.
> >
> > 						Timer interrupt fires
> > 						
> > 						irq_enter sees the cpu in
> > 						tick_broadcast_oneshot_mask and
> > 						sets the device to oneshot mode
> > 						
> > 						handle_periodic:
> > 						 Sees oneshot mode and adds
> > 						 period to
> > 						 dev->next_event(KTIME_MAX)
> > 			
> 
> Yep. It is also racing with the timer interrupt so having more than two
> CPUs must help widen the window (which is why we see it on the higher
> numbered CPUs).

The race above is about the timer interrupt. You mean the broadcast
one which is still enabled due to the dummy -> functional transition
issue, right? That helps a lot to make this more visible, because we
double the number of events.

> > +			 * because the CPU is running and therefor not
> 
> s/therefor/therefore/

Duh. That one haunts me forever.

/me goes off to split the patch into two separate fixes, add proper
changelogs and wait for Vincents confirmation.

I really wish, that x86 would have been the only architecture which
made use of that broadcast nonsense. Though the ARM folks went there
and created the same mess as x86 but raised to the power of N, where

    N = Number of odd ARM chips designed by morons who thought that
      	copying the already publicly documented idiocy of x86 is a
      	brilliant idea.

Thanks,

	tglx

Re: next-20130627 breaks i.MX6 sabre sd UART console

[Stephen Boyd]

On 07/01/13 14:24, Thomas Gleixner wrote:
> On Mon, 1 Jul 2013, Stephen Boyd wrote:
>> On 07/01/13 13:14, Thomas Gleixner wrote:
>>> The issue is very subtle. What happens is:
>>>
>>> CPU0						CPU1
>>>
>>> Switch to oneshot mode
>>>
>>>  Copy the bits from tick_broadcast_mask to
>>>  tick_broadcast_oneshot_mask. We need to do
>>>  that so the other cpus reach the timer irq
>>>  and the softirq which switches them to
>>>  oneshot.
>>>
>>>  Kick the broadcast device into oneshot.
>>>
>>> 						Timer interrupt fires
>>> 						
>>> 						irq_enter sees the cpu in
>>> 						tick_broadcast_oneshot_mask and
>>> 						sets the device to oneshot mode
>>> 						
>>> 						handle_periodic:
>>> 						 Sees oneshot mode and adds
>>> 						 period to
>>> 						 dev->next_event(KTIME_MAX)
>>> 			
>> Yep. It is also racing with the timer interrupt so having more than two
>> CPUs must help widen the window (which is why we see it on the higher
>> numbered CPUs).
> The race above is about the timer interrupt. You mean the broadcast
> one which is still enabled due to the dummy -> functional transition
> issue, right? That helps a lot to make this more visible, because we
> double the number of events.

I was thinking that tick_check_oneshot_broadcast() is racing with
tick_switch_to_oneshot() and because we have more CPUs we're more likely
to have a CPU fix up the handler in tick_switch_to_oneshot() after
tick_check_oneshot_broadcast() forces that CPU to oneshot mode and the
periodic handler runs. I wonder if I can reproduce it locally by making
tick_switch_to_oneshot() spin for a jiffy or two on CPU1.

-- 
Qualcomm Innovation Center, Inc. is a member of Code Aurora Forum,
hosted by The Linux Foundation

Re: next-20130627 breaks i.MX6 sabre sd UART console

[Thomas Gleixner]

On Mon, 1 Jul 2013, Stephen Boyd wrote:
> On 07/01/13 14:24, Thomas Gleixner wrote:
> > On Mon, 1 Jul 2013, Stephen Boyd wrote:
> >> On 07/01/13 13:14, Thomas Gleixner wrote:
> >>> The issue is very subtle. What happens is:
> >>>
> >>> CPU0						CPU1
> >>>
> >>> Switch to oneshot mode
> >>>
> >>>  Copy the bits from tick_broadcast_mask to
> >>>  tick_broadcast_oneshot_mask. We need to do
> >>>  that so the other cpus reach the timer irq
> >>>  and the softirq which switches them to
> >>>  oneshot.
> >>>
> >>>  Kick the broadcast device into oneshot.
> >>>
> >>> 						Timer interrupt fires
> >>> 						
> >>> 						irq_enter sees the cpu in
> >>> 						tick_broadcast_oneshot_mask and
> >>> 						sets the device to oneshot mode
> >>> 						
> >>> 						handle_periodic:
> >>> 						 Sees oneshot mode and adds
> >>> 						 period to
> >>> 						 dev->next_event(KTIME_MAX)
> >>> 			
> >> Yep. It is also racing with the timer interrupt so having more than two
> >> CPUs must help widen the window (which is why we see it on the higher
> >> numbered CPUs).
> > The race above is about the timer interrupt. You mean the broadcast
> > one which is still enabled due to the dummy -> functional transition
> > issue, right? That helps a lot to make this more visible, because we
> > double the number of events.
> 
> I was thinking that tick_check_oneshot_broadcast() is racing with
> tick_switch_to_oneshot() and because we have more CPUs we're more likely
> to have a CPU fix up the handler in tick_switch_to_oneshot() after
> tick_check_oneshot_broadcast() forces that CPU to oneshot mode and the
> periodic handler runs. I wonder if I can reproduce it locally by making
> tick_switch_to_oneshot() spin for a jiffy or two on CPU1.

tick_switch_to_oneshot() is invoked with interrupts disabled, so that
wont help. 

RE: next-20130627 breaks i.MX6 sabre sd UART console

[Stehle Vincent-B46079]

> From: Thomas Gleixner [mailto:tglx@linutronix.de]
(..)
> So we need two fixes:
> 
> 1) The replacement of the dummy timer and the effect on the broadcast
>    mask/device
> 
> 2) tick_check_oneshot_broadcast needs a sanity check
> 
> Patch below.

Hi,

Thank you for your patch Thomas; I think it works :)

With your patch, next-20130702 boots pretty far on i.MX6 sabre sd, until it crashes in wm8962_probe(). Without this patch, I don't even get the first kernel messages. (Both with ARM config imx_v6_v7_defconfig.)

Also, I am pretty sure the wm8962_probe() issue is unrelated, as it happened even before this timer thing.

Thank you!

Best regards,

V.

[tip:timers/core] tick: Prevent uncontrolled switch to oneshot mode

[tip-bot for Thomas Gleixner]

Commit-ID:  1f73a9806bdd07a5106409bbcab3884078bd34fe
Gitweb:     http://git.kernel.org/tip/1f73a9806bdd07a5106409bbcab3884078bd34fe
Author:     Thomas Gleixner <tglx@linutronix.de>
AuthorDate: Mon, 1 Jul 2013 22:14:10 +0200
Committer:  Thomas Gleixner <tglx@linutronix.de>
CommitDate: Tue, 2 Jul 2013 14:26:45 +0200

tick: Prevent uncontrolled switch to oneshot mode

When the system switches from periodic to oneshot mode, the broadcast
logic causes a possibility that a CPU which has not yet switched to
oneshot mode puts its own clock event device into oneshot mode without
updating the state and the timer handler.

CPU0				CPU1
				per cpu tickdev is in periodic mode
				and switched to broadcast

Switch to oneshot mode
 tick_broadcast_switch_to_oneshot()
  cpumask_copy(tick_oneshot_broacast_mask,
	       tick_broadcast_mask);

  broadcast device mode = oneshot

				Timer interrupt
						
				irq_enter()
				 tick_check_oneshot_broadcast()
				  dev->set_mode(ONESHOT);

				tick_handle_periodic()
				 if (dev->mode == ONESHOT)
				   dev->next_event += period;
				   FAIL.

We fail, because dev->next_event contains KTIME_MAX, if the device was
in periodic mode before the uncontrolled switch to oneshot happened.

We must copy the broadcast bits over to the oneshot mask, because
otherwise a CPU which relies on the broadcast would not been woken up
anymore after the broadcast device switched to oneshot mode.

So we need to verify in tick_check_oneshot_broadcast() whether the CPU
has already switched to oneshot mode. If not, leave the device
untouched and let the CPU switch controlled into oneshot mode.

This is a long standing bug, which was never noticed, because the main
user of the broadcast x86 cannot run into that scenario, AFAICT. The
nonarchitected timer mess of ARM creates a gazillion of differently
broken abominations which trigger the shortcomings of that broadcast
code, which better had never been necessary in the first place.

Reported-and-tested-by: Stehle Vincent-B46079 <B46079@freescale.com>
Reviewed-by: Stephen Boyd <sboyd@codeaurora.org>
Cc: John Stultz <john.stultz@linaro.org>,
Cc: Mark Rutland <mark.rutland@arm.com>
Link: http://lkml.kernel.org/r/alpine.DEB.2.02.1307012153060.4013@ionos.tec.linutronix.de
Cc: stable@vger.kernel.org
Signed-off-by: Thomas Gleixner <tglx@linutronix.de>
---
 kernel/time/tick-broadcast.c | 10 +++++++++-
 1 file changed, 9 insertions(+), 1 deletion(-)

diff --git a/kernel/time/tick-broadcast.c b/kernel/time/tick-broadcast.c
index 4790037..248f80d 100644
--- a/kernel/time/tick-broadcast.c
+++ b/kernel/time/tick-broadcast.c
@@ -492,7 +492,15 @@ void tick_check_oneshot_broadcast(int cpu)
 	if (cpumask_test_cpu(cpu, tick_broadcast_oneshot_mask)) {
 		struct tick_device *td = &per_cpu(tick_cpu_device, cpu);
 
-		clockevents_set_mode(td->evtdev, CLOCK_EVT_MODE_ONESHOT);
+		/*
+		 * We might be in the middle of switching over from
+		 * periodic to oneshot. If the CPU has not yet
+		 * switched over, leave the device alone.
+		 */
+		if (td->mode == TICKDEV_MODE_ONESHOT) {
+			clockevents_set_mode(td->evtdev,
+					     CLOCK_EVT_MODE_ONESHOT);
+		}
 	}
 }
 

[tip:timers/core] tick: Sanitize broadcast control logic

[tip-bot for Thomas Gleixner]

Commit-ID:  07bd1172902e782f288e4d44b1fde7dec0f08b6f
Gitweb:     http://git.kernel.org/tip/07bd1172902e782f288e4d44b1fde7dec0f08b6f
Author:     Thomas Gleixner <tglx@linutronix.de>
AuthorDate: Mon, 1 Jul 2013 22:14:10 +0200
Committer:  Thomas Gleixner <tglx@linutronix.de>
CommitDate: Tue, 2 Jul 2013 14:26:45 +0200

tick: Sanitize broadcast control logic

The recent implementation of a generic dummy timer resulted in a
different registration order of per cpu local timers which made the
broadcast control logic go belly up.

If the dummy timer is the first clock event device which is registered
for a CPU, then it is installed, the broadcast timer is initialized
and the CPU is marked as broadcast target.

If a real clock event device is installed after that, we can fail to
take the CPU out of the broadcast mask. In the worst case we end up
with two periodic timer events firing for the same CPU. One from the
per cpu hardware device and one from the broadcast.

Now the problem is that we have no way to distinguish whether the
system is in a state which makes broadcasting necessary or the
broadcast bit was set due to the nonfunctional dummy timer
installment.

To solve this we need to keep track of the system state seperately and
provide a more detailed decision logic whether we keep the CPU in
broadcast mode or not.

The old decision logic only clears the broadcast mode, if the newly
installed clock event device is not affected by power states.

The new logic clears the broadcast mode if one of the following is
true:

  - The new device is not affected by power states.

  - The system is not in a power state affected mode

  - The system has switched to oneshot mode. The oneshot broadcast is
    controlled from the deep idle state. The CPU is not in idle at
    this point, so it's safe to remove it from the mask.

If we clear the broadcast bit for the CPU when a new device is
installed, we also shutdown the broadcast device when this was the
last CPU in the broadcast mask.

If the broadcast bit is kept, then we leave the new device in shutdown
state and rely on the broadcast to deliver the timer interrupts via
the broadcast ipis.

Reported-and-tested-by: Stehle Vincent-B46079 <B46079@freescale.com>
Reviewed-by: Stephen Boyd <sboyd@codeaurora.org>
Cc: John Stultz <john.stultz@linaro.org>,
Cc: Mark Rutland <mark.rutland@arm.com>
Link: http://lkml.kernel.org/r/alpine.DEB.2.02.1307012153060.4013@ionos.tec.linutronix.de
Cc: stable@vger.kernel.org
Signed-off-by: Thomas Gleixner <tglx@linutronix.de>

---
 kernel/time/tick-broadcast.c | 70 +++++++++++++++++++++++++++++++++++++-------
 kernel/time/tick-common.c    |  3 +-
 2 files changed, 61 insertions(+), 12 deletions(-)

diff --git a/kernel/time/tick-broadcast.c b/kernel/time/tick-broadcast.c
index 248f80d..4430fa6 100644
--- a/kernel/time/tick-broadcast.c
+++ b/kernel/time/tick-broadcast.c
@@ -30,6 +30,7 @@
 
 static struct tick_device tick_broadcast_device;
 static cpumask_var_t tick_broadcast_mask;
+static cpumask_var_t tick_broadcast_on;
 static cpumask_var_t tmpmask;
 static DEFINE_RAW_SPINLOCK(tick_broadcast_lock);
 static int tick_broadcast_force;
@@ -140,8 +141,9 @@ static void tick_device_setup_broadcast_func(struct clock_event_device *dev)
  */
 int tick_device_uses_broadcast(struct clock_event_device *dev, int cpu)
 {
+	struct clock_event_device *bc = tick_broadcast_device.evtdev;
 	unsigned long flags;
-	int ret = 0;
+	int ret;
 
 	raw_spin_lock_irqsave(&tick_broadcast_lock, flags);
 
@@ -155,20 +157,59 @@ int tick_device_uses_broadcast(struct clock_event_device *dev, int cpu)
 		dev->event_handler = tick_handle_periodic;
 		tick_device_setup_broadcast_func(dev);
 		cpumask_set_cpu(cpu, tick_broadcast_mask);
-		tick_broadcast_start_periodic(tick_broadcast_device.evtdev);
+		tick_broadcast_start_periodic(bc);
 		ret = 1;
 	} else {
 		/*
-		 * When the new device is not affected by the stop
-		 * feature and the cpu is marked in the broadcast mask
-		 * then clear the broadcast bit.
+		 * Clear the broadcast bit for this cpu if the
+		 * device is not power state affected.
 		 */
-		if (!(dev->features & CLOCK_EVT_FEAT_C3STOP)) {
-			int cpu = smp_processor_id();
+		if (!(dev->features & CLOCK_EVT_FEAT_C3STOP))
 			cpumask_clear_cpu(cpu, tick_broadcast_mask);
-			tick_broadcast_clear_oneshot(cpu);
-		} else {
+		else
 			tick_device_setup_broadcast_func(dev);
+
+		/*
+		 * Clear the broadcast bit if the CPU is not in
+		 * periodic broadcast on state.
+		 */
+		if (!cpumask_test_cpu(cpu, tick_broadcast_on))
+			cpumask_clear_cpu(cpu, tick_broadcast_mask);
+
+		switch (tick_broadcast_device.mode) {
+		case TICKDEV_MODE_ONESHOT:
+			/*
+			 * If the system is in oneshot mode we can
+			 * unconditionally clear the oneshot mask bit,
+			 * because the CPU is running and therefore
+			 * not in an idle state which causes the power
+			 * state affected device to stop. Let the
+			 * caller initialize the device.
+			 */
+			tick_broadcast_clear_oneshot(cpu);
+			ret = 0;
+			break;
+
+		case TICKDEV_MODE_PERIODIC:
+			/*
+			 * If the system is in periodic mode, check
+			 * whether the broadcast device can be
+			 * switched off now.
+			 */
+			if (cpumask_empty(tick_broadcast_mask) && bc)
+				clockevents_shutdown(bc);
+			/*
+			 * If we kept the cpu in the broadcast mask,
+			 * tell the caller to leave the per cpu device
+			 * in shutdown state. The periodic interrupt
+			 * is delivered by the broadcast device.
+			 */
+			ret = cpumask_test_cpu(cpu, tick_broadcast_mask);
+			break;
+		default:
+			/* Nothing to do */
+			ret = 0;
+			break;
 		}
 	}
 	raw_spin_unlock_irqrestore(&tick_broadcast_lock, flags);
@@ -298,6 +339,7 @@ static void tick_do_broadcast_on_off(unsigned long *reason)
 	switch (*reason) {
 	case CLOCK_EVT_NOTIFY_BROADCAST_ON:
 	case CLOCK_EVT_NOTIFY_BROADCAST_FORCE:
+		cpumask_set_cpu(cpu, tick_broadcast_on);
 		if (!cpumask_test_and_set_cpu(cpu, tick_broadcast_mask)) {
 			if (tick_broadcast_device.mode ==
 			    TICKDEV_MODE_PERIODIC)
@@ -307,8 +349,12 @@ static void tick_do_broadcast_on_off(unsigned long *reason)
 			tick_broadcast_force = 1;
 		break;
 	case CLOCK_EVT_NOTIFY_BROADCAST_OFF:
-		if (!tick_broadcast_force &&
-		    cpumask_test_and_clear_cpu(cpu, tick_broadcast_mask)) {
+		if (tick_broadcast_force)
+			break;
+		cpumask_clear_cpu(cpu, tick_broadcast_on);
+		if (!tick_device_is_functional(dev))
+			break;
+		if (cpumask_test_and_clear_cpu(cpu, tick_broadcast_mask)) {
 			if (tick_broadcast_device.mode ==
 			    TICKDEV_MODE_PERIODIC)
 				tick_setup_periodic(dev, 0);
@@ -366,6 +412,7 @@ void tick_shutdown_broadcast(unsigned int *cpup)
 
 	bc = tick_broadcast_device.evtdev;
 	cpumask_clear_cpu(cpu, tick_broadcast_mask);
+	cpumask_clear_cpu(cpu, tick_broadcast_on);
 
 	if (tick_broadcast_device.mode == TICKDEV_MODE_PERIODIC) {
 		if (bc && cpumask_empty(tick_broadcast_mask))
@@ -821,6 +868,7 @@ bool tick_broadcast_oneshot_available(void)
 void __init tick_broadcast_init(void)
 {
 	zalloc_cpumask_var(&tick_broadcast_mask, GFP_NOWAIT);
+	zalloc_cpumask_var(&tick_broadcast_on, GFP_NOWAIT);
 	zalloc_cpumask_var(&tmpmask, GFP_NOWAIT);
 #ifdef CONFIG_TICK_ONESHOT
 	zalloc_cpumask_var(&tick_broadcast_oneshot_mask, GFP_NOWAIT);
diff --git a/kernel/time/tick-common.c b/kernel/time/tick-common.c
index edd45f6..64522ec 100644
--- a/kernel/time/tick-common.c
+++ b/kernel/time/tick-common.c
@@ -194,7 +194,8 @@ static void tick_setup_device(struct tick_device *td,
 	 * When global broadcasting is active, check if the current
 	 * device is registered as a placeholder for broadcast mode.
 	 * This allows us to handle this x86 misfeature in a generic
-	 * way.
+	 * way. This function also returns !=0 when we keep the
+	 * current active broadcast state for this CPU.
 	 */
 	if (tick_device_uses_broadcast(newdev, cpu))
 		return;