a success story

Hi, this is perhaps off-topic, but I was really pleased to find an
intermittent timing problem using lttng, and maybe an example of how
it can be used would be helpful to people considering adopting it.

The symptom was just that "something is taking too long". To describe
the operation of the system, there are three processes, isl_engine,
device_controll, and icsio. isl_engine talks to device_controll,
device_controll talks to icsio, icsio talks to devices outside of the
computer.

This is an lttv textDump trace of a normal event, slightly
postprocessed - the first and second fields are swapped, the third
field is ommitted, and only the fs.select and fs_data events are
shown:

42950500.120054930 fs_data.write: 1036, 1036, isl_engine, UNBRANDED,
1, 0x0, SYSCALL { fd = 5, count = 36, data = {
a%B\49\0\14\0\18\0\0\0[\99\c\4\0\0\0\0$\0\0\0\7\0\0\0\a\0\0\0 } }
NOTE: isl_engine says "do something" to device_controll
42950500.120069579 fs.select: 1034, 1034, icsio, UNBRANDED, 1, 0x0,
SYSCALL { fd = 5, timeout = 0 }
42950500.120070800 fs.select: 1034, 1034, icsio, UNBRANDED, 1, 0x0,
SYSCALL { fd = 6, timeout = 0 }
42950500.120072020 fs.select: 1034, 1034, icsio, UNBRANDED, 1, 0x0,
SYSCALL { fd = 7, timeout = 0 }
42950500.120073241 fs.select: 1034, 1034, icsio, UNBRANDED, 1, 0x0,
SYSCALL { fd = 8, timeout = 0 }
42950500.120233153 fs.select: 1034, 1034, icsio, UNBRANDED, 1, 0x0,
SYSCALL { fd = 5, timeout = 1 }
42950500.120234374 fs.select: 1034, 1034, icsio, UNBRANDED, 1, 0x0,
SYSCALL { fd = 6, timeout = 1 }
42950500.120235595 fs.select: 1034, 1034, icsio, UNBRANDED, 1, 0x0,
SYSCALL { fd = 7, timeout = 1 }
42950500.120236815 fs.select: 1034, 1034, icsio, UNBRANDED, 1, 0x0,
SYSCALL { fd = 8, timeout = 1 }
42950500.120239257 fs.select: 1035, 1035, device_controll, UNBRANDED,
1, 0x0, SYSCALL { fd = 6, timeout = 55 }
42950500.120240477 fs.select: 1035, 1035, device_controll, UNBRANDED,
1, 0x0, SYSCALL { fd = 10, timeout = 55 }
42950500.120241698 fs.select: 1035, 1035, device_controll, UNBRANDED,
1, 0x0, SYSCALL { fd = 11, timeout = 55 }
42950500.120247802 fs_data.read: 1035, 1035, device_controll,
UNBRANDED, 1, 0x0, SYSCALL { fd = 11, count = 256, data = {
a%B\49\0\14\0\18\0\0\0[\99\c\4\0\0\0\0$\0\0\0\7\0\0\0\a\0\0\0 } }
NOTE: device_controll hears "do something" from isl_engine
42950500.120258788 fs_data.write: 1035, 1035, device_controll,
UNBRANDED, 1, 0x0, SYSCALL { fd = 6, count = 40, data = {
a%B\4\4\0\a\0\1c\0\0\0\cd\f\b\4\2\0\0\0\10\0\0\0\3\0\0\0\1\0\0\0 } }
NOTE: device_control says "do something" to icsio
42950500.120278319 fs.select: 1035, 1035, device_controll, UNBRANDED,
1, 0x0, SYSCALL { fd = 6, timeout = 100 }
42950500.120279540 fs.select: 1035, 1035, device_controll, UNBRANDED,
1, 0x0, SYSCALL { fd = 10, timeout = 100 }
42950500.120280761 fs.select: 1035, 1035, device_controll, UNBRANDED,
1, 0x0, SYSCALL { fd = 11, timeout = 100 }
42950500.120285643 fs.select: 1034, 1034, icsio, UNBRANDED, 1, 0x0,
SYSCALL { fd = 5, timeout = 1 }
42950500.120286864 fs.select: 1034, 1034, icsio, UNBRANDED, 1, 0x0,
SYSCALL { fd = 6, timeout = 1 }
42950500.120288085 fs.select: 1034, 1034, icsio, UNBRANDED, 1, 0x0,
SYSCALL { fd = 7, timeout = 1 }
42950500.120289305 fs.select: 1034, 1034, icsio, UNBRANDED, 1, 0x0,
SYSCALL { fd = 8, timeout = 1 }
42950500.120295409 fs_data.read: 1034, 1034, icsio, UNBRANDED, 1, 0x0,
SYSCALL { fd = 8, count = 256, data = {
a%B\4\4\0\a\0\1c\0\0\0\cd\f\b\4\2\0\0\0\10\0\0\0\3\0\0\0\1\0\0\0 } }
NOTE: icsio hears "do something" from device_controll
42950500.120305175 fs_data.write: 1034, 1034, icsio, UNBRANDED, 1,
0x0, SYSCALL { fd = 5, count = 16, data = { \8\0\0\0\2\6\0\0#\2
\0\1\0\0\0 } } NOTE: icsio does something
42950500.120328368 fs_data.read: 1034, 1034, icsio, UNBRANDED, 1, 0x0,
SYSCALL { fd = 5, count = 16, data = { \8\0\0\0\82\5\0\0`\2 \0\0\0\0\0
} }
42950500.120335692 fs_data.write: 1034, 1034, icsio, UNBRANDED, 1,
0x0, SYSCALL { fd = 5, count = 16, data = { \8\0\0\0\2\6\0\0#\3
\0\7\0\0\0 } }
42950500.120374755 fs_data.read: 1034, 1034, icsio, UNBRANDED, 1, 0x0,
SYSCALL { fd = 5, count = 16, data = { \8\0\0\0\82\5\0\0`\3 \0\0\0\0\0
} }
42950500.120382079 fs_data.write: 1034, 1034, icsio, UNBRANDED, 1,
0x0, SYSCALL { fd = 5, count = 16, data = { \8\0\0\0\2\6\0\0#\4
\0\a\0\0\0 } }
42950500.120421141 fs_data.read: 1034, 1034, icsio, UNBRANDED, 1, 0x0,
SYSCALL { fd = 5, count = 16, data = { \8\0\0\0\82\5\0\0`\4 \0\0\0\0\0
} }
42950500.120428466 fs_data.write: 1034, 1034, icsio, UNBRANDED, 1,
0x0, SYSCALL { fd = 5, count = 16, data = { \8\0\0\0\2\6\0\0#\1 \0m^Q&
} }
42950500.120467528 fs_data.read: 1034, 1034, icsio, UNBRANDED, 1, 0x0,
SYSCALL { fd = 5, count = 16, data = { \8\0\0\0\82\5\0\0`\1 \0\0\0\0\0
} }
42950500.120474852 fs_data.write: 1034, 1034, icsio, UNBRANDED, 1,
0x0, SYSCALL { fd = 5, count = 16, data = { \8\0\0\0\2\6\0\0#\0
\0\10\0\0\0 } }
42950500.120523680 fs_data.read: 1034, 1034, icsio, UNBRANDED, 1, 0x0,
SYSCALL { fd = 5, count = 16, data = { \8\0\0\0\82\5\0\0`\0 \0\0\0\0\0
} }
42950500.120538329 fs_data.read: 1034, 1034, icsio, UNBRANDED, 1, 0x0,
SYSCALL { fd = 5, count = 16, data = { \8\0\0\0\82\2\0\0m^Q&\0\0\0\0 }
}
42950500.120546874 fs_data.write: 1034, 1034, icsio, UNBRANDED, 1,
0x0, SYSCALL { fd = 8, count = 32, data = {
a%B\4\10\0\a\0\14\0\0\0\cd\f\b\4\1\0\0\0\4\0\0\0\0\0\0\0\0\0\0\0 } }
NOTE: icsio says "I'm done" to device_controll
42950500.120556639 fs.select: 1034, 1034, icsio, UNBRANDED, 1, 0x0,
SYSCALL { fd = 5, timeout = 1 }
42950500.120557860 fs.select: 1034, 1034, icsio, UNBRANDED, 1, 0x0,
SYSCALL { fd = 6, timeout = 1 }
42950500.120559081 fs.select: 1034, 1034, icsio, UNBRANDED, 1, 0x0,
SYSCALL { fd = 7, timeout = 1 }
42950500.120560302 fs.select: 1034, 1034, icsio, UNBRANDED, 1, 0x0,
SYSCALL { fd = 8, timeout = 1 }
42950500.120562743 fs.select: 1035, 1035, device_controll, UNBRANDED,
1, 0x0, SYSCALL { fd = 6, timeout = 100 }
42950500.120563964 fs.select: 1035, 1035, device_controll, UNBRANDED,
1, 0x0, SYSCALL { fd = 10, timeout = 100 }
42950500.120565184 fs.select: 1035, 1035, device_controll, UNBRANDED,
1, 0x0, SYSCALL { fd = 11, timeout = 100 }
42950500.120571288 fs_data.read: 1035, 1035, device_controll,
UNBRANDED, 1, 0x0, SYSCALL { fd = 6, count = 256, data = {
a%B\4\10\0\a\0\14\0\0\0\cd\f\b\4\1\0\0\0\4\0\0\0\0\0\0\0\0\0\0\0 } }
NOTE: device_controll hears "I'm done" from icsio
42950500.120582274 fs_data.write: 1035, 1035, device_controll,
UNBRANDED, 1, 0x0, SYSCALL { fd = 11, count = 40, data = {
a%B\4\0\0\14\0\1c\0\0\0\cf\f\b\4\0\0\0\0'\0\0\0\c\0\0\0'\0\0\0 } }
NOTE:  device_controll says "I'm done" to isl_engiine
42950500.120595702 fs.select: 1035, 1035, device_controll, UNBRANDED,
1, 0x0, SYSCALL { fd = 6, timeout = 100 }
42950500.120596923 fs.select: 1035, 1035, device_controll, UNBRANDED,
1, 0x0, SYSCALL { fd = 10, timeout = 100 }
42950500.120598143 fs.select: 1035, 1035, device_controll, UNBRANDED,
1, 0x0, SYSCALL { fd = 11, timeout = 100 }
42950500.120600585 fs.select: 1034, 1034, icsio, UNBRANDED, 1, 0x0,
SYSCALL { fd = 5, timeout = 1 }
42950500.120601805 fs.select: 1034, 1034, icsio, UNBRANDED, 1, 0x0,
SYSCALL { fd = 6, timeout = 1 }
42950500.120603026 fs.select: 1034, 1034, icsio, UNBRANDED, 1, 0x0,
SYSCALL { fd = 7, timeout = 1 }
42950500.120604247 fs.select: 1034, 1034, icsio, UNBRANDED, 1, 0x0,
SYSCALL { fd = 8, timeout = 1 }
42950500.120612792 fs_data.read: 1036, 1036, isl_engine, UNBRANDED, 1,
0x0, SYSCALL { fd = 5, count = 256, data = {
a%B\4\0\0\14\0\1c\0\0\0\cf\f\b\4\0\0\0\0'\0\0\0\c\0\0\0'\0\0\0 } }
NOTE: isl_engine hears "I'm done" from device_controll
42950500.120635985 fs.select: 1035, 1035, device_controll, UNBRANDED,
1, 0x0, SYSCALL { fd = 6, timeout = 100 }
42950500.120637206 fs.select: 1035, 1035, device_controll, UNBRANDED,
1, 0x0, SYSCALL { fd = 10, timeout = 100 }
42950500.120638427 fs.select: 1035, 1035, device_controll, UNBRANDED,
1, 0x0, SYSCALL { fd = 11, timeout = 100 }

In the abnormal case, a bug causes device_controll to not perform its
select. Consequently, when icsio tries to say "I'm done" back to
device_controll, device_controll doesn't wake up the way it ought to
(and things take too long).

42950599.540054930 fs_data.write: 1036, 1036, isl_engine, UNBRANDED,
1, 0x0, SYSCALL { fd = 5, count = 36, data = {
a%B\49\0\14\0\18\0\0\0#\a7\c\4\0\0\0\0$\0\0\0\7\0\0\0\a\0\0\0 } }
42950599.540069579 fs.select: 1034, 1034, icsio, UNBRANDED, 1, 0x0,
SYSCALL { fd = 5, timeout = 0 }
42950599.540070800 fs.select: 1034, 1034, icsio, UNBRANDED, 1, 0x0,
SYSCALL { fd = 6, timeout = 0 }
42950599.540072020 fs.select: 1034, 1034, icsio, UNBRANDED, 1, 0x0,
SYSCALL { fd = 7, timeout = 0 }
42950599.540073241 fs.select: 1034, 1034, icsio, UNBRANDED, 1, 0x0,
SYSCALL { fd = 8, timeout = 0 }
42950599.540233153 fs.select: 1034, 1034, icsio, UNBRANDED, 1, 0x0,
SYSCALL { fd = 5, timeout = 1 }
42950599.540234374 fs.select: 1034, 1034, icsio, UNBRANDED, 1, 0x0,
SYSCALL { fd = 6, timeout = 1 }
42950599.540235595 fs.select: 1034, 1034, icsio, UNBRANDED, 1, 0x0,
SYSCALL { fd = 7, timeout = 1 }
42950599.540236815 fs.select: 1034, 1034, icsio, UNBRANDED, 1, 0x0,
SYSCALL { fd = 8, timeout = 1 }
42950599.540239257 fs.select: 1035, 1035, device_controll, UNBRANDED,
1, 0x0, SYSCALL { fd = 6, timeout = 56 }
42950599.540240477 fs.select: 1035, 1035, device_controll, UNBRANDED,
1, 0x0, SYSCALL { fd = 10, timeout = 56 }
42950599.540241698 fs.select: 1035, 1035, device_controll, UNBRANDED,
1, 0x0, SYSCALL { fd = 11, timeout = 56 }
42950599.540247802 fs_data.read: 1035, 1035, device_controll,
UNBRANDED, 1, 0x0, SYSCALL { fd = 11, count = 256, data = {
a%B\49\0\14\0\18\0\0\0#\a7\c\4\0\0\0\0$\0\0\0\7\0\0\0\a\0\0\0 } }
42950599.540261229 fs_data.write: 1035, 1035, device_controll,
UNBRANDED, 1, 0x0, SYSCALL { fd = 6, count = 40, data = {
a%B\4\4\0\a\0\1c\0\0\0]+\b\4\2\0\0\0\10\0\0\0\3\0\0\0\1\0\0\0 } }
	NOTE: device_controll does not do a select!
42950599.540277098 fs.select: 1034, 1034, icsio, UNBRANDED, 1, 0x0,
SYSCALL { fd = 5, timeout = 1 }
42950599.540278319 fs.select: 1034, 1034, icsio, UNBRANDED, 1, 0x0,
SYSCALL { fd = 6, timeout = 1 }
42950599.540279540 fs.select: 1034, 1034, icsio, UNBRANDED, 1, 0x0,
SYSCALL { fd = 7, timeout = 1 }
42950599.540280761 fs.select: 1034, 1034, icsio, UNBRANDED, 1, 0x0,
SYSCALL { fd = 8, timeout = 1 }
42950599.540285643 fs_data.read: 1034, 1034, icsio, UNBRANDED, 1, 0x0,
SYSCALL { fd = 8, count = 256, data = {
a%B\4\4\0\a\0\1c\0\0\0]+\b\4\2\0\0\0\10\0\0\0\3\0\0\0\1\0\0\0 } }
42950599.540295409 fs_data.write: 1034, 1034, icsio, UNBRANDED, 1,
0x0, SYSCALL { fd = 5, count = 16, data = { \8\0\0\0\2\6\0\0#\2
\0\1\0\0\0 } }
42950599.540333251 fs_data.read: 1034, 1034, icsio, UNBRANDED, 1, 0x0,
SYSCALL { fd = 5, count = 16, data = { \8\0\0\0\82\5\0\0`\2 \0\0\0\0\0
} }
42950599.540340575 fs_data.write: 1034, 1034, icsio, UNBRANDED, 1,
0x0, SYSCALL { fd = 5, count = 16, data = { \8\0\0\0\2\6\0\0#\3
\0\7\0\0\0 } }
42950599.540377196 fs_data.read: 1034, 1034, icsio, UNBRANDED, 1, 0x0,
SYSCALL { fd = 5, count = 16, data = { \8\0\0\0\82\5\0\0`\3 \0\0\0\0\0
} }
42950599.540384520 fs_data.write: 1034, 1034, icsio, UNBRANDED, 1,
0x0, SYSCALL { fd = 5, count = 16, data = { \8\0\0\0\2\6\0\0#\4
\0\a\0\0\0 } }
42950599.540416259 fs_data.read: 1034, 1034, icsio, UNBRANDED, 1, 0x0,
SYSCALL { fd = 5, count = 16, data = { \8\0\0\0\82\5\0\0`\4 \0\0\0\0\0
} }
42950599.540423583 fs_data.write: 1034, 1034, icsio, UNBRANDED, 1,
0x0, SYSCALL { fd = 5, count = 16, data = { \8\0\0\0\2\6\0\0#\1 \0QeQ&
} }
42950599.540462645 fs_data.read: 1034, 1034, icsio, UNBRANDED, 1, 0x0,
SYSCALL { fd = 5, count = 16, data = { \8\0\0\0\82\5\0\0`\1 \0\0\0\0\0
} }
42950599.540469970 fs_data.write: 1034, 1034, icsio, UNBRANDED, 1,
0x0, SYSCALL { fd = 5, count = 16, data = { \8\0\0\0\2\6\0\0#\0
\0\10\0\0\0 } }
42950599.540506591 fs_data.read: 1034, 1034, icsio, UNBRANDED, 1, 0x0,
SYSCALL { fd = 5, count = 16, data = { \8\0\0\0\82\5\0\0`\0 \0\0\0\0\0
} }
42950599.540528563 fs.select: 1034, 1034, icsio, UNBRANDED, 1, 0x0,
SYSCALL { fd = 5, timeout = 1 }
42950599.540529784 fs.select: 1034, 1034, icsio, UNBRANDED, 1, 0x0,
SYSCALL { fd = 6, timeout = 1 }
42950599.540531005 fs.select: 1034, 1034, icsio, UNBRANDED, 1, 0x0,
SYSCALL { fd = 7, timeout = 1 }
42950599.540532225 fs.select: 1034, 1034, icsio, UNBRANDED, 1, 0x0,
SYSCALL { fd = 8, timeout = 1 }
42950599.540540770 fs_data.read: 1034, 1034, icsio, UNBRANDED, 1, 0x0,
SYSCALL { fd = 5, count = 16, data = { \8\0\0\0\82\2\0\0QeQ&\0\0\0\0 }
}
42950599.540548095 fs_data.write: 1034, 1034, icsio, UNBRANDED, 1,
0x0, SYSCALL { fd = 8, count = 32, data = {
a%B\4\10\0\a\0\14\0\0\0]+\b\4\1\0\0\0\4\0\0\0\0\0\0\0\0\0\0\0 } }
	NOTE: why does the above message not wake up device_controll? see
previous note!
42950599.540714110 fs.select: 1034, 1034, icsio, UNBRANDED, 1, 0x0,
SYSCALL { fd = 5, timeout = 1 }
42950599.540715331 fs.select: 1034, 1034, icsio, UNBRANDED, 1, 0x0,
SYSCALL { fd = 6, timeout = 1 }
42950599.540716552 fs.select: 1034, 1034, icsio, UNBRANDED, 1, 0x0,
SYSCALL { fd = 7, timeout = 1 }
42950599.540717772 fs.select: 1034, 1034, icsio, UNBRANDED, 1, 0x0,
SYSCALL { fd = 8, timeout = 1 }

Thanks for building such a powerful tool!

Johnicholas