[ltt-dev] UST use case: Tracing QEMU/KVM

[ltt-dev] UST use case: Tracing QEMU/KVM

[Stefan Hajnoczi]

Here is feedback from adding UST tracing to QEMU/KVM.  Hopefully this
will be useful to developers and maybe I can learn a more about LTTng
UST from discussing hurdles I encountered.

The architecture of UST looks good: pure userspace tracing support,
tracepoints can be enumerated, enabled, and disabled at runtime.  The
manual at http://lttng.org/files/ust/manual/ust.html is a nice
quickstart although I suspect it only scratches the surface.

One note about the manual: the TP_PROTO() versus TPPROTO() change was
confusing.  Perhaps a note can be added to the manual that ust.git
uses TP_PROTO() but libust 0.4 uses TPPROTO()?

When running the instrumented binary, the listener thread outputs
noisy error messages:
libust[28133/28134]: Error: poll: Interrupted system call (in
multipoll_poll() at ../libustcomm/multipoll.c:84)
libust[28133/28134]: Error: error in multipoll_poll (in
listener_main() at tracectl.c:1015)

Strace shows:
poll([{fd=3, events=POLLIN}], 1, -1)    = ? ERESTART_RESTARTBLOCK (To
be restarted)
restart_syscall(<... resuming interrupted call ...>) = ?
ERESTART_RESTARTBLOCK (To be restarted)

Finally, I had to add #undefs to get QEMU to build after including UST
headers.  Unfortunately the UST headers include headers that pollute
the (macro) namespace.

Any thoughts on these issues?

My patch enabling UST sent to the QEMU mailing list:
http://www.mail-archive.com/kvm at vger.kernel.org/msg34830.html

Stefan

[ltt-dev] UST use case: Tracing QEMU/KVM

[Pierre-Marc Fournier]

Hi Stefan,

Thanks for the feedback! A few comments:

----- Original message -----
> Here is feedback from adding UST tracing to QEMU/KVM.? Hopefully this
> will be useful to developers and maybe I can learn a more about LTTng
> UST from discussing hurdles I encountered.
>
> The architecture of UST looks good: pure userspace tracing support,
> tracepoints can be enumerated, enabled, and disabled at runtime.? The
> manual at http://lttng.org/files/ust/manual/ust.html is a nice
> quickstart although I suspect it only scratches the surface.

If there are specific subjects in mind you feel would benefit from being covered in more depth in the manual, please let me know.

>
> One note about the manual: the TP_PROTO() versus TPPROTO() change was
> confusing.? Perhaps a note can be added to the manual that ust.git
> uses TP_PROTO() but libust 0.4 uses TPPROTO()?

This reflects an API change in the kernel. But you are right, this is confusing. I will do a 0.5 release next week, which will obsolete 0.4 and sync the manual.

>
> When running the instrumented binary, the listener thread outputs
> noisy error messages:
> libust[28133/28134]: Error: poll: Interrupted system call (in
> multipoll_poll() at ../libustcomm/multipoll.c:84)
> libust[28133/28134]: Error: error in multipoll_poll (in
> listener_main() at tracectl.c:1015)
>
> Strace shows:
> poll([{fd=3, events=POLLIN}], 1, -1)? ? ? = ? ERESTART_RESTARTBLOCK (To
> be restarted)
> restart_syscall(<... resuming interrupted call ...>) = ?
> ERESTART_RESTARTBLOCK (To be restarted)

Hmmm. Do you have any pointers to documentation about this return code? I suspect userspace should never see it. Could it be a kernel bug?

>
> Finally, I had to add #undefs to get QEMU to build after including UST
> headers.? Unfortunately the UST headers include headers that pollute
> the (macro) namespace.
>

From examining the patch, I expect you are referring to mutex_lock and _unlock. I just did a commit to fix this.

> Any thoughts on these issues?
>
> My patch enabling UST sent to the QEMU mailing list:
> http://www.mail-archive.com/kvm at vger.kernel.org/msg34830.html

Thanks!

Pierre-Marc

[ltt-dev] UST use case: Tracing QEMU/KVM

[Stefan Hajnoczi]

On Mon, May 24, 2010 at 4:57 AM, Pierre-Marc Fournier
<pierre-marc.fournier at polymtl.ca> wrote:

