kernel 3.2.1: BUG: scheduling while atomic: swapper/0/0/0x10000100

kernel 3.2.1: BUG: scheduling while atomic: swapper/0/0/0x10000100

[Francis Moreau]

Hi,

Just in case someone is interested, I've been hit by this:

[  236.734640] BUG: scheduling while atomic: swapper/0/0/0x10000100
[  236.734645] Modules linked in: nfsd nfs lockd fscache auth_rpcgss
nfs_acl sunrpc fuse af_packet ipv6 snd_hda_codec_hdmi arc4
snd_hda_codec_idt snd_hda_intel snd_hda_codec snd_hwdep brcmsmac
mac80211 brcmutil r8169 dell_laptop snd_seq_dummy cfg80211 uas rfkill
pl2303 snd_seq_oss snd_seq_midi_event snd_seq ums_realtek mii
usbserial usb_storage sr_mod crc8 cordic iTCO_wdt iTCO_vendor_support
snd_seq_device snd_pcm_oss snd_pcm snd_timer snd_mixer_oss snd
soundcore snd_page_alloc intel_ips i2c_i801 dcdbas sg mei(C) i915
drm_kms_helper drm i2c_algo_bit i2c_core coretemp binfmt_misc
cpufreq_ondemand cpufreq_conservative cpufreq_powersave acpi_cpufreq
freq_table mperf nvram joydev evdev dell_wmi sparse_keymap wmi dm_mod
video battery kvm_intel kvm ata_piix ahci libahci libata sd_mod
scsi_mod crc_t10dif ext4 jbd2 crc16 uhci_hcd ohci_hcd ehci_hcd usbhid
hid usbcore usb_common
[  236.734753] CPU 0
[  236.734755] Modules linked in: nfsd nfs lockd fscache auth_rpcgss
nfs_acl sunrpc fuse af_packet ipv6 snd_hda_codec_hdmi arc4
snd_hda_codec_idt snd_hda_intel snd_hda_codec snd_hwdep brcmsmac
mac80211 brcmutil r8169 dell_laptop snd_seq_dummy cfg80211 uas rfkill
pl2303 snd_seq_oss snd_seq_midi_event snd_seq ums_realtek mii
usbserial usb_storage sr_mod crc8 cordic iTCO_wdt iTCO_vendor_support
snd_seq_device snd_pcm_oss snd_pcm snd_timer snd_mixer_oss snd
soundcore snd_page_alloc intel_ips i2c_i801 dcdbas sg mei(C) i915
drm_kms_helper drm i2c_algo_bit i2c_core coretemp binfmt_misc
cpufreq_ondemand cpufreq_conservative cpufreq_powersave acpi_cpufreq
freq_table mperf nvram joydev evdev dell_wmi sparse_keymap wmi dm_mod
video battery kvm_intel kvm ata_piix ahci libahci libata sd_mod
scsi_mod crc_t10dif ext4 jbd2 crc16 uhci_hcd ohci_hcd ehci_hcd usbhid
hid usbcore usb_common
[  236.734836]
[  236.734841] Pid: 0, comm: swapper/0 Tainted: G         C   3.2.1 #1
Dell Inc. Vostro 3500/
[  236.734848] RIP: 0010:[<ffffffff8129e4c0>]  [<ffffffff8129e4c0>]
intel_idle+0xe0/0x150
[  236.734861] RSP: 0018:ffffffff81a01e48  EFLAGS: 00000206
[  236.734864] RAX: 0000000000000000 RBX: 0000000000000000 RCX: 0000000000000000
[  236.734868] RDX: 0000000000000fd7 RSI: 0000000000000000 RDI: 00000000003de058
[  236.734871] RBP: ffffffff81a01ea8 R08: 00000000fffffffd R09: 00000000000011a5
[  236.734875] R10: 00000037321ce712 R11: 0000000000000000 R12: ffff880137c0e800
[  236.734878] R13: ffffffff81a01dd8 R14: ffffffff81099b24 R15: ffffffff81a01dc8
[  236.734883] FS:  0000000000000000(0000) GS:ffff880137c00000(0000)
knlGS:0000000000000000
[  236.734887] CS:  0010 DS: 0000 ES: 0000 CR0: 000000008005003b
[  236.734890] CR2: 00007fb66bb1d000 CR3: 0000000001a05000 CR4: 00000000000006f0
[  236.734894] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[  236.734897] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
[  236.734901] Process swapper/0 (pid: 0, threadinfo ffffffff81a00000,
task ffffffff81a0d020)
[  236.734905] Stack:
[  236.734908]  0000000000000000 0000000000000fd7 0000000000000000
0000000000000fd7
[  236.734914]  0000000000000000 00000000003d5af1 ffffffff81a01e88
ffff880137c1a470
[  236.734920]  ffffffff81a59340 0000000000000000 0000000000000003
0000000000000000
[  236.734926] Call Trace:
[  236.734934]  [<ffffffff8136e848>] cpuidle_idle_call+0xd8/0x1b0
[  236.734942]  [<ffffffff8101302b>] cpu_idle+0xcb/0x120
[  236.734950]  [<ffffffff814412b2>] rest_init+0x72/0x80
[  236.734958]  [<ffffffff81ac7cd9>] start_kernel+0x3c5/0x3d0
[  236.734963]  [<ffffffff81ac7346>] x86_64_start_reservations+0x131/0x135
[  236.734969]  [<ffffffff81ac744d>] x86_64_start_kernel+0x103/0x112
[  236.734972] Code: c9 e8 c5 5a df ff 4c 29 f8 48 89 c7 e8 ba f9 dc
ff 49 89 c6 49 89 d7 48 89 45 a0 48 89 55 a8 48 89 45 b0 48 89 55 b8
fb 66 66 90 <66> 66 90 85 1d b7 b7 7b 00 75 0e 48 8d 75 cc bf 05 00 00
00 e8
[  236.735021] Call Trace:
[  236.735026]  [<ffffffff8136e848>] cpuidle_idle_call+0xd8/0x1b0
[  236.735031]  [<ffffffff8101302b>] cpu_idle+0xcb/0x120
[  236.735036]  [<ffffffff814412b2>] rest_init+0x72/0x80
[  236.735041]  [<ffffffff81ac7cd9>] start_kernel+0x3c5/0x3d0
[  236.735046]  [<ffffffff81ac7346>] x86_64_start_reservations+0x131/0x135
[  236.735051]  [<ffffffff81ac744d>] x86_64_start_kernel+0x103/0x112


