2.6.14-git3: scheduling while atomic from cpufreq on Athlon64

Hi,

I'm getting some "scheduling while atomic" messages from 2.6.14-git3 on boot and on suspend/resume, eg.:

NET: Registered protocol family 1
powernow-k8: Found 1 AMD Athlon 64 / Opteron processors (version 1.50.4)
powernow-k8:    0 : fid 0x0 (800 MHz), vid 0x12 (1100 mV)
powernow-k8:    1 : fid 0x8 (1600 MHz), vid 0x6 (1400 mV)
powernow-k8:    2 : fid 0xa (1800 MHz), vid 0x2 (1500 mV)

cpu_init done, current fid 0xa, vid 0x2
scheduling while atomic: swapper/0x00000001/1

Call Trace:<ffffffff8035014a>{schedule+122} <ffffffff80163576>{poison_obj+70}
       <ffffffff801be269>{sysfs_new_dirent+41} <ffffffff80162989>{dbg_redzone1+25}
       <ffffffff801be269>{sysfs_new_dirent+41} <ffffffff80163908>{cache_alloc_debugcheck_after+280}
       <ffffffff8011cf1b>{powernowk8_target+139} <ffffffff80162989>{dbg_redzone1+25}
       <ffffffff802e0830>{cpufreq_stat_notifier_policy+304}
       <ffffffff802dfdb4>{__cpufreq_driver_target+116} <ffffffff801be269>{sysfs_new_dirent+41}
       <ffffffff802e097e>{cpufreq_governor_performance+62}
       <ffffffff802dec8d>{__cpufreq_governor+173} <ffffffff802df3a8>{__cpufreq_set_policy+440}
       <ffffffff802df5bf>{cpufreq_set_policy+79} <ffffffff802df946>{cpufreq_add_dev+806}
       <ffffffff802df540>{handle_update+0} <ffffffff802ae21a>{sysdev_driver_register+170}
       <ffffffff802df106>{cpufreq_register_driver+198} <ffffffff8010c122>{init+194}
       <ffffffff8010f556>{child_rip+8} <ffffffff8010c060>{init+0}
       <ffffffff8010f54e>{child_rip+0} 

scheduling while atomic: swapper/0x00000001/1

Call Trace:<ffffffff8035014a>{schedule+122} <ffffffff802e2453>{cpufreq_frequency_table_target+371}
       <ffffffff8011d60c>{powernowk8_target+1916} <ffffffff802dfdb4>{__cpufreq_driver_target+116}
       <ffffffff801be269>{sysfs_new_dirent+41} <ffffffff802e097e>{cpufreq_governor_performance+62}
       <ffffffff802dec8d>{__cpufreq_governor+173} <ffffffff802df3a8>{__cpufreq_set_policy+440}
       <ffffffff802df5bf>{cpufreq_set_policy+79} <ffffffff802df946>{cpufreq_add_dev+806}
       <ffffffff802df540>{handle_update+0} <ffffffff802ae21a>{sysdev_driver_register+170}
       <ffffffff802df106>{cpufreq_register_driver+198} <ffffffff8010c122>{init+194}
       <ffffffff8010f556>{child_rip+8} <ffffffff8010c060>{init+0}
       <ffffffff8010f54e>{child_rip+0} 

input: AT Translated Set 2 keyboard//class/input as input1 scheduling while atomic: swapper/0x00000001/1

Call Trace:<ffffffff8035014a>{schedule+122} <ffffffff802e2453>{cpufreq_frequency_table_target+371}
       <ffffffff8011cf1b>{powernowk8_target+139} <ffffffff802dfdb4>{__cpufreq_driver_target+116}
       <ffffffff801be269>{sysfs_new_dirent+41} <ffffffff802e097e>{cpufreq_governor_performance+62}
       <ffffffff802dec8d>{__cpufreq_governor+173} <ffffffff802df417>{__cpufreq_set_policy+551}
       <ffffffff802df5bf>{cpufreq_set_policy+79} <ffffffff802df946>{cpufreq_add_dev+806}
       <ffffffff802df540>{handle_update+0} <ffffffff802ae21a>{sysdev_driver_register+170}
       <ffffffff802df106>{cpufreq_register_driver+198} <ffffffff8010c122>{init+194}
       <ffffffff8010f556>{child_rip+8} <ffffffff8010c060>{init+0}
       <ffffffff8010f54e>{child_rip+0} 

