[lttng-dev] Timestamps in babeltrace
Gerlando Falauto
gerlando.falauto at keymile.com
Tue Aug 28 09:00:15 EDT 2012
Hi,
picking up again from my own message...
I'm try this again after these few months, and I still get some similar
behavior.
Again, it's a 32-bit PowerPC with 4ms system tick (CONFIG_HZ=250). The
machine has neither NTP nor internal clock, therefore I set a given
timestamp before starting the test.
Traces were generated using the latest master branch of the three
repositories (lttng-modules, lttng-tools, userspace-rcu).
Running the following script on the target:
date -s "2012-08-28 09:00:00"
lttng create trace
lttng enable-channel -k mychannel
lttng enable-event sched_switch,sched_wakeup -k -c mychannel
lttng start
echo waiting 10 seconds
sleep 10
lttng stop
lttng destroy trace
date
(for which I get the following output):
Tue Aug 28 09:00:00 UTC 2012
Session trace created.
Traces will be written in /root/lttng-traces/trace-20120828-090000
Kernel channel mychannel enabled for session trace
kernel event sched_switch created in channel mychannel
kernel event sched_wakeup created in channel mychannel
Tracing started for session trace
waiting 10 seconds
Tracing stopped for session trace
Session trace destroyed
Tue Aug 28 09:00:10 UTC 2012
I get the following trace:
babeltrace --clock-date --clock-gmt
/path/to/root/lttng-traces/trace-20120828-090000/
[2012-08-28 09:00:00.348477307] (+?.?????????) mgcoge3ne sched_switch: {
cpu_id = 0 }, { prev_comm = "mng_clients", prev_tid = 452, prev_prio =
20, prev_state = 0, next_comm = "cons_recv_fds", next_tid = 461,
next_prio = 20 }
[2012-08-28 09:00:00.350913974] (+0.002436667) mgcoge3ne sched_switch: {
cpu_id = 0 }, { prev_comm = "cons_recv_fds", prev_tid = 461, prev_prio =
20, prev_state = 0, next_comm = "mng_clients", next_tid = 452, next_prio
= 20 }
[2012-08-28 09:00:00.352444701] (+0.001530727) mgcoge3ne sched_wakeup: {
cpu_id = 0 }, { comm = "lttng", tid = 492, prio = 120, success = 1,
target_cpu = 0 }
[2012-08-28 09:00:00.352584944] (+0.000140243) mgcoge3ne sched_wakeup: {
cpu_id = 0 }, { comm = "klogd", tid = 385, prio = 120, success = 1,
target_cpu = 0 }
[2012-08-28 09:00:00.352691186] (+0.000106242) mgcoge3ne sched_wakeup: {
cpu_id = 0 }, { comm = "kworker/0:1", tid = 99, prio = 120, success = 1,
target_cpu = 0 }
[2012-08-28 09:00:00.352853368] (+0.000162182) mgcoge3ne sched_switch: {
cpu_id = 0 }, { prev_comm = "mng_clients", prev_tid = 452, prev_prio =
20, prev_state = 0, next_comm = "klogd", next_tid = 385, next_prio = 20 }
[2012-08-28 09:00:00.353377247] (+0.000523879) mgcoge3ne sched_wakeup: {
cpu_id = 0 }, { comm = "syslogd", tid = 383, prio = 120, success = 1,
target_cpu = 0 }
[2012-08-28 09:00:00.354078519] (+0.000701272) mgcoge3ne sched_switch: {
cpu_id = 0 }, { prev_comm = "klogd", prev_tid = 385, prev_prio = 20,
prev_state = 0, next_comm = "kworker/0:1", next_tid = 99, next_prio = 20 }
[2012-08-28 09:00:00.354210095] (+0.000131576) mgcoge3ne sched_switch: {
cpu_id = 0 }, { prev_comm = "kworker/0:1", prev_tid = 99, prev_prio =
20, prev_state = 1, next_comm = "syslogd", next_tid = 383, next_prio = 20 }
[2012-08-28 09:00:00.355109428] (+0.000899333) mgcoge3ne sched_switch: {
cpu_id = 0 }, { prev_comm = "syslogd", prev_tid = 383, prev_prio = 20,
prev_state = 130, next_comm = "klogd", next_tid = 385, next_prio = 20 }
[2012-08-28 09:00:00.355501731] (+0.000392303) mgcoge3ne sched_wakeup: {
cpu_id = 0 }, { comm = "syslogd", tid = 383, prio = 120, success = 1,
target_cpu = 0 }
[2012-08-28 09:00:00.355620519] (+0.000118788) mgcoge3ne sched_switch: {
cpu_id = 0 }, { prev_comm = "klogd", prev_tid = 385, prev_prio = 20,
prev_state = 0, next_comm = "syslogd", next_tid = 383, next_prio = 20 }
[2012-08-28 09:00:00.356259610] (+0.000639091) mgcoge3ne sched_switch: {
cpu_id = 0 }, { prev_comm = "syslogd", prev_tid = 383, prev_prio = 20,
prev_state = 130, next_comm = "klogd", next_tid = 385, next_prio = 20 }
[2012-08-28 09:00:00.356807429] (+0.000547819) mgcoge3ne sched_wakeup: {
cpu_id = 0 }, { comm = "syslogd", tid = 383, prio = 120, success = 1,
target_cpu = 0 }
[2012-08-28 09:00:00.357136883] (+0.000329454) mgcoge3ne sched_switch: {
cpu_id = 0 }, { prev_comm = "klogd", prev_tid = 385, prev_prio = 20,
prev_state = 1, next_comm = "syslogd", next_tid = 383, next_prio = 20 }
[2012-08-28 09:00:00.357816762] (+0.000679879) mgcoge3ne sched_switch: {
cpu_id = 0 }, { prev_comm = "syslogd", prev_tid = 383, prev_prio = 20,
prev_state = 130, next_comm = "lttng", next_tid = 492, next_prio = 20 }
[2012-08-28 09:00:00.358233853] (+0.000417091) mgcoge3ne sched_wakeup: {
cpu_id = 0 }, { comm = "syslogd", tid = 383, prio = 120, success = 1,
target_cpu = 0 }
[2012-08-28 09:00:00.358371125] (+0.000137272) mgcoge3ne sched_switch: {
cpu_id = 0 }, { prev_comm = "lttng", prev_tid = 492, prev_prio = 20,
prev_state = 0, next_comm = "syslogd", next_tid = 383, next_prio = 20 }
[2012-08-28 09:00:00.360446034] (+0.002074909) mgcoge3ne sched_switch: {
cpu_id = 0 }, { prev_comm = "syslogd", prev_tid = 383, prev_prio = 20,
prev_state = 1, next_comm = "lttng", next_tid = 492, next_prio = 20 }
[2012-08-28 09:00:00.361265065] (+0.000819031) mgcoge3ne sched_wakeup: {
cpu_id = 0 }, { comm = "ksoftirqd/0", tid = 3, prio = 120, success = 1,
target_cpu = 0 }
[2012-08-28 09:00:00.361352459] (+0.000087394) mgcoge3ne sched_switch: {
cpu_id = 0 }, { prev_comm = "lttng", prev_tid = 492, prev_prio = 20,
prev_state = 0, next_comm = "ksoftirqd/0", next_tid = 3, next_prio = 20 }
[2012-08-28 09:00:00.361385974] (+0.000033515) mgcoge3ne sched_wakeup: {
cpu_id = 0 }, { comm = "lttng", tid = 492, prio = 120, success = 1,
target_cpu = 0 }
[2012-08-28 09:00:00.361461186] (+0.000075212) mgcoge3ne sched_switch: {
cpu_id = 0 }, { prev_comm = "ksoftirqd/0", prev_tid = 3, prev_prio = 20,
prev_state = 1, next_comm = "lttng", next_tid = 492, next_prio = 20 }
[2012-08-28 09:00:00.361540459] (+0.000079273) mgcoge3ne sched_wakeup: {
cpu_id = 0 }, { comm = "ksoftirqd/0", tid = 3, prio = 120, success = 1,
target_cpu = 0 }
[2012-08-28 09:00:00.361600641] (+0.000060182) mgcoge3ne sched_switch: {
cpu_id = 0 }, { prev_comm = "lttng", prev_tid = 492, prev_prio = 20,
prev_state = 0, next_comm = "ksoftirqd/0", next_tid = 3, next_prio = 20 }
[2012-08-28 09:00:00.361685247] (+0.000084606) mgcoge3ne sched_switch: {
cpu_id = 0 }, { prev_comm = "ksoftirqd/0", prev_tid = 3, prev_prio = 20,
prev_state = 1, next_comm = "lttng", next_tid = 492, next_prio = 20 }
[2012-08-28 09:00:00.362983004] (+0.001297757) mgcoge3ne sched_wakeup: {
cpu_id = 0 }, { comm = "sh", tid = 388, prio = 120, success = 1,
target_cpu = 0 }
[2012-08-28 09:00:00.363067247] (+0.000084243) mgcoge3ne sched_switch: {
cpu_id = 0 }, { prev_comm = "lttng", prev_tid = 492, prev_prio = 20,
prev_state = 64, next_comm = "sh", next_tid = 388, next_prio = 20 }
[2012-08-28 09:00:00.363663428] (+0.000596181) mgcoge3ne sched_wakeup: {
cpu_id = 0 }, { comm = "ksoftirqd/0", tid = 3, prio = 120, success = 1,
target_cpu = 0 }
[2012-08-28 09:00:00.363753004] (+0.000089576) mgcoge3ne sched_switch: {
cpu_id = 0 }, { prev_comm = "sh", prev_tid = 388, prev_prio = 20,
prev_state = 0, next_comm = "ksoftirqd/0", next_tid = 3, next_prio = 20 }
[2012-08-28 09:00:00.363788155] (+0.000035151) mgcoge3ne sched_wakeup: {
cpu_id = 0 }, { comm = "sh", tid = 388, prio = 120, success = 1,
target_cpu = 0 }
[2012-08-28 09:00:00.363856580] (+0.000068425) mgcoge3ne sched_switch: {
cpu_id = 0 }, { prev_comm = "ksoftirqd/0", prev_tid = 3, prev_prio = 20,
prev_state = 1, next_comm = "sh", next_tid = 388, next_prio = 20 }
[2012-08-28 09:00:00.363922519] (+0.000065939) mgcoge3ne sched_wakeup: {
cpu_id = 0 }, { comm = "ksoftirqd/0", tid = 3, prio = 120, success = 1,
target_cpu = 0 }
[2012-08-28 09:00:00.364054580] (+0.000132061) mgcoge3ne sched_switch: {
cpu_id = 0 }, { prev_comm = "sh", prev_tid = 388, prev_prio = 20,
prev_state = 0, next_comm = "ksoftirqd/0", next_tid = 3, next_prio = 20 }
[2012-08-28 09:00:00.364119004] (+0.000064424) mgcoge3ne sched_switch: {
cpu_id = 0 }, { prev_comm = "ksoftirqd/0", prev_tid = 3, prev_prio = 20,
prev_state = 1, next_comm = "sh", next_tid = 388, next_prio = 20 }
[2012-08-28 09:00:00.366897247] (+0.002778243) mgcoge3ne sched_switch: {
cpu_id = 0 }, { prev_comm = "sh", prev_tid = 388, prev_prio = 20,
prev_state = 0, next_comm = "cons_recv_fds", next_tid = 461, next_prio =
20 }
[2012-08-28 09:00:00.367404640] (+0.000507393) mgcoge3ne sched_switch: {
cpu_id = 0 }, { prev_comm = "cons_recv_fds", prev_tid = 461, prev_prio =
20, prev_state = 1, next_comm = "sh", next_tid = 388, next_prio = 20 }
[2012-08-28 09:00:00.367605549] (+0.000200909) mgcoge3ne sched_switch: {
cpu_id = 0 }, { prev_comm = "sh", prev_tid = 388, prev_prio = 20,
prev_state = 1, next_comm = "mng_clients", next_tid = 452, next_prio = 20 }
[2012-08-28 09:00:00.367966701] (+0.000361152) mgcoge3ne sched_switch: {
cpu_id = 0 }, { prev_comm = "mng_clients", prev_tid = 452, prev_prio =
20, prev_state = 1, next_comm = "sh", next_tid = 495, next_prio = 20 }
[2012-08-28 09:00:00.369751065] (+0.001784364) mgcoge3ne sched_switch: {
cpu_id = 0 }, { prev_comm = "sh", prev_tid = 495, prev_prio = 20,
prev_state = 130, next_comm = "cons_recv_fds", next_tid = 494, next_prio
= 20 }
[2012-08-28 09:00:00.370164277] (+0.000413212) mgcoge3ne sched_wakeup: {
cpu_id = 0 }, { comm = "sh", tid = 495, prio = 120, success = 1,
target_cpu = 0 }
[2012-08-28 09:00:00.371547186] (+0.001382909) mgcoge3ne sched_switch: {
cpu_id = 0 }, { prev_comm = "cons_recv_fds", prev_tid = 494, prev_prio =
20, prev_state = 130, next_comm = "sh", next_tid = 495, next_prio = 20 }
[2012-08-28 09:00:00.371978216] (+0.000431030) mgcoge3ne sched_wakeup: {
cpu_id = 0 }, { comm = "cons_recv_fds", tid = 494, prio = 120, success =
1, target_cpu = 0 }
[2012-08-28 09:00:00.372420277] (+0.000442061) mgcoge3ne sched_switch: {
cpu_id = 0 }, { prev_comm = "sh", prev_tid = 495, prev_prio = 20,
prev_state = 130, next_comm = "cons_recv_fds", next_tid = 494, next_prio
= 20 }
[2012-08-28 09:00:00.372877853] (+0.000457576) mgcoge3ne sched_wakeup: {
cpu_id = 0 }, { comm = "sh", tid = 495, prio = 120, success = 1,
target_cpu = 0 }
[2012-08-28 09:00:00.373435004] (+0.000557151) mgcoge3ne sched_switch: {
cpu_id = 0 }, { prev_comm = "cons_recv_fds", prev_tid = 494, prev_prio =
20, prev_state = 130, next_comm = "sh", next_tid = 495, next_prio = 20 }
[2012-08-28 09:00:00.373916641] (+0.000481637) mgcoge3ne sched_wakeup: {
cpu_id = 0 }, { comm = "cons_recv_fds", tid = 494, prio = 120, success =
1, target_cpu = 0 }
[2012-08-28 09:00:00.374868943] (+0.000952302) mgcoge3ne sched_switch: {
cpu_id = 0 }, { prev_comm = "sh", prev_tid = 495, prev_prio = 20,
prev_state = 130, next_comm = "cons_recv_fds", next_tid = 494, next_prio
= 20 }
[2012-08-28 09:00:00.375289610] (+0.000420667) mgcoge3ne sched_wakeup: {
cpu_id = 0 }, { comm = "sh", tid = 495, prio = 120, success = 1,
target_cpu = 0 }
[2012-08-28 09:00:00.375731186] (+0.000441576) mgcoge3ne sched_switch: {
cpu_id = 0 }, { prev_comm = "cons_recv_fds", prev_tid = 494, prev_prio =
20, prev_state = 130, next_comm = "sh", next_tid = 495, next_prio = 20 }
[2012-08-28 09:00:00.376117428] (+0.000386242) mgcoge3ne sched_wakeup: {
cpu_id = 0 }, { comm = "cons_recv_fds", tid = 494, prio = 120, success =
1, target_cpu = 0 }
[2012-08-28 09:00:00.378842034] (+0.002724606) mgcoge3ne sched_switch: {
cpu_id = 0 }, { prev_comm = "sleep", prev_tid = 495, prev_prio = 20,
prev_state = 0, next_comm = "cons_recv_fds", next_tid = 494, next_prio =
20 }
[2012-08-28 09:00:00.379333671] (+0.000491637) mgcoge3ne sched_switch: {
cpu_id = 0 }, { prev_comm = "cons_recv_fds", prev_tid = 494, prev_prio =
20, prev_state = 130, next_comm = "sleep", next_tid = 495, next_prio = 20 }
[2012-08-28 09:00:00.380850217] (+0.001516546) mgcoge3ne sched_switch: {
cpu_id = 0 }, { prev_comm = "sleep", prev_tid = 495, prev_prio = 20,
prev_state = 130, next_comm = "swapper", next_tid = 0, next_prio = 20 }
[2012-08-28 09:00:00.381269065] (+0.000418848) mgcoge3ne sched_wakeup: {
cpu_id = 0 }, { comm = "sleep", tid = 495, prio = 120, success = 1,
target_cpu = 0 }
[2012-08-28 09:00:00.381361004] (+0.000091939) mgcoge3ne sched_switch: {
cpu_id = 0 }, { prev_comm = "swapper", prev_tid = 0, prev_prio = 20,
prev_state = 0, next_comm = "sleep", next_tid = 495, next_prio = 20 }
[2012-08-28 09:00:00.386596822] (+0.005235818) mgcoge3ne sched_switch: {
cpu_id = 0 }, { prev_comm = "sleep", prev_tid = 495, prev_prio = 20,
prev_state = 1, next_comm = "swapper", next_tid = 0, next_prio = 20 }
[2012-08-28 09:00:00.394262762] (+0.007665940) mgcoge3ne sched_wakeup: {
cpu_id = 0 }, { comm = "cons_recv_fds", tid = 494, prio = 120, success =
1, target_cpu = 0 }
[2012-08-28 09:00:00.394357368] (+0.000094606) mgcoge3ne sched_switch: {
cpu_id = 0 }, { prev_comm = "swapper", prev_tid = 0, prev_prio = 20,
prev_state = 0, next_comm = "cons_recv_fds", next_tid = 494, next_prio =
20 }
[2012-08-28 09:00:00.394719974] (+0.000362606) mgcoge3ne sched_wakeup: {
cpu_id = 0 }, { comm = "cons_recv_fds", tid = 461, prio = 120, success =
1, target_cpu = 0 }
[2012-08-28 09:00:00.395709549] (+0.000989575) mgcoge3ne sched_switch: {
cpu_id = 0 }, { prev_comm = "cons_recv_fds", prev_tid = 494, prev_prio =
20, prev_state = 64, next_comm = "cons_recv_fds", next_tid = 461,
next_prio = 20 }
[2012-08-28 09:00:00.396408701] (+0.000699152) mgcoge3ne sched_wakeup: {
cpu_id = 0 }, { comm = "cons_poll_fds", tid = 462, prio = 120, success =
1, target_cpu = 0 }
[2012-08-28 09:00:00.398866640] (+0.002457939) mgcoge3ne sched_switch: {
cpu_id = 0 }, { prev_comm = "cons_recv_fds", prev_tid = 461, prev_prio =
20, prev_state = 0, next_comm = "cons_poll_fds", next_tid = 462,
next_prio = 20 }
[2012-08-28 09:00:00.398973428] (+0.000106788) mgcoge3ne sched_switch: {
cpu_id = 0 }, { prev_comm = "cons_poll_fds", prev_tid = 462, prev_prio =
20, prev_state = 2, next_comm = "cons_recv_fds", next_tid = 461,
next_prio = 20 }
[2012-08-28 09:00:00.399076034] (+0.000102606) mgcoge3ne sched_wakeup: {
cpu_id = 0 }, { comm = "cons_poll_fds", tid = 462, prio = 120, success =
1, target_cpu = 0 }
[2012-08-28 09:00:00.399131186] (+0.000055152) mgcoge3ne sched_switch: {
cpu_id = 0 }, { prev_comm = "cons_recv_fds", prev_tid = 461, prev_prio =
20, prev_state = 0, next_comm = "cons_poll_fds", next_tid = 462,
next_prio = 20 }
[2012-08-28 09:00:00.401086701] (+0.001955515) mgcoge3ne sched_switch: {
cpu_id = 0 }, { prev_comm = "cons_poll_fds", prev_tid = 462, prev_prio =
20, prev_state = 1, next_comm = "cons_recv_fds", next_tid = 461,
next_prio = 20 }
[2012-08-28 09:00:00.401670216] (+0.000583515) mgcoge3ne sched_switch: {
cpu_id = 0 }, { prev_comm = "cons_recv_fds", prev_tid = 461, prev_prio =
20, prev_state = 1, next_comm = "cons_recv_fds", next_tid = 496,
next_prio = 20 }
[2012-08-28 09:00:00.402858156] (+0.001187940) mgcoge3ne sched_switch: {
cpu_id = 0 }, { prev_comm = "cons_recv_fds", prev_tid = 496, prev_prio =
20, prev_state = 130, next_comm = "swapper", next_tid = 0, next_prio = 20 }
[2012-08-28 09:00:00.403272398] (+0.000414242) mgcoge3ne sched_wakeup: {
cpu_id = 0 }, { comm = "cons_recv_fds", tid = 496, prio = 120, success =
1, target_cpu = 0 }
[2012-08-28 09:00:00.403363852] (+0.000091454) mgcoge3ne sched_switch: {
cpu_id = 0 }, { prev_comm = "swapper", prev_tid = 0, prev_prio = 20,
prev_state = 0, next_comm = "cons_recv_fds", next_tid = 496, next_prio =
20 }
[2012-08-28 09:00:00.403830277] (+0.000466425) mgcoge3ne sched_switch: {
cpu_id = 0 }, { prev_comm = "cons_recv_fds", prev_tid = 496, prev_prio =
20, prev_state = 130, next_comm = "swapper", next_tid = 0, next_prio = 20 }
[2012-08-28 09:00:00.404193731] (+0.000363454) mgcoge3ne sched_wakeup: {
cpu_id = 0 }, { comm = "cons_recv_fds", tid = 496, prio = 120, success =
1, target_cpu = 0 }
[2012-08-28 09:00:00.404283852] (+0.000090121) mgcoge3ne sched_switch: {
cpu_id = 0 }, { prev_comm = "swapper", prev_tid = 0, prev_prio = 20,
prev_state = 0, next_comm = "cons_recv_fds", next_tid = 496, next_prio =
20 }
[2012-08-28 09:00:00.404909247] (+0.000625395) mgcoge3ne sched_switch: {
cpu_id = 0 }, { prev_comm = "cons_recv_fds", prev_tid = 496, prev_prio =
20, prev_state = 130, next_comm = "swapper", next_tid = 0, next_prio = 20 }
[2012-08-28 09:00:00.405407065] (+0.000497818) mgcoge3ne sched_wakeup: {
cpu_id = 0 }, { comm = "cons_recv_fds", tid = 496, prio = 120, success =
1, target_cpu = 0 }
[2012-08-28 09:00:00.405496823] (+0.000089758) mgcoge3ne sched_switch: {
cpu_id = 0 }, { prev_comm = "swapper", prev_tid = 0, prev_prio = 20,
prev_state = 0, next_comm = "cons_recv_fds", next_tid = 496, next_prio =
20 }
[2012-08-28 09:00:00.405854156] (+0.000357333) mgcoge3ne sched_wakeup: {
cpu_id = 0 }, { comm = "cons_recv_fds", tid = 461, prio = 120, success =
1, target_cpu = 0 }
[2012-08-28 09:00:00.405938822] (+0.000084666) mgcoge3ne sched_switch: {
cpu_id = 0 }, { prev_comm = "cons_recv_fds", prev_tid = 496, prev_prio =
20, prev_state = 0, next_comm = "cons_recv_fds", next_tid = 461,
next_prio = 20 }
[2012-08-28 09:00:00.406084095] (+0.000145273) mgcoge3ne sched_switch: {
cpu_id = 0 }, { prev_comm = "cons_recv_fds", prev_tid = 461, prev_prio =
20, prev_state = 1, next_comm = "cons_recv_fds", next_tid = 496,
next_prio = 20 }
[2012-08-28 09:00:00.407004519] (+0.000920424) mgcoge3ne sched_wakeup: {
cpu_id = 0 }, { comm = "cons_recv_fds", tid = 461, prio = 120, success =
1, target_cpu = 0 }
[2012-08-28 09:00:00.407075186] (+0.000070667) mgcoge3ne sched_switch: {
cpu_id = 0 }, { prev_comm = "cons_recv_fds", prev_tid = 496, prev_prio =
20, prev_state = 64, next_comm = "cons_recv_fds", next_tid = 461,
next_prio = 20 }
[2012-08-28 09:00:00.407706034] (+0.000630848) mgcoge3ne sched_wakeup: {
cpu_id = 0 }, { comm = "cons_poll_fds", tid = 462, prio = 120, success =
1, target_cpu = 0 }
[2012-08-28 09:00:00.407897368] (+0.000191334) mgcoge3ne sched_switch: {
cpu_id = 0 }, { prev_comm = "cons_recv_fds", prev_tid = 461, prev_prio =
20, prev_state = 1, next_comm = "cons_poll_fds", next_tid = 462,
next_prio = 20 }
[2012-08-28 09:00:00.408304580] (+0.000407212) mgcoge3ne sched_switch: {
cpu_id = 0 }, { prev_comm = "cons_poll_fds", prev_tid = 462, prev_prio =
20, prev_state = 1, next_comm = "swapper", next_tid = 0, next_prio = 20 }
[2012-08-28 09:00:04.547552602] (+4.139248022) mgcoge3ne sched_wakeup: {
cpu_id = 0 }, { comm = "kworker/0:1", tid = 99, prio = 120, success = 1,
target_cpu = 0 }
[2012-08-28 09:00:04.547632966] (+0.000080364) mgcoge3ne sched_switch: {
cpu_id = 0 }, { prev_comm = "swapper", prev_tid = 0, prev_prio = 20,
prev_state = 0, next_comm = "kworker/0:1", next_tid = 99, next_prio = 20 }
[2012-08-28 09:00:04.547736542] (+0.000103576) mgcoge3ne sched_switch: {
cpu_id = 0 }, { prev_comm = "kworker/0:1", prev_tid = 99, prev_prio =
20, prev_state = 1, next_comm = "swapper", next_tid = 0, next_prio = 20 }
[2012-08-28 09:00:04.691537693] (+0.143801151) mgcoge3ne sched_wakeup: {
cpu_id = 0 }, { comm = "flush-0:14", tid = 389, prio = 120, success = 1,
target_cpu = 0 }
[2012-08-28 09:00:04.691615027] (+0.000077334) mgcoge3ne sched_switch: {
cpu_id = 0 }, { prev_comm = "swapper", prev_tid = 0, prev_prio = 20,
prev_state = 0, next_comm = "flush-0:14", next_tid = 389, next_prio = 20 }
[2012-08-28 09:00:04.691705269] (+0.000090242) mgcoge3ne sched_switch: {
cpu_id = 0 }, { prev_comm = "flush-0:14", prev_tid = 389, prev_prio =
20, prev_state = 1, next_comm = "swapper", next_tid = 0, next_prio = 20 }
[2012-08-28 09:00:05.311535024] (+0.619829755) mgcoge3ne sched_wakeup: {
cpu_id = 0 }, { comm = "kworker/0:1", tid = 99, prio = 120, success = 1,
target_cpu = 0 }
[2012-08-28 09:00:05.311613084] (+0.000078060) mgcoge3ne sched_switch: {
cpu_id = 0 }, { prev_comm = "swapper", prev_tid = 0, prev_prio = 20,
prev_state = 0, next_comm = "kworker/0:1", next_tid = 99, next_prio = 20 }
[2012-08-28 09:00:05.311882903] (+0.000269819) mgcoge3ne sched_switch: {
cpu_id = 0 }, { prev_comm = "kworker/0:1", prev_tid = 99, prev_prio =
20, prev_state = 1, next_comm = "swapper", next_tid = 0, next_prio = 20 }
[2012-08-28 09:00:08.842504805] (+3.530621902) mgcoge3ne sched_wakeup: {
cpu_id = 0 }, { comm = "kworker/0:1", tid = 99, prio = 120, success = 1,
target_cpu = 0 }
[2012-08-28 09:00:08.842583350] (+0.000078545) mgcoge3ne sched_switch: {
cpu_id = 0 }, { prev_comm = "swapper", prev_tid = 0, prev_prio = 20,
prev_state = 0, next_comm = "kworker/0:1", next_tid = 99, next_prio = 20 }
[2012-08-28 09:00:08.842664562] (+0.000081212) mgcoge3ne sched_switch: {
cpu_id = 0 }, { prev_comm = "kworker/0:1", prev_tid = 99, prev_prio =
20, prev_state = 1, next_comm = "swapper", next_tid = 0, next_prio = 20 }
[2012-08-28 09:00:08.994502865] (+0.151838303) mgcoge3ne sched_wakeup: {
cpu_id = 0 }, { comm = "kworker/0:1", tid = 99, prio = 120, success = 1,
target_cpu = 0 }
[2012-08-28 09:00:08.994581229] (+0.000078364) mgcoge3ne sched_switch: {
cpu_id = 0 }, { prev_comm = "swapper", prev_tid = 0, prev_prio = 20,
prev_state = 0, next_comm = "kworker/0:1", next_tid = 99, next_prio = 20 }
[2012-08-28 09:00:08.994670441] (+0.000089212) mgcoge3ne sched_switch: {
cpu_id = 0 }, { prev_comm = "kworker/0:1", prev_tid = 99, prev_prio =
20, prev_state = 1, next_comm = "swapper", next_tid = 0, next_prio = 20 }
[2012-08-28 09:00:13.137477252] (+4.142806811) mgcoge3ne sched_wakeup: {
cpu_id = 0 }, { comm = "kworker/0:1", tid = 99, prio = 120, success = 1,
target_cpu = 0 }
[2012-08-28 09:00:13.137557191] (+0.000079939) mgcoge3ne sched_switch: {
cpu_id = 0 }, { prev_comm = "swapper", prev_tid = 0, prev_prio = 20,
prev_state = 0, next_comm = "kworker/0:1", next_tid = 99, next_prio = 20 }
[2012-08-28 09:00:13.137656101] (+0.000098910) mgcoge3ne sched_switch: {
cpu_id = 0 }, { prev_comm = "kworker/0:1", prev_tid = 99, prev_prio =
20, prev_state = 1, next_comm = "swapper", next_tid = 0, next_prio = 20 }
[2012-08-28 09:00:13.901469492] (+0.763813391) mgcoge3ne sched_wakeup: {
cpu_id = 0 }, { comm = "kworker/0:1", tid = 99, prio = 120, success = 1,
target_cpu = 0 }
[2012-08-28 09:00:13.901548037] (+0.000078545) mgcoge3ne sched_switch: {
cpu_id = 0 }, { prev_comm = "swapper", prev_tid = 0, prev_prio = 20,
prev_state = 0, next_comm = "kworker/0:1", next_tid = 99, next_prio = 20 }
[2012-08-28 09:00:13.902056037] (+0.000508000) mgcoge3ne sched_switch: {
cpu_id = 0 }, { prev_comm = "kworker/0:1", prev_tid = 99, prev_prio =
20, prev_state = 1, next_comm = "swapper", next_tid = 0, next_prio = 20 }
[2012-08-28 09:00:13.905507067] (+0.003451030) mgcoge3ne sched_wakeup: {
cpu_id = 0 }, { comm = "sync_supers", tid = 76, prio = 120, success = 1,
target_cpu = 0 }
[2012-08-28 09:00:13.905589916] (+0.000082849) mgcoge3ne sched_switch: {
cpu_id = 0 }, { prev_comm = "swapper", prev_tid = 0, prev_prio = 20,
prev_state = 0, next_comm = "sync_supers", next_tid = 76, next_prio = 20 }
[2012-08-28 09:00:13.905661613] (+0.000071697) mgcoge3ne sched_switch: {
cpu_id = 0 }, { prev_comm = "sync_supers", prev_tid = 76, prev_prio =
20, prev_state = 1, next_comm = "swapper", next_tid = 0, next_prio = 20 }
[2012-08-28 09:00:17.432437394] (+3.526775781) mgcoge3ne sched_wakeup: {
cpu_id = 0 }, { comm = "kworker/0:1", tid = 99, prio = 120, success = 1,
target_cpu = 0 }
[2012-08-28 09:00:17.432515636] (+0.000078242) mgcoge3ne sched_switch: {
cpu_id = 0 }, { prev_comm = "swapper", prev_tid = 0, prev_prio = 20,
prev_state = 0, next_comm = "kworker/0:1", next_tid = 99, next_prio = 20 }
[2012-08-28 09:00:17.432599636] (+0.000084000) mgcoge3ne sched_switch: {
cpu_id = 0 }, { prev_comm = "kworker/0:1", prev_tid = 99, prev_prio =
20, prev_state = 1, next_comm = "swapper", next_tid = 0, next_prio = 20 }
[2012-08-28 09:00:21.727404869] (+4.294805233) mgcoge3ne sched_wakeup: {
cpu_id = 0 }, { comm = "kworker/0:1", tid = 99, prio = 120, success = 1,
target_cpu = 0 }
[2012-08-28 09:00:21.727485232] (+0.000080363) mgcoge3ne sched_switch: {
cpu_id = 0 }, { prev_comm = "swapper", prev_tid = 0, prev_prio = 20,
prev_state = 0, next_comm = "kworker/0:1", next_tid = 99, next_prio = 20 }
[2012-08-28 09:00:21.727587050] (+0.000101818) mgcoge3ne sched_switch: {
cpu_id = 0 }, { prev_comm = "kworker/0:1", prev_tid = 99, prev_prio =
20, prev_state = 1, next_comm = "swapper", next_tid = 0, next_prio = 20 }
[2012-08-28 09:00:22.491405717] (+0.763818667) mgcoge3ne sched_wakeup: {
cpu_id = 0 }, { comm = "kworker/0:1", tid = 99, prio = 120, success = 1,
target_cpu = 0 }
[2012-08-28 09:00:22.491484384] (+0.000078667) mgcoge3ne sched_switch: {
cpu_id = 0 }, { prev_comm = "swapper", prev_tid = 0, prev_prio = 20,
prev_state = 0, next_comm = "kworker/0:1", next_tid = 99, next_prio = 20 }
[2012-08-28 09:00:22.491873414] (+0.000389030) mgcoge3ne sched_switch: {
cpu_id = 0 }, { prev_comm = "kworker/0:1", prev_tid = 99, prev_prio =
20, prev_state = 1, next_comm = "swapper", next_tid = 0, next_prio = 20 }
[2012-08-28 09:00:26.022372104] (+3.530498690) mgcoge3ne sched_wakeup: {
cpu_id = 0 }, { comm = "kworker/0:1", tid = 99, prio = 120, success = 1,
target_cpu = 0 }
[2012-08-28 09:00:26.022450467] (+0.000078363) mgcoge3ne sched_switch: {
cpu_id = 0 }, { prev_comm = "swapper", prev_tid = 0, prev_prio = 20,
prev_state = 0, next_comm = "kworker/0:1", next_tid = 99, next_prio = 20 }
[2012-08-28 09:00:26.022531134] (+0.000080667) mgcoge3ne sched_switch: {
cpu_id = 0 }, { prev_comm = "kworker/0:1", prev_tid = 99, prev_prio =
20, prev_state = 1, next_comm = "swapper", next_tid = 0, next_prio = 20 }
[2012-08-28 09:00:26.166376770] (+0.143845636) mgcoge3ne sched_wakeup: {
cpu_id = 0 }, { comm = "flush-0:14", tid = 389, prio = 120, success = 1,
target_cpu = 0 }
[2012-08-28 09:00:26.166453558] (+0.000076788) mgcoge3ne sched_switch: {
cpu_id = 0 }, { prev_comm = "swapper", prev_tid = 0, prev_prio = 20,
prev_state = 0, next_comm = "flush-0:14", next_tid = 389, next_prio = 20 }
[2012-08-28 09:00:26.166543558] (+0.000090000) mgcoge3ne sched_switch: {
cpu_id = 0 }, { prev_comm = "flush-0:14", prev_tid = 389, prev_prio =
20, prev_state = 1, next_comm = "swapper", next_tid = 0, next_prio = 20 }
[2012-08-28 09:00:30.317347278] (+4.150803720) mgcoge3ne sched_wakeup: {
cpu_id = 0 }, { comm = "kworker/0:1", tid = 99, prio = 120, success = 1,
target_cpu = 0 }
[2012-08-28 09:00:30.317427399] (+0.000080121) mgcoge3ne sched_switch: {
cpu_id = 0 }, { prev_comm = "swapper", prev_tid = 0, prev_prio = 20,
prev_state = 0, next_comm = "kworker/0:1", next_tid = 99, next_prio = 20 }
[2012-08-28 09:00:30.317528550] (+0.000101151) mgcoge3ne sched_switch: {
cpu_id = 0 }, { prev_comm = "kworker/0:1", prev_tid = 99, prev_prio =
20, prev_state = 1, next_comm = "swapper", next_tid = 0, next_prio = 20 }
[2012-08-28 09:00:31.081338729] (+0.763810179) mgcoge3ne sched_wakeup: {
cpu_id = 0 }, { comm = "kworker/0:1", tid = 99, prio = 120, success = 1,
target_cpu = 0 }
[2012-08-28 09:00:31.081417759] (+0.000079030) mgcoge3ne sched_switch: {
cpu_id = 0 }, { prev_comm = "swapper", prev_tid = 0, prev_prio = 20,
prev_state = 0, next_comm = "kworker/0:1", next_tid = 99, next_prio = 20 }
[2012-08-28 09:00:31.081881335] (+0.000463576) mgcoge3ne sched_switch: {
cpu_id = 0 }, { prev_comm = "kworker/0:1", prev_tid = 99, prev_prio =
20, prev_state = 1, next_comm = "swapper", next_tid = 0, next_prio = 20 }
[2012-08-28 09:00:34.612306086] (+3.530424751) mgcoge3ne sched_wakeup: {
cpu_id = 0 }, { comm = "kworker/0:1", tid = 99, prio = 120, success = 1,
target_cpu = 0 }
[2012-08-28 09:00:34.612384571] (+0.000078485) mgcoge3ne sched_switch: {
cpu_id = 0 }, { prev_comm = "swapper", prev_tid = 0, prev_prio = 20,
prev_state = 0, next_comm = "kworker/0:1", next_tid = 99, next_prio = 20 }
[2012-08-28 09:00:34.612465116] (+0.000080545) mgcoge3ne sched_switch: {
cpu_id = 0 }, { prev_comm = "kworker/0:1", prev_tid = 99, prev_prio =
20, prev_state = 1, next_comm = "swapper", next_tid = 0, next_prio = 20 }
[2012-08-28 09:00:38.907282170] (+4.294817054) mgcoge3ne sched_wakeup: {
cpu_id = 0 }, { comm = "kworker/0:1", tid = 99, prio = 120, success = 1,
target_cpu = 0 }
[2012-08-28 09:00:38.907362109] (+0.000079939) mgcoge3ne sched_switch: {
cpu_id = 0 }, { prev_comm = "swapper", prev_tid = 0, prev_prio = 20,
prev_state = 0, next_comm = "kworker/0:1", next_tid = 99, next_prio = 20 }
[2012-08-28 09:00:38.907461442] (+0.000099333) mgcoge3ne sched_switch: {
cpu_id = 0 }, { prev_comm = "kworker/0:1", prev_tid = 99, prev_prio =
20, prev_state = 1, next_comm = "swapper", next_tid = 0, next_prio = 20 }
[2012-08-28 09:00:39.622817924] (+0.715356482) mgcoge3ne sched_wakeup: {
cpu_id = 0 }, { comm = "syslogd", tid = 383, prio = 120, success = 1,
target_cpu = 0 }
[2012-08-28 09:00:39.622887803] (+0.000069879) mgcoge3ne sched_switch: {
cpu_id = 0 }, { prev_comm = "swapper", prev_tid = 0, prev_prio = 20,
prev_state = 0, next_comm = "syslogd", next_tid = 383, next_prio = 20 }
[2012-08-28 09:00:39.623148106] (+0.000260303) mgcoge3ne sched_switch: {
cpu_id = 0 }, { prev_comm = "syslogd", prev_tid = 383, prev_prio = 20,
prev_state = 1, next_comm = "swapper", next_tid = 0, next_prio = 20 }
[2012-08-28 09:00:39.671276530] (+0.048128424) mgcoge3ne sched_wakeup: {
cpu_id = 0 }, { comm = "kworker/0:1", tid = 99, prio = 120, success = 1,
target_cpu = 0 }
[2012-08-28 09:00:39.671355864] (+0.000079334) mgcoge3ne sched_switch: {
cpu_id = 0 }, { prev_comm = "swapper", prev_tid = 0, prev_prio = 20,
prev_state = 0, next_comm = "kworker/0:1", next_tid = 99, next_prio = 20 }
[2012-08-28 09:00:39.671687682] (+0.000331818) mgcoge3ne sched_switch: {
cpu_id = 0 }, { prev_comm = "kworker/0:1", prev_tid = 99, prev_prio =
20, prev_state = 1, next_comm = "swapper", next_tid = 0, next_prio = 20 }
[2012-08-28 09:00:39.675311742] (+0.003624060) mgcoge3ne sched_wakeup: {
cpu_id = 0 }, { comm = "sync_supers", tid = 76, prio = 120, success = 1,
target_cpu = 0 }
[2012-08-28 09:00:39.675394409] (+0.000082667) mgcoge3ne sched_switch: {
cpu_id = 0 }, { prev_comm = "swapper", prev_tid = 0, prev_prio = 20,
prev_state = 0, next_comm = "sync_supers", next_tid = 76, next_prio = 20 }
[2012-08-28 09:00:39.675466288] (+0.000071879) mgcoge3ne sched_switch: {
cpu_id = 0 }, { prev_comm = "sync_supers", prev_tid = 76, prev_prio =
20, prev_state = 1, next_comm = "swapper", next_tid = 0, next_prio = 20 }
[2012-08-28 09:00:43.202240735] (+3.526774447) mgcoge3ne sched_wakeup: {
cpu_id = 0 }, { comm = "kworker/0:1", tid = 99, prio = 120, success = 1,
target_cpu = 0 }
[2012-08-28 09:00:43.202318857] (+0.000078122) mgcoge3ne sched_switch: {
cpu_id = 0 }, { prev_comm = "swapper", prev_tid = 0, prev_prio = 20,
prev_state = 0, next_comm = "kworker/0:1", next_tid = 99, next_prio = 20 }
[2012-08-28 09:00:43.202402250] (+0.000083393) mgcoge3ne sched_switch: {
cpu_id = 0 }, { prev_comm = "kworker/0:1", prev_tid = 99, prev_prio =
20, prev_state = 1, next_comm = "swapper", next_tid = 0, next_prio = 20 }
[2012-08-28 09:00:43.346233038] (+0.143830788) mgcoge3ne sched_wakeup: {
cpu_id = 0 }, { comm = "sleep", tid = 495, prio = 120, success = 1,
target_cpu = 0 }
[2012-08-28 09:00:43.346330614] (+0.000097576) mgcoge3ne sched_switch: {
cpu_id = 0 }, { prev_comm = "swapper", prev_tid = 0, prev_prio = 20,
prev_state = 0, next_comm = "sleep", next_tid = 495, next_prio = 20 }
[2012-08-28 09:00:43.347314432] (+0.000983818) mgcoge3ne sched_wakeup: {
cpu_id = 0 }, { comm = "sh", tid = 388, prio = 120, success = 1,
target_cpu = 0 }
[2012-08-28 09:00:43.347383644] (+0.000069212) mgcoge3ne sched_switch: {
cpu_id = 0 }, { prev_comm = "sleep", prev_tid = 495, prev_prio = 20,
prev_state = 64, next_comm = "sh", next_tid = 388, next_prio = 20 }
[2012-08-28 09:00:43.349999825] (+0.002616181) mgcoge3ne sched_switch: {
cpu_id = 0 }, { prev_comm = "sh", prev_tid = 388, prev_prio = 20,
prev_state = 1, next_comm = "sh", next_tid = 497, next_prio = 20 }
[2012-08-28 09:00:43.351726735] (+0.001726910) mgcoge3ne sched_switch: {
cpu_id = 0 }, { prev_comm = "sh", prev_tid = 497, prev_prio = 20,
prev_state = 130, next_comm = "swapper", next_tid = 0, next_prio = 20 }
[2012-08-28 09:00:43.352191159] (+0.000464424) mgcoge3ne sched_wakeup: {
cpu_id = 0 }, { comm = "sh", tid = 497, prio = 120, success = 1,
target_cpu = 0 }
[2012-08-28 09:00:43.352283038] (+0.000091879) mgcoge3ne sched_switch: {
cpu_id = 0 }, { prev_comm = "swapper", prev_tid = 0, prev_prio = 20,
prev_state = 0, next_comm = "sh", next_tid = 497, next_prio = 20 }
[2012-08-28 09:00:43.353304492] (+0.001021454) mgcoge3ne sched_switch: {
cpu_id = 0 }, { prev_comm = "sh", prev_tid = 497, prev_prio = 20,
prev_state = 130, next_comm = "swapper", next_tid = 0, next_prio = 20 }
[2012-08-28 09:00:43.353711038] (+0.000406546) mgcoge3ne sched_wakeup: {
cpu_id = 0 }, { comm = "sh", tid = 497, prio = 120, success = 1,
target_cpu = 0 }
[2012-08-28 09:00:43.353802856] (+0.000091818) mgcoge3ne sched_switch: {
cpu_id = 0 }, { prev_comm = "swapper", prev_tid = 0, prev_prio = 20,
prev_state = 0, next_comm = "sh", next_tid = 497, next_prio = 20 }
[2012-08-28 09:00:43.357738795] (+0.003935939) mgcoge3ne sched_switch: {
cpu_id = 0 }, { prev_comm = "lttng", prev_tid = 497, prev_prio = 20,
prev_state = 130, next_comm = "swapper", next_tid = 0, next_prio = 20 }
[2012-08-28 09:00:43.358151644] (+0.000412849) mgcoge3ne sched_wakeup: {
cpu_id = 0 }, { comm = "lttng", tid = 497, prio = 120, success = 1,
target_cpu = 0 }
[2012-08-28 09:00:43.358400311] (+0.000248667) mgcoge3ne sched_switch: {
cpu_id = 0 }, { prev_comm = "swapper", prev_tid = 0, prev_prio = 20,
prev_state = 0, next_comm = "lttng", next_tid = 497, next_prio = 20 }
[2012-08-28 09:00:43.358873644] (+0.000473333) mgcoge3ne sched_switch: {
cpu_id = 0 }, { prev_comm = "lttng", prev_tid = 497, prev_prio = 20,
prev_state = 130, next_comm = "swapper", next_tid = 0, next_prio = 20 }
[2012-08-28 09:00:43.359283644] (+0.000410000) mgcoge3ne sched_wakeup: {
cpu_id = 0 }, { comm = "lttng", tid = 497, prio = 120, success = 1,
target_cpu = 0 }
[2012-08-28 09:00:43.359375523] (+0.000091879) mgcoge3ne sched_switch: {
cpu_id = 0 }, { prev_comm = "swapper", prev_tid = 0, prev_prio = 20,
prev_state = 0, next_comm = "lttng", next_tid = 497, next_prio = 20 }
[2012-08-28 09:00:43.360845098] (+0.001469575) mgcoge3ne sched_switch: {
cpu_id = 0 }, { prev_comm = "lttng", prev_tid = 497, prev_prio = 20,
prev_state = 130, next_comm = "swapper", next_tid = 0, next_prio = 20 }
[2012-08-28 09:00:43.361246492] (+0.000401394) mgcoge3ne sched_wakeup: {
cpu_id = 0 }, { comm = "lttng", tid = 497, prio = 120, success = 1,
target_cpu = 0 }
[2012-08-28 09:00:43.361338977] (+0.000092485) mgcoge3ne sched_switch: {
cpu_id = 0 }, { prev_comm = "swapper", prev_tid = 0, prev_prio = 20,
prev_state = 0, next_comm = "lttng", next_tid = 497, next_prio = 20 }
[2012-08-28 09:00:43.361800674] (+0.000461697) mgcoge3ne sched_switch: {
cpu_id = 0 }, { prev_comm = "lttng", prev_tid = 497, prev_prio = 20,
prev_state = 130, next_comm = "swapper", next_tid = 0, next_prio = 20 }
[2012-08-28 09:00:43.362320250] (+0.000519576) mgcoge3ne sched_wakeup: {
cpu_id = 0 }, { comm = "lttng", tid = 497, prio = 120, success = 1,
target_cpu = 0 }
[2012-08-28 09:00:43.362479463] (+0.000159213) mgcoge3ne sched_switch: {
cpu_id = 0 }, { prev_comm = "swapper", prev_tid = 0, prev_prio = 20,
prev_state = 0, next_comm = "lttng", next_tid = 497, next_prio = 20 }
[2012-08-28 09:00:43.363838068] (+0.001358605) mgcoge3ne sched_switch: {
cpu_id = 0 }, { prev_comm = "lttng", prev_tid = 497, prev_prio = 20,
prev_state = 130, next_comm = "swapper", next_tid = 0, next_prio = 20 }
[2012-08-28 09:00:43.364240553] (+0.000402485) mgcoge3ne sched_wakeup: {
cpu_id = 0 }, { comm = "lttng", tid = 497, prio = 120, success = 1,
target_cpu = 0 }
[2012-08-28 09:00:43.364332553] (+0.000092000) mgcoge3ne sched_switch: {
cpu_id = 0 }, { prev_comm = "swapper", prev_tid = 0, prev_prio = 20,
prev_state = 0, next_comm = "lttng", next_tid = 497, next_prio = 20 }
[2012-08-28 09:00:43.364792189] (+0.000459636) mgcoge3ne sched_switch: {
cpu_id = 0 }, { prev_comm = "lttng", prev_tid = 497, prev_prio = 20,
prev_state = 130, next_comm = "swapper", next_tid = 0, next_prio = 20 }
[2012-08-28 09:00:43.365205038] (+0.000412849) mgcoge3ne sched_wakeup: {
cpu_id = 0 }, { comm = "lttng", tid = 497, prio = 120, success = 1,
target_cpu = 0 }
[2012-08-28 09:00:43.365296916] (+0.000091878) mgcoge3ne sched_switch: {
cpu_id = 0 }, { prev_comm = "swapper", prev_tid = 0, prev_prio = 20,
prev_state = 0, next_comm = "lttng", next_tid = 497, next_prio = 20 }
[2012-08-28 09:00:43.366988129] (+0.001691213) mgcoge3ne sched_switch: {
cpu_id = 0 }, { prev_comm = "lttng", prev_tid = 497, prev_prio = 20,
prev_state = 130, next_comm = "swapper", next_tid = 0, next_prio = 20 }
[2012-08-28 09:00:43.367399705] (+0.000411576) mgcoge3ne sched_wakeup: {
cpu_id = 0 }, { comm = "lttng", tid = 497, prio = 120, success = 1,
target_cpu = 0 }
[2012-08-28 09:00:43.367492371] (+0.000092666) mgcoge3ne sched_switch: {
cpu_id = 0 }, { prev_comm = "swapper", prev_tid = 0, prev_prio = 20,
prev_state = 0, next_comm = "lttng", next_tid = 497, next_prio = 20 }
[2012-08-28 09:00:43.368825704] (+0.001333333) mgcoge3ne sched_switch: {
cpu_id = 0 }, { prev_comm = "lttng", prev_tid = 497, prev_prio = 20,
prev_state = 130, next_comm = "swapper", next_tid = 0, next_prio = 20 }
[2012-08-28 09:00:43.369229038] (+0.000403334) mgcoge3ne sched_wakeup: {
cpu_id = 0 }, { comm = "lttng", tid = 497, prio = 120, success = 1,
target_cpu = 0 }
[2012-08-28 09:00:43.369321280] (+0.000092242) mgcoge3ne sched_switch: {
cpu_id = 0 }, { prev_comm = "swapper", prev_tid = 0, prev_prio = 20,
prev_state = 0, next_comm = "lttng", next_tid = 497, next_prio = 20 }
[2012-08-28 09:00:43.370950675] (+0.001629395) mgcoge3ne sched_switch: {
cpu_id = 0 }, { prev_comm = "lttng", prev_tid = 497, prev_prio = 20,
prev_state = 130, next_comm = "swapper", next_tid = 0, next_prio = 20 }
[2012-08-28 09:00:43.371353220] (+0.000402545) mgcoge3ne sched_wakeup: {
cpu_id = 0 }, { comm = "lttng", tid = 497, prio = 120, success = 1,
target_cpu = 0 }
[2012-08-28 09:00:43.371445462] (+0.000092242) mgcoge3ne sched_switch: {
cpu_id = 0 }, { prev_comm = "swapper", prev_tid = 0, prev_prio = 20,
prev_state = 0, next_comm = "lttng", next_tid = 497, next_prio = 20 }
[2012-08-28 09:00:43.380016917] (+0.008571455) mgcoge3ne sched_switch: {
cpu_id = 0 }, { prev_comm = "lttng", prev_tid = 497, prev_prio = 20,
prev_state = 130, next_comm = "swapper", next_tid = 0, next_prio = 20 }
[2012-08-28 09:00:43.380428129] (+0.000411212) mgcoge3ne sched_wakeup: {
cpu_id = 0 }, { comm = "lttng", tid = 497, prio = 120, success = 1,
target_cpu = 0 }
[2012-08-28 09:00:43.380521159] (+0.000093030) mgcoge3ne sched_switch: {
cpu_id = 0 }, { prev_comm = "swapper", prev_tid = 0, prev_prio = 20,
prev_state = 0, next_comm = "lttng", next_tid = 497, next_prio = 20 }
[2012-08-28 09:00:43.381335462] (+0.000814303) mgcoge3ne sched_wakeup: {
cpu_id = 0 }, { comm = "mng_clients", tid = 452, prio = 120, success =
1, target_cpu = 0 }
[2012-08-28 09:00:43.381420795] (+0.000085333) mgcoge3ne sched_switch: {
cpu_id = 0 }, { prev_comm = "lttng", prev_tid = 497, prev_prio = 20,
prev_state = 0, next_comm = "mng_clients", next_tid = 452, next_prio = 20 }
[2012-08-28 09:00:43.381826250] (+0.000405455) mgcoge3ne sched_switch: {
cpu_id = 0 }, { prev_comm = "mng_clients", prev_tid = 452, prev_prio =
20, prev_state = 1, next_comm = "lttng", next_tid = 497, next_prio = 20 }
[2012-08-28 09:00:43.382007038] (+0.000180788) mgcoge3ne sched_wakeup: {
cpu_id = 0 }, { comm = "mng_clients", tid = 452, prio = 120, success =
1, target_cpu = 0 }
[2012-08-28 09:00:43.382081522] (+0.000074484) mgcoge3ne sched_switch: {
cpu_id = 0 }, { prev_comm = "lttng", prev_tid = 497, prev_prio = 20,
prev_state = 0, next_comm = "mng_clients", next_tid = 452, next_prio = 20 }
[2012-08-28 09:00:43.382528190] (+0.000446668) mgcoge3ne sched_switch: {
cpu_id = 0 }, { prev_comm = "mng_clients", prev_tid = 452, prev_prio =
20, prev_state = 1, next_comm = "lttng", next_tid = 497, next_prio = 20 }
[2012-08-28 09:00:43.383627341] (+0.001099151) mgcoge3ne sched_switch: {
cpu_id = 0 }, { prev_comm = "lttng", prev_tid = 497, prev_prio = 20,
prev_state = 130, next_comm = "swapper", next_tid = 0, next_prio = 20 }
[2012-08-28 09:00:43.384035280] (+0.000407939) mgcoge3ne sched_wakeup: {
cpu_id = 0 }, { comm = "lttng", tid = 497, prio = 120, success = 1,
target_cpu = 0 }
[2012-08-28 09:00:43.384128189] (+0.000092909) mgcoge3ne sched_switch: {
cpu_id = 0 }, { prev_comm = "swapper", prev_tid = 0, prev_prio = 20,
prev_state = 0, next_comm = "lttng", next_tid = 497, next_prio = 20 }
[2012-08-28 09:00:43.385790613] (+0.001662424) mgcoge3ne sched_wakeup: {
cpu_id = 0 }, { comm = "mng_clients", tid = 452, prio = 120, success =
1, target_cpu = 0 }
[2012-08-28 09:00:43.385877704] (+0.000087091) mgcoge3ne sched_switch: {
cpu_id = 0 }, { prev_comm = "lttng", prev_tid = 497, prev_prio = 20,
prev_state = 0, next_comm = "mng_clients", next_tid = 452, next_prio = 20 }
[2012-08-28 09:00:43.386442190] (+0.000564486) mgcoge3ne sched_switch: {
cpu_id = 0 }, { prev_comm = "mng_clients", prev_tid = 452, prev_prio =
20, prev_state = 1, next_comm = "lttng", next_tid = 497, next_prio = 20 }
[2012-08-28 09:00:43.386978008] (+0.000535818) mgcoge3ne sched_wakeup: {
cpu_id = 0 }, { comm = "mng_clients", tid = 452, prio = 120, success =
1, target_cpu = 0 }
[2012-08-28 09:00:43.387074129] (+0.000096121) mgcoge3ne sched_switch: {
cpu_id = 0 }, { prev_comm = "lttng", prev_tid = 497, prev_prio = 20,
prev_state = 0, next_comm = "mng_clients", next_tid = 452, next_prio = 20 }
So again, I get these huge 3.3 (or so) seconds gaps, and a final
timestamp which is 43 seconds instead of the 10 seconds which actually
went by.
BTW, I also tried with TMF under Eclipse, and here I get even weirder
results. Here's a table of correspondence (as there must be some occult
side to it!) for the timestamps as reported by babeltrace vs. Eclipse:
[2012-08-28 09:00:00.348477307] -> 2033-05-07 16:49:22.035276997
...
[2012-08-28 09:00:00.408304580] -> 2033-05-07 16:49:22.112912324
....
[2012-08-28 09:00:04.691537693] -> 2039-11-23 09:06:50.748861638
Under Eclipse, the latest event of this 10-second trace lies sometime
within year 2124.
No clue, anyone?
Thank you,
Gerlando
On 12/16/2011 11:15 AM, Gerlando Falauto wrote:
> Hi,
>
> I am trying to use LLTng 2.0 (since I have no alternative for a 3.0
> kernel!) and I of course use babeltrace to read them.
> Problem is, I can't make any sense out of the timestamps, as I get
> something like (two CPU-hog bash processes):
>
> [1658841591493] sched_switch: { 0 }, { prev_comm = "bash", prev_tid =
> 647, prev_prio = 20, prev_state = 0, next_comm = "bash", next_tid = 646,
> next_prio = 20 }
> [1658845590645] sched_switch: { 0 }, { prev_comm = "bash", prev_tid =
> 646, prev_prio = 20, prev_state = 0, next_comm = "bash", next_tid = 647,
> next_prio = 20 }
> [1658849590039] sched_switch: { 0 }, { prev_comm = "bash", prev_tid =
> 647, prev_prio = 20, prev_state = 0, next_comm = "bash", next_tid = 646,
> next_prio = 20 }
> [1658853591069] sched_switch: { 0 }, { prev_comm = "bash", prev_tid =
> 646, prev_prio = 20, prev_state = 0, next_comm = "bash", next_tid = 647,
> next_prio = 20 }
> [1662152559395] sched_switch: { 0 }, { prev_comm = "bash", prev_tid =
> 647, prev_prio = 20, prev_state = 0, next_comm = "bash", next_tid = 646,
> next_prio = 20 }
> [1662156587941] sched_switch: { 0 }, { prev_comm = "bash", prev_tid =
> 646, prev_prio = 20, prev_state = 0, next_comm = "bash", next_tid = 647,
> next_prio = 20 }
> [1662160557698] sched_switch: { 0 }, { prev_comm = "bash", prev_tid =
> 647, prev_prio = 20, prev_state = 0, next_comm = "bash", next_tid = 646,
> next_prio = 20 }
> [1662164557517] sched_switch: { 0 }, { prev_comm = "bash", prev_tid =
> 646, prev_prio = 20, prev_state = 0, next_comm = "bash", next_tid = 647,
> next_prio = 20 }
> [....................................cut...........................]
> [1663140553029] sched_switch: { 0 }, { prev_comm = "bash", prev_tid =
> 646, prev_prio = 20, prev_state = 0, next_comm = "bash", next_tid = 647,
> next_prio = 20 }
> [1663144555029] sched_switch: { 0 }, { prev_comm = "bash", prev_tid =
> 647, prev_prio = 20, prev_state = 0, next_comm = "bash", next_tid = 646,
> next_prio = 20 }
> [1663148552423] sched_switch: { 0 }, { prev_comm = "bash", prev_tid =
> 646, prev_prio = 20, prev_state = 0, next_comm = "bash", next_tid = 647,
> next_prio = 20 }
> [1666447519719] sched_switch: { 0 }, { prev_comm = "bash", prev_tid =
> 647, prev_prio = 20, prev_state = 0, next_comm = "bash", next_tid = 646,
> next_prio = 20 }
> [1666451561355] sched_switch: { 0 }, { prev_comm = "bash", prev_tid =
> 646, prev_prio = 20, prev_state = 0, next_comm = "kworker/0:1", next_tid
> = 94, next_prio = 20 }
> [1666451863719] sched_switch: { 0 }, { prev_comm = "kworker/0:1",
> prev_tid = 94, prev_prio = 20, prev_state = 1, next_comm = "bash",
> next_tid = 647, next_prio = 20 }
>
> Which made me think timestamps were expressed in nanoseconds, as I am
> running this on 4ms-tick PowerPC (CONFIG_HZ=250), and the difference
> between timestamps is approximately 4,000,000.
> However, I get these huge 3.3 second gaps between for instance between
> 1658853591069 and 1662152559395.
> Curiously enough, these leap 3.3 seconds occur exactly (well, within 4ms
> precision...) every second. Kind of like the "seconds" part of the
> timestamp is calculated on a wrong-base arithmetics or so....
> This also makes sense as the seconds' portion of the timestamp is
> essentially 4.3 times bigger than the uptime (and any time stretch is
> 4.3 times bigger than reality, for that matter).
>
> Any suggestions?
>
> Thanks!
> Gerlando
>
> P.S. This also happens without my hack for flight recording mode...
More information about the lttng-dev
mailing list