2004-09-27 08:01:26

by Reuben Farrelly

[permalink] [raw]
Subject: Stack traces in 2.6.9-rc2-mm4

Since upgrading from -mm3 to -mm4, I'm now getting messages like this
logged every second or so:

Sep 27 18:28:06 tornado kernel: using smp_processor_id() in preemptible
code: swapper/1
Sep 27 18:28:06 tornado kernel: [<c0104dce>] dump_stack+0x17/0x19
Sep 27 18:28:06 tornado kernel: [<c0117fc6>] smp_processor_id+0x80/0x86
Sep 27 18:28:06 tornado kernel: [<c0282bf3>] make_request+0x174/0x2e7
Sep 27 18:28:06 tornado kernel: [<c02073dd>] generic_make_request+0xda/0x190
Sep 27 18:28:06 tornado kernel: [<c02074ee>] submit_bio+0x5b/0xf5
Sep 27 18:28:06 tornado kernel: [<c015673b>] submit_bh+0xd2/0x11b
Sep 27 18:28:06 tornado kernel: [<c0156807>] ll_rw_block+0x83/0x85
Sep 27 18:28:06 tornado kernel: [<c019e4f8>] search_by_key+0xeb/0x1158
Sep 27 18:28:06 tornado kernel: [<c018c546>]
reiserfs_read_locked_inode+0x5f/0xfe
Sep 27 18:28:06 tornado kernel: [<c018c685>] reiserfs_iget+0x79/0x82
Sep 27 18:28:06 tornado kernel: [<c0187bc4>] reiserfs_lookup+0xf6/0x147
Sep 27 18:28:06 tornado kernel: [<c015e72c>] real_lookup+0xbe/0xe2
Sep 27 18:28:06 tornado kernel: [<c015e94c>] do_lookup+0x6a/0x75
Sep 27 18:28:06 tornado kernel: [<c015eae0>] link_path_walk+0x189/0xd3a
Sep 27 18:28:06 tornado kernel: [<c015f92d>] path_lookup+0x97/0x157
Sep 27 18:28:06 tornado kernel: [<c0160029>] open_namei+0x87/0x60a
Sep 27 18:28:06 tornado kernel: [<c01519b9>] filp_open+0x29/0x48
Sep 27 18:28:06 tornado kernel: [<c0151dca>] sys_open+0x31/0x61
Sep 27 18:28:06 tornado kernel: [<c010053b>] init+0xd3/0x185
Sep 27 18:28:06 tornado kernel: [<c01022e9>] kernel_thread_helper+0x5/0xb

The traces all look very similar, viz
Sep 27 18:28:10 tornado kernel: using smp_processor_id() in preemptible
code: initlog/1449
Sep 27 18:28:10 tornado kernel: using smp_processor_id() in preemptible
code: pdflush/45
Sep 27 18:28:19 tornado kernel: using smp_processor_id() in preemptible
code: spamd/2146

Is there a fix to shut this all up or a suggested patch to revert?

Box is a P4 Intel 2.8Ghz single processor, SMP/HT with PREEMPT on..

Thanks,
Reuben


2004-09-27 08:56:32

by Ingo Molnar

[permalink] [raw]
Subject: Re: Stack traces in 2.6.9-rc2-mm4


* Reuben Farrelly <[email protected]> wrote:

> Since upgrading from -mm3 to -mm4, I'm now getting messages like this
> logged every second or so:
>
> Sep 27 18:28:06 tornado kernel: using smp_processor_id() in preemptible code: swapper/1
> Sep 27 18:28:06 tornado kernel: [<c0104dce>] dump_stack+0x17/0x19
> Sep 27 18:28:06 tornado kernel: [<c0117fc6>] smp_processor_id+0x80/0x86
> Sep 27 18:28:06 tornado kernel: [<c0282bf3>] make_request+0x174/0x2e7
> Sep 27 18:28:06 tornado kernel: [<c02073dd>] generic_make_request+0xda/0x190

this is the remove-bkl patch's debugging feature showing that there's
more preempt-unsafe disk statistics code in the RAID code.

i've attached a patch that introduces preempt and non-preempt versions
of the statistics code and updates the block code to use the appropriate
ones - does this fix all the smp_processor_id() warnings you get?

Ingo