scheduling while atomic: swapper/0x00000001/1

Call Trace:<ffffffff8035014a>{schedule+122} <ffffffff802e2453>{cpufreq_frequency_table_target+371}
       <ffffffff8011d60c>{powernowk8_target+1916} <ffffffff802dfdb4>{__cpufreq_driver_target+116}
       <ffffffff801be269>{sysfs_new_dirent+41} <ffffffff802e097e>{cpufreq_governor_performance+62}
       <ffffffff802dec8d>{__cpufreq_governor+173} <ffffffff802df417>{__cpufreq_set_policy+551}
       <ffffffff802df5bf>{cpufreq_set_policy+79} <ffffffff802df946>{cpufreq_add_dev+806}
       <ffffffff802df540>{handle_update+0} <ffffffff802ae21a>{sysdev_driver_register+170}
       <ffffffff802df106>{cpufreq_register_driver+198} <ffffffff8010c122>{init+194}
       <ffffffff8010f556>{child_rip+8} <ffffffff8010c060>{init+0}
       <ffffffff8010f54e>{child_rip+0} 

Additionally there are some problems with freezing processes by swsusp.

"Rafael J. Wysocki" <[email protected]> wrote:

Quoted 11 lines

scheduling while atomic: swapper/0x00000001/1

Call Trace:<ffffffff8035014a>{schedule+122} <ffffffff802e2453>{cpufreq_frequency_table_target+371}
       <ffffffff8011d60c>{powernowk8_target+1916} <ffffffff802dfdb4>{__cpufreq_driver_target+116}
       <ffffffff801be269>{sysfs_new_dirent+41} <ffffffff802e097e>{cpufreq_governor_performance+62}
       <ffffffff802dec8d>{__cpufreq_governor+173} <ffffffff802df417>{__cpufreq_set_policy+551}
       <ffffffff802df5bf>{cpufreq_set_policy+79} <ffffffff802df946>{cpufreq_add_dev+806}
       <ffffffff802df540>{handle_update+0} <ffffffff802ae21a>{sysdev_driver_register+170}
       <ffffffff802df106>{cpufreq_register_driver+198} <ffffffff8010c122>{init+194}
       <ffffffff8010f556>{child_rip+8} <ffffffff8010c060>{init+0}
       <ffffffff8010f54e>{child_rip+0} 

Well I can't find it. Ingo, didn't you have a debug patch which would help us identify where this atomic section started?

Quoted 1 line

Additionally there are some problems with freezing processes by swsusp.

Quoted 1 line · Andrew Morton

"Rafael J. Wysocki" <[email protected]> wrote:

}-- snip --{

Quoted 12 lines

Quoted 11 lines

scheduling while atomic: swapper/0x00000001/1

Call Trace:<ffffffff8035014a>{schedule+122} <ffffffff802e2453>{cpufreq_frequency_table_target+371}
       <ffffffff8011d60c>{powernowk8_target+1916} <ffffffff802dfdb4>{__cpufreq_driver_target+116}
       <ffffffff801be269>{sysfs_new_dirent+41} <ffffffff802e097e>{cpufreq_governor_performance+62}
       <ffffffff802dec8d>{__cpufreq_governor+173} <ffffffff802df417>{__cpufreq_set_policy+551}
       <ffffffff802df5bf>{cpufreq_set_policy+79} <ffffffff802df946>{cpufreq_add_dev+806}
       <ffffffff802df540>{handle_update+0} <ffffffff802ae21a>{sysdev_driver_register+170}
       <ffffffff802df106>{cpufreq_register_driver+198} <ffffffff8010c122>{init+194}
       <ffffffff8010f556>{child_rip+8} <ffffffff8010c060>{init+0}
       <ffffffff8010f54e>{child_rip+0} 

Quoted 2 lines

Well I can't find it. Ingo, didn't you have a debug patch which would help us identify where this atomic section started?

This is 100% reproducible on my box so I'll try to figure out what's up tomorrow (unless someone else does it earlier ;-)). Now I can only say it did not happen with 2.6.14-rc5-mm1.

Quoted 2 lines

Quoted 2 lines

Additionally there are some problems with freezing processes by swsusp.

Once the box has not suspended due to a process refusing to freeze, but I was unable to trace the problem at that time. This does not seem to be readily reproducible, however.

Greetings,
Rafael

Quoted 18 lines · Rafael J. Wysocki

Quoted 1 line · Andrew Morton

