Re: [RFC PATCH lttng-ust] Implement register_done waiting via LD_AUDIT

Re: [RFC PATCH lttng-ust] Implement register_done waiting via LD_AUDIT

[Alexander Monakov]

Hello,

I'm not aware of the context of this patch, but please note that the amount of
overhead from non-empty LD_AUDIT is currently extremely high in all released
Glibc versions.  The forced high overhead is, as I understand, misaligned with
LTTng's aim to provide low-overhead tracing.

Non-empty LD_AUDIT behaves as if one of auditing libraries provided PLT hooks.
This causes the dynamic linker to install register save-restore helpers for
each PLT call, even if they are not needed (if no PLT hooks were in fact
provided).

Here's the Glibc bug that shows a ~19x slowdown on a microbenchmark that
repeatedly calls sqrt() from libm.so.  The proposed patch was not accepted,
with the review suggesting a different approach.

https://sourceware.org/bugzilla/show_bug.cgi?id=15533

Could you explain the problem your patch aims to solve?  Sorry if it was
already explained elsewhere; please point me to the discussion in that case.

Alexander

Re: [RFC PATCH lttng-ust] Implement register_done waiting via LD_AUDIT

[Woegerer, Paul]

Hi Alexander,

The idea of this patch is to prevent deadlocks in the initialization
phase of lttng-ust when forks (e.g. for daemons) are happening in the
traced application.

lttng-ust uses a semaphore to block further execution of the program
until lttng-ust is fully initialized (see lttng-ust-comm.c:1496 in
lttng_ust_init() "switch (timeout_mode)"). The initialization of
lttng-ust happens in the ust_listener_thread that gets started from
lttng_ust_init(). If initialization is done the semaphore gets posted
(search for sem_post) and the static ctor lttng_ust_init() is able to
complete.

Unfortunately the current approach of delaying execution of main until
lttng-ust is available has several drawbacks. E.g. the dynamic linker
lock is taken during the execution the static ctor. Using glibc
functions that also require the same lock as part of the lttng-ust
initialization easily gets us into a deadlock situation.

This patch is trying to delay execution of main with a different
technique (using a named semaphore in la_preinit to wait for lttng-ust
initialization).


Note that this is not the only issue that prevents us from using
LD_AUDIT effectively for our own purposes:

https://sourceware.org/bugzilla/show_bug.cgi?id=11177#c8
prevents us from using my current patch e.g. to trace firefox (and other
applications that link against libicu*.so)

https://sourceware.org/bugzilla/show_bug.cgi?id=16592 prevents us from
using LD_AUDIT as a generic function enter/exit framework for public
functions (all glibc functions, glib, ....).

Having a stable LD_AUDIT interface would be extremely valuable in the
context of tracing. Unfortunately in it's current state it's just a nice
toy to play with.


HTH,
Paul


On 07/01/2014 05:19 PM, Alexander Monakov wrote:
> Hello,
> 
> I'm not aware of the context of this patch, but please note that the amount of
> overhead from non-empty LD_AUDIT is currently extremely high in all released
> Glibc versions.  The forced high overhead is, as I understand, misaligned with
> LTTng's aim to provide low-overhead tracing.
> 
> Non-empty LD_AUDIT behaves as if one of auditing libraries provided PLT hooks.
> This causes the dynamic linker to install register save-restore helpers for
> each PLT call, even if they are not needed (if no PLT hooks were in fact
> provided).
> 
> Here's the Glibc bug that shows a ~19x slowdown on a microbenchmark that
> repeatedly calls sqrt() from libm.so.  The proposed patch was not accepted,
> with the review suggesting a different approach.
> 
> https://sourceware.org/bugzilla/show_bug.cgi?id=15533
> 
> Could you explain the problem your patch aims to solve?  Sorry if it was
> already explained elsewhere; please point me to the discussion in that case.
> 
> Alexander
> 


-- 
Paul Woegerer, SW Development Engineer
Sourcery Analyzer <http://go.mentor.com/sourceryanalyzer>
Mentor Graphics, Embedded Software Division

Re: [RFC PATCH lttng-ust] Implement register_done waiting via LD_AUDIT

