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