Thanks for the quick reply, Pierre-Marc.

> If there are specific subjects in mind you feel would benefit from being covered in more depth in the manual, please let me know.

For large programs or programs that closely manage resources, a
documented list of resources that libust uses would be useful.  This
information can be used to understand whether libust might interfere
with the program being traced.  For example, will heap allocations be
made after startup?  Will file descriptors be held open?  The listener
thread?

I don't understand the --create-trace, --alloc-trace, --destroy-trace,
and subbuf concepts that ustctl exposes.  Perhaps these are documented
in kernel LTTng and I haven't read that.

>> One note about the manual: the TP_PROTO() versus TPPROTO() change was
>> confusing.? Perhaps a note can be added to the manual that ust.git
>> uses TP_PROTO() but libust 0.4 uses TPPROTO()?
>
> This reflects an API change in the kernel. But you are right, this is confusing. I will do a 0.5 release next week, which will obsolete 0.4 and sync the manual.

Thanks.

>> poll([{fd=3, events=POLLIN}], 1, -1)? ? ? = ? ERESTART_RESTARTBLOCK (To
>> be restarted)
>> restart_syscall(<... resuming interrupted call ...>) = ?
>> ERESTART_RESTARTBLOCK (To be restarted)
>
> Hmmm. Do you have any pointers to documentation about this return code? I suspect userspace should never see it. Could it be a kernel bug?

I have sent an example that triggers this behavior and explains how it
can occur.

>> Finally, I had to add #undefs to get QEMU to build after including UST
>> headers.? Unfortunately the UST headers include headers that pollute
>> the (macro) namespace.
>>
>
> From examining the patch, I expect you are referring to mutex_lock and _unlock. I just did a commit to fix this.

Great, thanks.

Stefan

[ltt-dev] UST use case: Tracing QEMU/KVM

[Pierre-Marc Fournier]

Stefan Hajnoczi wrote:
> On Mon, May 24, 2010 at 4:57 AM, Pierre-Marc Fournier
> <pierre-marc.fournier at polymtl.ca> wrote:
> 
> Thanks for the quick reply, Pierre-Marc.
> 
>> If there are specific subjects in mind you feel would benefit from being covered in more depth in the manual, please let me know.
> 
> For large programs or programs that closely manage resources, a
> documented list of resources that libust uses would be useful.  This
> information can be used to understand whether libust might interfere
> with the program being traced.  For example, will heap allocations be
> made after startup?  Will file descriptors be held open?  The listener
> thread?

Currently, ust is designed to be transparent to the running process in 
most cases. However, if your program makes very unusual assumptions 
about the usage of some resources, this could result in a conflict.

- Yes, heap allocations can be made after startup.
- Sockets will definitely be kept open by the listener thread.
- Currently, I don't think any file descriptors are kept open, but it 
could be the case in the future.
- SystemV shared memory segments are mapped in the address space.
- A listener thread is always started to wait for connections from 
ustctl or ustd.

If you feel it would be important to avoid some of these things, please 
let me know.

> 
> I don't understand the --create-trace, --alloc-trace, --destroy-trace,
> and subbuf concepts that ustctl exposes.  Perhaps these are documented
> in kernel LTTng and I haven't read that.

Normally you should not need to go to LTTng kernel tracer documentation 
to understand.

I just pushed an updated manpage for ustctl in the git which clarifies 
these concepts. If you think things could be even clearer, let me know.

> 
>>> One note about the manual: the TP_PROTO() versus TPPROTO() change was
>>> confusing.  Perhaps a note can be added to the manual that ust.git
>>> uses TP_PROTO() but libust 0.4 uses TPPROTO()?
>> This reflects an API change in the kernel. But you are right, this is confusing. I will do a 0.5 release next week, which will obsolete 0.4 and sync the manual.
> 
> Thanks.
> 
>>> poll([{fd=3, events=POLLIN}], 1, -1)      = ? ERESTART_RESTARTBLOCK (To
>>> be restarted)
>>> restart_syscall(<... resuming interrupted call ...>) = ?
>>> ERESTART_RESTARTBLOCK (To be restarted)
>> Hmmm. Do you have any pointers to documentation about this return code? I suspect userspace should never see it. Could it be a kernel bug?
> 
> I have sent an example that triggers this behavior and explains how it
> can occur.
> 

