[lttng-dev] Limited event types displayed.

[Neil Bryan]

Hello Forum,

Now that I have got LTTng built, I have tried some preliminary tests. Unfortunately the results are not quite as I expect.
I have used LTTng previously, although I did not perform the kernel integration. Using Eclipse TFM I could see various processes in the Control Flow tab.
With low-level kernel events (interrupts, sched_wakeup etc) causing threads to run or remain blocked. On my system I only see event data in the Histogram view and in the Statistics tab.
Something has not been enabled in my build (tracepoints?) and I only have a limited amount of instrumentation. My Control Flow tab is blank and I don't see any driver threads or stuff
that I am interested. Any clues as to what is missing?

I imported this into eclipse as a Generic CTF Trace. Using LTTng kernel trace gave me a Validation Failed error. I have checked the plug-ins and features on eclipse (Version: Kepler Service Release 2
Build id: 20140224-0627) and all looks sensible.

A brief snippet running babeltrace on the collected trace reveals:

[01:00:04.612915372] (+0.009500290) irq_handler_entry: { cpu_id = 0 }, { irq = 690, name = "serial" }
[01:00:04.612922812] (+0.000007440) sched_wakeup: { cpu_id = 0 }, { comm = "kworker/0:1", tid = 305, prio = 120, success = 1, target_cpu = 0 }
[01:00:04.612927192] (+0.000004380) irq_handler_exit: { cpu_id = 0 }, { irq = 690, ret = 1 }
[01:00:04.612936292] (+0.000009100) sched_switch: { cpu_id = 0 }, { prev_comm = "swapper/0", prev_tid = 0, prev_prio = 20, prev_state = 0, next_comm = "kworker/0:1", next_tid = 305, next_prio = 20 }
[01:00:04.612946732] (+0.000010440) sched_stat_runtime: { cpu_id = 0 }, { comm = "kworker/0:1", tid = 305, runtime = 24080, vruntime = 16806205315 }
[01:00:04.612949162] (+0.000002430) sched_wakeup: { cpu_id = 0 }, { comm = "sh", tid = 737, prio = 120, success = 1, target_cpu = 0 }
[01:00:04.612955572] (+0.000006410) sched_stat_runtime: { cpu_id = 0 }, { comm = "kworker/0:1", tid = 305, runtime = 9450, vruntime = 16806214765 }
[01:00:04.612958762] (+0.000003190) sched_switch: { cpu_id = 0 }, { prev_comm = "kworker/0:1", prev_tid = 305, prev_prio = 20, prev_state = 1, next_comm = "sh", next_tid = 737, next_prio = 20 }
[01:00:04.612968132] (+0.000009370) exit_syscall: { cpu_id = 0 }, { ret = 3 }
[01:00:04.612977692] (+0.000009560) sys_unknown: { cpu_id = 0 }, { id = 175, args = [ [0] = 0, [1] = 672496, [2] = 672624, [3] = 8, [4] = 672624, [5] = 0 ] }
[01:00:04.612980852] (+0.000003160) exit_syscall: { cpu_id = 0 }, { ret = 175 }
[01:00:04.612992172] (+0.000011320) sys_unknown: { cpu_id = 0 }, { id = 4, args = [ [0] = 2, [1] = 692232, [2] = 1, [3] = 0, [4] = 1995966936, [5] = 1 ] }
[01:00:04.613000852] (+0.000008680) irq_handler_entry: { cpu_id = 0 }, { irq = 690, name = "serial" }
[01:00:04.613005092] (+0.000004240) sched_wakeup: { cpu_id = 0 }, { comm = "sh", tid = 737, prio = 120, success = 1, target_cpu = 0 }
[01:00:04.613009332] (+0.000004240) irq_handler_exit: { cpu_id = 0 }, { irq = 690, ret = 1 }
[01:00:04.613015122] (+0.000005790) exit_syscall: { cpu_id = 0 }, { ret = 4 }
[01:00:04.613018292] (+0.000003170) sys_unknown: { cpu_id = 0 }, { id = 175, args = [ [0] = 2, [1] = 672624, [2] = 0, [3] = 8, [4] = 0, [5] = 2 ] }
[01:00:04.613020812] (+0.000002520) exit_syscall: { cpu_id = 0 }, { ret = 175 }
[01:00:04.613025972] (+0.000005160) sys_unknown: { cpu_id = 0 }, { id = 3, args = [ [0] = 0, [1] = 2125890263, [2] = 1, [3] = 2183135232, [4] = 1995967256, [5] = 673032 ] }
[01:00:04.613033202] (+0.000007230) sched_stat_runtime: { cpu_id = 0 }, { comm = "sh", tid = 737, runtime = 77130, vruntime = 16806387825 }
[01:00:04.613040642] (+0.000007440) sched_switch: { cpu_id = 0 }, { prev_comm = "sh", prev_tid = 737, prev_prio = 20, prev_state = 1, next_comm = "swapper/0", next_tid = 0, next_prio = 20 }
[01:00:04.613393572] (+0.000352930) irq_handler_entry: { cpu_id = 1 }, { irq = 525, name = "twd" }
[01:00:04.613394242] (+0.000000670) irq_handler_entry: { cpu_id = 0 }, { irq = 525, name = "twd" }
[01:00:04.613396802] (+0.000002560) softirq_raise: { cpu_id = 1 }, { vec = 1 }
[01:00:04.613400192] (+0.000003390) softirq_raise: { cpu_id = 1 }, { vec = 7 }
[01:00:04.613401732] (+0.000001540) softirq_raise: { cpu_id = 0 }, { vec = 1 }



Thank you for any help you can offer.

Regards,

Neil.
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.lttng.org/pipermail/lttng-dev/attachments/20150219/8cc47629/attachment-0001.html>