BUG: [preempt-rt] scheduling while atomic: stapio

BUG: [preempt-rt] scheduling while atomic: stapio

[Kiran]

Hi,

I am getting the following bug report in dmesg when I run pfaults.stp
script in the systemtap.examples/memory. I am using systemtap-0.9.7 and
kernel version is 2.6.29-rt4.

BUG: scheduling while atomic: stapio/0x00000001/26142, CPU#3
Modules linked in: stap_246f93f30a500769142af9987624737a_5072 ipv6 
autofs4 i2c_dev i2c_core hidp rfcomm l2cap bluetooth sunrpc dm_mirror 
dm_region_hash dm_log dm_multipath scsi_dh dm_mod video output sbs 
sbshc battery ac parport_pc lp parport sg bnx2 serio_raw button shpchp 
k8temp hwmon pcspkr mptsas mptscsih scsi_transport_sas mptbase sd_mod 
scsi_mod ext3 jbd mbcache uhci_hcd ohci_hcd ehci_hcd [last unloaded: 
stap_8455b451d15976a5e16919831aef7e51_3974]
Pid: 26142, comm: stapio Not tainted 2.6.29.1-rt4 #1
Call Trace:
 [<ffffffff81040341>] __schedule_bug+0x6f/0x8a
 [<ffffffff8136f748>] __schedule+0x9f/0x94a
 [<ffffffff81370433>] schedule+0x1d/0x46
 [<ffffffff81370597>] schedule_timeout+0x37/0x1a9
 [<ffffffff810415a9>] ? check_preempt_wakeup+0x138/0x16e
 [<ffffffff8136f3f2>] wait_for_common+0xcb/0x159
 [<ffffffff81043694>] ? default_wake_function+0x0/0x38
 [<ffffffff8136f5b9>] wait_for_completion+0x2b/0x41
 [<ffffffff8109cbc9>] __synchronize_sched+0x57/0x72
 [<ffffffff8105f335>] ? wakeme_after_rcu+0x0/0x36
 [<ffffffff81067016>] ? srcu_readers_active_idx+0x5e/0x89
 [<ffffffff810670b0>] synchronize_srcu+0x6f/0x96
 [<ffffffff8106787d>] srcu_notifier_chain_unregister+0x60/0x82
 [<ffffffff812a2dea>] cpufreq_unregister_notifier+0x35/0x5c
 [<ffffffffa02e0a1f>] _stp_kill_time+0xb6/0xbd [stap_246f93f30a500769142af9987624737a_5072]
 [<ffffffffa02e1749>] probe_1391+0x3c/0xa8 [stap_246f93f30a500769142af9987624737a_5072]
 [<ffffffffa02e2621>] enter_end_probe+0x14a/0x1e3 [stap_246f93f30a500769142af9987624737a_5072]
 [<ffffffffa02e2ed1>] _stp_cleanup_and_exit+0x2df/0x2f8 [stap_246f93f30a500769142af9987624737a_5072]
 [<ffffffffa02e51df>] _stp_ctl_write_cmd+0x460/0x7f8 [stap_246f93f30a500769142af9987624737a_5072]
 [<ffffffff81044e0b>] ? __wake_up+0x4d/0x6e 
 [<ffffffff81229bca>] ? tty_ldisc_deref+0x74/0x8f
 [<ffffffff81169d20>] ? security_file_permission+0x24/0x3a
 [<ffffffff810f00f7>] vfs_write+0xc1/0x180
 [<ffffffff810f07c3>] sys_write+0x56/0x93
 [<ffffffff8100beeb>] system_call_fastpath+0x16/0x1b

Could someone please provide pointers on the cause of this bug?

Re: BUG: [preempt-rt] scheduling while atomic: stapio

[Jim Keniston]

On Wed, 2009-05-20 at 15:14 +0530, Kiran wrote:
> Hi,
> 
> I am getting the following bug report in dmesg when I run pfaults.stp
> script in the systemtap.examples/memory. I am using systemtap-0.9.7 and
> kernel version is 2.6.29-rt4.

The first thing that comes to mind is that spinlocks are different in
(at least some) real-time kernels.  They can give up and sleep after a
while.  If you want spinlocks that are guaranteed not to sleep, you have
to use the raw_* versions of the spinlock functions.  That's about the
extent of my (mis)information on the subject.  I'm cc-ing an RT guy
(Darren) in case he can help.

Jim Keniston