"Rafael J. Wysocki" <[email protected]> wrote:

}-- snip --{

Quoted 14 lines

Quoted 11 lines

scheduling while atomic: swapper/0x00000001/1

Call Trace:<ffffffff8035014a>{schedule+122} <ffffffff802e2453>{cpufreq_frequency_table_target+371}
       <ffffffff8011d60c>{powernowk8_target+1916} <ffffffff802dfdb4>{__cpufreq_driver_target+116}
       <ffffffff801be269>{sysfs_new_dirent+41} <ffffffff802e097e>{cpufreq_governor_performance+62}
       <ffffffff802dec8d>{__cpufreq_governor+173} <ffffffff802df417>{__cpufreq_set_policy+551}
       <ffffffff802df5bf>{cpufreq_set_policy+79} <ffffffff802df946>{cpufreq_add_dev+806}
       <ffffffff802df540>{handle_update+0} <ffffffff802ae21a>{sysdev_driver_register+170}
       <ffffffff802df106>{cpufreq_register_driver+198} <ffffffff8010c122>{init+194}
       <ffffffff8010f556>{child_rip+8} <ffffffff8010c060>{init+0}
       <ffffffff8010f54e>{child_rip+0} 

Well I can't find it. Ingo, didn't you have a debug patch which would help us identify where this atomic section started?

Quoted 3 lines

This is 100% reproducible on my box so I'll try to figure out what's up tomorrow (unless someone else does it earlier ;-)). Now I can only say it did not happen with 2.6.14-rc5-mm1.

This could be because of the new patch, i added preempt_disable() instead of taking cpucontrol lock in __cpufreq_driver_target().

The reason is we now enter the same code path from the cpu_up() and cpu_down() generated cpu notifier callbacks and ends up trying to lock when the call path already has the cpucontrol lock.

Its happening because we do set_cpus_allowed() in powernowk8_target().

Hi,

Quoted 1 line

of taking cpucontrol lock in __cpufreq_driver_target().

Yes, that's it.

Quoted 4 lines

The reason is we now enter the same code path from the cpu_up() and cpu_down() generated cpu notifier callbacks and ends up trying to lock when the call path already has the cpucontrol lock.

Quoted 1 line

Its happening because we do set_cpus_allowed() in powernowk8_target().

Unfortunately, powernowk8_target() calls schedule() right after set_cpus_allowed(), so it throws "scheduling while atomic" on every call, because of the preempt_disable()/_enable() around it.

Greetings,
Rafael

Quoted 10 lines · Rafael J. Wysocki

Hi,

Quoted 1 line

of taking cpucontrol lock in __cpufreq_driver_target().

Yes, that's it.

Quoted 4 lines

The reason is we now enter the same code path from the cpu_up() and cpu_down() generated cpu notifier callbacks and ends up trying to lock when the call path already has the cpucontrol lock.

Quoted 9 lines

Quoted 1 line

Its happening because we do set_cpus_allowed() in powernowk8_target().

Unfortunately, powernowk8_target() calls schedule() right after set_cpus_allowed(), so it throws "scheduling while atomic" on every call, because of the preempt_disable()/_enable() around it.

Greetings,
Rafael

Thanks Rafael,

could you try this patch instead? I hate to keep these state variables and thats why i went with the preempt approach, too bad it seems it wont work for more than just the case you mentioned.

seems ugly, but i dont find a better looking cure...

Quoted 7 lines · Ashok Raj

Thanks Rafael,

could you try this patch instead? I hate to keep these state variables and thats why i went with the preempt approach, too bad it seems it wont work for more than just the case you mentioned.

seems ugly, but i dont find a better looking cure...

It fixes my problem.

Quoted 10 lines · Rafael J. Wysocki

Hi,

Quoted 1 line

of taking cpucontrol lock in __cpufreq_driver_target().

Yes, that's it.

Quoted 4 lines

The reason is we now enter the same code path from the cpu_up() and cpu_down() generated cpu notifier callbacks and ends up trying to lock when the call path already has the cpucontrol lock.

Quoted 9 lines

Quoted 1 line

Its happening because we do set_cpus_allowed() in powernowk8_target().

Unfortunately, powernowk8_target() calls schedule() right after set_cpus_allowed(), so it throws "scheduling while atomic" on every call, because of the preempt_disable()/_enable() around it.

Greetings,
Rafael

Thanks Rafael,