-- 
Francis

Re: kernel 3.2.1: BUG: scheduling while atomic: swapper/0/0/0x10000100

[Arend van Spriel]

On 01/24/2012 04:59 PM, Francis Moreau wrote:
> Hi,
> 
> Just in case someone is interested, I've been hit by this:
> 
> [  236.734640] BUG: scheduling while atomic: swapper/0/0/0x10000100

Hi Francis

I hit that problem yesterday as well on 3.3.0-rc1. I suspected it came
from my development changes on brcmfmac, but you are not using that.
Still I am looking into it trying some kernel hacking options in Kconfig.

Gr. AvS

Re: kernel 3.2.1: BUG: scheduling while atomic: swapper/0/0/0x10000100

[Francis Moreau]

Hi Arend,

On Wed, Jan 25, 2012 at 9:17 AM, Arend van Spriel <arend@broadcom.com> wrote:
> On 01/24/2012 04:59 PM, Francis Moreau wrote:
>> Hi,
>>
>> Just in case someone is interested, I've been hit by this:
>>
>> [  236.734640] BUG: scheduling while atomic: swapper/0/0/0x10000100
>
> I hit that problem yesterday as well on 3.3.0-rc1. I suspected it came
> from my development changes on brcmfmac, but you are not using that.

I'm not sure it's related to the brcmfmac, because the RFKILL switch
was off when it happened.

Were you writting/reading from/to a SD card by any chances when it did trigger ?

