[lttng-dev] LTTng unreliable and useless under heavy loaded systems?

Thu Jan 8 08:54:13 EST 2015

Hi

Thanks for your detailed inputs! I read the Readme of latency_tracker. 
The watch-block-event.sh you provide brought me on the track of using 
"--snapshot" which is, as Mathieu mentioned, exactly what I need. Thanks 
Mathieu as well! I'm now able to trace my system and I can successfully 
analyze the traces with Eclipse. Thanks to the --snapshot mode, the 
events that are actually important to me are now part of the trace. When 
I initially read the LTTng docs, and I came to the chapter "snapshot", I 
unfortunately decided to skip it because I (for whatever reason) 
expected something different for "snapshots" (something like the current 
state/callstacks of the CPUs).

Btw: While latency_tracker looks really great, I didn't use it so far, 
as I already have a very good trigger if a jitter occurs. But I'm glad 
to know it exists, maybe I'll use it the next time I have to optimize a 
system.

For the records, if someone finds this message on the net, I briefly 
describe how I perform the measurement:
     lttng create --snapshot victory
     lttng enable-channel channel0 -k --subbuf-size 16M --num-subbuf 2
     lttng add-context -k -t procname -c channel0
     lttng enable-event -k --all -c channel0
     lttng start
     chrt -f 50 ./run_my_test-application_here
     lttng stop
     lttng destroy
I've extended my test application to execute 'lttng snapshot record' 
when a certain jitter occurred (cMaxMs):
     if( dRoundTripTime > cMaxMs ) {
        system("lttng snapshot record");
     }

A few notes:
   * In my case, I had to increase the subbuf sizes. The default sizes 
were to small, because my system is intentionally under heavy load.
   * I first tried to use 'num-subbuf 1' because I thought that's ok in 
'snapshot mode', but that caused LTTng to misbehave: it didn't create 
proper trace files. Unfortunately, it didn't yield any warning/error. 
Wouldn't it make sense to print an warning/error in that case?
   * Just as a side note: With the measurement above, the trace 
sometimes still doesn't contain the events I'm interested in. But I 
guess this is just because the call to "system()" and the execution of 
lttng-consumerd may take that long so that the event in the buffer have 
already been overwritten. (I wonder whether 'lttng snapshot record' is 
optimized so that it immediately causes the tracer to stop overwriting 
old events in the buffer?)

Although it's not that important anymore, I'm curious about the 
following: Assuming that the occurrence of "my" jitter is not depending 
on timings. I could then claim that I don't care about the system slow 
down due to tracing. That said, I claim I don't really care about how 
may times LTTng must switch the subbuffers, because I guess that this 
happens right in the context of "tracing an event" - so the only thing 
the additional switchings do is to consume some CPU. But it does not 
cause more events to be lost. Am I right? (If not: How is buffer 
switching implemented, roughly?)

Thanks for your great & immediate help and keep up the great work on 
LTTng & co!
Raphael

P.S. Just in case someone cares: So far, I found that among others, 
kswapd0 and khugepaged are two components that cause jitter on my system.

