[lttng-dev] some events lost

[Sébastien Barthélémy]

Hello,

season greetings to all.

after having played with LTTng on my desktop, I'm now trying it on the target.
It is basically working, except that I sometimes have gaps in the trace.

In the excerpt bellow, the following line should occur every 10ms:

  dcm:pcs: { 0 }, { state = 1 }

[26388074315803] dcm:pcs: { 0 }, { state = 0 }
[26388074337525] dcm:pcs: { 0 }, { state = 2 }
[26388074553202] dcm:pcs: { 0 }, { state = 0 }
[26388080255238] motionthread:after_wait: { 0 }, { }
[26388083846597] dcm:pcs: { 0 }, { state = 1 }
[26388083885151] sensorlog:begin_update: { 0 }, { }
[26388083957229] sensorlog:end_update: { 0 }, { }
[26388084460942] dcm:pcs: { 0 }, { state = 0 }
[26388084483641] dcm:pcs: { 0 }, { state = 2 }
[26388084704836] dcm:pcs: { 0 }, { state = 0 }
[26388085046790] motionthread:before_wait: { 0 }, { }
[26388093840106] dcm:pcs: { 0 }, { state = 1 }
[26388093884526] sensorlog:begin_update: { 0 }, { }
[26388093955767] sensorlog:end_update: { 0 }, { }
[26388094349126] dcm:pcs: { 0 }, { state = 0 }
<---------------------------------------------------- ~160 ms lost (16
cycles) --->
[26388254296385] dcm:pcs: { 0 }, { state = 1 }
[26388254360152] sensorlog:begin_update: { 0 }, { }
[26388254431323] sensorlog:end_update: { 0 }, { }
[26388255093720] dcm:pcs: { 0 }, { state = 0 }
[26388255116978] dcm:pcs: { 0 }, { state = 2 }
[26388255336008] dcm:pcs: { 0 }, { state = 0 }
[26388260256354] motionthread:after_wait: { 0 }, { }
[26388264318669] dcm:pcs: { 0 }, { state = 1 }
[26388264366442] sensorlog:begin_update: { 0 }, { }
[26388264448019] sensorlog:end_update: { 0 }, { }
[26388264850319] dcm:pcs: { 0 }, { state = 0 }
[26388264873507] dcm:pcs: { 0 }, { state = 2 }
[26388265136468] dcm:pcs: { 0 }, { state = 0 }
[26388266660386] motionthread:before_wait: { 0 }, { }
[26388274310780] dcm:pcs: { 0 }, { state = 1 }
[26388274355760] sensorlog:begin_update: { 0 }, { }
[26388274427279] sensorlog:end_update: { 0 }, { }


>From another log system I can tell the traced program is going well,
so this is probably a problem with the way I use LTTng.

Any hint on the cause of this gap? How should I investigate this?
By the way, I'm using the bundle from 12/23.

The target system is running a 2.6.33.9 kernel, so the futex workaround
is active. Could it be the cause of this gap?
I have plans to upgrade the kernel, but cannot do it right now.

Or maybe the buffers get full? But I have not seen any message telling
so. I tried the
--subbuf-size (I'm not sure what a subbuffer is though) with no
success: lttng list reported no
change in the subbuffer size.

Maybe I'm not starting LTTng properly. Here is my test script:

killall lttng-sessiond  lttng-consumerd testdaemon-bin
rm -rf  ~/lttng-traces/*
lttng create
lttng enable-event -a -u
lttng start
sleep 1
LTTNG_UST_DEBUG=1 LD_PRELOAD=`find $PREFIX/lib/probes/ -type f -name
\*.so\* -printf "%p "` LD_LIBRARY_PATH=$PREFIX/lib
$PREFIX/bin/testdaemon-bin &
sleep 16 # wait for the system to start
test-script.py # make the system actually do something
sleep 4 # ensure the test is really finished
lttng stop
killall testdaemon-bin
lttng destroy

Best regards,
-- Sébastien