-- 
Francis

Re: kernel 3.2.1: BUG: scheduling while atomic: swapper/0/0/0x10000100

[Arend van Spriel]

On 01/25/2012 09:35 AM, Francis Moreau wrote:
> Hi Arend,
> 
> On Wed, Jan 25, 2012 at 9:17 AM, Arend van Spriel <arend@broadcom.com> wrote:
>> On 01/24/2012 04:59 PM, Francis Moreau wrote:
>>> Hi,
>>>
>>> Just in case someone is interested, I've been hit by this:
>>>
>>> [  236.734640] BUG: scheduling while atomic: swapper/0/0/0x10000100
>>
>> I hit that problem yesterday as well on 3.3.0-rc1. I suspected it came
>> from my development changes on brcmfmac, but you are not using that.
> 
> I'm not sure it's related to the brcmfmac, because the RFKILL switch
> was off when it happened.
> 
> Were you writting/reading from/to a SD card by any chances when it did trigger ?
> 

Nope. It was a USB device driver. Maybe it was conincidental that it
happened shortly after loading the driver, but I tend to mistrust my own
stuff ;-). I posted a question in my issue yesterday (see [1]).

Gr. AvS

[1] https://lkml.org/lkml/2012/1/24/83

Re: kernel 3.2.1: BUG: scheduling while atomic: swapper/0/0/0x10000100

[Josh Boyer]

On Wed, Jan 25, 2012 at 5:00 AM, Arend van Spriel <arend@broadcom.com> wrote:
> On 01/25/2012 09:35 AM, Francis Moreau wrote:
>> Hi Arend,
>>
>> On Wed, Jan 25, 2012 at 9:17 AM, Arend van Spriel <arend@broadcom.com> wrote:
>>> On 01/24/2012 04:59 PM, Francis Moreau wrote:
>>>> Hi,
>>>>
>>>> Just in case someone is interested, I've been hit by this:
>>>>
>>>> [  236.734640] BUG: scheduling while atomic: swapper/0/0/0x10000100
>>>
>>> I hit that problem yesterday as well on 3.3.0-rc1. I suspected it came
>>> from my development changes on brcmfmac, but you are not using that.
>>
>> I'm not sure it's related to the brcmfmac, because the RFKILL switch
>> was off when it happened.
>>
>> Were you writting/reading from/to a SD card by any chances when it did trigger ?
>>
>
> Nope. It was a USB device driver. Maybe it was conincidental that it
> happened shortly after loading the driver, but I tend to mistrust my own
> stuff ;-). I posted a question in my issue yesterday (see [1]).

We've had a few similar issues reported in Fedora yesterday after we
rebased to 3.2.1.
I've not found a common trend yet, but there is definitely an issue on
some hardware in
3.2.1

josh

Re: kernel 3.2.1: BUG: scheduling while atomic: swapper/0/0/0x10000100

[Francis Moreau]

Hello,

On Wed, Jan 25, 2012 at 1:11 PM, Josh Boyer <jwboyer@gmail.com> wrote:
>
> We've had a few similar issues reported in Fedora yesterday after we
> rebased to 3.2.1.

>From which kernel did you rebase to 3.2.1 ?

-- 
Francis

Re: kernel 3.2.1: BUG: scheduling while atomic: swapper/0/0/0x10000100

[Josh Boyer]

On Wed, Jan 25, 2012 at 11:37 AM, Francis Moreau <francis.moro@gmail.com> wrote:
> Hello,
>
> On Wed, Jan 25, 2012 at 1:11 PM, Josh Boyer <jwboyer@gmail.com> wrote:
>>
>> We've had a few similar issues reported in Fedora yesterday after we
>> rebased to 3.2.1.
>
> From which kernel did you rebase to 3.2.1 ?

Fedora 16 went from 3.1.9 to 3.2.1 earlier this week.  We hadn't been getting
reports like this until 3.2.1 showed up.  I asked one of the reporters to try
3.2.0 and they say it recreates there still, so it seems the issue showed up
with the 3.2 release.  One user managed to capture the trace below using a
kernel with a variety of debug options turned on.  It isn't the same backtrace
but it might be related.

