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