--- linux/drivers/block/ll_rw_blk.c.orig
+++ linux/drivers/block/ll_rw_blk.c
@@ -2099,13 +2099,13 @@ void drive_stat_acct(struct request *rq,
return;

if (rw == READ) {
- disk_stat_add(rq->rq_disk, read_sectors, nr_sectors);
+ __disk_stat_add(rq->rq_disk, read_sectors, nr_sectors);
if (!new_io)
- disk_stat_inc(rq->rq_disk, read_merges);
+ __disk_stat_inc(rq->rq_disk, read_merges);
} else if (rw == WRITE) {
- disk_stat_add(rq->rq_disk, write_sectors, nr_sectors);
+ __disk_stat_add(rq->rq_disk, write_sectors, nr_sectors);
if (!new_io)
- disk_stat_inc(rq->rq_disk, write_merges);
+ __disk_stat_inc(rq->rq_disk, write_merges);
}
if (new_io) {
disk_round_stats(rq->rq_disk);
@@ -2151,12 +2151,12 @@ void disk_round_stats(struct gendisk *di
{
unsigned long now = jiffies;

- disk_stat_add(disk, time_in_queue,
+ __disk_stat_add(disk, time_in_queue,
disk->in_flight * (now - disk->stamp));
disk->stamp = now;

if (disk->in_flight)
- disk_stat_add(disk, io_ticks, (now - disk->stamp_idle));
+ __disk_stat_add(disk, io_ticks, (now - disk->stamp_idle));
disk->stamp_idle = now;
}

@@ -2957,12 +2957,12 @@ void end_that_request_last(struct reques
unsigned long duration = jiffies - req->start_time;
switch (rq_data_dir(req)) {
case WRITE:
- disk_stat_inc(disk, writes);
- disk_stat_add(disk, write_ticks, duration);
+ __disk_stat_inc(disk, writes);
+ __disk_stat_add(disk, write_ticks, duration);
break;
case READ:
- disk_stat_inc(disk, reads);
- disk_stat_add(disk, read_ticks, duration);
+ __disk_stat_inc(disk, reads);
+ __disk_stat_add(disk, read_ticks, duration);
break;
}
disk_round_stats(disk);
--- linux/include/linux/genhd.h.orig
+++ linux/include/linux/genhd.h
@@ -112,13 +112,14 @@ struct gendisk {

/*
* Macros to operate on percpu disk statistics:
- * Since writes to disk_stats are serialised through the queue_lock,
- * smp_processor_id() should be enough to get to the per_cpu versions
- * of statistics counters
+ *
+ * The __ variants should only be called in critical sections. The full
+ * variants disable/enable preemption.
*/
#ifdef CONFIG_SMP
-#define disk_stat_add(gendiskp, field, addnd) \
+#define __disk_stat_add(gendiskp, field, addnd) \
(per_cpu_ptr(gendiskp->dkstats, smp_processor_id())->field += addnd)
+
#define disk_stat_read(gendiskp, field) \
({ \
typeof(gendiskp->dkstats->field) res = 0; \
@@ -142,7 +143,8 @@ static inline void disk_stat_set_all(str
}

#else
-#define disk_stat_add(gendiskp, field, addnd) (gendiskp->dkstats.field += addnd)
+#define __disk_stat_add(gendiskp, field, addnd) \
+ (gendiskp->dkstats.field += addnd)
#define disk_stat_read(gendiskp, field) (gendiskp->dkstats.field)

static inline void disk_stat_set_all(struct gendisk *gendiskp, int value) {
@@ -150,8 +152,21 @@ static inline void disk_stat_set_all(str
}
#endif

-#define disk_stat_inc(gendiskp, field) disk_stat_add(gendiskp, field, 1)
+#define disk_stat_add(gendiskp, field, addnd) \
+ do { \
+ preempt_disable(); \
+ __disk_stat_add(gendiskp, field, addnd); \
+ preempt_enable(); \
+ } while (0)
+
+#define __disk_stat_dec(gendiskp, field) __disk_stat_add(gendiskp, field, -1)
#define disk_stat_dec(gendiskp, field) disk_stat_add(gendiskp, field, -1)
+
+#define __disk_stat_inc(gendiskp, field) __disk_stat_add(gendiskp, field, 1)
+#define disk_stat_inc(gendiskp, field) disk_stat_add(gendiskp, field, 1)
+
+#define __disk_stat_sub(gendiskp, field, subnd) \
+ __disk_stat_add(gendiskp, field, -subnd)
#define disk_stat_sub(gendiskp, field, subnd) \
disk_stat_add(gendiskp, field, -subnd)

2004-09-27 09:18:39

by Reuben Farrelly

[permalink] [raw]
Subject: Re: Stack traces in 2.6.9-rc2-mm4

At 08:57 p.m. 27/09/2004, Ingo Molnar wrote:

>* Reuben Farrelly <[email protected]> wrote:
>
> > Since upgrading from -mm3 to -mm4, I'm now getting messages like this
> > logged every second or so:
> >
> > Sep 27 18:28:06 tornado kernel: using smp_processor_id() in preemptible
> code: swapper/1
> > Sep 27 18:28:06 tornado kernel: [<c0104dce>] dump_stack+0x17/0x19
> > Sep 27 18:28:06 tornado kernel: [<c0117fc6>] smp_processor_id+0x80/0x86
> > Sep 27 18:28:06 tornado kernel: [<c0282bf3>] make_request+0x174/0x2e7
> > Sep 27 18:28:06 tornado kernel: [<c02073dd>]
> generic_make_request+0xda/0x190
>
>this is the remove-bkl patch's debugging feature showing that there's
>more preempt-unsafe disk statistics code in the RAID code.
>
>i've attached a patch that introduces preempt and non-preempt versions
>of the statistics code and updates the block code to use the appropriate
>ones - does this fix all the smp_processor_id() warnings you get?
>
> Ingo

It certainly does, thanks muchly Ingo.

Reuben

2004-09-27 09:56:55

by Nick Piggin

[permalink] [raw]
Subject: Re: Stack traces in 2.6.9-rc2-mm4

Reuben Farrelly wrote:
> Since upgrading from -mm3 to -mm4, I'm now getting messages like this
> logged every second or so:
>
> Sep 27 18:28:06 tornado kernel: using smp_processor_id() in preemptible
>

snip

>
> Is there a fix to shut this all up or a suggested patch to revert?
>
> Box is a P4 Intel 2.8Ghz single processor, SMP/HT with PREEMPT on..
>

Looks like disk_stat_add in the sw-raid code. The proper fix is probably
to disable preempt around those regions - but just doing it the dumb
way (ie. in the driver code) looks like an unfortunate layering violation.

Maybe something like disk_stat_update_start / disk_stat_update_end that
gives you the per-cpu stat pointer as a "token" to be used by
disk_stat_inc/add/etc. Anyone?

Named slightly differently, so you keep backward compatibility, of course.

2004-09-27 23:12:45

by J.A. Magallon

[permalink] [raw]
Subject: Re: Stack traces in 2.6.9-rc2-mm4


On 2004.09.27, Ingo Molnar wrote:
>
> * Reuben Farrelly <[email protected]> wrote:
>
> > Since upgrading from -mm3 to -mm4, I'm now getting messages like this
> > logged every second or so:
> >
> > Sep 27 18:28:06 tornado kernel: using smp_processor_id() in preemptible code: swapper/1
> > Sep 27 18:28:06 tornado kernel: [<c0104dce>] dump_stack+0x17/0x19
> > Sep 27 18:28:06 tornado kernel: [<c0117fc6>] smp_processor_id+0x80/0x86
> > Sep 27 18:28:06 tornado kernel: [<c0282bf3>] make_request+0x174/0x2e7
> > Sep 27 18:28:06 tornado kernel: [<c02073dd>] generic_make_request+0xda/0x190
>
> this is the remove-bkl patch's debugging feature showing that there's
> more preempt-unsafe disk statistics code in the RAID code.
>
> i've attached a patch that introduces preempt and non-preempt versions
> of the statistics code and updates the block code to use the appropriate
> ones - does this fix all the smp_processor_id() warnings you get?
>

I got the same on another place...

Sep 28 00:48:51 werewolf xinetd[4228]: Reading included configuration file: /etc/xinetd.d/sshd-xinetd [file=/etc/xinetd.d/sshd-xinetd] [line=12]
Sep 28 00:48:51 werewolf kernel: using smp_processor_id() in preemptible code: X/4012
Sep 28 00:48:51 werewolf kernel: [smp_processor_id+135/141] smp_processor_id+0x87/0x8d
Sep 28 00:48:51 werewolf kernel: [add_timer_randomness+314/365] add_timer_randomness+0x13a/0x16d
Sep 28 00:48:51 werewolf kernel: [<b0206733>] add_timer_randomness+0x13a/0x16d
Sep 28 00:48:51 werewolf kernel: [input_event+85/999] input_event+0x55/0x3e7
Sep 28 00:48:51 werewolf kernel: [<b027fff1>] input_event+0x55/0x3e7
Sep 28 00:48:51 werewolf kernel: [kbd_rate+69/129] kbd_rate+0x45/0x81
Sep 28 00:48:51 werewolf kernel: [<b0213258>] kbd_rate+0x45/0x81
Sep 28 00:48:51 werewolf kernel: [vt_ioctl+1629/7101] vt_ioctl+0x65d/0x1bbd
Sep 28 00:48:51 werewolf kernel: [<b020fb81>] vt_ioctl+0x65d/0x1bbd
Sep 28 00:48:51 werewolf kernel: [handle_mm_fault+333/437] handle_mm_fault+0x14d/0x1b5
Sep 28 00:48:51 werewolf kernel: [<b0149579>] handle_mm_fault+0x14d/0x1b5
Sep 28 00:48:51 werewolf kernel: [do_page_fault+477/1427] do_page_fault+0x1dd/0x593
Sep 28 00:48:51 werewolf xinetd[4228]: Reading included configuration file: /etc/xinetd.d/talk [file=/etc/xinetd.d/talk] [line=16]
Sep 28 00:48:52 werewolf kernel: [<b0117479>] do_page_fault+0x1dd/0x593
Sep 28 00:48:52 werewolf kernel: [destroy_inode+53/55] destroy_inode+0x35/0x37
Sep 28 00:48:52 werewolf kernel: [<b016d407>] destroy_inode+0x35/0x37
Sep 28 00:48:52 werewolf kernel: [tty_ioctl+1224/1256] tty_ioctl+0x4c8/0x4e8
Sep 28 00:48:52 werewolf kernel: [<b020adda>] tty_ioctl+0x4c8/0x4e8
Sep 28 00:48:52 werewolf kernel: [sys_ioctl+489/581] sys_ioctl+0x1e9/0x245
Sep 28 00:48:52 werewolf kernel: [<b0167410>] sys_ioctl+0x1e9/0x245
Sep 28 00:48:52 werewolf kernel: [sysenter_past_esp+82/113] sysenter_past_esp+0x52/0x71
Sep 28 00:48:52 werewolf kernel: [<b0103fd1>] sysenter_past_esp+0x52/0x71
Sep 28 00:48:52 werewolf kernel: using smp_processor_id() in preemptible code: X/4012
Sep 28 00:48:52 werewolf kernel: [smp_processor_id+135/141] smp_processor_id+0x87/0x8d
Sep 28 00:48:52 werewolf kernel: [<b011bc8f>] smp_processor_id+0x87/0x8d
Sep 28 00:48:52 werewolf kernel: [add_timer_randomness+314/365] add_timer_randomness+0x13a/0x16d
Sep 28 00:48:52 werewolf kernel: [<b0206733>] add_timer_randomness+0x13a/0x16d
Sep 28 00:48:52 werewolf kernel: [input_event+85/999] input_event+0x55/0x3e7
Sep 28 00:48:52 werewolf kernel: [<b027fff1>] input_event+0x55/0x3e7
Sep 28 00:48:52 werewolf kernel: [kbd_rate+96/129] kbd_rate+0x60/0x81
Sep 28 00:48:52 werewolf kernel: [<b0213273>] kbd_rate+0x60/0x81
Sep 28 00:48:52 werewolf kernel: [vt_ioctl+1629/7101] vt_ioctl+0x65d/0x1bbd
Sep 28 00:48:52 werewolf kernel: [<b020fb81>] vt_ioctl+0x65d/0x1bbd
Sep 28 00:48:52 werewolf kernel: [handle_mm_fault+333/437] handle_mm_fault+0x14d/0x1b5
Sep 28 00:48:52 werewolf kernel: [<b0149579>] handle_mm_fault+0x14d/0x1b5
Sep 28 00:48:52 werewolf kernel: [do_page_fault+477/1427] do_page_fault+0x1dd/0x593
Sep 28 00:48:52 werewolf kernel: [<b0117479>] do_page_fault+0x1dd/0x593
Sep 28 00:48:52 werewolf kernel: [destroy_inode+53/55] destroy_inode+0x35/0x37
Sep 28 00:48:52 werewolf kernel: [<b016d407>] destroy_inode+0x35/0x37
Sep 28 00:48:52 werewolf kernel: [tty_ioctl+1224/1256] tty_ioctl+0x4c8/0x4e8
Sep 28 00:48:52 werewolf kernel: [<b020adda>] tty_ioctl+0x4c8/0x4e8
Sep 28 00:48:52 werewolf kernel: [sys_ioctl+489/581] sys_ioctl+0x1e9/0x245
Sep 28 00:48:52 werewolf kernel: [<b0167410>] sys_ioctl+0x1e9/0x245
Sep 28 00:48:52 werewolf kernel: [sysenter_past_esp+82/113] sysenter_past_esp+0x52/0x71
Sep 28 00:48:52 werewolf kernel: [<b0103fd1>] sysenter_past_esp+0x52/0x71
Sep 28 00:48:52 werewolf xinetd[4228]: Reading included configuration file: /etc/xinetd.d/tftp [file=/etc/xinetd.d/tftp] [line=12]
....

--
J.A. Magallon <jamagallon()able!es> \ Software is like sex:
werewolf!able!es \ It's better when it's free
Mandrakelinux release 10.1 (Community) for i586
Linux 2.6.9-rc2-mm4 (gcc 3.4.1 (Mandrakelinux (Alpha 3.4.1-3mdk)) #2


2004-09-28 07:19:51

by Ingo Molnar

[permalink] [raw]
Subject: Re: Stack traces in 2.6.9-rc2-mm4


* J.A. Magallon <[email protected]> wrote:

> I got the same on another place...
>
> Sep 28 00:48:51 werewolf kernel: using smp_processor_id() in preemptible
> code: X/4012
> Sep 28 00:48:51 werewolf kernel: [smp_processor_id+135/141]
> smp_processor_id+0x87/0x8d
> Sep 28 00:48:51 werewolf kernel: [add_timer_randomness+314/365]
> add_timer_randomness+0x13a/0x16d
> Sep 28 00:48:51 werewolf kernel: [<b0206733>]
> add_timer_randomness+0x13a/0x16d
> Sep 28 00:48:51 werewolf kernel: [input_event+85/999]
> input_event+0x55/0x3e7

the one below should fix this: a certain codepath in the random driver
relied on vt_ioctl() being under the BKL and implicitly disabling
preemption. The code wasnt buggy upstream but it's slighly unrobust so i
think we want the fix upstream too, independently of the remove-bkl
patch. This change has been in the -VP patchset for some time so it
should work fine.

Ingo

--- linux/drivers/char/random.c.orig
+++ linux/drivers/char/random.c
@@ -807,10 +807,11 @@ static void add_timer_randomness(struct
long delta, delta2, delta3;
int entropy = 0;

+ preempt_disable();
/* if over the trickle threshold, use only 1 in 4096 samples */
if ( random_state->entropy_count > trickle_thresh &&
(__get_cpu_var(trickle_count)++ & 0xfff))
- return;
+ goto out;

/*
* Use get_cycles() if implemented, otherwise fall back to
@@ -861,6 +862,8 @@ static void add_timer_randomness(struct
entropy = int_ln_12bits(delta);
}
batch_entropy_store(num, time, entropy);
+out:
+ preempt_enable();
}

void add_keyboard_randomness(unsigned char scancode)

2004-09-28 08:03:07

by Nick Piggin

[permalink] [raw]
Subject: Re: Stack traces in 2.6.9-rc2-mm4

Ingo Molnar wrote:
> * J.A. Magallon <[email protected]> wrote:
>
>
>>I got the same on another place...
>>
>>Sep 28 00:48:51 werewolf kernel: using smp_processor_id() in preemptible
>>code: X/4012
>>Sep 28 00:48:51 werewolf kernel: [smp_processor_id+135/141]
>>smp_processor_id+0x87/0x8d
>>Sep 28 00:48:51 werewolf kernel: [add_timer_randomness+314/365]
>>add_timer_randomness+0x13a/0x16d
>>Sep 28 00:48:51 werewolf kernel: [<b0206733>]
>>add_timer_randomness+0x13a/0x16d
>>Sep 28 00:48:51 werewolf kernel: [input_event+85/999]
>>input_event+0x55/0x3e7
>
>
> the one below should fix this: a certain codepath in the random driver
> relied on vt_ioctl() being under the BKL and implicitly disabling
> preemption. The code wasnt buggy upstream but it's slighly unrobust so i
> think we want the fix upstream too, independently of the remove-bkl
> patch. This change has been in the -VP patchset for some time so it
> should work fine.
>
> Ingo
>
> --- linux/drivers/char/random.c.orig
> +++ linux/drivers/char/random.c
> @@ -807,10 +807,11 @@ static void add_timer_randomness(struct
> long delta, delta2, delta3;
> int entropy = 0;
>
> + preempt_disable();
> /* if over the trickle threshold, use only 1 in 4096 samples */
> if ( random_state->entropy_count > trickle_thresh &&
> (__get_cpu_var(trickle_count)++ & 0xfff))
> - return;
> + goto out;
>

It looks like upstream code *is* buggy because that is a non-atomic
RMW operation on the per-cpu var, no? Hence you must disable preempt.

2004-09-28 10:23:32

by Ingo Molnar

[permalink] [raw]
Subject: Re: Stack traces in 2.6.9-rc2-mm4


* Nick Piggin <[email protected]> wrote:

> >+ preempt_disable();
> > /* if over the trickle threshold, use only 1 in 4096 samples */
> > if ( random_state->entropy_count > trickle_thresh &&
> > (__get_cpu_var(trickle_count)++ & 0xfff))
> >- return;
> >+ goto out;
> >
>
> It looks like upstream code *is* buggy because that is a non-atomic
> RMW operation on the per-cpu var, no? Hence you must disable preempt.

no, the upstream code (i.e. BK-curr) is not buggy, because there this
code runs under the BKL, implicitly as part of vt_ioctl() - and the BKL
disables preemption in the upstream kernel.

Yes, the code is fragile, but it's not buggy. With the remove-bkl patch
this fragility turned into an outright bug. (Fortunately the patch
detects all such incidents.)

Ingo

2004-09-28 10:48:49

by Nick Piggin

[permalink] [raw]
Subject: Re: Stack traces in 2.6.9-rc2-mm4

Ingo Molnar wrote:
> * Nick Piggin <[email protected]> wrote:
>
>
>>>+ preempt_disable();
>>> /* if over the trickle threshold, use only 1 in 4096 samples */
>>> if ( random_state->entropy_count > trickle_thresh &&
>>> (__get_cpu_var(trickle_count)++ & 0xfff))
>>>- return;
>>>+ goto out;
>>>
>>
>>It looks like upstream code *is* buggy because that is a non-atomic
>>RMW operation on the per-cpu var, no? Hence you must disable preempt.
>
>
> no, the upstream code (i.e. BK-curr) is not buggy, because there this
> code runs under the BKL, implicitly as part of vt_ioctl() - and the BKL
> disables preemption in the upstream kernel.
>
> Yes, the code is fragile, but it's not buggy. With the remove-bkl patch
> this fragility turned into an outright bug. (Fortunately the patch
> detects all such incidents.)
>

Ahh yeah you're right, sorry.

2004-09-30 21:58:50

by J.A. Magallon

[permalink] [raw]
Subject: Re: Stack traces in 2.6.9-rc2-mm4


On 2004.09.28, Ingo Molnar wrote:
>
> * J.A. Magallon <[email protected]> wrote:
>
> > I got the same on another place...
> >

Well, one more (I hope this at least serves to clean the kernel...).
This time using pump over 3c59x:

03:0a.0 Ethernet controller: 3Com Corporation 3c980-C 10/100baseTX NIC [Python-T] (rev 78)

Sep 30 23:54:41 werewolf pumpd[9843]: intf: numDns: 2
Sep 30 23:54:41 werewolf pumpd[9843]: intf: broadcast: 255.255.255.255
Sep 30 23:54:41 werewolf pumpd[9843]: intf: network: 82.198.40.0
Sep 30 23:54:41 werewolf kernel: using smp_processor_id() in preemptible code: pump/9843
Sep 30 23:54:41 werewolf kernel: [smp_processor_id+135/141] smp_processor_id+0x87/0x8d
Sep 30 23:54:41 werewolf kernel: [<b011bc8f>] smp_processor_id+0x87/0x8d
Sep 30 23:54:41 werewolf kernel: [pg0+1079594592/1337930752] death_by_timeout+0x11/0x65 [ip_conntrack]
Sep 30 23:54:41 werewolf kernel: [<f099fe60>] death_by_timeout+0x11/0x65 [ip_conntrack]
Sep 30 23:54:41 werewolf kernel: [pg0+1079600227/1337930752] ip_ct_selective_cleanup+0x68/0x6a [ip_conntrack]
Sep 30 23:54:41 werewolf kernel: [<f09a1463>] ip_ct_selective_cleanup+0x68/0x6a [ip_conntrack]
Sep 30 23:54:41 werewolf kernel: [pg0+1077916498/1337930752] masq_inet_event+0x14/0x17 [ipt_MASQUERADE]
Sep 30 23:54:41 werewolf kernel: [<f0806352>] masq_inet_event+0x14/0x17 [ipt_MASQUERADE]
Sep 30 23:54:41 werewolf kernel: [notifier_call_chain+21/43] notifier_call_chain+0x15/0x2b
Sep 30 23:54:41 werewolf kernel: [<b012cc43>] notifier_call_chain+0x15/0x2b
Sep 30 23:54:41 werewolf kernel: [inet_insert_ifa+206/335] inet_insert_ifa+0xce/0x14f
Sep 30 23:54:41 werewolf kernel: [<b02dcf96>] inet_insert_ifa+0xce/0x14f
Sep 30 23:54:41 werewolf kernel: [.text.lock.devinet+85/181] .text.lock.devinet+0x55/0xb5
Sep 30 23:54:41 werewolf kernel: [<b02de9dc>] .text.lock.devinet+0x55/0xb5
Sep 30 23:54:41 werewolf kernel: [devinet_ioctl+1273/1614] devinet_ioctl+0x4f9/0x64e
Sep 30 23:54:41 werewolf kernel: [<b02dda37>] devinet_ioctl+0x4f9/0x64e
Sep 30 23:54:41 werewolf kernel: [inet_ioctl+212/231] inet_ioctl+0xd4/0xe7
Sep 30 23:54:41 werewolf kernel: [<b02df95b>] inet_ioctl+0xd4/0xe7
Sep 30 23:54:41 werewolf kernel: [sock_ioctl+424/609] sock_ioctl+0x1a8/0x261
Sep 30 23:54:41 werewolf kernel: [<b029e30a>] sock_ioctl+0x1a8/0x261
Sep 30 23:54:41 werewolf kernel: [fget+73/94] fget+0x49/0x5e
Sep 30 23:54:41 werewolf kernel: [<b01577f7>] fget+0x49/0x5e
Sep 30 23:54:41 werewolf kernel: [sys_ioctl+489/581] sys_ioctl+0x1e9/0x245
Sep 30 23:54:41 werewolf kernel: [<b0167410>] sys_ioctl+0x1e9/0x245
Sep 30 23:54:41 werewolf kernel: [filp_close+72/138] filp_close+0x48/0x8a
Sep 30 23:54:41 werewolf kernel: [<b015613d>] filp_close+0x48/0x8a
Sep 30 23:54:41 werewolf kernel: [sysenter_past_esp+82/113] sysenter_past_esp+0x52/0x71
Sep 30 23:54:41 werewolf kernel: [<b0103fc5>] sysenter_past_esp+0x52/0x71
Sep 30 23:54:41 werewolf kernel: using smp_processor_id() in preemptible code: pump/9843
Sep 30 23:54:41 werewolf kernel: [smp_processor_id+135/141] smp_processor_id+0x87/0x8d
Sep 30 23:54:41 werewolf kernel: [<b011bc8f>] smp_processor_id+0x87/0x8d
Sep 30 23:54:41 werewolf kernel: [pg0+1079594488/1337930752] destroy_conntrack+0xc1/0x118 [ip_conntrack]
Sep 30 23:54:41 werewolf kernel: [<f099fdf8>] destroy_conntrack+0xc1/0x118 [ip_conntrack]
Sep 30 23:54:41 werewolf kernel: [pg0+1079600195/1337930752] ip_ct_selective_cleanup+0x48/0x6a [ip_conntrack]
Sep 30 23:54:41 werewolf kernel: [<f09a1443>] ip_ct_selective_cleanup+0x48/0x6a [ip_conntrack]
Sep 30 23:54:41 werewolf kernel: [pg0+1077916498/1337930752] masq_inet_event+0x14/0x17 [ipt_MASQUERADE]
Sep 30 23:54:41 werewolf kernel: [<f0806352>] masq_inet_event+0x14/0x17 [ipt_MASQUERADE]
Sep 30 23:54:41 werewolf kernel: [notifier_call_chain+21/43] notifier_call_chain+0x15/0x2b
Sep 30 23:54:41 werewolf kernel: [<b012cc43>] notifier_call_chain+0x15/0x2b
Sep 30 23:54:41 werewolf kernel: [inet_insert_ifa+206/335] inet_insert_ifa+0xce/0x14f
Sep 30 23:54:41 werewolf kernel: [<b02dcf96>] inet_insert_ifa+0xce/0x14f
Sep 30 23:54:41 werewolf kernel: [.text.lock.devinet+85/181] .text.lock.devinet+0x55/0xb5
Sep 30 23:54:41 werewolf kernel: [<b02de9dc>] .text.lock.devinet+0x55/0xb5
Sep 30 23:54:41 werewolf kernel: [devinet_ioctl+1273/1614] devinet_ioctl+0x4f9/0x64e
Sep 30 23:54:41 werewolf kernel: [<b02dda37>] devinet_ioctl+0x4f9/0x64e
Sep 30 23:54:41 werewolf kernel: [inet_ioctl+212/231] inet_ioctl+0xd4/0xe7
Sep 30 23:54:41 werewolf kernel: [<b02df95b>] inet_ioctl+0xd4/0xe7
Sep 30 23:54:41 werewolf kernel: [sock_ioctl+424/609] sock_ioctl+0x1a8/0x261
Sep 30 23:54:41 werewolf kernel: [<b029e30a>] sock_ioctl+0x1a8/0x261
Sep 30 23:54:41 werewolf kernel: [fget+73/94] fget+0x49/0x5e
Sep 30 23:54:41 werewolf kernel: [<b01577f7>] fget+0x49/0x5e
Sep 30 23:54:41 werewolf kernel: [sys_ioctl+489/581] sys_ioctl+0x1e9/0x245
Sep 30 23:54:41 werewolf kernel: [<b0167410>] sys_ioctl+0x1e9/0x245
Sep 30 23:54:41 werewolf kernel: [filp_close+72/138] filp_close+0x48/0x8a
Sep 30 23:54:41 werewolf kernel: [<b015613d>] filp_close+0x48/0x8a
Sep 30 23:54:41 werewolf kernel: [sysenter_past_esp+82/113] sysenter_past_esp+0x52/0x71
Sep 30 23:54:41 werewolf kernel: [<b0103fc5>] sysenter_past_esp+0x52/0x71

And I aldo get many times this one:

Sep 30 23:54:41 werewolf kernel: ACPI: PCI interrupt 0000:03:0a.0[A] -> GSI 22 (level, low) -> IRQ 22

TIA

--
J.A. Magallon <jamagallon()able!es> \ Software is like sex:
werewolf!able!es \ It's better when it's free
Mandrakelinux release 10.1 (Community) for i586
Linux 2.6.9-rc2-mm4 (gcc 3.4.1 (Mandrakelinux (Alpha 3.4.1-3mdk)) #1


2004-09-30 22:55:32

by Ingo Molnar

[permalink] [raw]
Subject: Re: Stack traces in 2.6.9-rc2-mm4


* J.A. Magallon <[email protected]> wrote:

> Sep 30 23:54:41 werewolf pumpd[9843]: intf: broadcast: 255.255.255.255
> Sep 30 23:54:41 werewolf pumpd[9843]: intf: network: 82.198.40.0
> Sep 30 23:54:41 werewolf kernel: using smp_processor_id() in preemptible
> code: pump/9843
> Sep 30 23:54:41 werewolf kernel: [smp_processor_id+135/141]
> smp_processor_id+0x87/0x8d
> Sep 30 23:54:41 werewolf kernel: [<b011bc8f>] smp_processor_id+0x87/0x8d
> Sep 30 23:54:41 werewolf kernel: [pg0+1079594592/1337930752]
> death_by_timeout+0x11/0x65 [ip_conntrack]
> Sep 30 23:54:41 werewolf kernel: [<f099fe60>] death_by_timeout+0x11/0x65
> [ip_conntrack]

does the patch below fix these for you?

Ingo

--- include/linux/netfilter_ipv4/ip_conntrack.h.orig
+++ include/linux/netfilter_ipv4/ip_conntrack.h
@@ -311,7 +311,7 @@ struct ip_conntrack_stat
unsigned int expect_delete;
};

-#define CONNTRACK_STAT_INC(count) (__get_cpu_var(ip_conntrack_stat).count++)
+#define CONNTRACK_STAT_INC(count) (per_cpu(ip_conntrack_stat, _smp_processor_id()).count++)

/* eg. PROVIDES_CONNTRACK(ftp); */
#define PROVIDES_CONNTRACK(name) \

2004-09-30 23:16:43

by J.A. Magallon

[permalink] [raw]
Subject: Re: Stack traces in 2.6.9-rc2-mm4


On 2004.10.01, Ingo Molnar wrote:
>
> * J.A. Magallon <[email protected]> wrote:
>
> > Sep 30 23:54:41 werewolf pumpd[9843]: intf: broadcast: 255.255.255.255
> > Sep 30 23:54:41 werewolf pumpd[9843]: intf: network: 82.198.40.0
> > Sep 30 23:54:41 werewolf kernel: using smp_processor_id() in preemptible
> > code: pump/9843
> > Sep 30 23:54:41 werewolf kernel: [smp_processor_id+135/141]
> > smp_processor_id+0x87/0x8d
> > Sep 30 23:54:41 werewolf kernel: [<b011bc8f>] smp_processor_id+0x87/0x8d
> > Sep 30 23:54:41 werewolf kernel: [pg0+1079594592/1337930752]
> > death_by_timeout+0x11/0x65 [ip_conntrack]
> > Sep 30 23:54:41 werewolf kernel: [<f099fe60>] death_by_timeout+0x11/0x65
> > [ip_conntrack]
>
> does the patch below fix these for you?
>
> Ingo
>
> --- include/linux/netfilter_ipv4/ip_conntrack.h.orig
> +++ include/linux/netfilter_ipv4/ip_conntrack.h
> @@ -311,7 +311,7 @@ struct ip_conntrack_stat
> unsigned int expect_delete;
> };
>
> -#define CONNTRACK_STAT_INC(count) (__get_cpu_var(ip_conntrack_stat).count++)
> +#define CONNTRACK_STAT_INC(count) (per_cpu(ip_conntrack_stat, _smp_processor_id()).count++)
>
> /* eg. PROVIDES_CONNTRACK(ftp); */
> #define PROVIDES_CONNTRACK(name) \

Yes, It has killed the stack trace.
But this messa from ACPI (I suspect it is unrelated) stays:

Oct 1 01:14:33 werewolf pumpd[5813]: intf: numDns: 2
Oct 1 01:14:33 werewolf pumpd[5813]: intf: broadcast: 255.255.255.255
Oct 1 01:14:33 werewolf pumpd[5813]: intf: network: 82.198.40.0
Oct 1 01:14:33 werewolf kernel: ACPI: PCI interrupt 0000:03:0a.0[A] -> GSI 22 (level, low) -> IRQ 22
Oct 1 01:14:33 werewolf pumpd[5813]: configured interface eth0
Oct 1 01:14:33 werewolf ifup: done.

Thanks.

--
J.A. Magallon <jamagallon()able!es> \ Software is like sex:
werewolf!able!es \ It's better when it's free
Mandrakelinux release 10.1 (Community) for i586
Linux 2.6.9-rc2-mm4 (gcc 3.4.1 (Mandrakelinux (Alpha 3.4.1-3mdk)) #1