could you try this patch instead? I hate to keep these state variables and thats why i went with the preempt approach, too bad it seems it wont work for more than just the case you mentioned.

seems ugly, but i dont find a better looking cure...

...

seems ugly, but i dont find a better looking cure...

When calling target drivers to set frequency, we used to take cpucontrol semaphore. When we modified the code to accomodate CPU hotplug, there was an attempt to take a double lock leading to a deadlock. Since the code called from under the CPU hotplug notifiers already hold the cpucontrol lock.

we attempted to circumvent this ugly state keeping by just doing a simple preempt_disable() and preempt_enable(), but that appears to get in the way when cpufreq drivers attempt to do set_cpus_allowed() since this call will go to sleep.

Now we just keep a state variable and each notifier path is supposed to set this to avoid the cpufreq driver taking double locks.

Signed-off-by Ashok Raj <[email protected]>

-----------------------------------------------------------------

 drivers/cpufreq/cpufreq.c       |   35 +++++++++++++++++++----------------
 drivers/cpufreq/cpufreq_stats.c |    2 ++
 include/linux/cpufreq.h         |    2 ++
 3 files changed, 23 insertions(+), 16 deletions(-)

Index: linux-2.6.14-rc4-mm1/drivers/cpufreq/cpufreq.c
===================================================================

drivers/cpufreq/cpufreq.c +19 -16

@@ -38,6 +38,8 @@ static struct cpufreq_driver   	*cpufreq
 static struct cpufreq_policy	*cpufreq_cpu_data[NR_CPUS];
 static DEFINE_SPINLOCK(cpufreq_driver_lock);
 
+int cpufreq_hotplug_inprogress;
+EXPORT_SYMBOL_GPL(cpufreq_hotplug_inprogress);
 
 /* internal prototypes */
 static int __cpufreq_governor(struct cpufreq_policy *policy, unsigned int event);