[Alexander Monakov]

On Tue, 1 Jul 2014, Woegerer, Paul wrote:
> Unfortunately the current approach of delaying execution of main until
> lttng-ust is available has several drawbacks. E.g. the dynamic linker
> lock is taken during the execution the static ctor. Using glibc
> functions that also require the same lock as part of the lttng-ust
> initialization easily gets us into a deadlock situation.

That's surprising; in my experience dlopen/dlsym from a static DSO ctor work,
so I wonder what functions are causing a deadlock for you.

> This patch is trying to delay execution of main with a different
> technique (using a named semaphore in la_preinit to wait for lttng-ust
> initialization).

Frankly I don't think LD_AUDIT is the right tool for the job in this case,
even ignoring its flakiness in glibc; better to fix your current approach if
possible.

> Having a stable LD_AUDIT interface would be extremely valuable in the
> context of tracing.

Oh, but the interface is extremely stable, it was unchanging for a long time
now; it's just the implementation... ;)  (sorry, could not resist)

Also note that LD_AUDIT on Linux is glibc-specific, not available on other
libcs that are otherwise quite useful, such as Bionic.

Alexander

Re: [RFC PATCH lttng-ust] Implement register_done waiting via LD_AUDIT

[Woegerer, Paul]

On 07/01/2014 07:14 PM, Alexander Monakov wrote:
> On Tue, 1 Jul 2014, Woegerer, Paul wrote:
>> Unfortunately the current approach of delaying execution of main until
>> lttng-ust is available has several drawbacks. E.g. the dynamic linker
>> lock is taken during the execution the static ctor. Using glibc
>> functions that also require the same lock as part of the lttng-ust
>> initialization easily gets us into a deadlock situation.
> 
> That's surprising; in my experience dlopen/dlsym from a static DSO ctor work,
> so I wonder what functions are causing a deadlock for you.

Base address state tracing, see liblttng-ust/lttng-ust-baddr.c:189

       dl_iterate_phdr(extract_soinfo_events, &data);

>> This patch is trying to delay execution of main with a different
>> technique (using a named semaphore in la_preinit to wait for lttng-ust
>> initialization).
> 
> Frankly I don't think LD_AUDIT is the right tool for the job in this case,
> even ignoring its flakiness in glibc; better to fix your current approach if
> possible.

This is just an RFC. I'm not saying it should be merged as it is. I just
want to discuss the situation so that we find a better solution.

The current approach is to delay the execution of the application by
putting a sem_wait into the static ctor of lttng-ust (lttng_ust_init).

If you gave a better idea how to make the application wait on the
initialization of lttng-ust (handle_register_done) that does not prevent
the static ctor from completing please share it with me.

>> Having a stable LD_AUDIT interface would be extremely valuable in the
>> context of tracing.
> 
> Oh, but the interface is extremely stable, it was unchanging for a long time
> now; it's just the implementation... ;)  (sorry, could not resist)

Being cynic won't help us either. I just saw your comments on
https://sourceware.org/bugzilla/show_bug.cgi?id=15533
It's a shame that your patch is not in mainline.

> Also note that LD_AUDIT on Linux is glibc-specific, not available on other
> libcs that are otherwise quite useful, such as Bionic.

That's a problem. I agree.


--
Thanks for your comments,
Paul


-- 
Paul Woegerer, SW Development Engineer
Sourcery Analyzer <http://go.mentor.com/sourceryanalyzer>
Mentor Graphics, Embedded Software Division

Re: [RFC PATCH lttng-ust] Implement register_done waiting via LD_AUDIT

[Mathieu Desnoyers]

----- Original Message -----
> From: "Alexander Monakov" <amonakov@ispras.ru>
> To: "Paul Woegerer" <Paul_Woegerer@mentor.com>
> Cc: lttng-dev@lists.lttng.org, "mathieu desnoyers" <mathieu.desnoyers@efficios.com>
> Sent: Tuesday, July 1, 2014 1:14:16 PM
> Subject: Re: [lttng-dev] [RFC PATCH lttng-ust] Implement register_done waiting via LD_AUDIT
> 
> On Tue, 1 Jul 2014, Woegerer, Paul wrote:
> > Unfortunately the current approach of delaying execution of main until
> > lttng-ust is available has several drawbacks. E.g. the dynamic linker
> > lock is taken during the execution the static ctor. Using glibc
> > functions that also require the same lock as part of the lttng-ust
> > initialization easily gets us into a deadlock situation.
> 
> That's surprising; in my experience dlopen/dlsym from a static DSO ctor work,
> so I wonder what functions are causing a deadlock for you.