> 
> BUG: scheduling while atomic: stapio/0x00000001/26142, CPU#3
> Modules linked in: stap_246f93f30a500769142af9987624737a_5072 ipv6 
> autofs4 i2c_dev i2c_core hidp rfcomm l2cap bluetooth sunrpc dm_mirror 
> dm_region_hash dm_log dm_multipath scsi_dh dm_mod video output sbs 
> sbshc battery ac parport_pc lp parport sg bnx2 serio_raw button shpchp 
> k8temp hwmon pcspkr mptsas mptscsih scsi_transport_sas mptbase sd_mod 
> scsi_mod ext3 jbd mbcache uhci_hcd ohci_hcd ehci_hcd [last unloaded: 
> stap_8455b451d15976a5e16919831aef7e51_3974]
> Pid: 26142, comm: stapio Not tainted 2.6.29.1-rt4 #1
> Call Trace:
>  [<ffffffff81040341>] __schedule_bug+0x6f/0x8a
>  [<ffffffff8136f748>] __schedule+0x9f/0x94a
>  [<ffffffff81370433>] schedule+0x1d/0x46
>  [<ffffffff81370597>] schedule_timeout+0x37/0x1a9
>  [<ffffffff810415a9>] ? check_preempt_wakeup+0x138/0x16e
>  [<ffffffff8136f3f2>] wait_for_common+0xcb/0x159
>  [<ffffffff81043694>] ? default_wake_function+0x0/0x38
>  [<ffffffff8136f5b9>] wait_for_completion+0x2b/0x41
>  [<ffffffff8109cbc9>] __synchronize_sched+0x57/0x72
>  [<ffffffff8105f335>] ? wakeme_after_rcu+0x0/0x36
>  [<ffffffff81067016>] ? srcu_readers_active_idx+0x5e/0x89
>  [<ffffffff810670b0>] synchronize_srcu+0x6f/0x96
>  [<ffffffff8106787d>] srcu_notifier_chain_unregister+0x60/0x82
>  [<ffffffff812a2dea>] cpufreq_unregister_notifier+0x35/0x5c
>  [<ffffffffa02e0a1f>] _stp_kill_time+0xb6/0xbd [stap_246f93f30a500769142af9987624737a_5072]
>  [<ffffffffa02e1749>] probe_1391+0x3c/0xa8 [stap_246f93f30a500769142af9987624737a_5072]
>  [<ffffffffa02e2621>] enter_end_probe+0x14a/0x1e3 [stap_246f93f30a500769142af9987624737a_5072]
>  [<ffffffffa02e2ed1>] _stp_cleanup_and_exit+0x2df/0x2f8 [stap_246f93f30a500769142af9987624737a_5072]
>  [<ffffffffa02e51df>] _stp_ctl_write_cmd+0x460/0x7f8 [stap_246f93f30a500769142af9987624737a_5072]
>  [<ffffffff81044e0b>] ? __wake_up+0x4d/0x6e 
>  [<ffffffff81229bca>] ? tty_ldisc_deref+0x74/0x8f
>  [<ffffffff81169d20>] ? security_file_permission+0x24/0x3a
>  [<ffffffff810f00f7>] vfs_write+0xc1/0x180
>  [<ffffffff810f07c3>] sys_write+0x56/0x93
>  [<ffffffff8100beeb>] system_call_fastpath+0x16/0x1b
> 
> Could someone please provide pointers on the cause of this bug?
> 
> 
> 

Re: BUG: [preempt-rt] scheduling while atomic: stapio

[Josh Stone]

On 05/20/2009 02:44 AM, Kiran wrote:
> BUG: scheduling while atomic: stapio/0x00000001/26142, CPU#3
> [...]
>  [<ffffffff812a2dea>] cpufreq_unregister_notifier+0x35/0x5c
>  [<ffffffffa02e0a1f>] _stp_kill_time+0xb6/0xbd [stap_246f93f30a500769142af9987624737a_5072]
>  [<ffffffffa02e1749>] probe_1391+0x3c/0xa8 [stap_246f93f30a500769142af9987624737a_5072]
>  [<ffffffffa02e2621>] enter_end_probe+0x14a/0x1e3 [stap_246f93f30a500769142af9987624737a_5072]

enter_end_probe will call preempt_disable, and apparently the call path
from cpufreq_unregister_notifier can sleep.  Is this true only of the RT
kernel?

I organized the init/kill_time calls this way to avoid running our time
code when it's not used.  I'll see if I can tweak it to run in a
sleep-able context...

Josh

Re: BUG: [preempt-rt] scheduling while atomic: stapio

[Darren Hart]

