* [BUG] using smp_processor_id() in preemptible
@ 2008-11-15 23:30 Luis Henriques
2008-11-16 7:10 ` Ingo Molnar
0 siblings, 1 reply; 3+ messages in thread
From: Luis Henriques @ 2008-11-15 23:30 UTC (permalink / raw)
To: Ingo Molnar; +Cc: linux-kernel
Hi Ingo,
while running latencytop, got the following:
...
[ 775.663239] BUG: using smp_processor_id() in preemptible [00000000] code: latencytop/6585
[ 775.663303] caller is native_sched_clock+0x3a/0x80
[ 775.663314] Pid: 6585, comm: latencytop Tainted: G W 2.6.28-rc4-00355-g9c7c354 #1
[ 775.663322] Call Trace:
[ 775.663343] [<ffffffff803a94e4>] debug_smp_processor_id+0xe4/0xf0
[ 775.663356] [<ffffffff80213f7a>] native_sched_clock+0x3a/0x80
[ 775.663368] [<ffffffff80213e19>] sched_clock+0x9/0x10
[ 775.663381] [<ffffffff8024550d>] proc_sched_show_task+0x8bd/0x10e0
[ 775.663395] [<ffffffff8034466e>] sched_show+0x3e/0x80
[ 775.663408] [<ffffffff8031039b>] seq_read+0xdb/0x350
[ 775.663421] [<ffffffff80368776>] ? security_file_permission+0x16/0x20
[ 775.663435] [<ffffffff802f4198>] vfs_read+0xc8/0x170
[ 775.663447] [<ffffffff802f4335>] sys_read+0x55/0x90
[ 775.663460] [<ffffffff8020c67a>] system_call_fastpath+0x16/0x1b
...
I am running 2.6.28-rc4-00355-g9c7c354 and, after taking a look at the code, it
looks like the problem is in commit 7cbaef9c83e58bbd4bdd534b09052b6c5ec457d5,
where native_sched_clock is modified to use __cycles_2_ns instead of
cycles_2_ns.
--
Luis Henriques
^ permalink raw reply [flat|nested] 3+ messages in thread
* Re: [BUG] using smp_processor_id() in preemptible
2008-11-15 23:30 [BUG] using smp_processor_id() in preemptible Luis Henriques
@ 2008-11-16 7:10 ` Ingo Molnar
2008-11-18 11:05 ` Michal Hocko
0 siblings, 1 reply; 3+ messages in thread
From: Ingo Molnar @ 2008-11-16 7:10 UTC (permalink / raw)
To: Luis Henriques; +Cc: linux-kernel
* Luis Henriques <henrix@sapo.pt> wrote:
> Hi Ingo,
>
> while running latencytop, got the following:
>
> [ 775.663239] BUG: using smp_processor_id() in preemptible [00000000] code: latencytop/6585
> [ 775.663303] caller is native_sched_clock+0x3a/0x80
> [ 775.663314] Pid: 6585, comm: latencytop Tainted: G W 2.6.28-rc4-00355-g9c7c354 #1
> [ 775.663322] Call Trace:
> [ 775.663343] [<ffffffff803a94e4>] debug_smp_processor_id+0xe4/0xf0
> [ 775.663356] [<ffffffff80213f7a>] native_sched_clock+0x3a/0x80
> [ 775.663368] [<ffffffff80213e19>] sched_clock+0x9/0x10
> [ 775.663381] [<ffffffff8024550d>] proc_sched_show_task+0x8bd/0x10e0
> [ 775.663395] [<ffffffff8034466e>] sched_show+0x3e/0x80
> [ 775.663408] [<ffffffff8031039b>] seq_read+0xdb/0x350
> [ 775.663421] [<ffffffff80368776>] ? security_file_permission+0x16/0x20
> [ 775.663435] [<ffffffff802f4198>] vfs_read+0xc8/0x170
> [ 775.663447] [<ffffffff802f4335>] sys_read+0x55/0x90
> [ 775.663460] [<ffffffff8020c67a>] system_call_fastpath+0x16/0x1b
> ...
>
> I am running 2.6.28-rc4-00355-g9c7c354 and, after taking a look at
> the code, it looks like the problem is in commit
> 7cbaef9c83e58bbd4bdd534b09052b6c5ec457d5, where native_sched_clock
> is modified to use __cycles_2_ns instead of cycles_2_ns.
indeed. Does the fix below work for you?
Thanks,
Ingo
-------------->
>From 29d7b90c15035741d15421b36000509212b3e135 Mon Sep 17 00:00:00 2001
From: Ingo Molnar <mingo@elte.hu>
Date: Sun, 16 Nov 2008 08:07:15 +0100
Subject: [PATCH] sched: fix kernel warning on /proc/sched_debug access
Luis Henriques reported that with CONFIG_PREEMPT=y + CONFIG_PREEMPT_DEBUG=y +
CONFIG_SCHED_DEBUG=y + CONFIG_LATENCYTOP=y enabled, the following warning
triggers when using latencytop:
> [ 775.663239] BUG: using smp_processor_id() in preemptible [00000000] code: latencytop/6585
> [ 775.663303] caller is native_sched_clock+0x3a/0x80
> [ 775.663314] Pid: 6585, comm: latencytop Tainted: G W 2.6.28-rc4-00355-g9c7c354 #1
> [ 775.663322] Call Trace:
> [ 775.663343] [<ffffffff803a94e4>] debug_smp_processor_id+0xe4/0xf0
> [ 775.663356] [<ffffffff80213f7a>] native_sched_clock+0x3a/0x80
> [ 775.663368] [<ffffffff80213e19>] sched_clock+0x9/0x10
> [ 775.663381] [<ffffffff8024550d>] proc_sched_show_task+0x8bd/0x10e0
> [ 775.663395] [<ffffffff8034466e>] sched_show+0x3e/0x80
> [ 775.663408] [<ffffffff8031039b>] seq_read+0xdb/0x350
> [ 775.663421] [<ffffffff80368776>] ? security_file_permission+0x16/0x20
> [ 775.663435] [<ffffffff802f4198>] vfs_read+0xc8/0x170
> [ 775.663447] [<ffffffff802f4335>] sys_read+0x55/0x90
> [ 775.663460] [<ffffffff8020c67a>] system_call_fastpath+0x16/0x1b
> ...
This breakage was caused by me via:
7cbaef9: sched: optimize sched_clock() a bit
Change the calls to cpu_clock().
Reported-by: Luis Henriques <henrix@sapo.pt>
---
kernel/sched_debug.c | 5 +++--
1 files changed, 3 insertions(+), 2 deletions(-)
diff --git a/kernel/sched_debug.c b/kernel/sched_debug.c
index 48ecc51..26ed8e3 100644
--- a/kernel/sched_debug.c
+++ b/kernel/sched_debug.c
@@ -423,10 +423,11 @@ void proc_sched_show_task(struct task_struct *p, struct seq_file *m)
#undef __P
{
+ unsigned int this_cpu = raw_smp_processor_id();
u64 t0, t1;
- t0 = sched_clock();
- t1 = sched_clock();
+ t0 = cpu_clock(this_cpu);
+ t1 = cpu_clock(this_cpu);
SEQ_printf(m, "%-35s:%21Ld\n",
"clock-delta", (long long)(t1-t0));
}
^ permalink raw reply related [flat|nested] 3+ messages in thread
* Re: [BUG] using smp_processor_id() in preemptible
2008-11-16 7:10 ` Ingo Molnar
@ 2008-11-18 11:05 ` Michal Hocko
0 siblings, 0 replies; 3+ messages in thread
From: Michal Hocko @ 2008-11-18 11:05 UTC (permalink / raw)
To: Ingo Molnar; +Cc: Luis Henriques, linux-kernel
On Sun 16-11-08 08:10:59, Ingo Molnar wrote:
>
> * Luis Henriques <henrix@sapo.pt> wrote:
>
> > Hi Ingo,
> >
> > while running latencytop, got the following:
> >
> > [ 775.663239] BUG: using smp_processor_id() in preemptible [00000000] code: latencytop/6585
> > [ 775.663303] caller is native_sched_clock+0x3a/0x80
> > [ 775.663314] Pid: 6585, comm: latencytop Tainted: G W 2.6.28-rc4-00355-g9c7c354 #1
> > [ 775.663322] Call Trace:
> > [ 775.663343] [<ffffffff803a94e4>] debug_smp_processor_id+0xe4/0xf0
> > [ 775.663356] [<ffffffff80213f7a>] native_sched_clock+0x3a/0x80
> > [ 775.663368] [<ffffffff80213e19>] sched_clock+0x9/0x10
> > [ 775.663381] [<ffffffff8024550d>] proc_sched_show_task+0x8bd/0x10e0
> > [ 775.663395] [<ffffffff8034466e>] sched_show+0x3e/0x80
> > [ 775.663408] [<ffffffff8031039b>] seq_read+0xdb/0x350
> > [ 775.663421] [<ffffffff80368776>] ? security_file_permission+0x16/0x20
> > [ 775.663435] [<ffffffff802f4198>] vfs_read+0xc8/0x170
> > [ 775.663447] [<ffffffff802f4335>] sys_read+0x55/0x90
> > [ 775.663460] [<ffffffff8020c67a>] system_call_fastpath+0x16/0x1b
> > ...
> >
> > I am running 2.6.28-rc4-00355-g9c7c354 and, after taking a look at
> > the code, it looks like the problem is in commit
> > 7cbaef9c83e58bbd4bdd534b09052b6c5ec457d5, where native_sched_clock
> > is modified to use __cycles_2_ns instead of cycles_2_ns.
>
> indeed. Does the fix below work for you?
Yes, it fixes problem on my end... (reported at
http://www.gossamer-threads.com/lists/linux/kernel/997205).
>
> Thanks,
>
> Ingo
>
> -------------->
> From 29d7b90c15035741d15421b36000509212b3e135 Mon Sep 17 00:00:00 2001
> From: Ingo Molnar <mingo@elte.hu>
> Date: Sun, 16 Nov 2008 08:07:15 +0100
> Subject: [PATCH] sched: fix kernel warning on /proc/sched_debug access
>
> Luis Henriques reported that with CONFIG_PREEMPT=y + CONFIG_PREEMPT_DEBUG=y +
> CONFIG_SCHED_DEBUG=y + CONFIG_LATENCYTOP=y enabled, the following warning
> triggers when using latencytop:
>
> > [ 775.663239] BUG: using smp_processor_id() in preemptible [00000000] code: latencytop/6585
> > [ 775.663303] caller is native_sched_clock+0x3a/0x80
> > [ 775.663314] Pid: 6585, comm: latencytop Tainted: G W 2.6.28-rc4-00355-g9c7c354 #1
> > [ 775.663322] Call Trace:
> > [ 775.663343] [<ffffffff803a94e4>] debug_smp_processor_id+0xe4/0xf0
> > [ 775.663356] [<ffffffff80213f7a>] native_sched_clock+0x3a/0x80
> > [ 775.663368] [<ffffffff80213e19>] sched_clock+0x9/0x10
> > [ 775.663381] [<ffffffff8024550d>] proc_sched_show_task+0x8bd/0x10e0
> > [ 775.663395] [<ffffffff8034466e>] sched_show+0x3e/0x80
> > [ 775.663408] [<ffffffff8031039b>] seq_read+0xdb/0x350
> > [ 775.663421] [<ffffffff80368776>] ? security_file_permission+0x16/0x20
> > [ 775.663435] [<ffffffff802f4198>] vfs_read+0xc8/0x170
> > [ 775.663447] [<ffffffff802f4335>] sys_read+0x55/0x90
> > [ 775.663460] [<ffffffff8020c67a>] system_call_fastpath+0x16/0x1b
> > ...
>
> This breakage was caused by me via:
>
> 7cbaef9: sched: optimize sched_clock() a bit
>
> Change the calls to cpu_clock().
>
> Reported-by: Luis Henriques <henrix@sapo.pt>
Tested-by: Michal Hocko <mhocko@suse.cz>
> ---
> kernel/sched_debug.c | 5 +++--
> 1 files changed, 3 insertions(+), 2 deletions(-)
>
> diff --git a/kernel/sched_debug.c b/kernel/sched_debug.c
> index 48ecc51..26ed8e3 100644
> --- a/kernel/sched_debug.c
> +++ b/kernel/sched_debug.c
> @@ -423,10 +423,11 @@ void proc_sched_show_task(struct task_struct *p, struct seq_file *m)
> #undef __P
>
> {
> + unsigned int this_cpu = raw_smp_processor_id();
> u64 t0, t1;
>
> - t0 = sched_clock();
> - t1 = sched_clock();
> + t0 = cpu_clock(this_cpu);
> + t1 = cpu_clock(this_cpu);
> SEQ_printf(m, "%-35s:%21Ld\n",
> "clock-delta", (long long)(t1-t0));
> }
>
> --
> To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at http://vger.kernel.org/majordomo-info.html
> Please read the FAQ at http://www.tux.org/lkml/
--
Michal Hocko
L3 team
SUSE LINUX s.r.o.
Lihovarska 1060/12
190 00 Praha 9
Czech Republic
^ permalink raw reply [flat|nested] 3+ messages in thread
end of thread, other threads:[~2008-11-18 11:05 UTC | newest]
Thread overview: 3+ messages (download: mbox.gz follow: Atom feed
-- links below jump to the message on this page --
2008-11-15 23:30 [BUG] using smp_processor_id() in preemptible Luis Henriques
2008-11-16 7:10 ` Ingo Molnar
2008-11-18 11:05 ` Michal Hocko
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox