Date:	Thu, 8 Aug 2013 10:22:46 -0700
From:	Sören Brinkmann <soren.brinkmann@...inx.com>
To:	Mark Rutland <mark.rutland@....com>
CC:	Daniel Lezcano <daniel.lezcano@...aro.org>,
	Russell King <linux@....linux.org.uk>,
	Stephen Boyd <sboyd@...eaurora.org>,
	Michal Simek <michal.simek@...inx.com>,
	"linux-kernel@...r.kernel.org" <linux-kernel@...r.kernel.org>,
	Stuart Menefy <stuart.menefy@...com>,
	John Stultz <john.stultz@...aro.org>,
	Thomas Gleixner <tglx@...utronix.de>,
	"linux-arm-kernel@...ts.infradead.org" 
	<linux-arm-kernel@...ts.infradead.org>
Subject: Re: Enable arm_global_timer for Zynq brakes boot

On Thu, Aug 08, 2013 at 06:16:50PM +0100, Mark Rutland wrote:
> On Thu, Aug 08, 2013 at 06:11:26PM +0100, Sören Brinkmann wrote:
> > Hi Daniel,
> > 
> > On Thu, Aug 01, 2013 at 07:48:04PM +0200, Daniel Lezcano wrote:
> > > On 08/01/2013 07:43 PM, Sören Brinkmann wrote:
> > > > On Thu, Aug 01, 2013 at 07:29:12PM +0200, Daniel Lezcano wrote:
> > > >> On 08/01/2013 01:38 AM, Sören Brinkmann wrote:
> > > >>> On Thu, Aug 01, 2013 at 01:01:27AM +0200, Daniel Lezcano wrote:
> > > >>>> On 08/01/2013 12:18 AM, Sören Brinkmann wrote:
> > > >>>>> On Wed, Jul 31, 2013 at 11:08:51PM +0200, Daniel Lezcano wrote:
> > > >>>>>> On 07/31/2013 10:58 PM, Sören Brinkmann wrote:
> > > >>>>>>> On Wed, Jul 31, 2013 at 10:49:06PM +0200, Daniel Lezcano wrote:
> > > >>>>>>>> On 07/31/2013 12:34 AM, Sören Brinkmann wrote:
> > > >>>>>>>>> On Tue, Jul 30, 2013 at 10:47:15AM +0200, Daniel Lezcano wrote:
> > > >>>>>>>>>> On 07/30/2013 02:03 AM, Sören Brinkmann wrote:
> > > >>>>>>>>>>> Hi Daniel,
> > > >>>>>>>>>>>
> > > >>>>>>>>>>> On Mon, Jul 29, 2013 at 02:51:49PM +0200, Daniel Lezcano wrote:
> > > >>>>>>>>>>> (snip)
> > > >>>>>>>>>>>>
> > > >>>>>>>>>>>> the CPUIDLE_FLAG_TIMER_STOP flag tells the cpuidle framework the local
> > > >>>>>>>>>>>> timer will be stopped when entering to the idle state. In this case, the
> > > >>>>>>>>>>>> cpuidle framework will call clockevents_notify(ENTER) and switches to a
> > > >>>>>>>>>>>> broadcast timer and will call clockevents_notify(EXIT) when exiting the
> > > >>>>>>>>>>>> idle state, switching the local timer back in use.
> > > >>>>>>>>>>>
> > > >>>>>>>>>>> I've been thinking about this, trying to understand how this makes my
> > > >>>>>>>>>>> boot attempts on Zynq hang. IIUC, the wrongly provided TIMER_STOP flag
> > > >>>>>>>>>>> would make the timer core switch to a broadcast device even though it
> > > >>>>>>>>>>> wouldn't be necessary. But shouldn't it still work? It sounds like we do
> > > >>>>>>>>>>> something useless, but nothing wrong in a sense that it should result in
> > > >>>>>>>>>>> breakage. I guess I'm missing something obvious. This timer system will
> > > >>>>>>>>>>> always remain a mystery to me.
> > > >>>>>>>>>>>
> > > >>>>>>>>>>> Actually this more or less leads to the question: What is this
> > > >>>>>>>>>>> 'broadcast timer'. I guess that is some clockevent device which is
> > > >>>>>>>>>>> common to all cores? (that would be the cadence_ttc for Zynq). Is the
> > > >>>>>>>>>>> hang pointing to some issue with that driver?
> > > >>>>>>>>>>
> > > >>>>>>>>>> If you look at the /proc/timer_list, which timer is used for broadcasting ?
> > > >>>>>>>>>
> > > >>>>>>>>> So, the correct run results (full output attached).
> > > >>>>>>>>>
> > > >>>>>>>>> The vanilla kernel uses the twd timers as local timers and the TTC as
> > > >>>>>>>>> broadcast device:
> > > >>>>>>>>>     Tick Device: mode:     1
> > > >>>>>>>>>     Broadcast device
> > > >>>>>>>>>     Clock Event Device: ttc_clockevent
> > > >>>>>>>>>
> > > >>>>>>>>> When I remove the offending CPUIDLE flag and add the DT fragment to
> > > >>>>>>>>> enable the global timer, the twd timers are still used as local timers
> > > >>>>>>>>> and the broadcast device is the global timer:
> > > >>>>>>>>>     Tick Device: mode:     1
> > > >>>>>>>>>     Broadcast device
> > > >>>>>>>>>     Clock Event Device: arm_global_timer
> > > >>>>>>>>>
> > > >>>>>>>>> Again, since boot hangs in the actually broken case, I don't see way to
> > > >>>>>>>>> obtain this information for that case.
> > > >>>>>>>>
> > > >>>>>>>> Can't you use the maxcpus=1 option to ensure the system to boot up ?
> > > >>>>>>>
> > > >>>>>>> Right, that works. I forgot about that option after you mentioned, that
> > > >>>>>>> it is most likely not that useful.
> > > >>>>>>>
> > > >>>>>>> Anyway, this are those sysfs files with an unmodified cpuidle driver and
> > > >>>>>>> the gt enabled and having maxcpus=1 set.
> > > >>>>>>>
> > > >>>>>>> /proc/timer_list:
> > > >>>>>>>       Tick Device: mode:     1
> > > >>>>>>>       Broadcast device
> > > >>>>>>>       Clock Event Device: arm_global_timer
> > > >>>>>>>        max_delta_ns:   12884902005
> > > >>>>>>>        min_delta_ns:   1000
> > > >>>>>>>        mult:           715827876
> > > >>>>>>>        shift:          31
> > > >>>>>>>        mode:           3
> > > >>>>>>
> > > >>>>>> Here the mode is 3 (CLOCK_EVT_MODE_ONESHOT)
> > > >>>>>>
> > > >>>>>> The previous timer_list output you gave me when removing the offending
> > > >>>>>> cpuidle flag, it was 1 (CLOCK_EVT_MODE_SHUTDOWN).
> > > >>>>>>
> > > >>>>>> Is it possible you try to get this output again right after onlining the
> > > >>>>>> cpu1 in order to check if the broadcast device switches to SHUTDOWN ?
> > > >>>>>
> > > >>>>> How do I do that? I tried to online CPU1 after booting with maxcpus=1
> > > >>>>> and that didn't end well:
> > > >>>>>         # echo 1 > online && cat /proc/timer_list
> > > >>>>
> > > >>>> Hmm, I was hoping to have a small delay before the kernel hangs but
> > > >>>> apparently this is not the case... :(
> > > >>>>
> > > >>>> I suspect the global timer is shutdown at one moment but I don't
> > > >>>> understand why and when.
> > > >>>>
> > > >>>> Can you add a stack trace in the "clockevents_shutdown" function with
> > > >>>> the clockevent device name ? Perhaps, we may see at boot time an
> > > >>>> interesting trace when it hangs.
> > > >>>
> > > >>> I did this change:
> > > >>>   diff --git a/kernel/time/clockevents.c b/kernel/time/clockevents.c
> > > >>>   index 38959c8..3ab11c1 100644
> > > >>>   --- a/kernel/time/clockevents.c
> > > >>>   +++ b/kernel/time/clockevents.c
> > > >>>   @@ -92,6 +92,8 @@ void clockevents_set_mode(struct clock_event_device *dev,
> > > >>>     */
> > > >>>    void clockevents_shutdown(struct clock_event_device *dev)
> > > >>>    {
> > > >>>   +       pr_info("ce->name:%s\n", dev->name);
> > > >>>   +       dump_stack();
> > > >>>           clockevents_set_mode(dev, CLOCK_EVT_MODE_SHUTDOWN);
> > > >>>           dev->next_event.tv64 = KTIME_MAX;
> > > >>>    }
> > > >>>
> > > >>> It is hit a few times during boot, so I attach a full boot log. I really
> > > >>> don't know what to look for, but I hope you can spot something in it. I
> > > >>> really appreciate you taking the time.
> > > >>
> > > >> Thanks for the traces.
> > > >
> > > > Sure.
> > > >
> > > >>
> > > >> If you try without the ttc_clockevent configured in the kernel (but with
> > > >> twd and gt), does it boot ?
> > > >
> > > > Absence of the TTC doesn't seem to make any difference. It hangs at the
> > > > same location.
> > >
> > > Ok, IMO there is a problem with the broadcast device registration (may
> > > be vs twd).
> > 
> > I have an idea, but no real evidence to prove it:
> > Some of the registers in the arm_global_timer are banked per CPU. I.e.
> > some code must be executed on the CPU the timer is associated with
> > (struct clock_event_device.cpumask) to have the intended effect
> > As far as I can tell, there is no guarantee, that the set_mode()
> > and program_next_event() calls execute on the correct CPU.
> 
> I believe the core clockevents code enforces that, or all other percpu
> clockevent_device drivers would be horrifically broken.

Well, I have some evidence. I booted into the system (bootlog attached).
It seems to be luck to not deadlock.
In between I also had some additional print statements in the global
timer driver which seemed to back up my suspicion.

This is the ugly hack I added to the clockevents core:

diff --git a/kernel/time/clockevents.c b/kernel/time/clockevents.c
index 38959c8..419c973 100644
--- a/kernel/time/clockevents.c
+++ b/kernel/time/clockevents.c
@@ -59,6 +59,20 @@ u64 clockevent_delta2ns(unsigned long latch, struct clock_event_device *evt)
 }
 EXPORT_SYMBOL_GPL(clockevent_delta2ns);
 
+struct ce_set_mode_args {
+	struct clock_event_device *dev;
+	enum clock_event_mode mode;
+};
+
+static struct ce_set_mode_args ce_mode_args;
+
+static void ce_set_mode_xcall(void *info)
+{
+	struct ce_set_mode_args *args = info;
+
+	args->dev->set_mode(args->mode, args->dev);
+}
+
 /**
  * clockevents_set_mode - set the operating mode of a clock event device
  * @dev:	device to modify
@@ -70,7 +84,10 @@ void clockevents_set_mode(struct clock_event_device *dev,
 				 enum clock_event_mode mode)
 {
 	if (dev->mode != mode) {
-		dev->set_mode(mode, dev);
+		ce_mode_args.mode = mode;
+		ce_mode_args.dev = dev;
+		smp_call_function_any(dev->cpumask, ce_set_mode_xcall,
+				&ce_mode_args, 1);
 		dev->mode = mode;
 
 		/*
@@ -96,6 +113,20 @@ void clockevents_shutdown(struct clock_event_device *dev)
 	dev->next_event.tv64 = KTIME_MAX;
 }
 
+struct ce_prog_eve_args {
+	struct clock_event_device *dev;
+	unsigned long clc;
+};
+
+static struct ce_prog_eve_args ce_prog_eve_args;
+
+static void  ce_prog_event_xcall(void *info)
+{
+	struct ce_prog_eve_args *args = info;
+
+	args->dev->set_next_event(args->clc, args->dev);
+}
+
 #ifdef CONFIG_GENERIC_CLOCKEVENTS_MIN_ADJUST
 
 /* Limit min_delta to a jiffie */
@@ -141,6 +172,7 @@ static int clockevents_program_min_delta(struct clock_event_device *dev)
 	unsigned long long clc;
 	int64_t delta;
 	int i;
+	int cpu;
 
 	for (i = 0;;) {
 		delta = dev->min_delta_ns;
@@ -151,8 +183,11 @@ static int clockevents_program_min_delta(struct clock_event_device *dev)
 
 		dev->retries++;
 		clc = ((unsigned long long) delta * dev->mult) >> dev->shift;
-		if (dev->set_next_event((unsigned long) clc, dev) == 0)
-			return 0;
+		ce_prog_eve_args.clc = clc;
+		ce_prog_eve_args.dev = dev;
+		smp_call_function_any(dev->cpumask, ce_prog_event_xcall,
+				&ce_prog_eve_args, 1);
+		return 0;
 
 		if (++i > 2) {
 			/*
@@ -179,6 +214,7 @@ static int clockevents_program_min_delta(struct clock_event_device *dev)
 {
 	unsigned long long clc;
 	int64_t delta;
+	int ret;
 
 	delta = dev->min_delta_ns;
 	dev->next_event = ktime_add_ns(ktime_get(), delta);
@@ -188,7 +224,13 @@ static int clockevents_program_min_delta(struct clock_event_device *dev)
 
 	dev->retries++;
 	clc = ((unsigned long long) delta * dev->mult) >> dev->shift;
-	return dev->set_next_event((unsigned long) clc, dev);
+	ce_prog_eve_args.clc = clc;
+	ce_prog_eve_args.dev = dev;
+	smp_call_function_any(dev->cpumask, ce_prog_event_xcall,
+			&ce_prog_eve_args, 1);
+	ret = 0;
+
+	return ret;
 }
 
 #endif /* CONFIG_GENERIC_CLOCKEVENTS_MIN_ADJUST */
@@ -230,7 +272,11 @@ int clockevents_program_event(struct clock_event_device *dev, ktime_t expires,
 	delta = max(delta, (int64_t) dev->min_delta_ns);
 
 	clc = ((unsigned long long) delta * dev->mult) >> dev->shift;
-	rc = dev->set_next_event((unsigned long) clc, dev);
+	ce_prog_eve_args.clc = clc;
+	ce_prog_eve_args.dev = dev;
+	smp_call_function_any(dev->cpumask, ce_prog_event_xcall,
+			&ce_prog_eve_args, 1);
+	rc = 0;
 
 	return (rc && force) ? clockevents_program_min_delta(dev) : rc;
 }


 	Sören


View attachment "boot.log" of type "text/plain" (21366 bytes)

Powered by blists - more mailing lists