Will look at this shortly.

[ltt-dev] UST use case: Tracing QEMU/KVM

[Stefan Hajnoczi]

On Wed, May 26, 2010 at 11:46 PM, Pierre-Marc Fournier
<pierre-marc.fournier at polymtl.ca> wrote:
>> For large programs or programs that closely manage resources, a
>> documented list of resources that libust uses would be useful. ?This
>> information can be used to understand whether libust might interfere
>> with the program being traced. ?For example, will heap allocations be
>> made after startup? ?Will file descriptors be held open? ?The listener
>> thread?
>
> Currently, ust is designed to be transparent to the running process in most
> cases. However, if your program makes very unusual assumptions about the
> usage of some resources, this could result in a conflict.
>
> - Yes, heap allocations can be made after startup.
> - Sockets will definitely be kept open by the listener thread.
> - Currently, I don't think any file descriptors are kept open, but it could
> be the case in the future.
> - SystemV shared memory segments are mapped in the address space.
> - A listener thread is always started to wait for connections from ustctl or
> ustd.
>
> If you feel it would be important to avoid some of these things, please let
> me know.

Thanks for explaining, sounds fine to me.  If you want to add this as
an appendix to the documentation I think it is useful information for
an application developer who wants to integrate UST support.

>> I don't understand the --create-trace, --alloc-trace, --destroy-trace,
>> and subbuf concepts that ustctl exposes. ?Perhaps these are documented
>> in kernel LTTng and I haven't read that.
>
> Normally you should not need to go to LTTng kernel tracer documentation to
> understand.
>
> I just pushed an updated manpage for ustctl in the git which clarifies these
> concepts. If you think things could be even clearer, let me know.

Great thanks, will check out the documentation.

Stefan

[ltt-dev] UST use case: Tracing QEMU/KVM

[Pierre-Marc Fournier]

Stefan Hajnoczi wrote:
> On Wed, May 26, 2010 at 11:46 PM, Pierre-Marc Fournier
> <pierre-marc.fournier at polymtl.ca> wrote:
>>> For large programs or programs that closely manage resources, a
>>> documented list of resources that libust uses would be useful.  This
>>> information can be used to understand whether libust might interfere
>>> with the program being traced.  For example, will heap allocations be
>>> made after startup?  Will file descriptors be held open?  The listener
>>> thread?
>> Currently, ust is designed to be transparent to the running process in most
>> cases. However, if your program makes very unusual assumptions about the
>> usage of some resources, this could result in a conflict.
>>
>> - Yes, heap allocations can be made after startup.
>> - Sockets will definitely be kept open by the listener thread.
>> - Currently, I don't think any file descriptors are kept open, but it could
>> be the case in the future.
>> - SystemV shared memory segments are mapped in the address space.
>> - A listener thread is always started to wait for connections from ustctl or
>> ustd.
>>
>> If you feel it would be important to avoid some of these things, please let
>> me know.
> 
> Thanks for explaining, sounds fine to me.  If you want to add this as
> an appendix to the documentation I think it is useful information for
> an application developer who wants to integrate UST support.
> 

Just added a section (8) about this in the manual.

Thanks.

pmf

[ltt-dev] UST use case: Tracing QEMU/KVM

[Stefan Hajnoczi]

On Thu, May 27, 2010 at 8:36 PM, Pierre-Marc Fournier
<pierre-marc.fournier at polymtl.ca> wrote:
Pierre-Marc,
Thanks for your responsiveness and willingness to engage.  This
addresses the technical questions I had about using UST in QEMU/KVM.

I am proposing tracing QEMU patches for merge, and hopefully the patch
that adds UST support will be accepted.

The non-technical issue that remains is the availability of UST
packages across Linux distributions.  The Debian packages are good
start, although there does not seem to be an lttv package.  Developers
wanting to add tracing to their programs may be put off by unpackaged
software.  Do you have any thoughts on growing the popularity of UST?

Stefan

[ltt-dev] UST use case: Tracing QEMU/KVM

[Mathieu Desnoyers]

