[ltt-dev] Problem on combine kernel trace and userspace trace.

[Mathieu Desnoyers]

* Tony Jones (tonyj at suse.de) wrote:
> Sam Liao wrote:
> > >> I'm trying to combine the kernel trace and userspace trace, and it
> > >> seems that the
> > >> the userspace events can not be recognized to the right process with the kernel
> > >> events. I'm not sure if this is a problem of timestamp between kernel
> > >> and userspace.
> 
> Mathieu Desnoyers wrote:
> > > should work. Make sure your architecture (on x86) has synchronized
> > > contant TSCs. LTTng complains about using a work-around in dmesg if it
> > > is not the case. 
> 
> Sam Liao wrote:
> > Thanks, after apply with the "rdtsc" clock source and set up the correct
> > clock frequency,  the kernel trace and ust trace seems to be consistent
> > now.
> 
> Hi.
> 
> I'm not having much luck with this. First attempt at it, so I'm curious if 
> it's user error?

Just so you know, we're about to release a clock_gettime vDSO in LTTng
for UST which will take care of all this automagically.

Meanwhile, it looks like you forgot to switch your UST from the generic
"clock_gettime MONOTONIC" clock source to rdtsc.

Thanks,

Mathieu

> 
> 
> New HP Proliant DL785 (16 core)
> 
> To keep things simple I asserted maxcpus=1 on the cmdline so /proc/cpuinfo is:
> 
> # cat /proc/cpuinfo
> processor	: 0
> vendor_id	: AuthenticAMD
> cpu family	: 16
> model		: 9
> model name	: AMD Opteron(tm) Processor 6128
> stepping	: 1
> cpu MHz		: 800.000
> cache size	: 512 KB
> physical id	: 0
> siblings	: 1
> core id		: 0
> cpu cores	: 1
> apicid		: 16
> initial apicid	: 0
> fpu		: yes
> fpu_exception	: yes
> cpuid level	: 5
> wp		: yes
> flags		: fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov pat pse36 clflush mmx fxsr sse sse2 ht syscall nx mmxext fxsr_opt pdpe1gb rdtscp lm 3dnowext 3dnow constant_tsc up rep_good nonstop_tsc extd_apicid amd_dcm pni monitor cx16 popcnt lahf_lm cmp_legacy svm extapic cr8_legacy abm sse4a misalignsse 3dnowprefetch osvw ibs skinit wdt nodeid_msr npt lbrv svm_lock nrip_save
> bogomips	: 4000.18
> TLB size	: 1024 4K pages
> clflush size	: 64
> cache_alignment	: 64
> address sizes	: 48 bits physical, 48 bits virtual
> power management: ts ttp tm stc 100mhzsteps hwpstate
> 
> 
> versions:
> kernel 2.6.34.7
> ust 0.9
> lttctl 0.88
> lttv 0.12.36
> 
> # dmesg | egrep "tsc|LTT"
> [    0.361042] Switching to clocksource tsc
> [    1.722190] LTT : ltt-relay init
> [ 1868.196100] LTT: 14 events written in channel metadata (cpu 0, index 0)
> [ 1948.140099] LTT: 96 events written in channel metadata (cpu 0, index 0)
> [ 1948.140263] LTT: 12921 events written in channel kernel (cpu 0, index 0)
> [ 1982.495770] LTT: 96 events written in channel metadata (cpu 0, index 0)
> [ 1982.495779] LTT : unread channel metadata offset is 262144 and cons_off : 0 (cpu 0)
> [ 1982.495786] LTT : metadata : commit count : 262144, subbuf size 262144
> [ 1982.495850] LTT : unread channel swap_state offset is 65536 and cons_off : 0 (cpu 0)
> [ 1982.495857] LTT : swap_state : commit count : 65536, subbuf size 65536
> [ 1982.495884] LTT : unread channel module_state offset is 65536 and cons_off : 0 (cpu 0)
> [ 1982.495890] LTT : module_state : commit count : 65536, subbuf size 65536
> [ 1982.495915] LTT : unread channel softirq_state offset is 65536 and cons_off : 0 (cpu 0)
> [ 1982.495922] LTT : softirq_state : commit count : 65536, subbuf size 65536
> [ 1982.495947] LTT : unread channel syscall_state offset is 65536 and cons_off : 0 (cpu 0)
> [ 1982.495954] LTT : syscall_state : commit count : 65536, subbuf size 65536
> [ 1982.495979] LTT : unread channel irq_state offset is 65536 and cons_off : 0 (cpu 0)
> [ 1982.495985] LTT : irq_state : commit count : 65536, subbuf size 65536
> [ 1982.496055] LTT: 12657 events written in channel kernel (cpu 0, index 0)
> [ 1982.496062] LTT : unread channel kernel offset is 1048576 and cons_off : 0 (cpu 0)
> [ 1982.496070] LTT : kernel : commit count : 1048576, subbuf size 1048576
> 
> 
> The last ust timestamp is before the first kernel trace timestamp.
> 
> # rm -rf /tmp/trace? /root/.usttraces
> # lttctl -C -w /tmp/traceK traceK 
> Linux Trace Toolkit Trace Control 0.88-09242010
> 
> Controlling trace : traceK
> 
> lttctl: Creating trace
> lttctl: Forking lttd
> Linux Trace Toolkit Trace Daemon 0.88-09242010
> 
> Reading from debugfs directory : /sys/kernel/debug/ltt/traceK
> Writing to trace directory : /tmp/traceK
> 
> lttctl: Starting trace
> 
> # usttrace ./ust
> Waiting for ustd to shutdown...
> Trace was output in:  /root/.usttraces/svr2-20101210050221043250710
> 
> # lttctl -D traceK
> Linux Trace Toolkit Trace Control 0.88-09242010
> 
> Controlling trace : traceK
> 
> lttctl: Pausing trace
> lttctl: Destroying trace
> 
> # mv /root/.usttraces/svr2-20101210050221043250710/3689_5549038222480296963 /tmp/traceU
> 
> # lttv -m textDump -t /tmp/traceK | head -3
> Trace set contains 1 traces
> 
> metadata.core_marker_id: 2994.531659669 (/tmp/traceK/metadata_0), 0, 0, , , 0, 0x0, MODE_UNKNOWN { channel = "kernel", name = "page_fault_get_user_entry", event_id = 0, int = 4, long = 8, pointer = 8, size_t = 8, alignment = 0 }
> 
> # lttv -m textDump -t /tmp/traceU | head -3
> Trace set contains 1 traces
> 
> metadata.core_marker_id: 2840.195433153 (/tmp/traceU/metadata_0), 0, 0, , , 0, 0x0, MODE_UNKNOWN { channel = "ust", name = "potential_exec", event_id = 0, int = 4, long = 8, pointer = 8, size_t = 8, alignment = 0 }
> 
> # lttv -m textDump -t /tmp/traceU | tail -3
> ust.time_end: 2840.198082665 (/tmp/traceU/ust_0), 0, 0, , , 0, 0x0, MODE_UNKNOWN
> End trace set
> 

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