Jim Keniston wrote:
> On Wed, 2009-05-20 at 15:14 +0530, Kiran wrote:
>> Hi,

Hi Josh,

Sorry for the delay in responding, I'm on paternity leave right now, so 
I'm experiencing high email response latency ;-)

>>
>> I am getting the following bug report in dmesg when I run pfaults.stp

I presume that is a page fault tapset of some sort?

>> script in the systemtap.examples/memory. I am using systemtap-0.9.7 and
>> kernel version is 2.6.29-rt4.
> 
> The first thing that comes to mind is that spinlocks are different in
> (at least some) real-time kernels.  They can give up and sleep after a
> while.  If you want spinlocks that are guaranteed not to sleep, you have
> to use the raw_* versions of the spinlock functions.

Just the declaration actually, the functions are the same.

--
Darren

> That's about the
> extent of my (mis)information on the subject.  I'm cc-ing an RT guy
> (Darren) in case he can help.
> 
> Jim Keniston
> 
>> BUG: scheduling while atomic: stapio/0x00000001/26142, CPU#3
>> Modules linked in: stap_246f93f30a500769142af9987624737a_5072 ipv6 
>> autofs4 i2c_dev i2c_core hidp rfcomm l2cap bluetooth sunrpc dm_mirror 
>> dm_region_hash dm_log dm_multipath scsi_dh dm_mod video output sbs 
>> sbshc battery ac parport_pc lp parport sg bnx2 serio_raw button shpchp 
>> k8temp hwmon pcspkr mptsas mptscsih scsi_transport_sas mptbase sd_mod 
>> scsi_mod ext3 jbd mbcache uhci_hcd ohci_hcd ehci_hcd [last unloaded: 
>> stap_8455b451d15976a5e16919831aef7e51_3974]
>> Pid: 26142, comm: stapio Not tainted 2.6.29.1-rt4 #1
>> Call Trace:
>>  [<ffffffff81040341>] __schedule_bug+0x6f/0x8a
>>  [<ffffffff8136f748>] __schedule+0x9f/0x94a
>>  [<ffffffff81370433>] schedule+0x1d/0x46
>>  [<ffffffff81370597>] schedule_timeout+0x37/0x1a9
>>  [<ffffffff810415a9>] ? check_preempt_wakeup+0x138/0x16e
>>  [<ffffffff8136f3f2>] wait_for_common+0xcb/0x159
>>  [<ffffffff81043694>] ? default_wake_function+0x0/0x38
>>  [<ffffffff8136f5b9>] wait_for_completion+0x2b/0x41
>>  [<ffffffff8109cbc9>] __synchronize_sched+0x57/0x72
>>  [<ffffffff8105f335>] ? wakeme_after_rcu+0x0/0x36
>>  [<ffffffff81067016>] ? srcu_readers_active_idx+0x5e/0x89
>>  [<ffffffff810670b0>] synchronize_srcu+0x6f/0x96
>>  [<ffffffff8106787d>] srcu_notifier_chain_unregister+0x60/0x82
>>  [<ffffffff812a2dea>] cpufreq_unregister_notifier+0x35/0x5c
>>  [<ffffffffa02e0a1f>] _stp_kill_time+0xb6/0xbd [stap_246f93f30a500769142af9987624737a_5072]
>>  [<ffffffffa02e1749>] probe_1391+0x3c/0xa8 [stap_246f93f30a500769142af9987624737a_5072]
>>  [<ffffffffa02e2621>] enter_end_probe+0x14a/0x1e3 [stap_246f93f30a500769142af9987624737a_5072]
>>  [<ffffffffa02e2ed1>] _stp_cleanup_and_exit+0x2df/0x2f8 [stap_246f93f30a500769142af9987624737a_5072]
>>  [<ffffffffa02e51df>] _stp_ctl_write_cmd+0x460/0x7f8 [stap_246f93f30a500769142af9987624737a_5072]
>>  [<ffffffff81044e0b>] ? __wake_up+0x4d/0x6e 
>>  [<ffffffff81229bca>] ? tty_ldisc_deref+0x74/0x8f
>>  [<ffffffff81169d20>] ? security_file_permission+0x24/0x3a
>>  [<ffffffff810f00f7>] vfs_write+0xc1/0x180
>>  [<ffffffff810f07c3>] sys_write+0x56/0x93
>>  [<ffffffff8100beeb>] system_call_fastpath+0x16/0x1b
>>
>> Could someone please provide pointers on the cause of this bug?
>>
>>
>>
> 


-- 
Darren Hart
IBM Linux Technology Center
Real-Time Linux Team