backtrace:
:BUG: sleeping function called from invalid context at
drivers/base/power/runtime.c:785
:in_atomic(): 1, irqs_disabled(): 0, pid: 0, name: swapper/0
:1 lock held by swapper/0/0:
: #0:  (&chip->rts51x_suspend_timer){+.-...}, at: [<ffffffff8108d711>]
run_timer_softirq+0x111/0x600
:Pid: 0, comm: swapper/0 Tainted: G        W    3.2.0-2.fc17.x86_64.debug #1
:Call Trace:
: <IRQ>  [<ffffffff8105ee7a>] __might_sleep+0x13a/0x1f0
: [<ffffffffa00180b0>] ? rts51x_modi_suspend_timer+0x50/0x50 [ums_realtek]
: [<ffffffff813fdee3>] __pm_runtime_idle+0xa3/0xb0
: [<ffffffffa00180b0>] ? rts51x_modi_suspend_timer+0x50/0x50 [ums_realtek]
: [<ffffffff8146ed30>] usb_autopm_put_interface+0x30/0x40
: [<ffffffffa0018125>] rts51x_suspend_timer_fn+0x75/0x80 [ums_realtek]
: [<ffffffff8108d7a6>] run_timer_softirq+0x1a6/0x600
: [<ffffffff8108d711>] ? run_timer_softirq+0x111/0x600
: [<ffffffff81084700>] __do_softirq+0xe0/0x370
: [<ffffffff8101fcc3>] ? native_sched_clock+0x13/0x80
: [<ffffffff8167f27c>] call_softirq+0x1c/0x30
: [<ffffffff8101a3e5>] do_softirq+0xa5/0xe0
: [<ffffffff81084d15>] irq_exit+0xe5/0xf0
: [<ffffffff8167fc3e>] smp_apic_timer_interrupt+0x6e/0x99
: [<ffffffff8167daf3>] apic_timer_interrupt+0x73/0x80
: <EOI>  [<ffffffff8101fd39>] ? sched_clock+0x9/0x10
: [<ffffffff81363f9b>] ? intel_idle+0xfb/0x160
: [<ffffffff81363f97>] ? intel_idle+0xf7/0x160
: [<ffffffff814fa7f3>] cpuidle_idle_call+0xb3/0x520
: [<ffffffff81017265>] cpu_idle+0xe5/0x130
: [<ffffffff8164aff3>] rest_init+0xd7/0xe4
: [<ffffffff8164af1c>] ? csum_partial_copy_generic+0x16c/0x16c
: [<ffffffff81f60c39>] start_kernel+0x3ec/0x3f9
: [<ffffffff81f60347>] x86_64_start_reservations+0x132/0x136
: [<ffffffff81f6044b>] x86_64_start_kernel+0x100/0x10f

Not sure if that is a common trend yet or not.

josh

https://bugzilla.redhat.com/show_bug.cgi?id=784345
https://bugzilla.redhat.com/show_bug.cgi?id=784414

Re: kernel 3.2.1: BUG: scheduling while atomic: swapper/0/0/0x10000100

[Arend van Spriel]

