[ltt-dev] CONFIG_HAVE_TRACE_CLOCK_GENERIC timestamp problem on PXA255

[Mathieu Desnoyers]

* Steve Langstaff (steve.langstaff at pebblebay.com) wrote:
> I have built LTTng for kernel 2.6.30-rc5 + patch set 0.137 using
> CONFIG_HAVE_TRACE_CLOCK_GENERIC on my PXA255.
> 
> All of the LTTng stuff is configured to be built-in to the kernel, rather
> than loadable modules.
> 
> I am having trouble with the timestamps that are logged in the traces - they
> don't seem to 'tick' at the right rate.
> 
> Here is my test program... it starts a trace, logs a START user event,
> sleeps for 1 second, logs a STOP user event and then stops the trace:
> 
> /tmp # cat sleeper.sh
> #!/bin/sh
> lttctl -C -w /tmp/sleeper sleeper
> echo `date` START > /tmp/debugfs/ltt/write_event
> sleep 1
> echo `date` STOP >/tmp/debugfs/ltt/write_event
> lttctl -D sleeper
> 
> ----
> 
> Here is the test program running:
> 
> /tmp # ./sleeper.sh
> Linux Trace Toolkit Trace Control 0.67-05032009
> 
> Controlling trace : sleeper
> 
> lttctl: Creating trace
> lttctl: Forking lttd
> Linux Trace Toolkit Trace Daemon 0.67-05032009
> 
> Reading from debugfs directory : /tmp/debugfs/ltt/sleeper
> Writing to trace directory : /tmp/sleeper
> 
> lttctl: Starting trace
> Linux Trace Toolkit Trace Control 0.67-05032009
> 
> Controlling trace : sleeper
> 
> lttctl: Pausing trace
> lttctl: Destroying trace
> 
> ----
> 
> I then tar up the trace directory and copy it to my host machine - that
> shouldn't be a problem because the traces are self-describing, right?
> 
> Here are the timestamps that I see when I examine the trace with lttv -m
> textDump sleeper | fgrep UTC
> 
> userspace.event: 4661.842551269
> (/home/steve/Projects/TEMP/sleeper/userspace_0), 351, 351, sleeper.sh, ,
> 259, 0x0, SYSCALL { string = "Thu Jan 1 01:33:27 UTC 1970 START" }
> 
> userspace.event: 4661.844299316
> (/home/steve/Projects/TEMP/sleeper/userspace_0), 351, 351, sleeper.sh, ,
> 259, 0x0, SYSCALL { string = "Thu Jan 1 01:33:28 UTC 1970 STOP" }
> 
> See how the 'seconds' field is stuck at 4661 - this appears to be the case
> on all traces that I take.
> 
> Any ideas where I could start looking?
> 
> Am I just flogging a dead horse trying to get meaningful data from LTTng on
> a PXA255?
> 

Hrm, this should at least follow the correct tick rate.

Everything you need to know about it is in patch 

trace-clock-generic.patch

which touches :

 include/asm-generic/trace-clock.h |   64 +++++++++++++++++++++++++
 include/linux/trace-clock.h       |   17 ++++++
 init/Kconfig                      |    6 ++
 kernel/trace/Makefile             |    1
 kernel/trace/trace-clock.c        |   97 ++++++++++++++++++++++++++++++++++++++
 5 files changed, 185 insertions(+)

A few things to check :

- if your system is in NO_HZ
- your HZ value
- if the timer handler trace_clock_timer_fct is called (try adding a
  printk in there)
- If the timer frequency reported by trace_clock_frequency() is correct.

Hope this helps,

Mathieu

> 
> 
> _______________________________________________
> ltt-dev mailing list
> ltt-dev at lists.casi.polymtl.ca
> 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