It works because the glibc uses a nestable mutex internally. Unfortunately,
it does not cover our use-case. It can be summarized as this simplified list
of actions:

liblttng-ust constructor executes during application startup (or if lttng-ust is
dlopen'd):
  - spawns 2 lttng-ust listener threads (one for per-user, one for system-wide
    tracing),
  - Within each lttng-ust listener thread:
    - if we can connect to a session daemon, will await commands from the
      session daemon to setup tracing. At the end of the sequence of commands
      for application startup, the session daemon sends a "registration done"
      command.
    - When the registration done command is received, the thread posts the
      "constructor_wait" semaphore,
    - If the lttng-ust listener thread fails to connect to a session daemon,
      it posts the "constructor_wait" semaphore,
  - after having spawned the 2 lttng-ust listener threads, the liblttng-ust
    constructor waits on the "constructor_wait" semaphore, using the
    LTTNG_UST_REGISTER_TIMEOUT as a timeout (see lttng-ust(3)).

So if within the commands executed by the listener thread, we try to use
glibc functions that grab the dynamic loader lock (already being held while
calling constructors), we deadlock in this way:

  - constructor holding dl lock
    - constructor waiting on constructor_wait semaphore

  - listener thread trying to grab dl lock, which needs to be available
    before we can post the semaphore

The issue here is that nestable mutexes are good when a single thread is
trying to grab the same mutex in a nested fashion, but not when this
dependency is transitive through another lock or semaphore.

The reason why we wait on this "constructor_wait" semaphore is to ensure
that events traced at the beginning of the application are indeed traced.

> 
> > This patch is trying to delay execution of main with a different
> > technique (using a named semaphore in la_preinit to wait for lttng-ust
> > initialization).
> 
> Frankly I don't think LD_AUDIT is the right tool for the job in this case,
> even ignoring its flakiness in glibc; better to fix your current approach if
> possible.

Suggestions are very welcome. This issue is a real pain for us, and makes
it tricky to use glibc APIs related to the dynamic loader.

Thanks,

Mathieu

> 
> > Having a stable LD_AUDIT interface would be extremely valuable in the
> > context of tracing.
> 
> Oh, but the interface is extremely stable, it was unchanging for a long time
> now; it's just the implementation... ;)  (sorry, could not resist)
> 
> Also note that LD_AUDIT on Linux is glibc-specific, not available on other
> libcs that are otherwise quite useful, such as Bionic.
> 
> Alexander
> 

-- 
Mathieu Desnoyers
EfficiOS Inc.
http://www.efficios.com

Re: [RFC PATCH lttng-ust] Implement register_done waiting via LD_AUDIT

[Alexander Monakov]

Thanks Mathieu for such detailed response.  I did not understand the nature of
the deadlock until your explanation.

My suggestion for the immediate problem is: can you restructure the code so
that all preliminary work (connecting to the daemon etc.) is done directly
from the constructor before spawning the secondary thread?  So that you don't
have to suspend after launching the listener thread?  From your explanation it
looks like there's no particular reason to do that work in the listener
thread, except perhaps the convenience of programming (not needing to pass
around the socket, etc).

Admittedly the above is written from general principles, so I do apologize if
I'm not seeing some real LTTng-specific issues there and sound like an
armchair code analyst.

Apropos, and you might already know that: Glibc runs static constructors from
LD_PRELOAD'ed DSOs _after_ the ctors from libs loaded as dependencies.

Alexander

[RFC PATCH lttng-ust] Implement register_done waiting via LD_AUDIT

[Paul Woegerer]

Signed-off-by: Paul Woegerer <paul_woegerer@mentor.com>
---
 include/ust-comm.h                 |  34 +++++++++++++
 liblttng-ust/Makefile.am           |   5 +-
 liblttng-ust/lttng-ust-comm.c      | 100 +++++--------------------------------
 liblttng-ust/lttng-ust-startmain.c |  95 +++++++++++++++++++++++++++++++++++
 4 files changed, 145 insertions(+), 89 deletions(-)
 create mode 100644 liblttng-ust/lttng-ust-startmain.c

diff --git a/include/ust-comm.h b/include/ust-comm.h
index b9bbb39..b08892b 100644
--- a/include/ust-comm.h
+++ b/include/ust-comm.h
@@ -28,6 +28,7 @@
 
 #include <limits.h>
 #include <unistd.h>
+#include <stdio.h>
 #include <lttng/ust-abi.h>
 #include <lttng/ust-error.h>
 #include <lttng/ust-compiler.h>
@@ -238,4 +239,37 @@ int ustcomm_register_channel(int sock,
 int ustcomm_setsockopt_rcv_timeout(int sock, unsigned int msec);
 int ustcomm_setsockopt_snd_timeout(int sock, unsigned int msec);
 
+/*
+ * Get notify_sock timeout, in ms.
+ * -1: don't wait. 0: wait forever. >0: timeout, in ms.
+ */
+static inline
+long ustcomm_get_timeout(void)
+{
+	static const char *str_timeout;
+	static int got_timeout_env;
+
+	long constructor_delay_ms = LTTNG_UST_DEFAULT_CONSTRUCTOR_TIMEOUT_MS;
+
+	if (!got_timeout_env) {
+		str_timeout = getenv("LTTNG_UST_REGISTER_TIMEOUT");
+		got_timeout_env = 1;
+	}
+	if (str_timeout)
+		constructor_delay_ms = strtol(str_timeout, NULL, 10);
+	return constructor_delay_ms;
+}
+
+struct ustcomm_ctor_semname
+{
+	char name[NAME_MAX-4];
+};
+
+static inline
+const char *ustcomm_get_ctor_semname(struct ustcomm_ctor_semname *semname)
+{
+	snprintf(semname->name, sizeof(semname->name), "/lttng-ust-ctor_sem_%d", getpid());
+	return semname->name;
+}
+
 #endif	/* _LTTNG_UST_COMM_H */
diff --git a/liblttng-ust/Makefile.am b/liblttng-ust/Makefile.am
index e2e1baa..0c45f04 100644
--- a/liblttng-ust/Makefile.am
+++ b/liblttng-ust/Makefile.am
@@ -3,7 +3,7 @@ AM_CFLAGS = -fno-strict-aliasing
 
 noinst_LTLIBRARIES = liblttng-ust-runtime.la liblttng-ust-support.la
 
-lib_LTLIBRARIES = liblttng-ust-tracepoint.la liblttng-ust.la
+lib_LTLIBRARIES = liblttng-ust-startmain.la liblttng-ust-tracepoint.la liblttng-ust.la
 
 liblttng_ust_tracepoint_la_SOURCES = \
 	tracepoint.c \
@@ -66,6 +66,9 @@ liblttng_ust_support_la_SOURCES = \
 	lttng-ring-buffer-metadata-client.h \
 	lttng-ring-buffer-metadata-client.c
 
+liblttng_ust_startmain_la_SOURCES = \
+	lttng-ust-startmain.c
+
 liblttng_ust_la_SOURCES =
 
 liblttng_ust_la_LDFLAGS = -no-undefined -version-info $(LTTNG_UST_LIBRARY_VERSION)
diff --git a/liblttng-ust/lttng-ust-comm.c b/liblttng-ust/lttng-ust-comm.c
index 5df33f5..0d40c12 100644
--- a/liblttng-ust/lttng-ust-comm.c
+++ b/liblttng-ust/lttng-ust-comm.c
@@ -172,7 +172,7 @@ void ust_unlock(void)
  * - timeout (ensuring applications are resilient to session
  *   daemon problems).
  */
-static sem_t constructor_wait;
+static sem_t *ctor_sem_ptr;
 /*
  * Doing this for both the global and local sessiond.
  */
@@ -277,9 +277,6 @@ static const char *cmd_name_mapping[] = {
 	[ LTTNG_UST_EXCLUSION ] = "Add exclusions to event",
 };
 
-static const char *str_timeout;
-static int got_timeout_env;
-
 extern void lttng_ring_buffer_client_overwrite_init(void);
 extern void lttng_ring_buffer_client_overwrite_rt_init(void);
 extern void lttng_ring_buffer_client_discard_init(void);
@@ -374,64 +371,10 @@ int setup_local_apps(void)
 	return 0;
 }
 
-/*
- * Get notify_sock timeout, in ms.
- * -1: don't wait. 0: wait forever. >0: timeout, in ms.
- */
-static
-long get_timeout(void)
-{
-	long constructor_delay_ms = LTTNG_UST_DEFAULT_CONSTRUCTOR_TIMEOUT_MS;
-
-	if (!got_timeout_env) {
-		str_timeout = getenv("LTTNG_UST_REGISTER_TIMEOUT");
-		got_timeout_env = 1;
-	}
-	if (str_timeout)
-		constructor_delay_ms = strtol(str_timeout, NULL, 10);
-	return constructor_delay_ms;
-}
-
 static
 long get_notify_sock_timeout(void)
 {
-	return get_timeout();
-}
-
-/*
- * Return values: -1: don't wait. 0: wait forever. 1: timeout wait.
- */
-static
-int get_constructor_timeout(struct timespec *constructor_timeout)
-{
-	long constructor_delay_ms;
-	int ret;
-
-	constructor_delay_ms = get_timeout();
-
-	switch (constructor_delay_ms) {
-	case -1:/* fall-through */
-	case 0:
-		return constructor_delay_ms;
-	default:
-		break;
-	}
-
-	/*
-	 * If we are unable to find the current time, don't wait.
-	 */
-	ret = clock_gettime(CLOCK_REALTIME, constructor_timeout);
-	if (ret) {
-		return -1;
-	}
-	constructor_timeout->tv_sec += constructor_delay_ms / 1000UL;
-	constructor_timeout->tv_nsec +=
-		(constructor_delay_ms % 1000UL) * 1000000UL;
-	if (constructor_timeout->tv_nsec >= 1000000000UL) {
-		constructor_timeout->tv_sec++;
-		constructor_timeout->tv_nsec -= 1000000000UL;
-	}
-	return 1;
+	return ustcomm_get_timeout();
 }
 
 static
@@ -482,7 +425,7 @@ int handle_register_done(struct sock_info *sock_info)
 	}
 	ret = uatomic_add_return(&sem_count, -1);
 	if (ret == 0) {
-		ret = sem_post(&constructor_wait);
+		ret = sem_post(ctor_sem_ptr);
 		assert(!ret);
 	}
 	return 0;
