[ltt-dev] OMAP3/4 trace clock and lockdep tracing

[ltt-dev] OMAP3/4 trace clock and lockdep tracing

[Harald Gustafsson]

Hi,

I'm currently porting the higher precision OMAP3/4 trace clock aka
non-generic to another dual-core ARMv7 architecture. The port is not
fully debugged yet but I discovered one strange thing that I wonder if
anyone have experienced on the OMAP3/4 as well. If I use the
non-generic trace clock and have lockdep tracing turned on the system
freezes (no output) but the soft lockup cleaner kills of a process
each 61 seconds and dumps its output. Without the non-generic clock I
don't have this problem and without the lockdep tracing I don't have
this problem even when using the non-generic clock. To clarify it is
the lockdep tracing that show the problem, if I only have lockdep
configured it is no problem.

Have anyone run lockdep tracing on the OMAP3/4 using the non-generic
trace clock (i.e. normal LTTng config) and had this problem? This
would help me understand if it is only a porting issue or if there is
some deeper bug to find.

I use a 2.6.34 kernel (with LOCKDEP, LOCKDEP_DEBUG, DEBUG_LOCK_ALLOC,
PROVE_LOCKING, DEBUG_SPINLOCK, LOCK_STAT, and DEBUG_TRACE_CLOCK on)
with lttng 0.221 currently for compatibility with other SW and HW.

Regards,
 Harald Gustafsson

[ltt-dev] OMAP3/4 trace clock and lockdep tracing

[Mathieu Desnoyers]

* Harald Gustafsson (hgu1972 at gmail.com) wrote:
> Hi,
> 
> I'm currently porting the higher precision OMAP3/4 trace clock aka
> non-generic to another dual-core ARMv7 architecture. The port is not
> fully debugged yet but I discovered one strange thing that I wonder if
> anyone have experienced on the OMAP3/4 as well. If I use the
> non-generic trace clock and have lockdep tracing turned on the system
> freezes (no output) but the soft lockup cleaner kills of a process
> each 61 seconds and dumps its output. Without the non-generic clock I
> don't have this problem and without the lockdep tracing I don't have
> this problem even when using the non-generic clock. To clarify it is
> the lockdep tracing that show the problem, if I only have lockdep
> configured it is no problem.
> 
> Have anyone run lockdep tracing on the OMAP3/4 using the non-generic
> trace clock (i.e. normal LTTng config) and had this problem? This
> would help me understand if it is only a porting issue or if there is
> some deeper bug to find.
> 
> I use a 2.6.34 kernel (with LOCKDEP, LOCKDEP_DEBUG, DEBUG_LOCK_ALLOC,
> PROVE_LOCKING, DEBUG_SPINLOCK, LOCK_STAT, and DEBUG_TRACE_CLOCK on)
> with lttng 0.221 currently for compatibility with other SW and HW.

Hrm, I should probably do this, can you try this patch out ? Can you
test it and report if it fixes your problem ?


ARM omap trace clock notrace

* Harald Gustafsson (hgu1972 at gmail.com) wrote:
> Hi,
> 
> I'm currently porting the higher precision OMAP3/4 trace clock aka
> non-generic to another dual-core ARMv7 architecture. The port is not
> fully debugged yet but I discovered one strange thing that I wonder if
> anyone have experienced on the OMAP3/4 as well. If I use the
> non-generic trace clock and have lockdep tracing turned on the system
> freezes (no output) but the soft lockup cleaner kills of a process
> each 61 seconds and dumps its output. Without the non-generic clock I
> don't have this problem and without the lockdep tracing I don't have
> this problem even when using the non-generic clock. To clarify it is
> the lockdep tracing that show the problem, if I only have lockdep
> configured it is no problem.
>
[...]
> I use a 2.6.34 kernel (with LOCKDEP, LOCKDEP_DEBUG, DEBUG_LOCK_ALLOC,
> PROVE_LOCKING, DEBUG_SPINLOCK, LOCK_STAT, and DEBUG_TRACE_CLOCK on)