* Stefan Hajnoczi (stefanha at gmail.com) wrote:
> On Thu, May 27, 2010 at 8:36 PM, Pierre-Marc Fournier
> <pierre-marc.fournier at polymtl.ca> wrote:
> Pierre-Marc,
> Thanks for your responsiveness and willingness to engage.  This
> addresses the technical questions I had about using UST in QEMU/KVM.
> 
> I am proposing tracing QEMU patches for merge, and hopefully the patch
> that adds UST support will be accepted.
> 
> The non-technical issue that remains is the availability of UST
> packages across Linux distributions.  The Debian packages are good
> start, although there does not seem to be an lttv package.  Developers
> wanting to add tracing to their programs may be put off by unpackaged
> software.  Do you have any thoughts on growing the popularity of UST?

CCing Jon Bernard and Kerstin Jonsson who are actually working on
preparing Debian packages.

Thanks,

Mathieu

> 
> Stefan
> 
> _______________________________________________
> ltt-dev mailing list
> ltt-dev at lists.casi.polymtl.ca
> http://lists.casi.polymtl.ca/cgi-bin/mailman/listinfo/ltt-dev
> 

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

[ltt-dev] UST use case: Tracing QEMU/KVM

[Stefan Hajnoczi]

/*
 * This example demonstrates the UST listener thread receiving signals and
 * returning from poll().
 *
 * $ gcc -o poll_eintr poll_eintr.c -lust -lpthread
 * $ ./poll_eintr
 * main thread id=0x7f9c31a766a0
 * ^CSIGINT handled in thread id=0x7f9c30ed7910
 * libust[2615/2616]: Error: poll: Interrupted system call (in multipoll_poll() at ../libustcomm/multipoll.c:84)
 * libust[2615/2616]: Error: error in multipoll_poll (in listener_main() at tracectl.c:1015)
 *
 * This happens because all other threads have SIGINT blocked, whereas libust
 * does not block signals in the client thread.  Therefore the signal is
 * handled in the client thread, poll() is interrupted, and an error is
 * printed.
 *
 * I think the correct behavior is to block signals in the client thread so it
 * will not interfere with signal handling of the main program.
 */

#include <stdio.h>
#include <unistd.h>
#include <signal.h>
#include <pthread.h>

static void sigint_handler(int signo)
{
	fprintf(stderr, "SIGINT handled in thread id=0x%lx\n", pthread_self());
}

int main(int argc, char **argv)
{
	sigset_t newmask;

	fprintf(stderr, "main thread id=0x%lx\n", pthread_self());

	/* Block SIGINT in this thread */
	sigemptyset(&newmask);
	sigaddset(&newmask, SIGINT);
	pthread_sigmask(SIG_SETMASK, &newmask, NULL);

	/* Set up a handler for SIGINT */
	signal(SIGINT, sigint_handler);

	/* Now wait for signals, the UST listener thread will receive it */
	for (;;) {
		pause();
		fprintf(stderr, "pause returned in main thread\n");
	}
	return 0;
}

[ltt-dev] UST use case: Tracing QEMU/KVM

[Pierre-Marc Fournier]

Stefan Hajnoczi wrote:
> /*
>  * This example demonstrates the UST listener thread receiving signals and
>  * returning from poll().
>  *
>  * $ gcc -o poll_eintr poll_eintr.c -lust -lpthread
>  * $ ./poll_eintr
>  * main thread id=0x7f9c31a766a0
>  * ^CSIGINT handled in thread id=0x7f9c30ed7910
>  * libust[2615/2616]: Error: poll: Interrupted system call (in multipoll_poll() at ../libustcomm/multipoll.c:84)
>  * libust[2615/2616]: Error: error in multipoll_poll (in listener_main() at tracectl.c:1015)
>  *
>  * This happens because all other threads have SIGINT blocked, whereas libust
>  * does not block signals in the client thread.  Therefore the signal is
>  * handled in the client thread, poll() is interrupted, and an error is
>  * printed.
>  *
>  * I think the correct behavior is to block signals in the client thread so it
>  * will not interfere with signal handling of the main program.
>  */

I completely agree. I just pushed a change that blocks all signals in 
the listener thread.

Thanks!