@@ -59,6 +61,18 @@ static DECLARE_RWSEM		(cpufreq_notifier_
 static LIST_HEAD(cpufreq_governor_list);
 static DECLARE_MUTEX		(cpufreq_governor_sem);
 
+static void cpufreq_lock_hotplug(void)
+{
+	if (!cpufreq_hotplug_inprogress)
+		lock_cpu_hotplug();
+}
+
+static void cpufreq_unlock_hotplug(void)
+{
+	if (!cpufreq_hotplug_inprogress)
+		unlock_cpu_hotplug();
+}
+
 struct cpufreq_policy * cpufreq_cpu_get(unsigned int cpu)
 {
 	struct cpufreq_policy *data;

@@ -1114,25 +1128,12 @@ int __cpufreq_driver_target(struct cpufr
 {
 	int retval = -EINVAL;
 
-	/*
-	 * Converted the lock_cpu_hotplug to preempt_disable()
-	 * and preempt enable. This is a bit kludgy and relies on
-	 * how cpu hotplug works. All we need is a gaurantee that cpu hotplug
-	 * wont make progress on any cpu. Once we do preempt_disable(), this
-	 * would ensure hotplug threads dont get on this cpu, thereby delaying
-	 * the cpu remove process.
-	 *
-	 * we removed the lock_cpu_hotplug since we need to call this function via
-	 * cpu hotplug callbacks, which result in locking the cpu hotplug
-	 * thread itself. Agree this is not very clean, cpufreq community
-	 * could improve this if required. - Ashok Raj <[email protected]>
-	 */
-	preempt_disable();
+	cpufreq_lock_hotplug();
 	dprintk("target for CPU %u: %u kHz, relation %u\n", policy->cpu,
 		target_freq, relation);
 	if (cpu_online(policy->cpu) && cpufreq_driver->target)
 		retval = cpufreq_driver->target(policy, target_freq, relation);
-	preempt_enable();
+	cpufreq_unlock_hotplug();
 	return retval;
 }
 EXPORT_SYMBOL_GPL(__cpufreq_driver_target);

@@ -1432,8 +1433,9 @@ static int __cpuinit cpufreq_cpu_callbac
 	struct sys_device *sys_dev;
 
 	sys_dev = get_cpu_sysdev(cpu);
-
+
 	if (sys_dev) {
+		cpufreq_hotplug_inprogress = 1;
 		switch (action) {
 			case CPU_ONLINE:
 				(void) cpufreq_add_dev(sys_dev);

@@ -1455,6 +1457,7 @@ static int __cpuinit cpufreq_cpu_callbac
 				(void) cpufreq_remove_dev(sys_dev);
 				break;
 		}
+		cpufreq_hotplug_inprogress = 0;
 	}
 	return NOTIFY_OK;
 }

Index: linux-2.6.14-rc4-mm1/drivers/cpufreq/cpufreq_stats.c
===================================================================

drivers/cpufreq/cpufreq_stats.c +2 -0

@@ -302,6 +302,7 @@ static int __cpuinit cpufreq_stat_cpu_ca
 {
 	unsigned int cpu = (unsigned long)hcpu;
 
+	cpufreq_hotplug_inprogress = 1;
 	switch (action) {
 		case CPU_ONLINE:
 			cpufreq_update_policy(cpu);

@@ -310,6 +311,7 @@ static int __cpuinit cpufreq_stat_cpu_ca
 			cpufreq_stats_free_table(cpu);
 			break;
 	}
+	cpufreq_hotplug_inprogress = 0;
 	return NOTIFY_OK;
 }
 

Index: linux-2.6.14-rc4-mm1/include/linux/cpufreq.h
===================================================================

include/linux/cpufreq.h +2 -0

@@ -156,6 +156,8 @@ struct cpufreq_governor {
 	struct module		*owner;
 };
 
+extern int cpufreq_hotplug_inprogress;
+
 /* pass a target to the cpufreq driver 
  */
 extern int cpufreq_driver_target(struct cpufreq_policy *policy,

Quoted 6 lines · Ashok Raj

...

seems ugly, but i dont find a better looking cure...

Could you take another look, please? It really is pretty gross.

And the second rule of pretty-gross code is to clearly comment it - draw

Quoted 6 lines · Ashok Raj

...

seems ugly, but i dont find a better looking cure...

Could you take another look, please? It really is pretty gross.

Now we leave a trace in current->flags indicating current thread already
is under cpucontrol lock held, so we dont attempt to do this another time.

..
+#define PF_HOTPLUG_CPU 0x01000000 /* Currently performing CPU hotplug */

Quoted 7 lines · Ashok Raj

Now we leave a trace in current->flags indicating current thread already
is under cpucontrol lock held, so we dont attempt to do this another time.

..
+#define PF_HOTPLUG_CPU 0x01000000 /* Currently performing CPU hotplug */

It's still hacky - I mean, we could use this trick to avoid recursion onto any lock in the kernel whenever we get ourselves into a mess. We'd gain an awful lot of PF_* flags.

So we should still view this as a temporary fix.

I don't think I've seen an analysis of the actual deadlock yet. Are you able to provide a stack trace of the offending callpath?

Quoted 9 lines · Andrew Morton

Quoted 7 lines · Ashok Raj

Now we leave a trace in current->flags indicating current thread already
is under cpucontrol lock held, so we dont attempt to do this another time.

..
+#define PF_HOTPLUG_CPU 0x01000000 /* Currently performing CPU hotplug */

Quoted 8 lines

It's still hacky - I mean, we could use this trick to avoid recursion onto any lock in the kernel whenever we get ourselves into a mess. We'd gain an awful lot of PF_* flags.

So we should still view this as a temporary fix.

I don't think I've seen an analysis of the actual deadlock yet. Are you able to provide a stack trace of the offending callpath?

Hi Andrew,

we call the exact same functions in cpufreq during startup and in response to cpu hotplug events, to create or destroy
sysfs entries /sys/devices/system/cpu/cpuX/cpufreq/*. cpufreq_add_dev().

problem is cpufreq_set_policy() eventually ends up calling __cpufreq_driver_target() during the CPU_ONLINE, and CPU_DOWN_PREPARE that takes cpucontrol lock.

Since when we already in the cpu notifier callbacks, cpucontrol is already held by the cpu_up() or the cpu_down() that caused the double lock.

Since when we already in the cpu notifier callbacks, cpucontrol is already held by the cpu_up() or the cpu_down() that caused the double lock.

Well I can't find it. Ingo, didn't you have a debug patch which would help us identify where this atomic section started?

Quoted 2 lines · Andrew Morton

Well I can't find it. Ingo, didn't you have a debug patch which would help us identify where this atomic section started?

yes. Find below the preempt-trace.patch, updated and merged to 2.6.14.

Rafael, just enable CONFIG_DEBUG_PREEMPT and repeat the reproducer.

Quoted 1 line

Additionally there are some problems with freezing processes by swsusp.

More details on this?