Re: BUG: [preempt-rt] scheduling while atomic: stapio

[Darren Hart]

Josh Stone wrote:
> On 05/20/2009 02:44 AM, Kiran wrote:
>> BUG: scheduling while atomic: stapio/0x00000001/26142, CPU#3
>> [...]
>>  [<ffffffff812a2dea>] cpufreq_unregister_notifier+0x35/0x5c
>>  [<ffffffffa02e0a1f>] _stp_kill_time+0xb6/0xbd [stap_246f93f30a500769142af9987624737a_5072]
>>  [<ffffffffa02e1749>] probe_1391+0x3c/0xa8 [stap_246f93f30a500769142af9987624737a_5072]
>>  [<ffffffffa02e2621>] enter_end_probe+0x14a/0x1e3 [stap_246f93f30a500769142af9987624737a_5072]
> 
> enter_end_probe will call preempt_disable, and apparently the call path
> from cpufreq_unregister_notifier can sleep.  Is this true only of the RT
> kernel?

The call into the __synchronize_sched() from synchronize_rcu() appears 
to be able to sleep regardless of -rt.  It's possible -rt is more likely 
to make them sleep.


-- 
Darren Hart
IBM Linux Technology Center
Real-Time Linux Team

Re: BUG: [preempt-rt] scheduling while atomic: stapio

[Paul E. McKenney]

On Wed, May 27, 2009 at 09:43:22AM -0700, Darren Hart wrote:
> Josh Stone wrote:
>> On 05/20/2009 02:44 AM, Kiran wrote:
>>> BUG: scheduling while atomic: stapio/0x00000001/26142, CPU#3
>>> [...]
>>>  [<ffffffff812a2dea>] cpufreq_unregister_notifier+0x35/0x5c
>>>  [<ffffffffa02e0a1f>] _stp_kill_time+0xb6/0xbd 
>>> [stap_246f93f30a500769142af9987624737a_5072]
>>>  [<ffffffffa02e1749>] probe_1391+0x3c/0xa8 
>>> [stap_246f93f30a500769142af9987624737a_5072]
>>>  [<ffffffffa02e2621>] enter_end_probe+0x14a/0x1e3 
>>> [stap_246f93f30a500769142af9987624737a_5072]
>> enter_end_probe will call preempt_disable, and apparently the call path
>> from cpufreq_unregister_notifier can sleep.  Is this true only of the RT
>> kernel?
>
> The call into the __synchronize_sched() from synchronize_rcu() appears to 
> be able to sleep regardless of -rt.  It's possible -rt is more likely to 
> make them sleep.

One would expect __synchronize_sched() to sleep, except on non-rt
uniprocessor systems.  So a uniprocessor system might well see this
only when running -rt.

							Thanx, Paul

Re: BUG: [preempt-rt] scheduling while atomic: stapio

[Josh Stone]

On 05/27/2009 02:01 PM, Paul E. McKenney wrote:
> On Wed, May 27, 2009 at 09:43:22AM -0700, Darren Hart wrote:
>> Josh Stone wrote:
>>> On 05/20/2009 02:44 AM, Kiran wrote:
>>>> BUG: scheduling while atomic: stapio/0x00000001/26142, CPU#3
>>>> [...]
>>>>  [<ffffffff812a2dea>] cpufreq_unregister_notifier+0x35/0x5c
>>>>  [<ffffffffa02e0a1f>] _stp_kill_time+0xb6/0xbd 
>>>> [stap_246f93f30a500769142af9987624737a_5072]
>>>>  [<ffffffffa02e1749>] probe_1391+0x3c/0xa8 
>>>> [stap_246f93f30a500769142af9987624737a_5072]
>>>>  [<ffffffffa02e2621>] enter_end_probe+0x14a/0x1e3 
>>>> [stap_246f93f30a500769142af9987624737a_5072]
>>> enter_end_probe will call preempt_disable, and apparently the call path
>>> from cpufreq_unregister_notifier can sleep.  Is this true only of the RT
>>> kernel?
>>
>> The call into the __synchronize_sched() from synchronize_rcu() appears to 
>> be able to sleep regardless of -rt.  It's possible -rt is more likely to 
>> make them sleep.
> 
> One would expect __synchronize_sched() to sleep, except on non-rt
> uniprocessor systems.  So a uniprocessor system might well see this
> only when running -rt.

Thanks for the confirmation guys.  I went ahead and rearranged our code
that calls cpufreq_unregister_notifier to run in a context that is
permitted to sleep, so it shouldn't be a problem anymore.

Josh