[lttng-dev] some events lost

[Mathieu Desnoyers]

* Sébastien Barthélémy (barthelemy at crans.org) wrote:
> 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?

You should try increasing the size of your buffers. run:

lttng enable-channel --help

to see the options. Then you'll have to use "-c channel_name" to attach
your events (enable-event) to this channel.

> 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 doubt it.

> 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.

you have to do e.g.

lttng create
lttng enable-channel mychan --subbuf-size 262144 --num-subbuf 8
lttng enable-event -u -a -c mychan
lttng start
...
lttng stop
lttng destroy

Otherwise your event data will go into the "default" channel (channel0)
whish has default config.

About having no message that tells there have been events lost: I
currently disabled the functions that print this, because printing from
the consumer daemon is not really helpful, since it is normally used
without console output (except in verbose mode). However, the
information is available in the trace files, so I have a TODO item
somewhere on my todo list to make babeltrace print a warning when it
figures out that events have been dropped.

Best regards,

Mathieu

> 
> 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
> 
> _______________________________________________
> lttng-dev mailing list
> lttng-dev at lists.lttng.org
> http://lists.lttng.org/cgi-bin/mailman/listinfo/lttng-dev
> 

-- 
Mathieu Desnoyers
Operating System Efficiency R&D Consultant
EfficiOS Inc.
http://www.efficios.com