On 01/07/2015 05:56 PM, Julien Desfossez wrote:
> Hi Raphael,
>
> First of all, thanks for your input, it is really interesting for us to
> have detailled use cases like that.
>
> One first thing that come to mind is the amount of events enabled. When
> you use "lttng enable-event -k --all", you enable around 240 trace
> points (and all the syscalls), and much more if you have the sources of
> your kernel on the same machine (which allows the compilation and
> installation of the ext4/btrfs/kvm events). There are some very verbose
> tracepoint in the default list that might not be useful for the analysis
> you are trying to perform.
>
> I understand that, you want as much information as possible since you
> don't know what is exactly the problem, but instead of enabling
> everything, I would suggest a more iterative approach: first just enable
> the sched_switch and syscall events, and then when you get a better idea
> of what is going on, enable some specific subsystems.
>
> Also, when you increase the amount of subbuffers (and lower the
> subbuf-size), you increase the rate of subbuffer switches, which is the
> heaviest operation in the tracer. So you could maybe try other
> parameters such as 4x8 (if you want to limit to 32MB per CPU per
> channel). For the crash you got, it might be related to an out-of-memory
> problem, but it will be interesting to investigate this issue.
> I don't think there is a proper methodology to identify the perfect size
> for your use-case (other than trial/error), writing the trace on a
> dedicated and faster disk helps a lot.
>
> I know this can be frustrating to wait for hours for a problem to appear
> and end up with a huge trace that misses the important events. If the
> iterative strategy is not an option for you, you might be interested by
> a project I have started recently to automate the triggering of
> recording LTTng snapshots based on unusual latencies detected from the
> kernel [1]. The idea is to only write the trace in memory (no I/O) with
> the ring-buffer in flight-recorder mode, and when an interesting event
> is detected, extract the content of the ring-buffer and write it on
> disk/network. The amount of background information you get in your
> snapshot depends on the rate of events and size of the ring-buffer.
> This project is in a really early phase and I would not advise it yet
> for production use, but if you are interested by it, you can try it, the
> examples work reliably for me, and if you need help setting it up or
> adapting it to your needs, don't hesitate to contact me, at this stage
> all the feedbacks/suggestions are important.
>
> I hope this gives you some ideas on what could be your next steps.
> Please, let us know if you manage to find a way to solve this problem.
>
> Thanks,
>
> Julien
>
> [1] https://github.com/jdesfossez/latency_tracker
>
> On 15-01-07 11:10 AM, Raphael Zulliger wrote:
>> First of all: LTTng seems to be a great piece of software. Great docs
>> and good visualization tools (Eclipse) are available. I mention this to
>> clarify that I like LTTng...
>>
>> ... unfortunately, for the issue I've started using it, it doesn't work
>> very well. I contact the list because I hope you have some tips and
>> tricks for me.
>>
>> I have a Ubuntu 14.04/32, i5 Quadcore. The goal is to run an existing
>> application as jitter less as possible. To tune the system, I've
>> programmed a simple test-application which sends a UDP frame to an
>> embedded system and waits for the response. If the time until test-app
>> receives the response is bigger than 5ms, it consider that a big jitter
>> and exits. In that case, I want to find out what caused the jitter of >
>> 5ms. NOTE: I run my application with real-time prio 99 (which could
>> matter in this case, I guess)
>>
>> Here's how I initially run my measurement (all as sudo):
>>    lttng create
>>    lttng enable-channel channel0 -k
>>    lttng enable-event -k --all -c channel0
>>    lttng start
>>    chrt -f 50 ./run_my_test-application_here
>>    lttng stop
>>    lttng destroy
>> Then, I start compiling a kernel image and run bonnie++ to generate
>> system load. It takes about 1h until a jitter > 5ms occurs... but it
>> happens.
>>
>> Unfortunately, whenever the big jitter (which are around 6ms up to 25ms)
>> occur, LTTng is not able to record the events around the time the delay
>> happened. Means: I got really nice graphs in Eclipse - but not at the
>> points where it would be useful... I also verified this with "babeltrace
>> .... > /dev/null" which reported the loss of various events.
>>
>> I read the docs and then tried to increase the buffers. I tried several
>> numbers, the final version is:
>>    lttng enable-channel channel0 -k --num-subbuf 32 --subbuf-size 1M
>> But it doesn't help. From my point of view, the result is still the same
>> as before it doesn't obviously loose less events than before. (Side
>> note: Actually, I also tried with "subbuf 16" and "subbuf-size 10M" but
>> then my system crashed: X gone, no keyboard input possible anymore but
>> (surprisingly) no kernel dump)
>>
>> (Side note: There's one more thing to mention: The system is setup with
>> isolcpu=1,2,3 (because core 1..3 run real-time apps other than the one
>> mentioned here) - thus everything, including lttng daemons, ran on CPU0
>> so far.)
>>
>> Finally, I tried to run lttng-sessiond and lttng-consumerd on a separate
>> CPU core (CPU3) and even changed policy to SCHED_FIFO and prio to 99 -
>> but lttng still looses events. This really surpises me...
>>
>> I do understand that it is a good feature that lttng discards events
>> when buffers are full... but in my case, it seems to render lttng useless.
>> (Note: I did not yes use the "buffer overwrite" feature, but I guess the
>> events of interest will still be lost)
>>
>> My question: Is there anything else I can do on my system (which is a
>> not a production system, just a developer machine) to make lttng work
>> for my scenario?
>>
>> Any input is very welcome!
>> Raphael
>>
>> _______________________________________________
>> lttng-dev mailing list
>> lttng-dev at lists.lttng.org
>> http://lists.lttng.org/cgi-bin/mailman/listinfo/lttng-dev