Let's make sure the trace lock read primitive don't call into lockdep.

Signed-off-by: Mathieu Desnoyers <mathieu.desnoyers at efficios.com>
---
 arch/arm/plat-omap/include/plat/trace-clock.h |   10 +++++-----
 1 file changed, 5 insertions(+), 5 deletions(-)

Index: linux-2.6-lttng/arch/arm/plat-omap/include/plat/trace-clock.h
===================================================================
--- linux-2.6-lttng.orig/arch/arm/plat-omap/include/plat/trace-clock.h
+++ linux-2.6-lttng/arch/arm/plat-omap/include/plat/trace-clock.h
@@ -1,5 +1,5 @@
 /*
- * Copyright (C) 2009 Mathieu Desnoyers
+ * Copyright (C) 2009, 2010, 2011 Mathieu Desnoyers
  *
  * Trace clock ARM OMAP3 definitions.
  */
@@ -122,12 +122,12 @@ static inline u64 trace_clock_read64(voi
 #ifdef CONFIG_DEBUG_TRACE_CLOCK
 	unsigned long flags;
 
-	local_irq_save(flags);
+	raw_local_irq_save(flags);
 	per_cpu(last_clock_nest, smp_processor_id())++;
 	barrier();
 #endif
 
-	preempt_disable();
+	preempt_disable_notrace();
 	pm_count = &per_cpu(pm_save_count, smp_processor_id());
 	if (likely(pm_count->fast_clock_ready)) {
 		cf = &pm_count->cf[ACCESS_ONCE(pm_count->index)];
@@ -136,12 +136,12 @@ static inline u64 trace_clock_read64(voi
 	} else
 		val = _trace_clock_read_slow();
 	trace_clock_debug(val);
-	preempt_enable();
+	preempt_enable_notrace();
 
 #ifdef CONFIG_DEBUG_TRACE_CLOCK
 	barrier();
 	per_cpu(last_clock_nest, smp_processor_id())--;
-	local_irq_restore(flags);
+	raw_local_irq_restore(flags);
 #endif
 	return val;
 }


-- 
Mathieu Desnoyers
Operating System Efficiency R&D Consultant
EfficiOS Inc.
http://www.efficios.com

[ltt-dev] OMAP3/4 trace clock and lockdep tracing

[Harald Gustafsson]

2011/4/6 Mathieu Desnoyers <compudj at krystal.dyndns.org>:
> Hrm, I should probably do this, can you try this patch out ? Can you
> test it and report if it fixes your problem ?

Thanks it fixes the problem. I made the corresponding changes in my
architecture's trace-clock.h which is a copy & paste of the omap
version. So I assume this would also work for the OMAP.

Now I only have the clock mismatch between the cores to deal with,
lttv complains for threads that are inserted before they are forked
(range is 10 us - 10 ms mismatch depending on run). I think it is due
to that the cores enters/leaves WFI unsynced and hence runs on cycle
counter and 32kHz clock in a different pattern and I get some error
due to this.  So far I run cpufreq on performance to not introduce
even more uncertainty. Have you tried the code on a OMAP4?

Regards,
  Harald

[ltt-dev] OMAP3/4 trace clock and lockdep tracing

[Mathieu Desnoyers]

* Harald Gustafsson (hgu1972 at gmail.com) wrote:
> 2011/4/6 Mathieu Desnoyers <compudj at krystal.dyndns.org>:
> > Hrm, I should probably do this, can you try this patch out ? Can you
> > test it and report if it fixes your problem ?
> 
> Thanks it fixes the problem. I made the corresponding changes in my
> architecture's trace-clock.h which is a copy & paste of the omap
> version. So I assume this would also work for the OMAP.
> 
> Now I only have the clock mismatch between the cores to deal with,
> lttv complains for threads that are inserted before they are forked
> (range is 10 us - 10 ms mismatch depending on run). I think it is due
> to that the cores enters/leaves WFI unsynced and hence runs on cycle
> counter and 32kHz clock in a different pattern and I get some error
> due to this.  So far I run cpufreq on performance to not introduce
> even more uncertainty. Have you tried the code on a OMAP4?

I haven't tested this on OMAP4 personally, so I'm really interested in
your feedback. I did my development on OMAP3 UP, but I designed the
trace clock to support SMP (but it's not tested by myself, others have
reported success though). You might want to try with and without:

- power management suspend/resume
- cpufreq changes

There is code in trace clock to support each of these. 10 ms offset
between the cores is way too much, so I guess there is something wrong
there. First identifying if it's suspend/resume or cpufreq that are
causing the problems would help us there.

What do you mean by "enters/leaves WFI" ? (WFI TLA means ?)

Given what you say above, cpufreq running in performance mode should
make it OK as far as cpufreq is concerned, although there might be some
discrepancy at boot time if the cpufreq mode is only changed later.

I suspect that the problem might come from that your OMAP4 architecture
does not call the trace clock resync after power management resume, like
OMAP3 is doing. You might also want to have a look at the Linaro 2.6.38
git tree, which integrates LTTng with Linaro, which might have better
support for OMAP4 suspend/resume.

I'm really interested in fixing this up, but I'll need your help for
testing.

Thanks!

Mathieu

> 
> Regards,
>   Harald
> 

-- 
Mathieu Desnoyers
Operating System Efficiency R&D Consultant
EfficiOS Inc.
http://www.efficios.com

[ltt-dev] OMAP3/4 trace clock and lockdep tracing

[Harald Gustafsson]

2011/4/6 Mathieu Desnoyers <compudj at krystal.dyndns.org>:
> I haven't tested this on OMAP4 personally, so I'm really interested in
> your feedback. I did my development on OMAP3 UP, but I designed the
> trace clock to support SMP (but it's not tested by myself, others have
> reported success though).
Good to know that other have succeeded on a SMP system.

> You might want to try with and without:
>
> - power management suspend/resume
> - cpufreq changes
For initial debug I could turn these off, but the use cases we are to
analyse must have these on, and have correct trace clock for these
activities.

> There is code in trace clock to support each of these. 10 ms offset
> between the cores is way too much, so I guess there is something wrong
> there. First identifying if it's suspend/resume or cpufreq that are
> causing the problems would help us there.
Yes it must be something with the suspend/resume and not resyncing correctly.

> What do you mean by "enters/leaves WFI" ? (WFI TLA means ?)
Wait-For-Instruction is the last instruction that the processor do
before actually sleep or idle. It hangs on this until it is again
waked-up. Hence I placed the calls to save clock and resync before and
after these points.

> Given what you say above, cpufreq running in performance mode should
> make it OK as far as cpufreq is concerned, although there might be some
> discrepancy at boot time if the cpufreq mode is only changed later.
I have discovered that the idle code sometimes enters a state clocked
at 32kHz, hence that would mess up the clock counter. This might be
the cause of the problem, but I have not had time to look in more
detail.

> I suspect that the problem might come from that your OMAP4 architecture
> does not call the trace clock resync after power management resume, like
> OMAP3 is doing.
Note that this is not an OMAP4 arch I'm running on but another dual
core SMP ARMv7. I thought I called resync at all places but maybe not.

> You might also want to have a look at the Linaro 2.6.38
> git tree, which integrates LTTng with Linaro, which might have better
> support for OMAP4 suspend/resume.
I have not checked that yet, need to take a closer look later on.

> I'm really interested in fixing this up, but I'll need your help for
> testing.
That's generous of you, I'm happy to do testing but it might be
difficult since you don't have access to the actual architecture files
and the issue likely is in those. Could I get back on this one, since
I would like to have good performance on this, but I'm using code that
my employer has not yet released (need to follow process). For now I
decided to implement a much simpler trace clock, due to that people
were waiting on the solution, that always is in sync between cores and
don't need resync at idle/wake-up but still has decent resolution. It
looks like this:

static atomic64_t last_clock_val;
inline u64 trace_clock_read64(void)
{
    u64 clock_val, ret, inc_clock_val;

    do {
	clock_val = cnt32_to_63(clock32k->read(clock32k)) << TRACE_CLOCK_32K_BITSHIFT;
	inc_clock_val = atomic64_add_return(1,&last_clock_val); //contains
memory barrier
    } while( (clock_val > inc_clock_val) &&
(atomic64_cmpxchg(&last_clock_val, inc_clock_val, clock_val) !=
inc_clock_val));

    if(clock_val > inc_clock_val)
	ret = clock_val;
    else
	ret = inc_clock_val;
    return ret;
}

Same concept as the generic jiffy + counter, but using an always on
32kHz clock and no timers. It speculatively increase the LSBs of the
atomic clock variable and replace it with the up shifted 32kHz clock
if it has ticked up. Worst case it spins the while loop 1<<
TRACE_CLOCK_32K_BITSHIFT times if two threads goes in lock-step for
each line (although the atomic operations can also spin). We are still
looking into improving it, but it seems to work. ARM has faster cache
snooping than x86 so it is less of a problem that it uses a shared
atomic between cores. I'm also speculating in using a cycle counter
progress instead of an inc of 1, but that would mean the
TRACE_CLOCK_32K_BITSHIFT needs to be larger and that is problematic.

Regards,
 Harald

[ltt-dev] OMAP3/4 trace clock and lockdep tracing

[Mathieu Desnoyers]

* Harald Gustafsson (hgu1972 at gmail.com) wrote:
> 2011/4/6 Mathieu Desnoyers <compudj at krystal.dyndns.org>:
> > I haven't tested this on OMAP4 personally, so I'm really interested in
> > your feedback. I did my development on OMAP3 UP, but I designed the
> > trace clock to support SMP (but it's not tested by myself, others have
> > reported success though).
> Good to know that other have succeeded on a SMP system.
> 
> > You might want to try with and without:
> >
> > - power management suspend/resume
> > - cpufreq changes
> For initial debug I could turn these off, but the use cases we are to
> analyse must have these on, and have correct trace clock for these
> activities.
> 
> > There is code in trace clock to support each of these. 10 ms offset
> > between the cores is way too much, so I guess there is something wrong
> > there. First identifying if it's suspend/resume or cpufreq that are
> > causing the problems would help us there.
> Yes it must be something with the suspend/resume and not resyncing correctly.

Please note that you can be woken up by an interrupt, which means that
an IRQ handler will be executed before you resume to execute the
instruction that follows the WFI. Do you resync when woken up by these
interrupts ?

> 
> > What do you mean by "enters/leaves WFI" ? (WFI TLA means ?)
> Wait-For-Instruction is the last instruction that the processor do
> before actually sleep or idle. It hangs on this until it is again
> waked-up. Hence I placed the calls to save clock and resync before and
> after these points.
> 
> > Given what you say above, cpufreq running in performance mode should
> > make it OK as far as cpufreq is concerned, although there might be some
> > discrepancy at boot time if the cpufreq mode is only changed later.
> I have discovered that the idle code sometimes enters a state clocked
> at 32kHz, hence that would mess up the clock counter. This might be
> the cause of the problem, but I have not had time to look in more
> detail.
> 
> > I suspect that the problem might come from that your OMAP4 architecture
> > does not call the trace clock resync after power management resume, like
> > OMAP3 is doing.
> Note that this is not an OMAP4 arch I'm running on but another dual
> core SMP ARMv7. I thought I called resync at all places but maybe not.
> 
> > You might also want to have a look at the Linaro 2.6.38
> > git tree, which integrates LTTng with Linaro, which might have better
> > support for OMAP4 suspend/resume.
> I have not checked that yet, need to take a closer look later on.
> 
> > I'm really interested in fixing this up, but I'll need your help for
> > testing.
> That's generous of you, I'm happy to do testing but it might be
> difficult since you don't have access to the actual architecture files
> and the issue likely is in those. Could I get back on this one, since
> I would like to have good performance on this, but I'm using code that
> my employer has not yet released (need to follow process). For now I
> decided to implement a much simpler trace clock, due to that people
> were waiting on the solution, that always is in sync between cores and
> don't need resync at idle/wake-up but still has decent resolution. It
> looks like this:
> 
> static atomic64_t last_clock_val;
> inline u64 trace_clock_read64(void)
> {
>     u64 clock_val, ret, inc_clock_val;
> 
>     do {
> 	clock_val = cnt32_to_63(clock32k->read(clock32k)) << TRACE_CLOCK_32K_BITSHIFT;

You might want to use the trace clock 32 to 64 provided by LTTng instead
of cnt_32_to_63. See the kernel/trace/trace-clock-32-to-64.c.

> 	inc_clock_val = atomic64_add_return(1,&last_clock_val); //contains
> memory barrier
>     } while( (clock_val > inc_clock_val) &&
> (atomic64_cmpxchg(&last_clock_val, inc_clock_val, clock_val) !=
> inc_clock_val));

I'd have to look a little bit at this code to figure out exactly what it
does, but I'm glad it hear it works for you :)

Mathieu

> 
>     if(clock_val > inc_clock_val)
> 	ret = clock_val;
>     else
> 	ret = inc_clock_val;
>     return ret;
> }
> 
> Same concept as the generic jiffy + counter, but using an always on
> 32kHz clock and no timers. It speculatively increase the LSBs of the
> atomic clock variable and replace it with the up shifted 32kHz clock
> if it has ticked up. Worst case it spins the while loop 1<<
> TRACE_CLOCK_32K_BITSHIFT times if two threads goes in lock-step for
> each line (although the atomic operations can also spin). We are still
> looking into improving it, but it seems to work. ARM has faster cache
> snooping than x86 so it is less of a problem that it uses a shared
> atomic between cores. I'm also speculating in using a cycle counter
> progress instead of an inc of 1, but that would mean the
> TRACE_CLOCK_32K_BITSHIFT needs to be larger and that is problematic.
> 
> Regards,
>  Harald
> 

-- 
Mathieu Desnoyers
Operating System Efficiency R&D Consultant
EfficiOS Inc.
http://www.efficios.com

[ltt-dev] OMAP3/4 trace clock and lockdep tracing

[Harald Gustafsson]

I took a look at the Linaro lttng git, but they don't seem to have
adopted it more for the OMAP4 than in your git tree. There is a new
pm44xx.c file which don't contain any resync_trace_clock() calls which
should be needed and the trace-clock.c file is your ordinary one.

2011/4/7 Mathieu Desnoyers <compudj at krystal.dyndns.org>:
> Please note that you can be woken up by an interrupt, which means that
> an IRQ handler will be executed before you resume to execute the
> instruction that follows the WFI. Do you resync when woken up by these
> interrupts ?
No, which might be causing the issues, but do you resync in the IRQ
for OMAP3 I could not find any code that did that? rather the comment
saying that IRQ might have run before the call to the resync in the
pm34xx.c file.

>> ? ? ? clock_val = cnt32_to_63(clock32k->read(clock32k)) << TRACE_CLOCK_32K_BITSHIFT;
>
> You might want to use the trace clock 32 to 64 provided by LTTng instead
> of cnt_32_to_63. See the kernel/trace/trace-clock-32-to-64.c.

I did consider the trace-clock-32-to-64.c but decided that it was
overkill for extending a continuous running low rate clock, the
cnt32_to_63 macro in include/linux/cnt32_to_63.h is commonly used to
extend counters at least on ARM arch.

Harald