BUG: sleeping function called from invalid context at kernel/mutex.c:280

BUG: sleeping function called from invalid context at kernel/mutex.c:280

[Dave Young]

Hi,

with kernel 2.6.30-06692-g3fe0344, pppoe link, start firefox, then got
the messages from syslog:

Jun 19 10:14:07 darkstar kernel: [  189.313972] BUG: sleeping function
called from invalid context at kernel/mutex.c:280
Jun 19 10:14:07 darkstar kernel: [  189.313976] in_atomic(): 1,
irqs_disabled(): 0, pid: 2100, name: firefox-bin
Jun 19 10:14:07 darkstar kernel: [  189.313980] 6 locks held by
firefox-bin/2100:
Jun 19 10:14:07 darkstar kernel: [  189.313981]  #0:
(sk_lock-AF_INET){+.+.+.}, at: [<c12ed864>] lock_sock+0xa/0xc
Jun 19 10:14:07 darkstar kernel: [  189.313991]  #1:
(rcu_read_lock){.+.+..}, at: [<c12c002e>] dev_queue_xmit+0xd8/0x29c
Jun 19 10:14:07 darkstar kernel: [  189.314000]  #2:
(_xmit_PPP#2){+.-...}, at: [<c12cbee2>] __netif_tx_lock+0x11/0x18
Jun 19 10:14:07 darkstar kernel: [  189.314008]  #3:
(&ppp->wlock){+.-...}, at: [<c12224a8>] ppp_xmit_process+0x19/0x449
Jun 19 10:14:07 darkstar kernel: [  189.314015]  #4:
(&pch->downl){+.-...}, at: [<c1221cf2>] ppp_push+0x63/0x4d2
Jun 19 10:14:07 darkstar kernel: [  189.314021]  #5:
(&ap->xmit_lock){+.-...}, at: [<c1224ef0>] ppp_async_push+0x2f/0x3d0
Jun 19 10:14:07 darkstar kernel: [  189.314029] Pid: 2100, comm:
firefox-bin Not tainted 2.6.30-06692-g3fe0344-dirty #77
Jun 19 10:14:07 darkstar kernel: [  189.314031] Call Trace:
Jun 19 10:14:07 darkstar kernel: [  189.314036]  [<c102315e>]
__might_sleep+0xe1/0xe6
Jun 19 10:14:07 darkstar kernel: [  189.314041]  [<c1335dfd>]
mutex_lock_nested+0x18/0x36
Jun 19 10:14:07 darkstar kernel: [  189.314046]  [<c118d82f>]
tty_throttle+0x10/0x38
Jun 19 10:14:07 darkstar kernel: [  189.314050]  [<c118cc1c>]
n_tty_receive_buf+0xf6e/0xf76
Jun 19 10:14:07 darkstar kernel: [  189.314055]  [<c1049e7e>] ?
__lock_acquire+0xa8d/0xaa9
Jun 19 10:14:07 darkstar kernel: [  189.314059]  [<c1048415>] ?
mark_lock+0x1e/0x1c7
Jun 19 10:14:07 darkstar kernel: [  189.314063]  [<c1048601>] ?
mark_held_locks+0x43/0x5b
Jun 19 10:14:07 darkstar kernel: [  189.314067]  [<c1336b39>] ?
_spin_unlock_irqrestore+0x3c/0x48
Jun 19 10:14:07 darkstar kernel: [  189.314071]  [<c104870a>] ?
trace_hardirqs_on_caller+0xf1/0x146
Jun 19 10:14:07 darkstar kernel: [  189.314075]  [<c104876a>] ?
trace_hardirqs_on+0xb/0xd
Jun 19 10:14:07 darkstar kernel: [  189.314078]  [<c118e2f7>] ?
tty_ldisc_try+0x32/0x38
Jun 19 10:14:07 darkstar kernel: [  189.314082]  [<c118fb43>]
pty_write+0x51/0x67
Jun 19 10:14:07 darkstar kernel: [  189.314086]  [<c1224f7f>]
ppp_async_push+0xbe/0x3d0
Jun 19 10:14:07 darkstar kernel: [  189.314089]  [<c12252c3>]
ppp_async_send+0x32/0x3d
Jun 19 10:14:07 darkstar kernel: [  189.314093]  [<c1221d04>]
ppp_push+0x75/0x4d2
Jun 19 10:14:07 darkstar kernel: [  189.314097]  [<c1336b39>] ?
_spin_unlock_irqrestore+0x3c/0x48
Jun 19 10:14:07 darkstar kernel: [  189.314101]  [<c104870a>] ?
trace_hardirqs_on_caller+0xf1/0x146
Jun 19 10:14:07 darkstar kernel: [  189.314104]  [<c104876a>] ?
trace_hardirqs_on+0xb/0xd
Jun 19 10:14:07 darkstar kernel: [  189.314109]  [<c12b778b>] ?
skb_dequeue+0x39/0x41
Jun 19 10:14:07 darkstar kernel: [  189.314112]  [<c122286e>]
ppp_xmit_process+0x3df/0x449
Jun 19 10:14:07 darkstar kernel: [  189.314116]  [<c12b76d2>] ?
skb_queue_tail+0x31/0x3a
Jun 19 10:14:07 darkstar kernel: [  189.314120]  [<c12229e7>]
ppp_start_xmit+0x10f/0x14b
Jun 19 10:14:07 darkstar kernel: [  189.314124]  [<c12be77e>]
dev_hard_start_xmit+0x1be/0x249
Jun 19 10:14:07 darkstar kernel: [  189.314128]  [<c12cc4d7>]
__qdisc_run+0xe3/0x1b6
Jun 19 10:14:07 darkstar kernel: [  189.314131]  [<c12bc94a>]
qdisc_run+0x18/0x1a
Jun 19 10:14:07 darkstar kernel: [  189.314135]  [<c12c00db>]
dev_queue_xmit+0x185/0x29c
Jun 19 10:14:07 darkstar kernel: [  189.314140]  [<c12e89fa>]
ip_finish_output2+0x199/0x1c3
Jun 19 10:14:07 darkstar kernel: [  189.314143]  [<c12e8563>] ?
nf_hook_thresh+0x39/0x4a
Jun 19 10:14:07 darkstar kernel: [  189.314147]  [<c12e8a24>] ?
ip_finish_output+0x0/0x39
Jun 19 10:14:07 darkstar kernel: [  189.314151]  [<c12e8a59>]
ip_finish_output+0x35/0x39
Jun 19 10:14:07 darkstar kernel: [  189.314155]  [<c12e9110>]
ip_output+0x82/0x87
Jun 19 10:14:07 darkstar kernel: [  189.314178]  [<c12e73ad>] dst_output+0x9/0xb
Jun 19 10:14:07 darkstar kernel: [  189.314182]  [<c12e860e>]
ip_local_out+0x17/0x1a
Jun 19 10:14:08 darkstar kernel: [  189.314186]  [<c12e9604>]
ip_queue_xmit+0x2bf/0x303
Jun 19 10:14:08 darkstar kernel: [  189.314190]  [<c104eca6>] ?
is_module_text_address+0x8/0x12
Jun 19 10:14:08 darkstar kernel: [  189.314194]  [<c1005bea>] ?
print_context_stack+0x2f/0x8c
Jun 19 10:14:08 darkstar kernel: [  189.314198]  [<c1048415>] ?
mark_lock+0x1e/0x1c7
Jun 19 10:14:08 darkstar kernel: [  189.314202]  [<c1048601>] ?
mark_held_locks+0x43/0x5b
Jun 19 10:14:08 darkstar kernel: [  189.314206]  [<c12fb556>] ?
tcp_v4_send_check+0x81/0x90
Jun 19 10:14:08 darkstar kernel: [  189.314210]  [<c12f741a>]
tcp_transmit_skb+0x574/0x5ae
Jun 19 10:14:08 darkstar kernel: [  189.314215]  [<c12f85d9>]
tcp_write_xmit+0x620/0x70d
Jun 19 10:14:08 darkstar kernel: [  189.314218]  [<c12ede2b>] ?
csum_and_copy_from_user+0x4e/0x6c
Jun 19 10:14:08 darkstar kernel: [  189.314223]  [<c12f86ee>]
tcp_push_one+0x28/0x2c
Jun 19 10:14:08 darkstar kernel: [  189.314226]  [<c12efd01>]
tcp_sendmsg+0x4ca/0x5b6
Jun 19 10:14:08 darkstar kernel: [  189.314230]  [<c12b2183>]
__sock_sendmsg+0x45/0x4e
Jun 19 10:14:08 darkstar kernel: [  189.314234]  [<c12b28da>]
sock_sendmsg+0xb8/0xce
Jun 19 10:14:08 darkstar kernel: [  189.314238]  [<c1049e7e>] ?
__lock_acquire+0xa8d/0xaa9
Jun 19 10:14:08 darkstar kernel: [  189.314242]  [<c103ae4d>] ?
autoremove_wake_function+0x0/0x30
Jun 19 10:14:08 darkstar kernel: [  189.314246]  [<c1336b39>] ?
_spin_unlock_irqrestore+0x3c/0x48
Jun 19 10:14:08 darkstar kernel: [  189.314251]  [<c1099c6d>] ?
fget_light+0x76/0x94
Jun 19 10:14:08 darkstar kernel: [  189.314255]  [<c1099c81>] ?
fget_light+0x8a/0x94
Jun 19 10:14:08 darkstar kernel: [  189.314258]  [<c12b237a>] ?
sockfd_lookup_light+0x16/0x48
Jun 19 10:14:08 darkstar kernel: [  189.314262]  [<c12b32af>]
sys_sendto+0xa4/0xc0
Jun 19 10:14:08 darkstar kernel: [  189.314266]  [<c1049e7e>] ?
__lock_acquire+0xa8d/0xaa9
Jun 19 10:14:08 darkstar kernel: [     [<c1049d0f>] __lock_acquire+0x91e/0xaa9
Jun 19 10:14:08 darkstar kernel: [  189.328319]    [<c1049f35>]
lock_acquire+0x9b/0xbe
Jun 19 10:14:08 darkstar kernel: [  189.328319]    [<c103e099>]
down_write_nested+0x32/0x50
Jun 19 10:14:08 darkstar kernel: [  189.328319]    [<c1028475>]
dup_mm+0xa6/0x302
Jun 19 10:14:08 darkstar kernel: [  189.328319]    [<c102911e>]
copy_process+0xa25/0x10b2
Jun 19 10:14:08 darkstar kernel: [  189.328319]    [<c10299ed>]
do_fork+0x12b/0x2a6
Jun 19 10:14:08 darkstar kernel: [  189.328319]    [<c1001f49>]
sys_clone+0x24/0x2b
Jun 19 10:14:08 darkstar kernel: [  189.328319]    [<c100331d>]
syscall_call+0x7/0xb
Jun 19 10:14:08 darkstar kernel: [  189.328319]    [<ffffffff>] 0xffffffff
Jun 19 10:14:08 darkstar kernel: [  189.328319]

[snip ...]

-- 
Regards
dave

Re: BUG: sleeping function called from invalid context at kernel/mutex.c:280

[Jarek Poplawski]

On 19-06-2009 04:36, Dave Young wrote:
> Hi,
> 
> with kernel 2.6.30-06692-g3fe0344, pppoe link, start firefox, then got
> the messages from syslog:

Hi,

probably you should say something about a char/serial driver used here.

Jarek P.
> 
> Jun 19 10:14:07 darkstar kernel: [  189.313972] BUG: sleeping function
> called from invalid context at kernel/mutex.c:280
> Jun 19 10:14:07 darkstar kernel: [  189.313976] in_atomic(): 1,
> irqs_disabled(): 0, pid: 2100, name: firefox-bin
> Jun 19 10:14:07 darkstar kernel: [  189.313980] 6 locks held by
> firefox-bin/2100:
> Jun 19 10:14:07 darkstar kernel: [  189.313981]  #0:
> (sk_lock-AF_INET){+.+.+.}, at: [<c12ed864>] lock_sock+0xa/0xc
> Jun 19 10:14:07 darkstar kernel: [  189.313991]  #1:
> (rcu_read_lock){.+.+..}, at: [<c12c002e>] dev_queue_xmit+0xd8/0x29c
> Jun 19 10:14:07 darkstar kernel: [  189.314000]  #2:
> (_xmit_PPP#2){+.-...}, at: [<c12cbee2>] __netif_tx_lock+0x11/0x18
> Jun 19 10:14:07 darkstar kernel: [  189.314008]  #3:
> (&ppp->wlock){+.-...}, at: [<c12224a8>] ppp_xmit_process+0x19/0x449
> Jun 19 10:14:07 darkstar kernel: [  189.314015]  #4:
> (&pch->downl){+.-...}, at: [<c1221cf2>] ppp_push+0x63/0x4d2
> Jun 19 10:14:07 darkstar kernel: [  189.314021]  #5:
> (&ap->xmit_lock){+.-...}, at: [<c1224ef0>] ppp_async_push+0x2f/0x3d0
> Jun 19 10:14:07 darkstar kernel: [  189.314029] Pid: 2100, comm:
> firefox-bin Not tainted 2.6.30-06692-g3fe0344-dirty #77
> Jun 19 10:14:07 darkstar kernel: [  189.314031] Call Trace:
> Jun 19 10:14:07 darkstar kernel: [  189.314036]  [<c102315e>]
> __might_sleep+0xe1/0xe6
> Jun 19 10:14:07 darkstar kernel: [  189.314041]  [<c1335dfd>]
> mutex_lock_nested+0x18/0x36
> Jun 19 10:14:07 darkstar kernel: [  189.314046]  [<c118d82f>]
> tty_throttle+0x10/0x38
> Jun 19 10:14:07 darkstar kernel: [  189.314050]  [<c118cc1c>]
> n_tty_receive_buf+0xf6e/0xf76
...

BUG: sleeping function called from invalid context at kernel/mutex.c:280

[Xiaotian Feng]

Hi,

    I got following messages when I resume from suspend with 2.6.31.
Is there anything wrong? Thanks.

BUG: sleeping function called from invalid context at kernel/mutex.c:280
in_atomic(): 0, irqs_disabled(): 1, pid: 2473, name: pm-suspend
2 locks held by pm-suspend/2473:
 #0:  (&buffer->mutex){......}, at: [<ffffffff8115ab13>]
sysfs_write_file+0x3c/0x137
 #1:  (pm_mutex){......}, at: [<ffffffff810865b5>] enter_state+0x39/0x130
Pid: 2473, comm: pm-suspend Not tainted 2.6.31 #1
Call Trace:
 [<ffffffff810792f0>] ? __debug_show_held_locks+0x22/0x24
 [<ffffffff8104a2ef>] __might_sleep+0x107/0x10b
 [<ffffffff8141fca9>] mutex_lock_nested+0x25/0x43
 [<ffffffff81073537>] clocksource_resume+0x1c/0x60
 [<ffffffff81072902>] timekeeping_resume+0x1e/0x1c8
 [<ffffffff812aee62>] __sysdev_resume+0x25/0xcf
 [<ffffffff812aef79>] sysdev_resume+0x6d/0xae
 [<ffffffff810864f8>] suspend_devices_and_enter+0x12b/0x1af
 [<ffffffff8108665b>] enter_state+0xdf/0x130
 [<ffffffff81085dc3>] state_store+0xb6/0xd3
 [<ffffffff81204c73>] kobj_attr_store+0x17/0x19
 [<ffffffff8115abd2>] sysfs_write_file+0xfb/0x137
 [<ffffffff811057d2>] vfs_write+0xae/0x10b
 [<ffffffff81208392>] ? __up_read+0x1a/0x7f
 [<ffffffff811058ef>] sys_write+0x4a/0x6e
 [<ffffffff81011b82>] system_call_fastpath+0x16/0x1b

Regards
Xiaotian

Re: BUG: sleeping function called from invalid context at kernel/mutex.c:280

[Michal Schmidt]

Dne Wed, 23 Sep 2009 17:27:08 +0800 Xiaotian Feng napsal(a):
> Hi,
> 
>     I got following messages when I resume from suspend with 2.6.31.
> Is there anything wrong? Thanks.
> 
> BUG: sleeping function called from invalid context at
> kernel/mutex.c:280 in_atomic(): 0, irqs_disabled(): 1, pid: 2473,
> name: pm-suspend 2 locks held by pm-suspend/2473:
>  #0:  (&buffer->mutex){......}, at: [<ffffffff8115ab13>]
> sysfs_write_file+0x3c/0x137
>  #1:  (pm_mutex){......}, at: [<ffffffff810865b5>]
> enter_state+0x39/0x130 Pid: 2473, comm: pm-suspend Not tainted 2.6.31
> #1 Call Trace:
>  [<ffffffff810792f0>] ? __debug_show_held_locks+0x22/0x24
>  [<ffffffff8104a2ef>] __might_sleep+0x107/0x10b
>  [<ffffffff8141fca9>] mutex_lock_nested+0x25/0x43
>  [<ffffffff81073537>] clocksource_resume+0x1c/0x60
>  [<ffffffff81072902>] timekeeping_resume+0x1e/0x1c8
>  [<ffffffff812aee62>] __sysdev_resume+0x25/0xcf
>  [<ffffffff812aef79>] sysdev_resume+0x6d/0xae
>  [<ffffffff810864f8>] suspend_devices_and_enter+0x12b/0x1af
>  [<ffffffff8108665b>] enter_state+0xdf/0x130
>  [<ffffffff81085dc3>] state_store+0xb6/0xd3
>  [<ffffffff81204c73>] kobj_attr_store+0x17/0x19
>  [<ffffffff8115abd2>] sysfs_write_file+0xfb/0x137
>  [<ffffffff811057d2>] vfs_write+0xae/0x10b
>  [<ffffffff81208392>] ? __up_read+0x1a/0x7f
>  [<ffffffff811058ef>] sys_write+0x4a/0x6e
>  [<ffffffff81011b82>] system_call_fastpath+0x16/0x1b
> 
> Regards
> Xiaotian

I've just noticed the same in the latest git.
sysdev_resume() runs with IRQs disabled, but clocksource_resume() uses
a mutex. Hmm, in 2.6.30 it used to be spinlock. This was changed to
mutex by:

commit 75c5158f70c065b9704b924503d96e8297838f79
Author: Martin Schwidefsky <schwidefsky@de.ibm.com>
Date:   Fri Aug 14 15:47:30 2009 +0200

    timekeeping: Update clocksource with stop_machine
    
    update_wall_time calls change_clocksource HZ times per second to
    check if a new clock source is available. In close to 100% of all
    calls there is no new clock. Replace the tick based check by an
    update done with stop_machine.

Michal

Re: BUG: sleeping function called from invalid context at kernel/mutex.c:280

[Martin Schwidefsky]

On Thu, 24 Sep 2009 15:33:19 +0200
Michal Schmidt <mschmidt@redhat.com> wrote:

> Dne Wed, 23 Sep 2009 17:27:08 +0800 Xiaotian Feng napsal(a):
> > Hi,
> > 
> >     I got following messages when I resume from suspend with 2.6.31.
> > Is there anything wrong? Thanks.
> > 
> > BUG: sleeping function called from invalid context at
> > kernel/mutex.c:280 in_atomic(): 0, irqs_disabled(): 1, pid: 2473,
> > name: pm-suspend 2 locks held by pm-suspend/2473:
> >  #0:  (&buffer->mutex){......}, at: [<ffffffff8115ab13>]
> > sysfs_write_file+0x3c/0x137
> >  #1:  (pm_mutex){......}, at: [<ffffffff810865b5>]
> > enter_state+0x39/0x130 Pid: 2473, comm: pm-suspend Not tainted 2.6.31
> > #1 Call Trace:
> >  [<ffffffff810792f0>] ? __debug_show_held_locks+0x22/0x24
> >  [<ffffffff8104a2ef>] __might_sleep+0x107/0x10b
> >  [<ffffffff8141fca9>] mutex_lock_nested+0x25/0x43
> >  [<ffffffff81073537>] clocksource_resume+0x1c/0x60
> >  [<ffffffff81072902>] timekeeping_resume+0x1e/0x1c8
> >  [<ffffffff812aee62>] __sysdev_resume+0x25/0xcf
> >  [<ffffffff812aef79>] sysdev_resume+0x6d/0xae
> >  [<ffffffff810864f8>] suspend_devices_and_enter+0x12b/0x1af
> >  [<ffffffff8108665b>] enter_state+0xdf/0x130
> >  [<ffffffff81085dc3>] state_store+0xb6/0xd3
> >  [<ffffffff81204c73>] kobj_attr_store+0x17/0x19
> >  [<ffffffff8115abd2>] sysfs_write_file+0xfb/0x137
> >  [<ffffffff811057d2>] vfs_write+0xae/0x10b
> >  [<ffffffff81208392>] ? __up_read+0x1a/0x7f
> >  [<ffffffff811058ef>] sys_write+0x4a/0x6e
> >  [<ffffffff81011b82>] system_call_fastpath+0x16/0x1b
> 
> I've just noticed the same in the latest git.
> sysdev_resume() runs with IRQs disabled, but clocksource_resume() uses
> a mutex. Hmm, in 2.6.30 it used to be spinlock. This was changed to
> mutex by:
> 
> commit 75c5158f70c065b9704b924503d96e8297838f79
> Author: Martin Schwidefsky <schwidefsky@de.ibm.com>
> Date:   Fri Aug 14 15:47:30 2009 +0200
> 
>     timekeeping: Update clocksource with stop_machine
>     
>     update_wall_time calls change_clocksource HZ times per second to
>     check if a new clock source is available. In close to 100% of all
>     calls there is no new clock. Replace the tick based check by an
>     update done with stop_machine.

Hmm, the spinlock to mutex conversion is necessary to make it possible
to use stop_machine to install the new clocksource. At the same time
clocksource_resume is called early in the resume cycle with interrupts
disabled and may not take a mutex. Question is: does it have to? There
shouldn't be any processes running that can change the list of
installed clocksources. Can you test if this patch fixes the problem?

--
Subject: [PATCH] clocksource: resume clocksource without taking the clocksource mutex

From: Martin Schwidefsky <schwidefsky@de.ibm.com>

git commit 75c5158f70c065b9 converted the clocksource spinlock to a
mutex. This causes the following BUG:

BUG: sleeping function called from invalid context at
kernel/mutex.c:280 in_atomic(): 0, irqs_disabled(): 1, pid: 2473,
name: pm-suspend 2 locks held by pm-suspend/2473:
 #0:  (&buffer->mutex){......}, at: [<ffffffff8115ab13>]
sysfs_write_file+0x3c/0x137
 #1:  (pm_mutex){......}, at: [<ffffffff810865b5>]
enter_state+0x39/0x130 Pid: 2473, comm: pm-suspend Not tainted 2.6.31
#1 Call Trace:
 [<ffffffff810792f0>] ? __debug_show_held_locks+0x22/0x24
 [<ffffffff8104a2ef>] __might_sleep+0x107/0x10b
 [<ffffffff8141fca9>] mutex_lock_nested+0x25/0x43
 [<ffffffff81073537>] clocksource_resume+0x1c/0x60
 [<ffffffff81072902>] timekeeping_resume+0x1e/0x1c8
 [<ffffffff812aee62>] __sysdev_resume+0x25/0xcf
 [<ffffffff812aef79>] sysdev_resume+0x6d/0xae
 [<ffffffff810864f8>] suspend_devices_and_enter+0x12b/0x1af
 [<ffffffff8108665b>] enter_state+0xdf/0x130
 [<ffffffff81085dc3>] state_store+0xb6/0xd3
 [<ffffffff81204c73>] kobj_attr_store+0x17/0x19
 [<ffffffff8115abd2>] sysfs_write_file+0xfb/0x137
 [<ffffffff811057d2>] vfs_write+0xae/0x10b
 [<ffffffff81208392>] ? __up_read+0x1a/0x7f
 [<ffffffff811058ef>] sys_write+0x4a/0x6e
 [<ffffffff81011b82>] system_call_fastpath+0x16/0x1b

clocksource_resume is called early in the resume process, there
is only one cpu, no processes are running and the interrupts are
disabled. It is therefore possible to resume the clocksources
without taking the clocksource mutex.

Reported-by: Xiaotian Feng <xtfeng@gmail.com>
Signed-off-by: Martin Schwidefsky <schwidefsky@de.ibm.com>
---

 kernel/time/clocksource.c |    4 ----
 1 file changed, 4 deletions(-)

diff -urpN linux-2.6/kernel/time/clocksource.c linux-2.6-clocksource/kernel/time/clocksource.c
--- linux-2.6/kernel/time/clocksource.c	2009-09-19 10:16:49.000000000 +0200
+++ linux-2.6-clocksource/kernel/time/clocksource.c	2009-09-24 17:09:09.000000000 +0200
@@ -394,15 +394,11 @@ void clocksource_resume(void)
 {
 	struct clocksource *cs;
 
-	mutex_lock(&clocksource_mutex);
-
 	list_for_each_entry(cs, &clocksource_list, list)
 		if (cs->resume)
 			cs->resume();
 
 	clocksource_resume_watchdog();
-
-	mutex_unlock(&clocksource_mutex);
 }
 
 /**

-- 
blue skies,
   Martin.

"Reality continues to ruin my life." - Calvin.

Re: BUG: sleeping function called from invalid context at kernel/mutex.c:280

[Michal Schmidt]

Dne Thu, 24 Sep 2009 17:29:52 +0200 Martin Schwidefsky napsal(a):
> On Thu, 24 Sep 2009 15:33:19 +0200
> Michal Schmidt <mschmidt@redhat.com> wrote:
> > I've just noticed the same in the latest git.
> > sysdev_resume() runs with IRQs disabled, but clocksource_resume()
> > uses a mutex. Hmm, in 2.6.30 it used to be spinlock. This was
> > changed to mutex by:
> > 
> > commit 75c5158f70c065b9704b924503d96e8297838f79
> > Author: Martin Schwidefsky <schwidefsky@de.ibm.com>
> > Date:   Fri Aug 14 15:47:30 2009 +0200
> > 
> >     timekeeping: Update clocksource with stop_machine
> >     
> >     update_wall_time calls change_clocksource HZ times per second to
> >     check if a new clock source is available. In close to 100% of
> > all calls there is no new clock. Replace the tick based check by an
> >     update done with stop_machine.
> 
> Hmm, the spinlock to mutex conversion is necessary to make it possible
> to use stop_machine to install the new clocksource. At the same time
> clocksource_resume is called early in the resume cycle with interrupts
> disabled and may not take a mutex. Question is: does it have to? There
> shouldn't be any processes running that can change the list of
> installed clocksources. Can you test if this patch fixes the problem?
> 
> --
> Subject: [PATCH] clocksource: resume clocksource without taking the
> clocksource mutex
> 
> From: Martin Schwidefsky <schwidefsky@de.ibm.com>
> 
> git commit 75c5158f70c065b9 converted the clocksource spinlock to a
> mutex. This causes the following BUG:
> 
> BUG: sleeping function called from invalid context at
> kernel/mutex.c:280 in_atomic(): 0, irqs_disabled(): 1, pid: 2473,
> name: pm-suspend 2 locks held by pm-suspend/2473:
>  #0:  (&buffer->mutex){......}, at: [<ffffffff8115ab13>]
> sysfs_write_file+0x3c/0x137
>  #1:  (pm_mutex){......}, at: [<ffffffff810865b5>]
> enter_state+0x39/0x130 Pid: 2473, comm: pm-suspend Not tainted 2.6.31
> #1 Call Trace:
>  [<ffffffff810792f0>] ? __debug_show_held_locks+0x22/0x24
>  [<ffffffff8104a2ef>] __might_sleep+0x107/0x10b
>  [<ffffffff8141fca9>] mutex_lock_nested+0x25/0x43
>  [<ffffffff81073537>] clocksource_resume+0x1c/0x60
>  [<ffffffff81072902>] timekeeping_resume+0x1e/0x1c8
>  [<ffffffff812aee62>] __sysdev_resume+0x25/0xcf
>  [<ffffffff812aef79>] sysdev_resume+0x6d/0xae
>  [<ffffffff810864f8>] suspend_devices_and_enter+0x12b/0x1af
>  [<ffffffff8108665b>] enter_state+0xdf/0x130
>  [<ffffffff81085dc3>] state_store+0xb6/0xd3
>  [<ffffffff81204c73>] kobj_attr_store+0x17/0x19
>  [<ffffffff8115abd2>] sysfs_write_file+0xfb/0x137
>  [<ffffffff811057d2>] vfs_write+0xae/0x10b
>  [<ffffffff81208392>] ? __up_read+0x1a/0x7f
>  [<ffffffff811058ef>] sys_write+0x4a/0x6e
>  [<ffffffff81011b82>] system_call_fastpath+0x16/0x1b
> 
> clocksource_resume is called early in the resume process, there
> is only one cpu, no processes are running and the interrupts are
> disabled. It is therefore possible to resume the clocksources
> without taking the clocksource mutex.
> 
> Reported-by: Xiaotian Feng <xtfeng@gmail.com>
> Signed-off-by: Martin Schwidefsky <schwidefsky@de.ibm.com>

Yes, this fixes the problem.
Tested-by: Michal Schmidt <mschmidt@redhat.com>