Hi list.
Just found this in syslog. It was during normal activity, about 6
minutes after resume-from-ram. I never saw this before.
Kernel .config is attached.
Please let me know if you need more info.
Best regards,
Fabio.
--------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Dec 24 14:34:58 tycho kernel: BUG: scheduling while atomic:
hald-addon-stor/0x20000000/1796
Dec 24 14:34:58 tycho kernel: [schedule+86/1976] __sched_text_start+0x56/0x7b8
Dec 24 14:34:58 tycho kernel: [smp_apic_timer_interrupt+112/121]
smp_apic_timer_interrupt+0x70/0x79
Dec 24 14:34:58 tycho kernel: [apic_timer_interrupt+40/48]
apic_timer_interrupt+0x28/0x30
Dec 24 14:34:58 tycho kernel: [__cond_resched+22/52] __cond_resched+0x16/0x34
Dec 24 14:34:58 tycho kernel: [cond_resched+35/42] cond_resched+0x23/0x2a
Dec 24 14:34:58 tycho kernel: [__reacquire_kernel_lock+32/60]
__reacquire_kernel_lock+0x20/0x3c
Dec 24 14:34:58 tycho kernel: [schedule+1926/1976]
__sched_text_start+0x786/0x7b8
Dec 24 14:34:58 tycho kernel: [scsi_get_cmd_from_req+23/48]
scsi_get_cmd_from_req+0x17/0x30
Dec 24 14:34:58 tycho kernel: [scsi_done+0/22] scsi_done+0x0/0x16
Dec 24 14:34:58 tycho kernel: [scsi_dispatch_cmd+401/457]
scsi_dispatch_cmd+0x191/0x1c9
Dec 24 14:34:58 tycho kernel: [scsi_request_fn+632/706]
scsi_request_fn+0x278/0x2c2
Dec 24 14:34:58 tycho kernel: [__cond_resched+22/52] __cond_resched+0x16/0x34
Dec 24 14:34:58 tycho kernel: [cond_resched+35/42] cond_resched+0x23/0x2a
Dec 24 14:34:58 tycho kernel: [wait_for_completion+16/156]
wait_for_completion+0x10/0x9c
Dec 24 14:34:58 tycho kernel: [blk_execute_rq_nowait+123/140]
blk_execute_rq_nowait+0x7b/0x8c
Dec 24 14:34:58 tycho kernel: [blk_execute_rq+139/158] blk_execute_rq+0x8b/0x9e
Dec 24 14:34:58 tycho kernel: [blk_end_sync_rq+0/35] blk_end_sync_rq+0x0/0x23
Dec 24 14:34:58 tycho kernel: [mempool_alloc+40/198] mempool_alloc+0x28/0xc6
Dec 24 14:34:58 tycho kernel: [get_request+471/496] get_request+0x1d7/0x1f0
Dec 24 14:34:58 tycho kernel: [get_request_wait+38/225]
get_request_wait+0x26/0xe1
Dec 24 14:34:58 tycho kernel: [scsi_execute+198/217] scsi_execute+0xc6/0xd9
Dec 24 14:34:58 tycho kernel: [sr_do_ioctl+154/480] sr_do_ioctl+0x9a/0x1e0
Dec 24 14:34:58 tycho kernel: [sr_drive_status+80/97] sr_drive_status+0x50/0x61
Dec 24 14:34:58 tycho kernel: [cdrom_ioctl+1652/2905] cdrom_ioctl+0x674/0xb59
Dec 24 14:34:58 tycho kernel: [__link_path_walk+2527/2851]
__link_path_walk+0x9df/0xb23
Dec 24 14:34:58 tycho kernel: [__activate_task+28/41] __activate_task+0x1c/0x29
Dec 24 14:34:58 tycho kernel: [sr_block_ioctl+71/127] sr_block_ioctl+0x47/0x7f
Dec 24 14:34:58 tycho kernel: [blkdev_driver_ioctl+78/94]
blkdev_driver_ioctl+0x4e/0x5e
Dec 24 14:34:58 tycho kernel: [blkdev_ioctl+1561/1638] blkdev_ioctl+0x619/0x666
Dec 24 14:34:58 tycho kernel: [get_unused_fd+74/169] get_unused_fd+0x4a/0xa9
Dec 24 14:34:58 tycho kernel: [exact_lock+7/13] exact_lock+0x7/0xd
Dec 24 14:34:58 tycho kernel: [kobject_get+15/19] kobject_get+0xf/0x13
Dec 24 14:34:58 tycho kernel: [sr_block_open+116/129] sr_block_open+0x74/0x81
Dec 24 14:34:58 tycho kernel: [do_open+470/597] do_open+0x1d6/0x255
Dec 24 14:34:58 tycho kernel: [bd_claim+16/86] bd_claim+0x10/0x56
Dec 24 14:34:58 tycho kernel: [blkdev_open+58/77] blkdev_open+0x3a/0x4d
Dec 24 14:34:58 tycho kernel: [__dentry_open+231/379] __dentry_open+0xe7/0x17b
Dec 24 14:34:58 tycho kernel: [nameidata_to_filp+36/51]
nameidata_to_filp+0x24/0x33
Dec 24 14:34:58 tycho kernel: [do_filp_open+50/57] do_filp_open+0x32/0x39
Dec 24 14:34:58 tycho kernel: [do_nanosleep+66/102] do_nanosleep+0x42/0x66
Dec 24 14:34:58 tycho kernel: [block_ioctl+24/27] block_ioctl+0x18/0x1b
Dec 24 14:34:58 tycho kernel: [block_ioctl+0/27] block_ioctl+0x0/0x1b
Dec 24 14:34:58 tycho kernel: [do_ioctl+31/98] do_ioctl+0x1f/0x62
Dec 24 14:34:58 tycho kernel: [get_unused_fd+74/169] get_unused_fd+0x4a/0xa9
Dec 24 14:34:58 tycho kernel: [vfs_ioctl+580/598] vfs_ioctl+0x244/0x256
Dec 24 14:34:58 tycho kernel: [do_sys_open+185/195] do_sys_open+0xb9/0xc3
Dec 24 14:34:58 tycho kernel: [sys_ioctl+51/76] sys_ioctl+0x33/0x4c
Dec 24 14:34:58 tycho kernel: [sysenter_past_esp+95/133]
sysenter_past_esp+0x5f/0x85
Dec 24 14:34:58 tycho kernel: =======================
------------------------------------------------------------------------------------------------------------------------------------------------------------------------
"Fabio Comolli" <[email protected]> writes:
> Just found this in syslog. It was during normal activity, about 6
> minutes after resume-from-ram. I never saw this before.
It seems someone missed to check PREEMPT_ACTIVE in __resched_legal().
Could you please test the following patch?
--
OGAWA Hirofumi <[email protected]>
Signed-off-by: OGAWA Hirofumi <[email protected]>
---
kernel/sched.c | 5 +++--
1 file changed, 3 insertions(+), 2 deletions(-)
diff -puN kernel/sched.c~__resched_legal kernel/sched.c
--- linux-2.6/kernel/sched.c~__resched_legal 2006-12-24 22:40:19.000000000 +0900
+++ linux-2.6-hirofumi/kernel/sched.c 2006-12-24 23:54:01.000000000 +0900
@@ -4619,10 +4619,11 @@ asmlinkage long sys_sched_yield(void)
static inline int __resched_legal(int expected_preempt_count)
{
-#ifdef CONFIG_PREEMPT
+#ifndef CONFIG_PREEMPT
+ expected_preempt_count = 0;
+#endif
if (unlikely(preempt_count() != expected_preempt_count))
return 0;
-#endif
if (unlikely(system_state != SYSTEM_RUNNING))
return 0;
return 1;
_
OK, I applied your patch to yesterday's Linus' GIT. I will run it for
some days and will let you know if the problem represents. Please note
that it happened only twice and I don't have any clue on how to
reproduce it.
I added Pavel and Rafael to CC-list because for the first time in at
least six months my laptop failed to resume after suspend-to-disk
(userland tools) with this kernel. Guys, do you think that this
failure could be related to this BUG?
Best regards and Happy Holidays,
Fabio
On 12/24/06, OGAWA Hirofumi <[email protected]> wrote:
> "Fabio Comolli" <[email protected]> writes:
>
> > Just found this in syslog. It was during normal activity, about 6
> > minutes after resume-from-ram. I never saw this before.
>
> It seems someone missed to check PREEMPT_ACTIVE in __resched_legal().
> Could you please test the following patch?
> --
> OGAWA Hirofumi <[email protected]>
>
>
>
> Signed-off-by: OGAWA Hirofumi <[email protected]>
> ---
>
> kernel/sched.c | 5 +++--
> 1 file changed, 3 insertions(+), 2 deletions(-)
>
> diff -puN kernel/sched.c~__resched_legal kernel/sched.c
> --- linux-2.6/kernel/sched.c~__resched_legal 2006-12-24 22:40:19.000000000 +0900
> +++ linux-2.6-hirofumi/kernel/sched.c 2006-12-24 23:54:01.000000000 +0900
> @@ -4619,10 +4619,11 @@ asmlinkage long sys_sched_yield(void)
>
> static inline int __resched_legal(int expected_preempt_count)
> {
> -#ifdef CONFIG_PREEMPT
> +#ifndef CONFIG_PREEMPT
> + expected_preempt_count = 0;
> +#endif
> if (unlikely(preempt_count() != expected_preempt_count))
> return 0;
> -#endif
> if (unlikely(system_state != SYSTEM_RUNNING))
> return 0;
> return 1;
> _
>
* OGAWA Hirofumi <[email protected]> wrote:
> "Fabio Comolli" <[email protected]> writes:
>
> > Just found this in syslog. It was during normal activity, about 6
> > minutes after resume-from-ram. I never saw this before.
>
> It seems someone missed to check PREEMPT_ACTIVE in __resched_legal().
but PREEMPT_ACTIVE is 0x10000000, not 0x20000000.
> Could you please test the following patch?
no. cond_resched() is always legal in the !PREEMPT case.
i found another bug and realized that the whole __resched_legal()
approach is fundamentally wrong! The patch below fixes this.
Ingo
------------------->
Subject: [patch] sched: remove __resched_legal() and fix cond_resched_softirq()
From: Ingo Molnar <[email protected]>
remove the __resched_legal() check: it is conceptually broken. The
biggest problem it had is that it can mask buggy cond_resched() calls. A
cond_resched() call is only legal if we are not in an atomic context.
But __resched_legal() hid this fact. Same goes for cond_resched_locked()
and cond_resched_softirq().
furthermore, the __legal_resched(0) call was buggy in
cond_resched_softirq() and caused unnecessary long softirq latencies!
the fix is to preserve the only valid inhibitor to voluntary preemption:
if the system is still booting. None of the other behavior of
__resched_legal() made any sense.
the effect of this fix should be more real bugs exposed, and shorter
softirq latencies.
Signed-off-by: Ingo Molnar <[email protected]>
---
kernel/sched.c | 17 +++--------------
1 file changed, 3 insertions(+), 14 deletions(-)
Index: linux/kernel/sched.c
===================================================================
--- linux.orig/kernel/sched.c
+++ linux/kernel/sched.c
@@ -4617,17 +4617,6 @@ asmlinkage long sys_sched_yield(void)
return 0;
}
-static inline int __resched_legal(int expected_preempt_count)
-{
-#ifdef CONFIG_PREEMPT
- if (unlikely(preempt_count() != expected_preempt_count))
- return 0;
-#endif
- if (unlikely(system_state != SYSTEM_RUNNING))
- return 0;
- return 1;
-}
-
static void __cond_resched(void)
{
#ifdef CONFIG_DEBUG_SPINLOCK_SLEEP
@@ -4647,7 +4636,7 @@ static void __cond_resched(void)
int __sched cond_resched(void)
{
- if (need_resched() && __resched_legal(0)) {
+ if (need_resched() && system_state == SYSTEM_RUNNING) {
__cond_resched();
return 1;
}
@@ -4673,7 +4662,7 @@ int cond_resched_lock(spinlock_t *lock)
ret = 1;
spin_lock(lock);
}
- if (need_resched() && __resched_legal(1)) {
+ if (need_resched() && system_state == SYSTEM_RUNNING) {
spin_release(&lock->dep_map, 1, _THIS_IP_);
_raw_spin_unlock(lock);
preempt_enable_no_resched();
@@ -4689,7 +4678,7 @@ int __sched cond_resched_softirq(void)
{
BUG_ON(!in_softirq());
- if (need_resched() && __resched_legal(0)) {
+ if (need_resched() && system_state == SYSTEM_RUNNING) {
raw_local_irq_disable();
_local_bh_enable();
raw_local_irq_enable();
Hi!
> some days and will let you know if the problem represents. Please note
> that it happened only twice and I don't have any clue on how to
> reproduce it.
>
> I added Pavel and Rafael to CC-list because for the first time in at
> least six months my laptop failed to resume after suspend-to-disk
> (userland tools) with this kernel. Guys, do you think that this
> failure could be related to this BUG?
everything is possible, but this one does not seem too likely. Is
failure reproducible?
Pavel
--
(english) http://www.livejournal.com/~pavelmachek
(cesky, pictures) http://atrey.karlin.mff.cuni.cz/~pavel/picture/horses/blog.html
Hi
On 12/26/06, Pavel Machek <[email protected]> wrote:
> Hi!
>
> > some days and will let you know if the problem represents. Please note
> > that it happened only twice and I don't have any clue on how to
> > reproduce it.
> >
> > I added Pavel and Rafael to CC-list because for the first time in at
> > least six months my laptop failed to resume after suspend-to-disk
> > (userland tools) with this kernel. Guys, do you think that this
> > failure could be related to this BUG?
>
> everything is possible, but this one does not seem too likely. Is
> failure reproducible?
>
Not at all. I applied Hirofumi's patch and the problem seems to be
gone. But it was impossible to reproduce even without it: the BUG
happened only twice and the resume failure only once.
> Pavel
Fabio
>
> --
> (english) http://www.livejournal.com/~pavelmachek
> (cesky, pictures) http://atrey.karlin.mff.cuni.cz/~pavel/picture/horses/blog.html
>
On Tue, 26 Dec 2006 18:15:31 +0100 Pavel Machek wrote:
> Hi!
>
> > some days and will let you know if the problem represents. Please note
> > that it happened only twice and I don't have any clue on how to
> > reproduce it.
> >
> > I added Pavel and Rafael to CC-list because for the first time in at
> > least six months my laptop failed to resume after suspend-to-disk
> > (userland tools) with this kernel. Guys, do you think that this
> > failure could be related to this BUG?
>
> everything is possible, but this one does not seem too likely. Is
> failure reproducible?
Ingo just posted a patch for this problem.
http://marc.theaimsgroup.com/?l=linux-kernel&m=116715139714252&w=2
---
~Randy
Ingo Molnar <[email protected]> writes:
> * OGAWA Hirofumi <[email protected]> wrote:
>
>> "Fabio Comolli" <[email protected]> writes:
>>
>> > Just found this in syslog. It was during normal activity, about 6
>> > minutes after resume-from-ram. I never saw this before.
>>
>> It seems someone missed to check PREEMPT_ACTIVE in __resched_legal().
>
> but PREEMPT_ACTIVE is 0x10000000, not 0x20000000.
>
>> Could you please test the following patch?
>
> no. cond_resched() is always legal in the !PREEMPT case.
>
> i found another bug and realized that the whole __resched_legal()
> approach is fundamentally wrong! The patch below fixes this.
Hmm.. but the path seems,
-> cond_resched()
-> if (__resched_legal()) /* preempt_count == 0 */
-> __cond_resched() /* preempt_count == 0x10000000 */
-> schedule()
[...]
-> cond_resched()
-> if (__resched_legal()) /* preempt_count == 0x10000000 */
-> __cond_resched() /* preempt_count == 0x20000000 */
-> schedule() /* warning */
Where is it prevented? Or warning is just wrong?
> ------------------->
> Subject: [patch] sched: remove __resched_legal() and fix cond_resched_softirq()
> From: Ingo Molnar <[email protected]>
>
> remove the __resched_legal() check: it is conceptually broken. The
> biggest problem it had is that it can mask buggy cond_resched() calls. A
> cond_resched() call is only legal if we are not in an atomic context.
> But __resched_legal() hid this fact. Same goes for cond_resched_locked()
> and cond_resched_softirq().
>
> furthermore, the __legal_resched(0) call was buggy in
> cond_resched_softirq() and caused unnecessary long softirq latencies!
>
> the fix is to preserve the only valid inhibitor to voluntary preemption:
> if the system is still booting. None of the other behavior of
> __resched_legal() made any sense.
>
> the effect of this fix should be more real bugs exposed, and shorter
> softirq latencies.
>
> Signed-off-by: Ingo Molnar <[email protected]>
> ---
> kernel/sched.c | 17 +++--------------
> 1 file changed, 3 insertions(+), 14 deletions(-)
>
> Index: linux/kernel/sched.c
> ===================================================================
> --- linux.orig/kernel/sched.c
> +++ linux/kernel/sched.c
> @@ -4617,17 +4617,6 @@ asmlinkage long sys_sched_yield(void)
> return 0;
> }
>
> -static inline int __resched_legal(int expected_preempt_count)
> -{
> -#ifdef CONFIG_PREEMPT
> - if (unlikely(preempt_count() != expected_preempt_count))
> - return 0;
> -#endif
> - if (unlikely(system_state != SYSTEM_RUNNING))
> - return 0;
> - return 1;
> -}
> -
> static void __cond_resched(void)
> {
> #ifdef CONFIG_DEBUG_SPINLOCK_SLEEP
> @@ -4647,7 +4636,7 @@ static void __cond_resched(void)
>
> int __sched cond_resched(void)
> {
> - if (need_resched() && __resched_legal(0)) {
> + if (need_resched() && system_state == SYSTEM_RUNNING) {
> __cond_resched();
> return 1;
> }
> @@ -4673,7 +4662,7 @@ int cond_resched_lock(spinlock_t *lock)
> ret = 1;
> spin_lock(lock);
> }
> - if (need_resched() && __resched_legal(1)) {
> + if (need_resched() && system_state == SYSTEM_RUNNING) {
> spin_release(&lock->dep_map, 1, _THIS_IP_);
> _raw_spin_unlock(lock);
> preempt_enable_no_resched();
> @@ -4689,7 +4678,7 @@ int __sched cond_resched_softirq(void)
> {
> BUG_ON(!in_softirq());
>
> - if (need_resched() && __resched_legal(0)) {
> + if (need_resched() && system_state == SYSTEM_RUNNING) {
> raw_local_irq_disable();
> _local_bh_enable();
> raw_local_irq_enable();
--
OGAWA Hirofumi <[email protected]>
* OGAWA Hirofumi <[email protected]> wrote:
> > i found another bug and realized that the whole __resched_legal()
> > approach is fundamentally wrong! The patch below fixes this.
>
> Hmm.. but the path seems,
>
> -> cond_resched()
> -> if (__resched_legal()) /* preempt_count == 0 */
> -> __cond_resched() /* preempt_count == 0x10000000 */
> -> schedule()
> [...]
> -> cond_resched()
> -> if (__resched_legal()) /* preempt_count == 0x10000000 */
> -> __cond_resched() /* preempt_count == 0x20000000 */
> -> schedule() /* warning */
>
> Where is it prevented? Or warning is just wrong?
this should be handled by the second version of the patch i sent out
yesterday. When we have PREEMPT_ACTIVE set, no schedule() call is legal.
Ingo