@@ -1390,10 +1333,9 @@ void lttng_ust_malloc_wrapper_init(void)
  */
 void __attribute__((constructor)) lttng_ust_init(void)
 {
-	struct timespec constructor_timeout;
 	sigset_t sig_all_blocked, orig_parent_mask;
 	pthread_attr_t thread_attr;
-	int timeout_mode;
+
 	int ret;
 
 	if (uatomic_xchg(&initialized, 1) == 1)
@@ -1431,10 +1373,14 @@ void __attribute__((constructor)) lttng_ust_init(void)
 	 */
 	lttng_ust_malloc_wrapper_init();
 
-	timeout_mode = get_constructor_timeout(&constructor_timeout);
-
-	ret = sem_init(&constructor_wait, 0, 0);
-	assert(!ret);
+	if (!ctor_sem_ptr) {
+		struct ustcomm_ctor_semname semname;
+		ustcomm_get_ctor_semname(&semname);
+		ctor_sem_ptr = sem_open(semname.name, O_CREAT | O_EXCL, S_IRWXU, 0);
+		if (ctor_sem_ptr == SEM_FAILED) {
+			PERROR("sem_open");
+		}
+	}
 
 	ret = setup_local_apps();
 	if (ret) {
@@ -1492,28 +1438,6 @@ void __attribute__((constructor)) lttng_ust_init(void)
 	if (ret) {
 		ERR("pthread_sigmask: %s", strerror(ret));
 	}
-
-	switch (timeout_mode) {
-	case 1:	/* timeout wait */
-		do {
-			ret = sem_timedwait(&constructor_wait,
-					&constructor_timeout);
-		} while (ret < 0 && errno == EINTR);
-		if (ret < 0 && errno == ETIMEDOUT) {
-			ERR("Timed out waiting for lttng-sessiond");
-		} else {
-			assert(!ret);
-		}
-		break;
-	case -1:/* wait forever */
-		do {
-			ret = sem_wait(&constructor_wait);
-		} while (ret < 0 && errno == EINTR);
-		assert(!ret);
-		break;
-	case 0:	/* no timeout */
-		break;
-	}
 }
 
 static
diff --git a/liblttng-ust/lttng-ust-startmain.c b/liblttng-ust/lttng-ust-startmain.c
new file mode 100644
index 0000000..7602839
--- /dev/null
+++ b/liblttng-ust/lttng-ust-startmain.c
@@ -0,0 +1,95 @@
+#include <errno.h>
+#include <stdlib.h>
+#include <stdint.h>
+#include <stddef.h>
+#include <stdio.h>
+#include <fcntl.h>
+#include <sys/types.h>
+#include <assert.h>
+#include <unistd.h>
+#include <time.h>
+#include <fcntl.h>
+#include <sys/stat.h>
+#include <semaphore.h>
+
+#include <lttng/ust-ctl.h>
+#include <ust-comm.h>
+#include "usterr.h"
+
+/*
+ * Return values: -1: don't wait. 0: wait forever. 1: timeout wait.
+ */
+static
+int get_constructor_timeout(struct timespec *constructor_timeout)
+{
+	long constructor_delay_ms;
+	int ret;
+
+	constructor_delay_ms = ustcomm_get_timeout();
+
+	switch (constructor_delay_ms) {
+	case -1:/* fall-through */
+	case 0:
+		return constructor_delay_ms;
+	default:
+		break;
+	}
+
+	/*
+	 * If we are unable to find the current time, don't wait.
+	 */
+	ret = clock_gettime(CLOCK_REALTIME, constructor_timeout);
+	if (ret) {
+		return -1;
+	}
+	constructor_timeout->tv_sec += constructor_delay_ms / 1000UL;
+	constructor_timeout->tv_nsec +=
+		(constructor_delay_ms % 1000UL) * 1000000UL;
+	if (constructor_timeout->tv_nsec >= 1000000000UL) {
+		constructor_timeout->tv_sec++;
+		constructor_timeout->tv_nsec -= 1000000000UL;
+	}
+	return 1;
+}
+
+unsigned int la_version(unsigned int version) {
+	return version;
+}
+
+void la_preinit(uintptr_t *cookie) {
+	struct timespec constructor_timeout;
+	struct ustcomm_ctor_semname semname;
+	sem_t *ctor_sem_ptr;
+	int ret;
+
+	ctor_sem_ptr = sem_open(ustcomm_get_ctor_semname(&semname), 0, 0);
+	if (ctor_sem_ptr == SEM_FAILED) {
+		PERROR("sem_open");
+	}
+	ret = sem_unlink(semname.name);
+	if (ret == -1) {
+		PERROR("sem_unlink");
+	}
+
+	switch (get_constructor_timeout(&constructor_timeout)) {
+	case 1:	/* timeout wait */
+		do {
+			ret = sem_timedwait(ctor_sem_ptr,
+					&constructor_timeout);
+		} while (ret < 0 && errno == EINTR);
+		if (ret < 0 && errno == ETIMEDOUT) {
+			ERR("Timed out waiting for lttng-sessiond");
+		} else {
+			assert(!ret);
+		}
+		break;
+	case -1:/* wait forever */
+		do {
+			ret = sem_wait(ctor_sem_ptr);
+		} while (ret < 0 && errno == EINTR);
+		assert(!ret);
+		break;
+	case 0:	/* no timeout */
+		break;
+	}
+}
-- 
2.0.0