[ltt-dev] Trace "destroy" hangs, lttd keeps running
Mathieu Desnoyers
mathieu.desnoyers at polymtl.ca
Thu Nov 19 11:52:44 EST 2009
* Ashwin Tanugula (ashwin.tanugula at broadcom.com) wrote:
> > >
> > > > I compared the mips code to the approach I took for intel (they were quite similar) and found the discrepancy. Please ignore the previous patch I just sent, and try this one instead:
> > >
> > >
> > > Mathieu,
> > >
> > >Even this patch does not fix the issue.
> > >
>
> > Well, it does seem to fix the trace clock hang issue on mips32, right ?
> > So we're getting there...
>
> Hi Mathieu,
>
> No, the trace clock hang issue is not fixed with this patch.
>
> I am sorry, I should have explained it better in my previous email.
>
> I continued my testing using "return 1;" to reproduce the errors with
> the viewer, so that I can send you my trace data.
>
OK. Then let's revert to the previous lttng assumption: synchronized
TSCs across MIPS cores. Does that work for you ? (I see that you
configured your kernel with support for 2 CPUs. Do you have an SMP
board ?)
MIPS assume synchronized TSC
Code for non-synchronized TSC support was broken (at least for MIPS32). I
suspect the spinlock did not do well with NMIs or something like this. Revert to
assuming synchronized TSCs across cores until someone send me a MIPS board to
play with.
Signed-off-by: Mathieu Desnoyers <mathieu.desnoyers at polymtl.ca>
---
arch/mips/Kconfig | 1
arch/mips/include/asm/trace-clock.h | 29 ++----
arch/mips/kernel/Makefile | 2
arch/mips/kernel/trace-clock.c | 171 ------------------------------------
4 files changed, 12 insertions(+), 191 deletions(-)
Index: linux-2.6-lttng/arch/mips/Kconfig
===================================================================
--- linux-2.6-lttng.orig/arch/mips/Kconfig 2009-11-19 11:36:16.000000000 -0500
+++ linux-2.6-lttng/arch/mips/Kconfig 2009-11-19 11:36:23.000000000 -0500
@@ -1739,7 +1739,6 @@ config HAVE_GET_CYCLES_32
depends on !CPU_R4400_WORKAROUNDS
select HAVE_TRACE_CLOCK
select HAVE_TRACE_CLOCK_32_TO_64
- select HAVE_UNSYNCHRONIZED_TSC
#
# Use the generic interrupt handling code in kernel/irq/:
Index: linux-2.6-lttng/arch/mips/include/asm/trace-clock.h
===================================================================
--- linux-2.6-lttng.orig/arch/mips/include/asm/trace-clock.h 2009-11-19 11:36:40.000000000 -0500
+++ linux-2.6-lttng/arch/mips/include/asm/trace-clock.h 2009-11-19 11:44:59.000000000 -0500
@@ -32,28 +32,15 @@ extern u64 trace_clock_read_synthetic_ts
* tracing needs to detect delays longer than 8 seconds, we need a full 64-bits
* TSC, whic is provided by trace-clock-32-to-64.
*/
-extern u64 trace_clock_async_tsc_read(void);
static inline u32 trace_clock_read32(void)
{
- u32 cycles;
-
- if (likely(tsc_is_sync()))
- cycles = (u32)get_cycles(); /* only need the 32 LSB */
- else
- cycles = (u32)trace_clock_async_tsc_read();
- return cycles;
+ return (u32)get_cycles(); /* only need the 32 LSB */
}
static inline u64 trace_clock_read64(void)
{
- u64 cycles;
-
- if (likely(tsc_is_sync()))
- cycles = trace_clock_read_synthetic_tsc();
- else
- cycles = trace_clock_async_tsc_read();
- return cycles;
+ return trace_clock_read_synthetic_tsc();
}
static inline u64 trace_clock_frequency(void)
@@ -66,11 +53,19 @@ static inline u32 trace_clock_freq_scale
return 1;
}
-extern void get_trace_clock(void);
-extern void put_trace_clock(void);
extern void get_synthetic_tsc(void);
extern void put_synthetic_tsc(void);
+static inline void get_trace_clock(void)
+{
+ get_synthetic_tsc();
+}
+
+static inline void put_trace_clock(void)
+{
+ put_synthetic_tsc();
+}
+
static inline void set_trace_clock_is_sync(int state)
{
}
Index: linux-2.6-lttng/arch/mips/kernel/trace-clock.c
===================================================================
--- linux-2.6-lttng.orig/arch/mips/kernel/trace-clock.c 2009-11-19 11:41:23.000000000 -0500
+++ /dev/null 1970-01-01 00:00:00.000000000 +0000
@@ -1,171 +0,0 @@
-/*
- * arch/mips/kernel/trace-clock.c
- *
- * Trace clock for mips.
- *
- * Mathieu Desnoyers <mathieu.desnoyers at polymtl.ca>, October 2008
- */
-
-#include <linux/module.h>
-#include <linux/trace-clock.h>
-#include <linux/jiffies.h>
-#include <linux/timer.h>
-#include <linux/spinlock.h>
-
-static u64 trace_clock_last_tsc;
-static DEFINE_PER_CPU(struct timer_list, update_timer);
-static DEFINE_SPINLOCK(async_tsc_lock);
-static int async_tsc_refcount; /* Number of readers */
-static int async_tsc_enabled; /* Async TSC enabled on all online CPUs */
-
-#if (BITS_PER_LONG == 64)
-static inline u64 trace_clock_cmpxchg64(u64 *ptr, u64 old, u64 new)
-{
- return cmpxchg64(ptr, old, new);
-}
-#else
-/*
- * Emulate an atomic 64-bits update with a spinlock.
- * Note : preempt_disable or irq save must be explicit with raw_spinlock_t.
- * Given we use a spinlock for this time base, we should never be called from
- * NMI context.
- */
-static raw_spinlock_t trace_clock_lock =
- (raw_spinlock_t)__RAW_SPIN_LOCK_UNLOCKED;
-
-/*
- * Must be called under irqoff+spinlock on MIPS32.
- */
-static inline u64 trace_clock_cmpxchg64(u64 *ptr, u64 old, u64 new)
-{
- u64 val;
-
- val = *ptr;
- if (likely(val == old))
- *ptr = new;
- return val;
-}
-#endif
-
-/*
- * Must be called under irqoff+spinlock on MIPS32.
- */
-static cycles_t read_last_tsc(void)
-{
- return trace_clock_last_tsc;
-}
-
-/*
- * Support for architectures with non-sync TSCs.
- * When the local TSC is discovered to lag behind the highest TSC counter, we
- * increment the TSC count of an amount that should be, ideally, lower than the
- * execution time of this routine, in cycles : this is the granularity we look
- * for : we must be able to order the events.
- *
- * MIPS32 does not have atomic 64-bit updates. Emulate it with irqoff+spinlock.
- */
-
-notrace u64 trace_clock_async_tsc_read(void)
-{
- u64 new_tsc, last_tsc;
-#if (BITS_PER_LONG == 32)
- unsigned long flags;
-
- local_irq_save(flags);
- __raw_spin_lock(&trace_clock_lock);
-#endif
-
- WARN_ON(!async_tsc_refcount || !async_tsc_enabled);
- new_tsc = trace_clock_read_synthetic_tsc();
- barrier();
- last_tsc = read_last_tsc();
- do {
- if (new_tsc < last_tsc)
- new_tsc = last_tsc + TRACE_CLOCK_MIN_PROBE_DURATION;
- /*
- * If cmpxchg fails with a value higher than the new_tsc, don't
- * retry : the value has been incremented and the events
- * happened almost at the same time.
- * We must retry if cmpxchg fails with a lower value :
- * it means that we are the CPU with highest frequency and
- * therefore MUST update the value.
- */
- last_tsc = trace_clock_cmpxchg64(&trace_clock_last_tsc,
- last_tsc, new_tsc);
- } while (unlikely(last_tsc < new_tsc));
-#if (BITS_PER_LONG == 32)
- __raw_spin_unlock(&trace_clock_lock);
- local_irq_restore(flags);
-#endif
- return new_tsc;
-}
-EXPORT_SYMBOL_GPL(trace_clock_async_tsc_read);
-
-static void update_timer_ipi(void *info)
-{
- (void)trace_clock_async_tsc_read();
-}
-
-/*
- * update_timer_fct : - Timer function to resync the clocks
- * @data: unused
- *
- * Fires every jiffy.
- */
-static void update_timer_fct(unsigned long data)
-{
- (void)trace_clock_async_tsc_read();
-
- per_cpu(update_timer, smp_processor_id()).expires = jiffies + 1;
- add_timer_on(&per_cpu(update_timer, smp_processor_id()),
- smp_processor_id());
-}
-
-static void enable_trace_clock(int cpu)
-{
- init_timer(&per_cpu(update_timer, cpu));
- per_cpu(update_timer, cpu).function = update_timer_fct;
- per_cpu(update_timer, cpu).expires = jiffies + 1;
- smp_call_function_single(cpu, update_timer_ipi, NULL, 1);
- add_timer_on(&per_cpu(update_timer, cpu), cpu);
-}
-
-static void disable_trace_clock(int cpu)
-{
- del_timer_sync(&per_cpu(update_timer, cpu));
-}
-
-void get_trace_clock(void)
-{
- int cpu;
-
- spin_lock(&async_tsc_lock);
- if (async_tsc_refcount++ || tsc_is_sync()) {
- get_synthetic_tsc();
- } else {
- async_tsc_enabled = 1;
- get_synthetic_tsc();
- for_each_online_cpu(cpu)
- enable_trace_clock(cpu);
- }
- spin_unlock(&async_tsc_lock);
-}
-EXPORT_SYMBOL_GPL(get_trace_clock);
-
-void put_trace_clock(void)
-{
- int cpu;
-
- spin_lock(&async_tsc_lock);
- WARN_ON(async_tsc_refcount <= 0);
- if (async_tsc_refcount != 1 || !async_tsc_enabled) {
- put_synthetic_tsc();
- } else {
- for_each_online_cpu(cpu)
- disable_trace_clock(cpu);
- async_tsc_enabled = 0;
- }
- async_tsc_refcount--;
- spin_unlock(&async_tsc_lock);
-}
-EXPORT_SYMBOL_GPL(put_trace_clock);
Index: linux-2.6-lttng/arch/mips/kernel/Makefile
===================================================================
--- linux-2.6-lttng.orig/arch/mips/kernel/Makefile 2009-11-19 11:47:20.000000000 -0500
+++ linux-2.6-lttng/arch/mips/kernel/Makefile 2009-11-19 11:47:27.000000000 -0500
@@ -88,8 +88,6 @@ obj-$(CONFIG_GPIO_TXX9) += gpio_txx9.o
obj-$(CONFIG_KEXEC) += machine_kexec.o relocate_kernel.o
obj-$(CONFIG_EARLY_PRINTK) += early_printk.o
-obj-$(CONFIG_HAVE_TRACE_CLOCK) += trace-clock.o
-
CFLAGS_cpu-bugs64.o = $(shell if $(CC) $(KBUILD_CFLAGS) -Wa,-mdaddi -c -o /dev/null -xc /dev/null >/dev/null 2>&1; then echo "-DHAVE_AS_SET_DADDI"; fi)
obj-$(CONFIG_HAVE_STD_PC_SERIAL_PORT) += 8250-platform.o
>
> Thanks,
> Ashwin
>
>
>
>
>
>
> >
> > [Merging emails]
> >
> >
> > > >
> > > > With "return 1;" I can sometimes generate the trace and sometime I cannot as lttd is still running even after destroying the trace.
> > > >
> > > > Please look at the attached log file.
> > > >
> >
> > > running lttd in verbose mode could eventually help here. (see lttd --help). You would have to start it separately from lttctl though (see lttctl --help to see how to create a trace, then start lttd, and then start tracing with lttctl).
> >
> >
> > Running lttd in verbose mode didn't help either.
> >
> > Here'swhat I did
> >
> > lttctl -c trace2
> > lttd/lttd -t /tmp/trace2 -c /proc/sys/debug/ltt/trace2 -N 1 -d -n -v
> > lttctl -s trace2
> >
> > To stop the trace
> >
> > lttctl -D trace2
> >
> >
> > lttd still is running at this point for traces longer than 5 minutes.
> >
>
> It would be useful to have the output of what lttd is doing after you
> issue "lttctl -D trace2".
>
> Hrm, and you might want to remove the "-d" parameter for lttd. I'm not
> sure it keeps the verbose output on the console.
>
> Is the system very busy while you take your trace ? I suppose the mips32
> board you have is single-cpu, am I correct ?
>
> Also please make sure to double-check the lttd version you are using
> (e.g. not a binary left over from an old build). This is especially
> important because the newer lttng-lttv-lttctl-lttd versions break
> compatibility with older versions.
>
> > I can generate and view the trace data for smaller traces (1 min) without any problems.
> >
>
> Great, at least this tells us that the trace clock now works. I'm having
> trouble reproducing your issue on my x86-64 machine though.
>
> Thanks,
>
> Mathieu
>
>
> >
> > > > i) ERROR:tracefile.c:1676:ltt_seek_next_event: assertion failed: (tf->event.offset < tf->buffer.data_size)
> > > > ./lttv-gui: line 10: 12602 Aborted (core dumped) $LTTV_CMD.real -m lttvwindow -m guievents -m guifilter -m guicontrolflow -m resourceview -m guistatistics -m guitracecontrol $*
> > > >
> > > >
> >
> > > This is a bit weird. Make sure you do a make clean of your lttv tree and rebuild. Also, compiling lttv with:
> >
> > > ./configure CFLAGS=-g
> > > make
> > > make install
> >
> > > and running:
> >
> > > gdb lttv.real
> > > set args -v -d -m textDump -t /tmp/trace run
> >
> > > and showing the stack trace with:
> >
> > > bt full
> >
> > > would help here. (btw, lttv -m textDump --help shows you the textDump help information)
> >
> > > You could also put the trace somewhere I can access it, so I can look at it with lttv on my local machine.
> >
> >
> > I was not able to reproduce this error.
> >
> > Thanks,
> > Ashwin
>
> --
> Mathieu Desnoyers
> OpenPGP key fingerprint: 8CD5 52C3 8E3C 4140 715F BA06 3F25 A8FE 3BAE 9A68
>
>
>
--
Mathieu Desnoyers
OpenPGP key fingerprint: 8CD5 52C3 8E3C 4140 715F BA06 3F25 A8FE 3BAE 9A68
More information about the lttng-dev
mailing list