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

[Tony Jones]

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?


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