Hi,
After applying LTTng 0.158 patches on 2.6.29-RT with SMP and NON-SMP
found BUG on ARM target.
LTTng 0.158 patches with 2.6.29 is working fine.
Linux kernel: 2.6.29-RT
RT patches: patch-2.6.29.6-rt24-broken-out.tar.bz2
http://www.kernel.org/pub/linux/kernel/projects/rt/patch-2.6.29.6-rt24-broken-out.tar.bz2
LTTng 0.158 patches are applied.
ARCH: ARM
Glibc: 2.9
gcc: 4.3.3
dmesg
{{{
BUG: sleeping function called from invalid context at kernel/rtmutex.c:685
in_atomic(): 1, irqs_disabled(): 128, pid: 720, name: lttd
Backtrace:
[<c002d434>] (dump_backtrace+0x0/0x10c) from [<c03a75d8>] (dump_stack+0x18/0x1c)
r7:000002ad r6:c045da78 r5:00001116 r4:c04ba400
[<c03a75c0>] (dump_stack+0x0/0x1c) from [<c0041028>] (__might_sleep+0x120/0x14c)
[<c0040f08>] (__might_sleep+0x0/0x14c) from [<c03a9b18>]
(rt_spin_lock+0x38/0x68)
r7:ce319d04 r6:c0763660 r5:c05107a0 r4:c05107a0
[<c03a9ae0>] (rt_spin_lock+0x0/0x68) from [<c00570b0>]
(lock_timer_base+0x30/0x54)
r4:c05107a0
[<c0057080>] (lock_timer_base+0x0/0x54) from [<c00571b4>] (del_timer+0x2c/0x6c)
r8:c0023570 r7:ce319d38 r6:00740000 r5:ceb19ca4 r4:c0763660
[<c0057188>] (del_timer+0x0/0x6c) from [<c008e5ec>]
(disable_synthetic_tsc_ipi+0x24/0x30)
r5:ceb19ca4 r4:00000001
[<c008e5c8>] (disable_synthetic_tsc_ipi+0x0/0x30) from [<c0072e00>]
(generic_smp_call_function_single_interrupt+0x98/0xf4)
[<c0072d68>] (generic_smp_call_function_single_interrupt+0x0/0xf4)
from [<c0028368>] (do_IPI+0xc8/0x15c)
[<c00282a0>] (do_IPI+0x0/0x15c) from [<c00280c4>] (_text+0xc4/0x128)
Exception stack(0xce319d98 to 0xce319de0)
9d80: ffffffff ce319df4
9da0: 00000001 00000001 00000000 c04f6600 ce319e4c ce319dc0 c03aafcc c002800c
9dc0: c0726f20 00000000 00000000 0000002c c0726f00 000006f8 00000001 00000001
r8:0000001d r7:00000000 r6:fc000000 r5:ce319dc0 r4:00000001
[<c0028000>] (_text+0x0/0x128) from [<c03aafcc>] (__irq_svc+0x4c/0x74)
Exception stack(0xce319dc0 to 0xce319e08)
9dc0: c0726f20 00000000 00000000 0000002c c0726f00 000006f8 00000001 00000001
9de0: 00000000 00000000 c04f6600 ce319e4c c04f6774 ce319e08 c00a4498 c0097220
9e00: 40000013 ffffffff
[<c009701c>] (free_pages_bulk+0x0/0x2e4) from [<c00981b0>]
(free_hot_cold_page+0x2e0/0x320)
[<c0097ed0>] (free_hot_cold_page+0x0/0x320) from [<c009825c>]
(free_hot_page+0x14/0x18)
r8:cf81bb20 r7:cf264400 r6:cd9f7e00 r5:cf12bee0 r4:00000007
[<c0098248>] (free_hot_page+0x0/0x18) from [<c00982a4>] (__free_pages+0x44/0x50)
[<c0098260>] (__free_pages+0x0/0x50) from [<c022ef5c>]
(relay_destroy_buf+0x80/0xd4)
[<c022eedc>] (relay_destroy_buf+0x0/0xd4) from [<c022f54c>]
(relay_remove_buf+0x30/0x34)
r7:cf4fddb8 r6:cf4fddb8 r5:cf12bef4 r4:cf12bee0
[<c022f51c>] (relay_remove_buf+0x0/0x34) from [<c0239a24>] (kref_put+0x74/0x84)
r4:c022f51c
[<c02399b0>] (kref_put+0x0/0x84) from [<c022f56c>]
(relay_file_release+0x1c/0x28)
r5:cf3cb500 r4:cf4fddb8
[<c022f550>] (relay_file_release+0x0/0x28) from [<c022ced8>]
(ltt_release+0x30/0x5c)
[<c022cea8>] (ltt_release+0x0/0x5c) from [<c00bf46c>] (__fput+0xfc/0x1c0)
r5:00000010 r4:cf3cb500
[<c00bf370>] (__fput+0x0/0x1c0) from [<c00bf56c>] (fput+0x3c/0x40)
[<c00bf530>] (fput+0x0/0x40) from [<c00bbb2c>] (filp_close+0x7c/0x88)
[<c00bbab0>] (filp_close+0x0/0x88) from [<c00bbc4c>] (sys_close+0x114/0x158)
r6:cdc0dc60 r5:0000009d r4:cf1018ec
[<c00bbb38>] (sys_close+0x0/0x158) from [<c0028ca0>] (ret_fast_syscall+0x0/0x3c)
}}}
After searching about the problem in lkml list, found the below link
http://lkml.org/lkml/2009/9/25/29
After disabling below lines of code, BUG is disappeared.
{{{
kernel/timer.c | 4 2 + 2 - 0 !
1 file changed, 2 insertions(+), 2 deletions(-)
Index: b/kernel/timer.c
===================================================================
--- a/kernel/timer.c
+++ b/kernel/timer.c
@@ -599,11 +599,11 @@ static struct tvec_base *lock_timer_base
struct tvec_base *prelock_base = timer->base;
base = tbase_get_base(prelock_base);
if (likely(base != NULL)) {
- spin_lock_irqsave(&base->lock, *flags);
if (likely(prelock_base == timer->base))
return base;
/* The timer has migrated to another CPU */
- spin_unlock_irqrestore(&base->lock, *flags);
}
cpu_relax();
}
}}}
Is this the right way to fix the BUG?
I am not sure.
please give me your comments.
Best regards
Naresh Kamboju
On Tue, 2010-02-16 at 20:47 +0530, naresh kamboju wrote:
> Hi,
>
> After applying LTTng 0.158 patches on 2.6.29-RT with SMP and NON-SMP
> found BUG on ARM target.
> LTTng 0.158 patches with 2.6.29 is working fine.
>
> Linux kernel: 2.6.29-RT
> RT patches: patch-2.6.29.6-rt24-broken-out.tar.bz2
> http://www.kernel.org/pub/linux/kernel/projects/rt/patch-2.6.29.6-rt24-broken-out.tar.bz2
>
> LTTng 0.158 patches are applied.
> ARCH: ARM
> Glibc: 2.9
> gcc: 4.3.3
Do you get this without the LTTng patches applied?
>
> dmesg
> {{{
> BUG: sleeping function called from invalid context at kernel/rtmutex.c:685
> in_atomic(): 1, irqs_disabled(): 128, pid: 720, name: lttd
> Backtrace:
> [<c002d434>] (dump_backtrace+0x0/0x10c) from [<c03a75d8>] (dump_stack+0x18/0x1c)
> r7:000002ad r6:c045da78 r5:00001116 r4:c04ba400
> [<c03a75c0>] (dump_stack+0x0/0x1c) from [<c0041028>] (__might_sleep+0x120/0x14c)
> [<c0040f08>] (__might_sleep+0x0/0x14c) from [<c03a9b18>]
> (rt_spin_lock+0x38/0x68)
> r7:ce319d04 r6:c0763660 r5:c05107a0 r4:c05107a0
> [<c03a9ae0>] (rt_spin_lock+0x0/0x68) from [<c00570b0>]
> (lock_timer_base+0x30/0x54)
> r4:c05107a0
> [<c0057080>] (lock_timer_base+0x0/0x54) from [<c00571b4>] (del_timer+0x2c/0x6c)
> r8:c0023570 r7:ce319d38 r6:00740000 r5:ceb19ca4 r4:c0763660
> [<c0057188>] (del_timer+0x0/0x6c) from [<c008e5ec>]
> (disable_synthetic_tsc_ipi+0x24/0x30)
> r5:ceb19ca4 r4:00000001
> [<c008e5c8>] (disable_synthetic_tsc_ipi+0x0/0x30) from [<c0072e00>]
> (generic_smp_call_function_single_interrupt+0x98/0xf4)
> [<c0072d68>] (generic_smp_call_function_single_interrupt+0x0/0xf4)
> from [<c0028368>] (do_IPI+0xc8/0x15c)
> [<c00282a0>] (do_IPI+0x0/0x15c) from [<c00280c4>] (_text+0xc4/0x128)
> Exception stack(0xce319d98 to 0xce319de0)
> 9d80: ffffffff ce319df4
> 9da0: 00000001 00000001 00000000 c04f6600 ce319e4c ce319dc0 c03aafcc c002800c
> 9dc0: c0726f20 00000000 00000000 0000002c c0726f00 000006f8 00000001 00000001
> r8:0000001d r7:00000000 r6:fc000000 r5:ce319dc0 r4:00000001
> [<c0028000>] (_text+0x0/0x128) from [<c03aafcc>] (__irq_svc+0x4c/0x74)
> Exception stack(0xce319dc0 to 0xce319e08)
> 9dc0: c0726f20 00000000 00000000 0000002c c0726f00 000006f8 00000001 00000001
> 9de0: 00000000 00000000 c04f6600 ce319e4c c04f6774 ce319e08 c00a4498 c0097220
> 9e00: 40000013 ffffffff
> [<c009701c>] (free_pages_bulk+0x0/0x2e4) from [<c00981b0>]
> (free_hot_cold_page+0x2e0/0x320)
> [<c0097ed0>] (free_hot_cold_page+0x0/0x320) from [<c009825c>]
> (free_hot_page+0x14/0x18)
> r8:cf81bb20 r7:cf264400 r6:cd9f7e00 r5:cf12bee0 r4:00000007
> [<c0098248>] (free_hot_page+0x0/0x18) from [<c00982a4>] (__free_pages+0x44/0x50)
> [<c0098260>] (__free_pages+0x0/0x50) from [<c022ef5c>]
> (relay_destroy_buf+0x80/0xd4)
> [<c022eedc>] (relay_destroy_buf+0x0/0xd4) from [<c022f54c>]
> (relay_remove_buf+0x30/0x34)
> r7:cf4fddb8 r6:cf4fddb8 r5:cf12bef4 r4:cf12bee0
> [<c022f51c>] (relay_remove_buf+0x0/0x34) from [<c0239a24>] (kref_put+0x74/0x84)
> r4:c022f51c
> [<c02399b0>] (kref_put+0x0/0x84) from [<c022f56c>]
> (relay_file_release+0x1c/0x28)
> r5:cf3cb500 r4:cf4fddb8
> [<c022f550>] (relay_file_release+0x0/0x28) from [<c022ced8>]
> (ltt_release+0x30/0x5c)
> [<c022cea8>] (ltt_release+0x0/0x5c) from [<c00bf46c>] (__fput+0xfc/0x1c0)
> r5:00000010 r4:cf3cb500
> [<c00bf370>] (__fput+0x0/0x1c0) from [<c00bf56c>] (fput+0x3c/0x40)
> [<c00bf530>] (fput+0x0/0x40) from [<c00bbb2c>] (filp_close+0x7c/0x88)
> [<c00bbab0>] (filp_close+0x0/0x88) from [<c00bbc4c>] (sys_close+0x114/0x158)
> r6:cdc0dc60 r5:0000009d r4:cf1018ec
> [<c00bbb38>] (sys_close+0x0/0x158) from [<c0028ca0>] (ret_fast_syscall+0x0/0x3c)
>
> }}}
>
> After searching about the problem in lkml list, found the below link
>
> http://lkml.org/lkml/2009/9/25/29
>
> After disabling below lines of code, BUG is disappeared.
> {{{
> kernel/timer.c | 4 2 + 2 - 0 !
> 1 file changed, 2 insertions(+), 2 deletions(-)
>
> Index: b/kernel/timer.c
> ===================================================================
> --- a/kernel/timer.c
> +++ b/kernel/timer.c
> @@ -599,11 +599,11 @@ static struct tvec_base *lock_timer_base
> struct tvec_base *prelock_base = timer->base;
> base = tbase_get_base(prelock_base);
> if (likely(base != NULL)) {
> - spin_lock_irqsave(&base->lock, *flags);
> if (likely(prelock_base == timer->base))
> return base;
> /* The timer has migrated to another CPU */
> - spin_unlock_irqrestore(&base->lock, *flags);
> }
> cpu_relax();
> }
> }}}
>
> Is this the right way to fix the BUG?
> I am not sure.
Heh, no it is not a fix, it just makes more bugs ;-)
That spinlock can not be removed. But I would be interested in knowing
if you can reproduce this without the LTTng patches.
Thanks,
-- Steve
On Tue, 16 Feb 2010, Steven Rostedt wrote:
> On Tue, 2010-02-16 at 20:47 +0530, naresh kamboju wrote:
> > Hi,
> >
> > After applying LTTng 0.158 patches on 2.6.29-RT with SMP and NON-SMP
> > found BUG on ARM target.
> > LTTng 0.158 patches with 2.6.29 is working fine.
> >
> > Linux kernel: 2.6.29-RT
> > RT patches: patch-2.6.29.6-rt24-broken-out.tar.bz2
> > http://www.kernel.org/pub/linux/kernel/projects/rt/patch-2.6.29.6-rt24-broken-out.tar.bz2
> >
> > LTTng 0.158 patches are applied.
> > ARCH: ARM
> > Glibc: 2.9
> > gcc: 4.3.3
>
> Do you get this without the LTTng patches applied?
I bet you wont.
> >
> > dmesg
> > {{{
> > BUG: sleeping function called from invalid context at kernel/rtmutex.c:685
> > in_atomic(): 1, irqs_disabled(): 128, pid: 720, name: lttd
----------------------------------------------------------^^^^
> > Backtrace:
> > [<c002d434>] (dump_backtrace+0x0/0x10c) from [<c03a75d8>] (dump_stack+0x18/0x1c)
> > r7:000002ad r6:c045da78 r5:00001116 r4:c04ba400
> > [<c03a75c0>] (dump_stack+0x0/0x1c) from [<c0041028>] (__might_sleep+0x120/0x14c)
> > [<c0040f08>] (__might_sleep+0x0/0x14c) from [<c03a9b18>]
> > (rt_spin_lock+0x38/0x68)
> > r7:ce319d04 r6:c0763660 r5:c05107a0 r4:c05107a0
> > [<c03a9ae0>] (rt_spin_lock+0x0/0x68) from [<c00570b0>]
> > (lock_timer_base+0x30/0x54)
> > r4:c05107a0
> > [<c0057080>] (lock_timer_base+0x0/0x54) from [<c00571b4>] (del_timer+0x2c/0x6c)
> > r8:c0023570 r7:ce319d38 r6:00740000 r5:ceb19ca4 r4:c0763660
> > [<c0057188>] (del_timer+0x0/0x6c) from [<c008e5ec>]
> > (disable_synthetic_tsc_ipi+0x24/0x30)
> > r5:ceb19ca4 r4:00000001
> > [<c008e5c8>] (disable_synthetic_tsc_ipi+0x0/0x30) from [<c0072e00>]
> > (generic_smp_call_function_single_interrupt+0x98/0xf4)
> > [<c0072d68>] (generic_smp_call_function_single_interrupt+0x0/0xf4)
> > from [<c0028368>] (do_IPI+0xc8/0x15c)
> > [<c00282a0>] (do_IPI+0x0/0x15c) from [<c00280c4>] (_text+0xc4/0x128)
The function is called from an IPI. That's a LTTNG problem, not a RT one.
Thanks,
tglx
* Thomas Gleixner ([email protected]) wrote:
> On Tue, 16 Feb 2010, Steven Rostedt wrote:
>
> > On Tue, 2010-02-16 at 20:47 +0530, naresh kamboju wrote:
> > > Hi,
> > >
> > > After applying LTTng 0.158 patches on 2.6.29-RT with SMP and NON-SMP
> > > found BUG on ARM target.
> > > LTTng 0.158 patches with 2.6.29 is working fine.
> > >
> > > Linux kernel: 2.6.29-RT
> > > RT patches: patch-2.6.29.6-rt24-broken-out.tar.bz2
> > > http://www.kernel.org/pub/linux/kernel/projects/rt/patch-2.6.29.6-rt24-broken-out.tar.bz2
> > >
> > > LTTng 0.158 patches are applied.
> > > ARCH: ARM
> > > Glibc: 2.9
> > > gcc: 4.3.3
> >
> > Do you get this without the LTTng patches applied?
>
> I bet you wont.
>
> > >
> > > dmesg
> > > {{{
> > > BUG: sleeping function called from invalid context at kernel/rtmutex.c:685
> > > in_atomic(): 1, irqs_disabled(): 128, pid: 720, name: lttd
>
> ----------------------------------------------------------^^^^
>
> > > Backtrace:
> > > [<c002d434>] (dump_backtrace+0x0/0x10c) from [<c03a75d8>] (dump_stack+0x18/0x1c)
> > > r7:000002ad r6:c045da78 r5:00001116 r4:c04ba400
> > > [<c03a75c0>] (dump_stack+0x0/0x1c) from [<c0041028>] (__might_sleep+0x120/0x14c)
> > > [<c0040f08>] (__might_sleep+0x0/0x14c) from [<c03a9b18>]
> > > (rt_spin_lock+0x38/0x68)
> > > r7:ce319d04 r6:c0763660 r5:c05107a0 r4:c05107a0
> > > [<c03a9ae0>] (rt_spin_lock+0x0/0x68) from [<c00570b0>]
> > > (lock_timer_base+0x30/0x54)
> > > r4:c05107a0
> > > [<c0057080>] (lock_timer_base+0x0/0x54) from [<c00571b4>] (del_timer+0x2c/0x6c)
> > > r8:c0023570 r7:ce319d38 r6:00740000 r5:ceb19ca4 r4:c0763660
> > > [<c0057188>] (del_timer+0x0/0x6c) from [<c008e5ec>]
> > > (disable_synthetic_tsc_ipi+0x24/0x30)
> > > r5:ceb19ca4 r4:00000001
> > > [<c008e5c8>] (disable_synthetic_tsc_ipi+0x0/0x30) from [<c0072e00>]
> > > (generic_smp_call_function_single_interrupt+0x98/0xf4)
> > > [<c0072d68>] (generic_smp_call_function_single_interrupt+0x0/0xf4)
> > > from [<c0028368>] (do_IPI+0xc8/0x15c)
> > > [<c00282a0>] (do_IPI+0x0/0x15c) from [<c00280c4>] (_text+0xc4/0x128)
>
> The function is called from an IPI. That's a LTTNG problem, not a RT one.
I use del_timer in IPI to delete lttng per-cpu timers on all CPUs. I
have to do this because timers created with add_timer_on are documented
to be incompatible with del_timer_sync():
* Synchronization rules: Callers must prevent restarting of the timer,
* otherwise this function is meaningless. It must not be called from
* interrupt contexts. The caller must not hold locks which would prevent
* completion of the timer's handler. The timer's handler must not call
* add_timer_on(). Upon exit the timer is not queued and the handler is
* not running on any CPU.
So I resort to doing a del_timer within an IPI to delete each local
timer. I disable interrupts within the IPI to ensure that a timer
interrupt cannot possibly nest in configurations permitting IRQ nesting
(editorial question: I think the x86 arch supported such nesting that at
some point, is it still the case ?).
Any solution in mind for this ? A worker thread maybe ?
Thanks,
Mathieu
>
> Thanks,
>
> tglx
>
> _______________________________________________
> ltt-dev mailing list
> [email protected]
> http://lists.casi.polymtl.ca/cgi-bin/mailman/listinfo/ltt-dev
>
--
Mathieu Desnoyers
OpenPGP key fingerprint: 8CD5 52C3 8E3C 4140 715F BA06 3F25 A8FE 3BAE 9A68
On Tue, 16 Feb 2010, Mathieu Desnoyers wrote:
> > The function is called from an IPI. That's a LTTNG problem, not a RT one.
>
> I use del_timer in IPI to delete lttng per-cpu timers on all CPUs. I
> have to do this because timers created with add_timer_on are documented
> to be incompatible with del_timer_sync():
>
> * Synchronization rules: Callers must prevent restarting of the timer,
> * otherwise this function is meaningless. It must not be called from
> * interrupt contexts. The caller must not hold locks which would prevent
> * completion of the timer's handler. The timer's handler must not call
> * add_timer_on(). Upon exit the timer is not queued and the handler is
> * not running on any CPU.
Errm. The documentation says:
"The timer's handler must not call add_timer_on()."
It's not talking about a timer which was initialized with
add_timer_on().
And your per cpu timer handlers have no requirement to call
add_timer_on() simply because add/mod_timer() is requeueing the timer
on the same cpu on which the handler runs.
So the IPI is just a solution for a non existing problem.
Thanks,
tglx
* Thomas Gleixner ([email protected]) wrote:
> On Tue, 16 Feb 2010, Mathieu Desnoyers wrote:
> > > The function is called from an IPI. That's a LTTNG problem, not a RT one.
> >
> > I use del_timer in IPI to delete lttng per-cpu timers on all CPUs. I
> > have to do this because timers created with add_timer_on are documented
> > to be incompatible with del_timer_sync():
> >
> > * Synchronization rules: Callers must prevent restarting of the timer,
> > * otherwise this function is meaningless. It must not be called from
> > * interrupt contexts. The caller must not hold locks which would prevent
> > * completion of the timer's handler. The timer's handler must not call
> > * add_timer_on(). Upon exit the timer is not queued and the handler is
> > * not running on any CPU.
>
> Errm. The documentation says:
>
> "The timer's handler must not call add_timer_on()."
>
> It's not talking about a timer which was initialized with
> add_timer_on().
>
> And your per cpu timer handlers have no requirement to call
> add_timer_on() simply because add/mod_timer() is requeueing the timer
> on the same cpu on which the handler runs.
>
> So the IPI is just a solution for a non existing problem.
Oh, right. Thanks for the explanation. I'll look into moving LTTng to a
saner del_timer_sync() scheme to delete the timers.
Thanks,
Mathieu
>
> Thanks,
>
> tglx
>
--
Mathieu Desnoyers
OpenPGP key fingerprint: 8CD5 52C3 8E3C 4140 715F BA06 3F25 A8FE 3BAE 9A68
Hi,
On Tue, Feb 16, 2010 at 10:35 PM, Mathieu Desnoyers
<[email protected]> wrote:
> * Thomas Gleixner ([email protected]) wrote:
>> On Tue, 16 Feb 2010, Mathieu Desnoyers wrote:
>> > > The function is called from an IPI. That's a LTTNG problem, not a RT one.
yes. it's seems be a LTTng0.158 problem.
I have tested with below combinations.
2.6.29 ->no issues
2.6.29+LTTng0.100 ->no issues
2.6.29+LTTng0.158 ->no issues
2.6.29-RT ->no issues
2.6.29-RT+LTTng0.100 ->no issues
2.6.29-RT+LTTng0.158 ->BUG reported.
>> >
>> > I use del_timer in IPI to delete lttng per-cpu timers on all CPUs. I
>> > have to do this because timers created with add_timer_on are documented
>> > to be incompatible with del_timer_sync():
>> >
>> > ?* Synchronization rules: Callers must prevent restarting of the timer,
>> > ?* otherwise this function is meaningless. It must not be called from
>> > ?* interrupt contexts. The caller must not hold locks which would prevent
>> > ?* completion of the timer's handler. The timer's handler must not call
>> > ?* add_timer_on(). Upon exit the timer is not queued and the handler is
>> > ?* not running on any CPU.
>>
>> Errm. The documentation says:
>>
>> ? ? ? "The timer's handler must not call add_timer_on()."
>>
>> It's not talking about a timer which was initialized with
>> add_timer_on().
>>
>> ?And your per cpu timer handlers have no requirement to call
>> add_timer_on() simply because add/mod_timer() is requeueing the timer
>> on the same cpu on which the handler runs.
>>
>> So the IPI is just a solution for a non existing problem.
>
> Oh, right. Thanks for the explanation. I'll look into moving LTTng to a
> saner del_timer_sync() scheme to delete the timers.
Could you give more info regarding, what kind of changes we can work on.
let me also work around on it.
Best regards,
Naresh Kamboju
>
> Thanks,
>
> Mathieu
>
>>
>> Thanks,
>>
>> ? ? ? tglx
>>
>
> --
> Mathieu Desnoyers
> OpenPGP key fingerprint: 8CD5 52C3 8E3C 4140 715F ?BA06 3F25 A8FE 3BAE 9A68
* naresh kamboju ([email protected]) wrote:
> Hi,
>
> On Tue, Feb 16, 2010 at 10:35 PM, Mathieu Desnoyers <[email protected]> wrote:
[...]
> > Oh, right. Thanks for the explanation. I'll look into moving LTTng to a
> > saner del_timer_sync() scheme to delete the timers.
>
> Could you give more info regarding, what kind of changes we can work on.
> let me also work around on it.
>
I just released LTTng 0.193 for kernel 2.6.32.4 which includes patches
fixing these odd per-cpu timer teardowns. The patches concerned are:
lttng transport lockless add timer on works with del timer sync
omap trace clock use del timer sync
x86 trace clock use mod timer
trace clock 32 to 64 use del timer sync
(they are at the end of the LTTng 0.193 tree)
Feedback is welcome,
Thanks,
Mathieu
--
Mathieu Desnoyers
OpenPGP key fingerprint: 8CD5 52C3 8E3C 4140 715F BA06 3F25 A8FE 3BAE 9A68
On Thu, Feb 18, 2010 at 4:38 AM, Mathieu Desnoyers
<[email protected]> wrote:
> * naresh kamboju ([email protected]) wrote:
>> Hi,
>>
>> On Tue, Feb 16, 2010 at 10:35 PM, Mathieu Desnoyers <[email protected]> wrote:
> [...]
>> > Oh, right. Thanks for the explanation. I'll look into moving LTTng to a
>> > saner del_timer_sync() scheme to delete the timers.
>>
>> Could you give more info regarding, what kind of changes we can work on.
>> let me also work around on it.
>>
>
> I just released LTTng 0.193 for kernel 2.6.32.4 which includes patches
> fixing these odd per-cpu timer teardowns.
I have downloaded LTTng 0.193 patches and viewed i can see below patches
1. lttng-transport-lockless-add-timer-on-works-with-del-timer-sync.patch
2. omap-trace-clock-use-del-timer-sync.patch
3. x86-trace-clock-use-mod-timer.patch
4. trace-clock-32-to-64-use-del-timer-sync.patch
Thank you very much.
>The patches concerned are:
>
> lttng transport lockless add timer on works with del timer sync
> omap trace clock use del timer sync
> x86 trace clock use mod timer
> trace clock 32 to 64 use del timer sync
>
> (they are at the end of the LTTng 0.193 tree)
>
> Feedback is welcome,
I have ARM environment and currently working with 2.6.29-RT on ARM-SMP
hardware.
Let me test and comeback.
Best regards,
Naresh Kamboju
>
> Thanks,
>
> Mathieu
>
> --
> Mathieu Desnoyers
> OpenPGP key fingerprint: 8CD5 52C3 8E3C 4140 715F ?BA06 3F25 A8FE 3BAE 9A68
>
On Mon, Feb 22, 2010 at 9:07 PM, naresh kamboju <[email protected]> wrote:
> On Thu, Feb 18, 2010 at 4:38 AM, Mathieu Desnoyers
> <[email protected]> wrote:
>> * naresh kamboju ([email protected]) wrote:
>>> Hi,
>>>
>>> On Tue, Feb 16, 2010 at 10:35 PM, Mathieu Desnoyers <[email protected]> wrote:
>> [...]
>>> > Oh, right. Thanks for the explanation. I'll look into moving LTTng to a
>>> > saner del_timer_sync() scheme to delete the timers.
>>>
>>> Could you give more info regarding, what kind of changes we can work on.
>>> let me also work around on it.
>>>
>>
>> I just released LTTng 0.193 for kernel 2.6.32.4 which includes patches
>> fixing these odd per-cpu timer teardowns.
>
> I have downloaded LTTng 0.193 patches and viewed i can see below patches
>
> 1. lttng-transport-lockless-add-timer-on-works-with-del-timer-sync.patch
> 2. omap-trace-clock-use-del-timer-sync.patch
> 3. x86-trace-clock-use-mod-timer.patch
> 4. trace-clock-32-to-64-use-del-timer-sync.patch
FYI.
I have ported LTTng 0.193 these four patches and able to resolve the
issues on Uni-processor (UP) on ARM arch Thank you.
A different bug is reported on SMP.
BUG: using smp_processor_id() in preemptible [00000000] code: lttctl/754
caller is put_synthetic_tsc+0x7c/0xf8
Backtrace:
[<c002d438>] (dump_backtrace+0x0/0x10c) from [<c03a7150>] (dump_stack+0x18/0x1c)
r7:c04c4994 r6:c008e24c r5:00000003 r4:ce0b6000
[<c03a7138>] (dump_stack+0x0/0x1c) from [<c02423b4>]
(debug_smp_processor_id+0xc0/0xec)
[<c02422f4>] (debug_smp_processor_id+0x0/0xec) from [<c008e24c>]
(put_synthetic_tsc+0x7c/0xf8)
r6:c04f82cc r5:c0023600 r4:00000003
[<c008e1d0>] (put_synthetic_tsc+0x0/0xf8) from [<c008e610>]
(put_trace_clock+0x68/0x7c)
r8:bece6eb9 r7:0000000b r6:ce0b7d2a r5:cc037600 r4:00000000
[<c008e5a8>] (put_trace_clock+0x0/0x7c) from [<c022a96c>]
(ltt_trace_destroy+0x40/0x94)
[<c022a92c>] (ltt_trace_destroy+0x0/0x94) from [<c0232f6c>]
(destroy_trace_write+0xbc/0x140)
r5:00000000 r4:0000000b
[<c0232eb0>] (destroy_trace_write+0x0/0x140) from [<c00be240>]
(vfs_write+0xb4/0x144)
r7:0000000b r6:ce0b7f70 r5:bece6eb9 r4:ceae7860
[<c00be18c>] (vfs_write+0x0/0x144) from [<c00be424>] (sys_write+0x48/0xf4)
r7:0000000b r6:ceae7860 r5:00000000 r4:00000000
[<c00be3dc>] (sys_write+0x0/0xf4) from [<c0028e3c>]
(__sys_trace_return+0x0/0x24)
patch trace-clock-32-to-64-use-del-timer-sync.patch is causing above
problem on SMP.
with out this patch on SMP reported the previous bug as BUG: sleeping
function called from invalid context at kernel/rtmutex.c:685
However, i'll investigate.
Best regards,
Naresh Kamboju
>> Thanks,
>>
>> Mathieu
>>
>> --
>> Mathieu Desnoyers
>> OpenPGP key fingerprint: 8CD5 52C3 8E3C 4140 715F ?BA06 3F25 A8FE 3BAE 9A68
>>
>
* naresh kamboju ([email protected]) wrote:
> On Mon, Feb 22, 2010 at 9:07 PM, naresh kamboju <[email protected]> wrote:
> > On Thu, Feb 18, 2010 at 4:38 AM, Mathieu Desnoyers
> > <[email protected]> wrote:
> >> * naresh kamboju ([email protected]) wrote:
> >>> Hi,
> >>>
> >>> On Tue, Feb 16, 2010 at 10:35 PM, Mathieu Desnoyers <[email protected]> wrote:
> >> [...]
> >>> > Oh, right. Thanks for the explanation. I'll look into moving LTTng to a
> >>> > saner del_timer_sync() scheme to delete the timers.
> >>>
> >>> Could you give more info regarding, what kind of changes we can work on.
> >>> let me also work around on it.
> >>>
> >>
> >> I just released LTTng 0.193 for kernel 2.6.32.4 which includes patches
> >> fixing these odd per-cpu timer teardowns.
> >
> > I have downloaded LTTng 0.193 patches and viewed i can see below patches
> >
> > 1. lttng-transport-lockless-add-timer-on-works-with-del-timer-sync.patch
> > 2. omap-trace-clock-use-del-timer-sync.patch
> > 3. x86-trace-clock-use-mod-timer.patch
> > 4. trace-clock-32-to-64-use-del-timer-sync.patch
>
> FYI.
>
> I have ported LTTng 0.193 these four patches and able to resolve the
> issues on Uni-processor (UP) on ARM arch Thank you.
>
> A different bug is reported on SMP.
>
> BUG: using smp_processor_id() in preemptible [00000000] code: lttctl/754
> caller is put_synthetic_tsc+0x7c/0xf8
>
> Backtrace:
> [<c002d438>] (dump_backtrace+0x0/0x10c) from [<c03a7150>] (dump_stack+0x18/0x1c)
> r7:c04c4994 r6:c008e24c r5:00000003 r4:ce0b6000
> [<c03a7138>] (dump_stack+0x0/0x1c) from [<c02423b4>]
> (debug_smp_processor_id+0xc0/0xec)
> [<c02422f4>] (debug_smp_processor_id+0x0/0xec) from [<c008e24c>]
> (put_synthetic_tsc+0x7c/0xf8)
> r6:c04f82cc r5:c0023600 r4:00000003
> [<c008e1d0>] (put_synthetic_tsc+0x0/0xf8) from [<c008e610>]
> (put_trace_clock+0x68/0x7c)
> r8:bece6eb9 r7:0000000b r6:ce0b7d2a r5:cc037600 r4:00000000
> [<c008e5a8>] (put_trace_clock+0x0/0x7c) from [<c022a96c>]
> (ltt_trace_destroy+0x40/0x94)
> [<c022a92c>] (ltt_trace_destroy+0x0/0x94) from [<c0232f6c>]
> (destroy_trace_write+0xbc/0x140)
> r5:00000000 r4:0000000b
> [<c0232eb0>] (destroy_trace_write+0x0/0x140) from [<c00be240>]
> (vfs_write+0xb4/0x144)
> r7:0000000b r6:ce0b7f70 r5:bece6eb9 r4:ceae7860
> [<c00be18c>] (vfs_write+0x0/0x144) from [<c00be424>] (sys_write+0x48/0xf4)
> r7:0000000b r6:ceae7860 r5:00000000 r4:00000000
> [<c00be3dc>] (sys_write+0x0/0xf4) from [<c0028e3c>]
> (__sys_trace_return+0x0/0x24)
>
>
> patch trace-clock-32-to-64-use-del-timer-sync.patch is causing above
> problem on SMP.
>
> with out this patch on SMP reported the previous bug as BUG: sleeping
> function called from invalid context at kernel/rtmutex.c:685
>
> However, i'll investigate.
Hrm, we should turn the arch/{arm/mach-omap2,x86/kernel}/trace-clock.c:
trace_clock_lock into a mutex, and kernel/trace/trace-clock-32-to-64.c:
synthetic_tsc_lock into a mutex too.
I used a spinlock previously on ARM because it was called from power
management resume, but now that the data structures touched by this code
path are per-cpu, this lock is not taken there, so it should be OK to
turn it into a mutex.
Can you try that and tell me if that fixes your issues ?
Thanks,
Mathieu
>
> Best regards,
> Naresh Kamboju
> >> Thanks,
> >>
> >> Mathieu
> >>
> >> --
> >> Mathieu Desnoyers
> >> OpenPGP key fingerprint: 8CD5 52C3 8E3C 4140 715F ?BA06 3F25 A8FE 3BAE 9A68
> >>
> >
>
> _______________________________________________
> ltt-dev mailing list
> [email protected]
> http://lists.casi.polymtl.ca/cgi-bin/mailman/listinfo/ltt-dev
>
--
Mathieu Desnoyers
OpenPGP key fingerprint: 8CD5 52C3 8E3C 4140 715F BA06 3F25 A8FE 3BAE 9A68
On Tue, Feb 23, 2010 at 6:00 PM, Mathieu Desnoyers
<[email protected]> wrote:
> * naresh kamboju ([email protected]) wrote:
>> On Mon, Feb 22, 2010 at 9:07 PM, naresh kamboju <[email protected]> wrote:
>> > On Thu, Feb 18, 2010 at 4:38 AM, Mathieu Desnoyers
>> > <[email protected]> wrote:
>> >> * naresh kamboju ([email protected]) wrote:
>> >>> On Tue, Feb 16, 2010 at 10:35 PM, Mathieu Desnoyers <[email protected]> wrote:
>> >>> > Oh, right. Thanks for the explanation. I'll look into moving LTTng to a
>> >>> > saner del_timer_sync() scheme to delete the timers.
>>
>> patch trace-clock-32-to-64-use-del-timer-sync.patch is causing above
>> problem on SMP.
>>
>> with out this patch on SMP reported the previous bug as BUG: sleeping
>> function called from invalid context at kernel/rtmutex.c:685
>>
>> However, i'll investigate.
>
> Hrm, we should turn the arch/{arm/mach-omap2,x86/kernel}/trace-clock.c:
> trace_clock_lock into a mutex, and kernel/trace/trace-clock-32-to-64.c:
> synthetic_tsc_lock into a mutex too.
I have modified kernel/trace/trace-clock-32-to-64.c spin_lock to
mutex_lock to all the calls
-static DEFINE_SPINLOCK(synthetic_tsc_lock);
+static DEFINE_MUTEX(synthetic_tsc_lock);
- spin_lock(&synthetic_tsc_lock);
+ mutex_lock(&synthetic_tsc_lock);
for arch/{arm/mach-omap2/kernel}/trace-clock.c is already modified as
above from the patch
omap-trace-clock-fix-mutex.patch
from LTTng patches 02-Feb-2009.
this patch was prepared by you to fix
BUG: sleeping function called from invalid context at kernel/mutex.c:207.
Still reporting same bug at my end :-(
let me try in all possible ways.
Best regards
Naresh Kamboju
>
> I used a spinlock previously on ARM because it was called from power
> management resume, but now that the data structures touched by this code
> path are per-cpu, this lock is not taken there, so it should be OK to
> turn it into a mutex.
>
> Can you try that and tell me if that fixes your issues ?
>
> Thanks,
>
> Mathieu
>
>>
>> Best regards,
>> Naresh Kamboju
>> >> Thanks,
>> >>
>> >> Mathieu
>> >>
>> >> --
>> >> Mathieu Desnoyers
>> >> OpenPGP key fingerprint: 8CD5 52C3 8E3C 4140 715F ?BA06 3F25 A8FE 3BAE 9A68
>> >>
>> >
>>
>> _______________________________________________
>> ltt-dev mailing list
>> [email protected]
>> http://lists.casi.polymtl.ca/cgi-bin/mailman/listinfo/ltt-dev
>>
>
> --
> Mathieu Desnoyers
> OpenPGP key fingerprint: 8CD5 52C3 8E3C 4140 715F ?BA06 3F25 A8FE 3BAE 9A68
>
* naresh kamboju ([email protected]) wrote:
> On Tue, Feb 23, 2010 at 6:00 PM, Mathieu Desnoyers
> <[email protected]> wrote:
> > * naresh kamboju ([email protected]) wrote:
> >> On Mon, Feb 22, 2010 at 9:07 PM, naresh kamboju <[email protected]> wrote:
> >> > On Thu, Feb 18, 2010 at 4:38 AM, Mathieu Desnoyers
> >> > <[email protected]> wrote:
> >> >> * naresh kamboju ([email protected]) wrote:
> >> >>> On Tue, Feb 16, 2010 at 10:35 PM, Mathieu Desnoyers <[email protected]> wrote:
> >> >>> > Oh, right. Thanks for the explanation. I'll look into moving LTTng to a
> >> >>> > saner del_timer_sync() scheme to delete the timers.
> >>
> >> patch trace-clock-32-to-64-use-del-timer-sync.patch is causing above
> >> problem on SMP.
> >>
> >> with out this patch on SMP reported the previous bug as BUG: sleeping
> >> function called from invalid context at kernel/rtmutex.c:685
> >>
> >> However, i'll investigate.
> >
> > Hrm, we should turn the arch/{arm/mach-omap2,x86/kernel}/trace-clock.c:
> > trace_clock_lock into a mutex, and kernel/trace/trace-clock-32-to-64.c:
> > synthetic_tsc_lock into a mutex too.
>
> I have modified kernel/trace/trace-clock-32-to-64.c spin_lock to
> mutex_lock to all the calls
>
> -static DEFINE_SPINLOCK(synthetic_tsc_lock);
> +static DEFINE_MUTEX(synthetic_tsc_lock);
>
> - spin_lock(&synthetic_tsc_lock);
> + mutex_lock(&synthetic_tsc_lock);
>
> for arch/{arm/mach-omap2/kernel}/trace-clock.c is already modified as
> above from the patch
> omap-trace-clock-fix-mutex.patch
> from LTTng patches 02-Feb-2009.
> this patch was prepared by you to fix
> BUG: sleeping function called from invalid context at kernel/mutex.c:207.
>
> Still reporting same bug at my end :-(
>
> let me try in all possible ways.
Please note that at the end of 2009, I moved the ARM LTTng omap trace clock to a
neater per-cpu design. So it's possible that the old implementation you use has
problems with the mutex. This could be fixed with the newer implementation.
If you can tell us more about the BUG you get with the mutex-based synthetic tsc
(what the callers are) I could tell you if this problem really goes away in
newer version.
Thanks,
Mathieu
>
> Best regards
> Naresh Kamboju
> >
> > I used a spinlock previously on ARM because it was called from power
> > management resume, but now that the data structures touched by this code
> > path are per-cpu, this lock is not taken there, so it should be OK to
> > turn it into a mutex.
> >
> > Can you try that and tell me if that fixes your issues ?
> >
> > Thanks,
> >
> > Mathieu
> >
> >>
> >> Best regards,
> >> Naresh Kamboju
> >> >> Thanks,
> >> >>
> >> >> Mathieu
> >> >>
> >> >> --
> >> >> Mathieu Desnoyers
> >> >> OpenPGP key fingerprint: 8CD5 52C3 8E3C 4140 715F ?BA06 3F25 A8FE 3BAE 9A68
> >> >>
> >> >
> >>
> >> _______________________________________________
> >> ltt-dev mailing list
> >> [email protected]
> >> http://lists.casi.polymtl.ca/cgi-bin/mailman/listinfo/ltt-dev
> >>
> >
> > --
> > Mathieu Desnoyers
> > OpenPGP key fingerprint: 8CD5 52C3 8E3C 4140 715F ?BA06 3F25 A8FE 3BAE 9A68
> >
On Tue, Feb 23, 2010 at 9:22 PM, Mathieu Desnoyers
<[email protected]> wrote:
> * naresh kamboju ([email protected]) wrote:
>> On Tue, Feb 23, 2010 at 6:00 PM, Mathieu Desnoyers
>> >>
>> >> with out this patch on SMP reported the previous bug as BUG: sleeping
>> >> function called from invalid context at kernel/rtmutex.c:685
>> >>
>> >> However, i'll investigate.
>> >
>> > Hrm, we should turn the arch/{arm/mach-omap2,x86/kernel}/trace-clock.c:
>> > trace_clock_lock into a mutex, and kernel/trace/trace-clock-32-to-64.c:
>> > synthetic_tsc_lock into a mutex too.
>>
>> I have modified kernel/trace/trace-clock-32-to-64.c spin_lock to
>> mutex_lock to all the calls
>>
>> -static DEFINE_SPINLOCK(synthetic_tsc_lock);
>> +static DEFINE_MUTEX(synthetic_tsc_lock);
>>
>> - ? ? ? spin_lock(&synthetic_tsc_lock);
>> + ? ? ? mutex_lock(&synthetic_tsc_lock);
>>
>> for arch/{arm/mach-omap2/kernel}/trace-clock.c is already modified as
>> above from the patch
>> omap-trace-clock-fix-mutex.patch
>> from LTTng patches 02-Feb-2009.
>> this patch was prepared by you to fix
>> BUG: sleeping function called from invalid context at kernel/mutex.c:207.
>>
>> Still reporting same bug at my end :-(
>>
>> let me try in all possible ways.
>
Hi Mathieu,
> Please note that at the end of 2009, I moved the ARM LTTng omap trace clock to a
> neater per-cpu design.
yes.
i'll review per-cpu related patch and investigating.
> So it's possible that the old implementation you use has
> problems with the mutex. This could be fixed with the newer implementation.
currently i am using lttng-0.158 version patches of course these are OCT-2009.
now i'll check the with latest LTTng version patches and changes made
in latest repo.
>
> If you can tell us more about the BUG you get with the mutex-based synthetic tsc
> (what the callers are) I could tell you if this problem really goes away in
> newer version.
As I said previously, i was able to fix this BUG on ARM-UP kernels
after your fix patches :-)
currently checking the what could the issue making BUG on ARM-SMP,
doing workarounds on what are the function calls are differing in the
context of smp call which are making delay in spin locks and how the
lttng will lookafter timing issues w.r.t to RT kernels when i execute
lttng test cases.
If you have any inputs regarding lttng vs timers n locking, please welcome :-)
FYI
of course, it would be difficult to have same env to reproduce this
BUG at your end just want to share my analysis report.
generic_smp_call_function_single_interrupt ---------- kernel/smp.c
|
\/
disable_synthetic_tsc_ip ----------------------------------
kernel/trace/trace-clock-32-to-64.c
|
\/
del_timer ------------------------------------------------- kernel/timer.c
|
\/
lock_timer_base --------------------------------------- kernel/timer.c
|
\/
rt_spin_lock --------------------------------kernel/rtmutex.c
|
\/
__might_sleep ------------------------ kernel/sched.c
BUG: sleeping function called from invalid context at kernel/rtmutex.c:685
in_atomic(): 1, irqs_disabled(): 128, pid: 720, name: lttd
Backtrace:
[<c002d434>] (dump_backtrace+0x0/0x10c) from [<c03a75d8>] (dump_stack+0x18/0x1c)
r7:000002ad r6:c045da78 r5:00001116 r4:c04ba400
[<c03a75c0>] (dump_stack+0x0/0x1c) from [<c0041028>] (__might_sleep+0x120/0x14c)
[<c0040f08>] (__might_sleep+0x0/0x14c) from [<c03a9b18>]
(rt_spin_lock+0x38/0x68)
r7:ce319d04 r6:c0763660 r5:c05107a0 r4:c05107a0
[<c03a9ae0>] (rt_spin_lock+0x0/0x68) from [<c00570b0>]
(lock_timer_base+0x30/0x54)
r4:c05107a0
[<c0057080>] (lock_timer_base+0x0/0x54) from [<c00571b4>] (del_timer+0x2c/0x6c)
r8:c0023570 r7:ce319d38 r6:00740000 r5:ceb19ca4 r4:c0763660
[<c0057188>] (del_timer+0x0/0x6c) from [<c008e5ec>]
(disable_synthetic_tsc_ipi+0x24/0x30)
r5:ceb19ca4 r4:00000001
[<c008e5c8>] (disable_synthetic_tsc_ipi+0x0/0x30) from [<c0072e00>]
(generic_smp_call_function_single_interrupt+0x98/0xf4)
[<c0072d68>] (generic_smp_call_function_single_interrupt+0x0/0xf4)
from [<c0028368>] (do_IPI+0xc8/0x15c)
[<c00282a0>] (do_IPI+0x0/0x15c) from [<c00280c4>] (_text+0xc4/0x128)
Thank you.
Best regards
Naresh Kamboju
>
> Thanks,
>
> Mathieu
>\