On 01/25/2012 05:49 PM, Josh Boyer wrote:
> On Wed, Jan 25, 2012 at 11:37 AM, Francis Moreau <francis.moro@gmail.com> wrote:
>> Hello,
>>
>> On Wed, Jan 25, 2012 at 1:11 PM, Josh Boyer <jwboyer@gmail.com> wrote:
>>>
>>> We've had a few similar issues reported in Fedora yesterday after we
>>> rebased to 3.2.1.
>>
>> From which kernel did you rebase to 3.2.1 ?
> 
> Fedora 16 went from 3.1.9 to 3.2.1 earlier this week.  We hadn't been getting
> reports like this until 3.2.1 showed up.  I asked one of the reporters to try
> 3.2.0 and they say it recreates there still, so it seems the issue showed up
> with the 3.2 release.  One user managed to capture the trace below using a
> kernel with a variety of debug options turned on.  It isn't the same backtrace
> but it might be related.
> 
> backtrace:
> :BUG: sleeping function called from invalid context at
> drivers/base/power/runtime.c:785
> :in_atomic(): 1, irqs_disabled(): 0, pid: 0, name: swapper/0
> :1 lock held by swapper/0/0:
> : #0:  (&chip->rts51x_suspend_timer){+.-...}, at: [<ffffffff8108d711>]
> run_timer_softirq+0x111/0x600
> :Pid: 0, comm: swapper/0 Tainted: G        W    3.2.0-2.fc17.x86_64.debug #1
> :Call Trace:
> : <IRQ>  [<ffffffff8105ee7a>] __might_sleep+0x13a/0x1f0
> : [<ffffffffa00180b0>] ? rts51x_modi_suspend_timer+0x50/0x50 [ums_realtek]
> : [<ffffffff813fdee3>] __pm_runtime_idle+0xa3/0xb0
> : [<ffffffffa00180b0>] ? rts51x_modi_suspend_timer+0x50/0x50 [ums_realtek]
> : [<ffffffff8146ed30>] usb_autopm_put_interface+0x30/0x40

This trace seems to indicate what is wrong. At least for this one user.
The usb_autopm_put_interface() call seems result in a sleep and the
rts51x_suspend_timer_fn is holding a lock. Below the code indicated in
the trace.

runtime.c:
768 /**
769  * __pm_runtime_idle - Entry point for runtime idle operations.
770  * @dev: Device to send idle notification for.
771  * @rpmflags: Flag bits.
772  *
773  * If the RPM_GET_PUT flag is set, decrement the device's usage
count and
774  * return immediately if it is larger than zero.  Then carry out an idle
775  * notification, either synchronous or asynchronous.
776  *
777  * This routine may be called in atomic context if the RPM_ASYNC
flag is set,
778  * or if pm_runtime_irq_safe() has been called.
779  */
780 int __pm_runtime_idle(struct device *dev, int rpmflags)
781 {
782         unsigned long flags;
783         int retval;
784
785         might_sleep_if(!(rpmflags & RPM_ASYNC) && !dev->power.irq_safe);

This issue can either be caused in ums_realtek module or the usb autopm
code. Have not looked into that.

Gr. AvS

Re: kernel 3.2.1: BUG: scheduling while atomic: swapper/0/0/0x10000100

[Francis Moreau]

On Thu, Jan 26, 2012 at 10:04 AM, Arend van Spriel <arend@broadcom.com> wrote:
> On 01/25/2012 05:49 PM, Josh Boyer wrote:
>> On Wed, Jan 25, 2012 at 11:37 AM, Francis Moreau <francis.moro@gmail.com> wrote:
>>> Hello,
>>>
>>> On Wed, Jan 25, 2012 at 1:11 PM, Josh Boyer <jwboyer@gmail.com> wrote:
>>>>
>>>> We've had a few similar issues reported in Fedora yesterday after we
>>>> rebased to 3.2.1.
>>>
>>> From which kernel did you rebase to 3.2.1 ?
>>
>> Fedora 16 went from 3.1.9 to 3.2.1 earlier this week.  We hadn't been getting
>> reports like this until 3.2.1 showed up.  I asked one of the reporters to try
>> 3.2.0 and they say it recreates there still, so it seems the issue showed up
>> with the 3.2 release.  One user managed to capture the trace below using a
>> kernel with a variety of debug options turned on.  It isn't the same backtrace
>> but it might be related.
>>
>> backtrace:
>> :BUG: sleeping function called from invalid context at
>> drivers/base/power/runtime.c:785
>> :in_atomic(): 1, irqs_disabled(): 0, pid: 0, name: swapper/0
>> :1 lock held by swapper/0/0:
>> : #0:  (&chip->rts51x_suspend_timer){+.-...}, at: [<ffffffff8108d711>]
>> run_timer_softirq+0x111/0x600
>> :Pid: 0, comm: swapper/0 Tainted: G        W    3.2.0-2.fc17.x86_64.debug #1
>> :Call Trace:
>> : <IRQ>  [<ffffffff8105ee7a>] __might_sleep+0x13a/0x1f0
>> : [<ffffffffa00180b0>] ? rts51x_modi_suspend_timer+0x50/0x50 [ums_realtek]
>> : [<ffffffff813fdee3>] __pm_runtime_idle+0xa3/0xb0
>> : [<ffffffffa00180b0>] ? rts51x_modi_suspend_timer+0x50/0x50 [ums_realtek]
>> : [<ffffffff8146ed30>] usb_autopm_put_interface+0x30/0x40
>
> This trace seems to indicate what is wrong. At least for this one user.
> The usb_autopm_put_interface() call seems result in a sleep and the
> rts51x_suspend_timer_fn is holding a lock. Below the code indicated in
> the trace.
>
> runtime.c:
> 768 /**
> 769  * __pm_runtime_idle - Entry point for runtime idle operations.
> 770  * @dev: Device to send idle notification for.
> 771  * @rpmflags: Flag bits.
> 772  *
> 773  * If the RPM_GET_PUT flag is set, decrement the device's usage
> count and
> 774  * return immediately if it is larger than zero.  Then carry out an idle
> 775  * notification, either synchronous or asynchronous.
> 776  *
> 777  * This routine may be called in atomic context if the RPM_ASYNC
> flag is set,
> 778  * or if pm_runtime_irq_safe() has been called.
> 779  */
> 780 int __pm_runtime_idle(struct device *dev, int rpmflags)
> 781 {
> 782         unsigned long flags;
> 783         int retval;
> 784
> 785         might_sleep_if(!(rpmflags & RPM_ASYNC) && !dev->power.irq_safe);
>
> This issue can either be caused in ums_realtek module or the usb autopm
> code. Have not looked into that.
>

Just a wild guess: it seems that we're affected using different HW
configs with different USB devices, so it would indicate that usb
autopm is the culprit.

-- 
Francis

Re: kernel 3.2.1: BUG: scheduling while atomic: swapper/0/0/0x10000100

[Arend van Spriel]

On 01/26/2012 10:16 AM, Francis Moreau wrote:
> On Thu, Jan 26, 2012 at 10:04 AM, Arend van Spriel <arend@broadcom.com> wrote:
>> On 01/25/2012 05:49 PM, Josh Boyer wrote:
>>> On Wed, Jan 25, 2012 at 11:37 AM, Francis Moreau <francis.moro@gmail.com> wrote:
>>>> Hello,
>>>>
>>>> On Wed, Jan 25, 2012 at 1:11 PM, Josh Boyer <jwboyer@gmail.com> wrote:
>>>>>
>>>>> We've had a few similar issues reported in Fedora yesterday after we
>>>>> rebased to 3.2.1.
>>>>
>>>> From which kernel did you rebase to 3.2.1 ?
>>>
>>> Fedora 16 went from 3.1.9 to 3.2.1 earlier this week.  We hadn't been getting
>>> reports like this until 3.2.1 showed up.  I asked one of the reporters to try
>>> 3.2.0 and they say it recreates there still, so it seems the issue showed up
>>> with the 3.2 release.  One user managed to capture the trace below using a
>>> kernel with a variety of debug options turned on.  It isn't the same backtrace
>>> but it might be related.
>>>
>>> backtrace:
>>> :BUG: sleeping function called from invalid context at
>>> drivers/base/power/runtime.c:785
>>> :in_atomic(): 1, irqs_disabled(): 0, pid: 0, name: swapper/0
>>> :1 lock held by swapper/0/0:
>>> : #0:  (&chip->rts51x_suspend_timer){+.-...}, at: [<ffffffff8108d711>]
>>> run_timer_softirq+0x111/0x600
>>> :Pid: 0, comm: swapper/0 Tainted: G        W    3.2.0-2.fc17.x86_64.debug #1
>>> :Call Trace:
>>> : <IRQ>  [<ffffffff8105ee7a>] __might_sleep+0x13a/0x1f0
>>> : [<ffffffffa00180b0>] ? rts51x_modi_suspend_timer+0x50/0x50 [ums_realtek]
>>> : [<ffffffff813fdee3>] __pm_runtime_idle+0xa3/0xb0
>>> : [<ffffffffa00180b0>] ? rts51x_modi_suspend_timer+0x50/0x50 [ums_realtek]
>>> : [<ffffffff8146ed30>] usb_autopm_put_interface+0x30/0x40
>>
>> This trace seems to indicate what is wrong. At least for this one user.
>> The usb_autopm_put_interface() call seems result in a sleep and the
>> rts51x_suspend_timer_fn is holding a lock. Below the code indicated in
>> the trace.
>>
>> runtime.c:
>> 768 /**
>> 769  * __pm_runtime_idle - Entry point for runtime idle operations.
>> 770  * @dev: Device to send idle notification for.
>> 771  * @rpmflags: Flag bits.
>> 772  *
>> 773  * If the RPM_GET_PUT flag is set, decrement the device's usage
>> count and
>> 774  * return immediately if it is larger than zero.  Then carry out an idle
>> 775  * notification, either synchronous or asynchronous.
>> 776  *
>> 777  * This routine may be called in atomic context if the RPM_ASYNC
>> flag is set,
>> 778  * or if pm_runtime_irq_safe() has been called.
>> 779  */
>> 780 int __pm_runtime_idle(struct device *dev, int rpmflags)
>> 781 {
>> 782         unsigned long flags;
>> 783         int retval;
>> 784
>> 785         might_sleep_if(!(rpmflags & RPM_ASYNC) && !dev->power.irq_safe);
>>
>> This issue can either be caused in ums_realtek module or the usb autopm
>> code. Have not looked into that.
>>
> 
> Just a wild guess: it seems that we're affected using different HW
> configs with different USB devices, so it would indicate that usb
> autopm is the culprit.
> 

Did a git log between the versions (git log v3.1.9..v3.2.1 --
drivers/usb/core). One commit caught my eye:

commit d727b60659a1173eb4142a5fc521ce67c28b34e1
Merge: 3ee72ca 2a5306c
Author: Rafael J. Wysocki <rjw@sisk.pl>
Date:   Fri Oct 7 23:16:55 2011 +0200

    Merge branch 'pm-runtime' into pm-for-linus

    * pm-runtime:
      PM / Tracing: build rpm-traces.c only if CONFIG_PM_RUNTIME is set
      PM / Runtime: Replace dev_dbg() with trace_rpm_*()
      PM / Runtime: Introduce trace points for tracing rpm_* functions
      PM / Runtime: Don't run callbacks under lock for power.irq_safe set
      USB: Add wakeup info to debugging messages
      PM / Runtime: pm_runtime_idle() can be called in atomic context
      PM / Runtime: Add macro to test for runtime PM events
      PM / Runtime: Add might_sleep() to runtime PM functions

Might be worth to try with CONFIG_PM_RUNTIME disabled. However, I have
not yet found how to reproduce the problem.

Gr. AvS

[PATCH] USB: Realtek cr: fix autopm scheduling while atomic

[Stanislaw Gruszka]

Resolves:
https://bugzilla.redhat.com/show_bug.cgi?id=784345

Reported-by: Francis Moreau <francis.moro@gmail.com>
Reported-and-tested-by: Christian D <chrisudeussen@gmail.com>
Reported-and-tested-by: Jimmy Dorff <jdorff@phy.duke.edu>
Reported-and-tested-by: collura@ieee.org
Cc: stable@vger.kernel.org # 3.2+
Signed-off-by: Stanislaw Gruszka <sgruszka@redhat.com>

diff --git a/drivers/usb/storage/realtek_cr.c b/drivers/usb/storage/realtek_cr.c
index 1f62723..d32f720 100644
--- a/drivers/usb/storage/realtek_cr.c
+++ b/drivers/usb/storage/realtek_cr.c
@@ -789,7 +789,7 @@ static void rts51x_suspend_timer_fn(unsigned long data)
 			rts51x_set_stat(chip, RTS51X_STAT_SS);
 			/* ignore mass storage interface's children */
 			pm_suspend_ignore_children(&us->pusb_intf->dev, true);
-			usb_autopm_put_interface(us->pusb_intf);
+			usb_autopm_put_interface_async(us->pusb_intf);
 			US_DEBUGP("%s: RTS51X_STAT_SS 01,"
 				"intf->pm_usage_cnt:%d, power.usage:%d\n",
 				__func__,

Re: kernel 3.2.1: BUG: scheduling while atomic: swapper/0/0/0x10000100

[Stanislaw Gruszka]

On Thu, Jan 26, 2012 at 10:49:47AM +0100, Arend van Spriel wrote:
> >>> backtrace:
> >>> :BUG: sleeping function called from invalid context at
> >>> drivers/base/power/runtime.c:785
> >>> :in_atomic(): 1, irqs_disabled(): 0, pid: 0, name: swapper/0
> >>> :1 lock held by swapper/0/0:
> >>> : #0:  (&chip->rts51x_suspend_timer){+.-...}, at: [<ffffffff8108d711>]
> >>> run_timer_softirq+0x111/0x600
> >>> :Pid: 0, comm: swapper/0 Tainted: G        W    3.2.0-2.fc17.x86_64.debug #1
> >>> :Call Trace:
> >>> : <IRQ>  [<ffffffff8105ee7a>] __might_sleep+0x13a/0x1f0
> >>> : [<ffffffffa00180b0>] ? rts51x_modi_suspend_timer+0x50/0x50 [ums_realtek]
> >>> : [<ffffffff813fdee3>] __pm_runtime_idle+0xa3/0xb0
> >>> : [<ffffffffa00180b0>] ? rts51x_modi_suspend_timer+0x50/0x50 [ums_realtek]
> >>> : [<ffffffff8146ed30>] usb_autopm_put_interface+0x30/0x40
> >>
> >> This trace seems to indicate what is wrong. At least for this one user.
> >> The usb_autopm_put_interface() call seems result in a sleep and the
> >> rts51x_suspend_timer_fn is holding a lock. Below the code indicated in
> >> the trace.
> >>
> >> runtime.c:
> >> 768 /**
> >> 769  * __pm_runtime_idle - Entry point for runtime idle operations.
> >> 770  * @dev: Device to send idle notification for.
> >> 771  * @rpmflags: Flag bits.
> >> 772  *
> >> 773  * If the RPM_GET_PUT flag is set, decrement the device's usage
> >> count and
> >> 774  * return immediately if it is larger than zero.  Then carry out an idle
> >> 775  * notification, either synchronous or asynchronous.
> >> 776  *
> >> 777  * This routine may be called in atomic context if the RPM_ASYNC
> >> flag is set,
> >> 778  * or if pm_runtime_irq_safe() has been called.
> >> 779  */
> >> 780 int __pm_runtime_idle(struct device *dev, int rpmflags)
> >> 781 {
> >> 782         unsigned long flags;
> >> 783         int retval;
> >> 784
> >> 785         might_sleep_if(!(rpmflags & RPM_ASYNC) && !dev->power.irq_safe);
> >>
> >> This issue can either be caused in ums_realtek module or the usb autopm
> >> code. Have not looked into that.
> >>
> > 
> > Just a wild guess: it seems that we're affected using different HW
> > configs with different USB devices, so it would indicate that usb
> > autopm is the culprit.

Except Arend, all other users reporting that have ums_realtek, so they
hit that driver issue. I just posted ums_realtek fix.

Arend issue is different, it happens on different kernel version 3.3-rc1 vs 3.2.

Stanislaw