Christian Babeux | 28 Nov 22:39 2014

[PATCH lttng-ust] Fix: Shorthand option -cp not supported in all version of Java

Signed-off-by: Christian Babeux <christian.babeux <at> efficios.com>
---
 doc/examples/java-jul/Makefile           | 2 +-
 doc/examples/java-jul/run                | 2 +-
 doc/examples/java-log4j/Makefile         | 2 +-
 doc/examples/java-log4j/run              | 2 +-
 liblttng-ust-java-agent/java/Makefile.am | 4 ++--
 liblttng-ust-java/Makefile.am            | 2 +-
 6 files changed, 7 insertions(+), 7 deletions(-)

diff --git a/doc/examples/java-jul/Makefile b/doc/examples/java-jul/Makefile
index a45719d..1431b60 100644
--- a/doc/examples/java-jul/Makefile
+++ b/doc/examples/java-jul/Makefile
 <at>  <at>  -32,7 +32,7  <at>  <at>  else
 endif

 JFLAGS = -g
-JC = javac -cp "$(CLASSPATH):."
+JC = javac -classpath "$(CLASSPATH):."
 .SUFFIXES: .java .class
 .java.class:
 	$(JC) $(JFLAGS) $*.java
diff --git a/doc/examples/java-jul/run b/doc/examples/java-jul/run
index b8342f7..1beac85 100755
--- a/doc/examples/java-jul/run
+++ b/doc/examples/java-jul/run
 <at>  <at>  -19,6 +19,6  <at>  <at>  else
 	LIBPATH="/usr/local/lib:/usr/lib"
 fi
(Continue reading)

Eugene Ivanov | 28 Nov 10:36 2014

Question about URCU implementation: single global RCU "lock" VS per object RCU "locks"

Hi,

All RCU flavors seem to use single common global counter, thread list, etc (to be precisely it seems that rcu_*lock is a single per-process "lock"). So if I use multiple data structures, i.e. rculfhashes, I protect them via single shared RCU "lock". In case of QSBR it looks problematic: reclamation of objects from object A depends on QS of threads which use another objects. What is the reason of such design? Especially in comparison with per-object RCU primitives. Any performance implications?

--
Eugene
_______________________________________________
lttng-dev mailing list
lttng-dev <at> lists.lttng.org
http://lists.lttng.org/cgi-bin/mailman/listinfo/lttng-dev
Philippe Proulx | 27 Nov 23:35 2014
Picon

[PATCH lttng-tools] Fix: channel names are not validated

This patch ensures:

  1. A channel name does not contain any '/' character, since
     relative paths may be injected in the channel name
     otherwise (knowing that the channel name is eventually
     part of a file name)
  2. A channel name does not start with a '.' character, since
     trace readers (Babeltrace is one of them) could interpret
     files starting with a dot as hidden files and ignore
     them when opening the CTF trace

Fixes: #751

Signed-off-by: Philippe Proulx <eeppeliteloop <at> gmail.com>
---
 include/lttng/lttng-error.h              |  1 +
 src/bin/lttng-sessiond/cmd.c             |  6 ++++++
 src/bin/lttng/commands/enable_channels.c | 20 +++++++++++++++++---
 src/common/error.c                       |  1 +
 4 files changed, 25 insertions(+), 3 deletions(-)

diff --git a/include/lttng/lttng-error.h b/include/lttng/lttng-error.h
index 1220e48..efdca65 100644
--- a/include/lttng/lttng-error.h
+++ b/include/lttng/lttng-error.h
 <at>  <at>  -133,6 +133,7  <at>  <at>  enum lttng_error_code {
 	LTTNG_ERR_EXCLUSION_INVAL        = 110, /* Invalid event exclusion data */
 	LTTNG_ERR_EXCLUSION_NOMEM        = 111, /* Lack of memory while processing event exclusions */
 	LTTNG_ERR_INVALID_EVENT_NAME     = 112, /* Invalid event name */
+	LTTNG_ERR_INVALID_CHANNEL_NAME   = 113, /* Invalid channel name */

 	/* MUST be last element */
 	LTTNG_ERR_NR,                           /* Last element */
diff --git a/src/bin/lttng-sessiond/cmd.c b/src/bin/lttng-sessiond/cmd.c
index 33ab492..1ede96f 100644
--- a/src/bin/lttng-sessiond/cmd.c
+++ b/src/bin/lttng-sessiond/cmd.c
 <at>  <at>  -18,6 +18,7  <at>  <at> 
 #define _GNU_SOURCE
 #define _LGPL_SOURCE
 #include <assert.h>
+#include <string.h>
 #include <inttypes.h>
 #include <urcu/list.h>
 #include <urcu/uatomic.h>
 <at>  <at>  -944,6 +945,11  <at>  <at>  int cmd_enable_channel(struct ltt_session *session,
 	assert(attr);
 	assert(domain);

+	/* Validate channel name */
+	if (attr->name[0] == '.' || strchr(attr->name, '/') != NULL) {
+		return LTTNG_ERR_INVALID_CHANNEL_NAME;
+	}
+
 	DBG("Enabling channel %s for session %s", attr->name, session->name);

 	rcu_read_lock();
diff --git a/src/bin/lttng/commands/enable_channels.c b/src/bin/lttng/commands/enable_channels.c
index f8272e9..b49c20d 100644
--- a/src/bin/lttng/commands/enable_channels.c
+++ b/src/bin/lttng/commands/enable_channels.c
 <at>  <at>  -275,9 +275,16  <at>  <at>  static int enable_channel(char *session_name)
 	/* Strip channel list (format: chan1,chan2,...) */
 	channel_name = strtok(opt_channels, ",");
 	while (channel_name != NULL) {
-		/* Copy channel name and normalize it */
-		strncpy(chan.name, channel_name, NAME_MAX);
-		chan.name[NAME_MAX - 1] = '\0';
+		/* Validate channel name's length */
+		if (strlen(channel_name) >= NAME_MAX) {
+			ERR("Channel name is too long (max. %u characters)",
+			    NAME_MAX - 1);
+			error = 1;
+			goto skip_enable;
+		}
+
+		/* Copy channel name */
+		strcpy(chan.name, channel_name);

 		DBG("Enabling channel %s", channel_name);

 <at>  <at>  -292,6 +299,12  <at>  <at>  static int enable_channel(char *session_name)
 						lttng_strerror(ret), session_name);
 				warn = 1;
 				break;
+			case LTTNG_ERR_INVALID_CHANNEL_NAME:
+				ERR("Invalid channel name: \"%s\". "
+				    "Channel names may not start with '.', and "
+				    "may not contain '/'.", channel_name);
+				error = 1;
+				break;
 			default:
 				ERR("Channel %s: %s (session %s)", channel_name,
 						lttng_strerror(ret), session_name);
 <at>  <at>  -304,6 +317,7  <at>  <at>  static int enable_channel(char *session_name)
 			success = 1;
 		}

+skip_enable:
 		if (lttng_opt_mi) {
 			/* Mi print the channel element and leave it open */
 			ret = mi_lttng_channel(writer, &chan, 1);
diff --git a/src/common/error.c b/src/common/error.c
index 2cebbf9..d3e3b94 100644
--- a/src/common/error.c
+++ b/src/common/error.c
 <at>  <at>  -166,6 +166,7  <at>  <at>  static const char *error_string_array[] = {
 	[ ERROR_INDEX(LTTNG_ERR_MI_IO_FAIL) ] = "IO error while writing MI output",
 	[ ERROR_INDEX(LTTNG_ERR_MI_NOT_IMPLEMENTED) ] = "Mi feature not implemented",
 	[ ERROR_INDEX(LTTNG_ERR_INVALID_EVENT_NAME) ] = "Invalid event name",
+	[ ERROR_INDEX(LTTNG_ERR_INVALID_CHANNEL_NAME) ] = "Invalid channel name",

 	/* Last element */
 	[ ERROR_INDEX(LTTNG_ERR_NR) ] = "Unknown error code"
--

-- 
2.1.3
Francis Giraldeau | 27 Nov 22:55 2014
Picon

Python tracef() jams the interpreter on registration

I did a prototype of UST instrumentation to record all function entry/return of Python programs (works with CPython >= 3). 


Here is an example of the trace:

$ ./go.sh
...
[16:50:17.443042690] (+0.000053969) berta python:call: { cpu_id = 6 }, { co_name = "<module>" }
[16:50:17.443056837] (+0.000014147) berta python:call: { cpu_id = 6 }, { co_name = "cafe" }

It works when only the event python:call is enabled. When all events are enabled (lttng enable-event -a -u), then the python program hangs on a call to futex wait. It does not respond to CTRL-C signal, and must be killed. Here is the full stack trace in GDB, showing that it seems related to the registration of tracef() probe. Below that, there is the lttng-sessiond log. I reproduced the problem with lttng 2.5x stable and the git master. Any idea about what can go wrong? 

Thanks,

Francis

==========

Program received signal SIGSTOP, Stopped (signal).
0x00007ffff7bcaf2c in __lll_lock_wait () from /lib/x86_64-linux-gnu/libpthread.so.0
(gdb) bt
#0  0x00007ffff7bcaf2c in __lll_lock_wait () from /lib/x86_64-linux-gnu/libpthread.so.0
#1  0x00007ffff7bc6657 in _L_lock_909 () from /lib/x86_64-linux-gnu/libpthread.so.0
#2  0x00007ffff7bc6480 in pthread_mutex_lock () from /lib/x86_64-linux-gnu/libpthread.so.0
#3  0x00007ffff6102aec in ust_lock_nocheck () at lttng-ust-comm.c:150
#4  0x00007ffff61083a5 in lttng_probe_register (
    desc=0x7ffff633e9c0 <__probe_desc___lttng_ust_tracef>) at lttng-probes.c:204
#5  0x00007ffff60fc301 in __lttng_events_init__lttng_ust_tracef ()
    at ../include/lttng/ust-tracepoint-event.h:797
#6  0x00007ffff7dea13a in call_init (l=<optimized out>, argc=argc <at> entry=2, 
    argv=argv <at> entry=0x7fffffffdcf8, env=env <at> entry=0x7fffffffdd10) at dl-init.c:78
#7  0x00007ffff7dea223 in call_init (env=<optimized out>, argv=<optimized out>, 
    argc=<optimized out>, l=<optimized out>) at dl-init.c:36
#8  _dl_init (main_map=main_map <at> entry=0xafa730, argc=2, argv=0x7fffffffdcf8, env=0x7fffffffdd10)
    at dl-init.c:126
#9  0x00007ffff7deec70 in dl_open_worker (a=a <at> entry=0x7fffffffc1f8) at dl-open.c:577
#10 0x00007ffff7de9ff4 in _dl_catch_error (objname=objname <at> entry=0x7fffffffc1e8, 
    errstring=errstring <at> entry=0x7fffffffc1f0, mallocedp=mallocedp <at> entry=0x7fffffffc1e0, 
    operate=operate <at> entry=0x7ffff7dee9a0 <dl_open_worker>, args=args <at> entry=0x7fffffffc1f8)
    at dl-error.c:187
#11 0x00007ffff7dee3bb in _dl_open (
    file=0x7ffff6593f50 "./build/lib.linux-x86_64-3.4/lttngProfile.cpython-34m.so", 
    mode=-2147483646, caller_dlopen=<optimized out>, nsid=-2, argc=2, argv=0x7fffffffdcf8, 
    env=0x7fffffffdd10) at dl-open.c:661
#12 0x00007ffff75f302b in dlopen_doit (a=a <at> entry=0x7fffffffc410) at dlopen.c:66
#13 0x00007ffff7de9ff4 in _dl_catch_error (objname=0xadd910, errstring=0xadd918, mallocedp=0xadd908, 
    operate=0x7ffff75f2fd0 <dlopen_doit>, args=0x7fffffffc410) at dl-error.c:187
#14 0x00007ffff75f362d in _dlerror_run (operate=operate <at> entry=0x7ffff75f2fd0 <dlopen_doit>, 
    args=args <at> entry=0x7fffffffc410) at dlerror.c:163
#15 0x00007ffff75f30c1 in __dlopen (file=<optimized out>, mode=<optimized out>) at dlopen.c:87
#16 0x000000000050fa6e in _PyImport_GetDynLoadFunc ()
#17 0x0000000000580f2d in ?? ()
#18 0x000000000057b98a in PyEval_EvalFrameEx ()
#19 0x000000000057d3d3 in PyEval_EvalCodeEx ()
#20 0x000000000057bfaa in PyEval_EvalFrameEx ()
#21 0x000000000057d3d3 in PyEval_EvalCodeEx ()
#22 0x000000000057e0eb in ?? ()
#23 0x000000000043810a in PyObject_Call ()
#24 0x0000000000579616 in PyEval_EvalFrameEx ()
#25 0x000000000057d3d3 in PyEval_EvalCodeEx ()
#26 0x000000000057bfaa in PyEval_EvalFrameEx ()
#27 0x000000000057c0db in PyEval_EvalFrameEx ()
#28 0x000000000057c0db in PyEval_EvalFrameEx ()
#29 0x000000000057c0db in PyEval_EvalFrameEx ()
#30 0x000000000057d3d3 in PyEval_EvalCodeEx ()
#31 0x000000000057df80 in ?? ()
#32 0x000000000043810a in PyObject_Call ()
#33 0x000000000050c06b in _PyObject_CallMethodIdObjArgs ()
#34 0x00000000004bbda1 in PyImport_ImportModuleLevelObject ()
#35 0x00000000005fa00b in ?? ()
#36 0x000000000043810a in PyObject_Call ()
#37 0x00000000004367b8 in ?? ()
#38 0x0000000000578de9 in PyEval_EvalFrameEx ()
#39 0x000000000057d3d3 in PyEval_EvalCodeEx ()
#40 0x000000000060ba83 in PyRun_FileExFlags ()
#41 0x000000000060bc85 in PyRun_SimpleFileExFlags ()
#42 0x000000000060d3ac in Py_Main ()
#43 0x000000000041ec0d in main ()
(gdb) 

DEBUG1 - 16:56:11.529554 [21776/21781]: UST registration received with pid:21853 ppid:21833 uid:1000 gid:1000 sock:23 name:python3 (version 6.0) (in thread_registration_apps() at main.c:2084)
DEBUG1 - 16:56:11.529580 [21776/21781]: Futex n to 1 wake done (in futex_nto1_wake() at futex.c:105)
DEBUG1 - 16:56:11.529597 [21776/21781]: Accepting application registration (in thread_registration_apps() at main.c:1976)
DEBUG1 - 16:56:11.529601 [21776/21780]: Futex n to 1 wait done (in futex_nto1_wait() at futex.c:91)
DEBUG1 - 16:56:11.529631 [21776/21780]: Futex n to 1 prepare done (in futex_nto1_prepare() at futex.c:76)
DEBUG1 - 16:56:11.529640 [21776/21780]: Dispatching UST registration pid:21853 ppid:21833 uid:1000 gid:1000 sock:23 name:python3 (version 6.0) (in thread_dispatch_ust_registration() at main.c:1750)
DEBUG1 - 16:56:11.529619 [21776/21781]: UST registration received with pid:21853 ppid:21833 uid:1000 gid:1000 sock:30 name:python3 (version 6.0) (in thread_registration_apps() at main.c:2084)
DEBUG1 - 16:56:11.529662 [21776/21781]: Futex n to 1 wake done (in futex_nto1_wake() at futex.c:105)
DEBUG1 - 16:56:11.529669 [21776/21781]: Accepting application registration (in thread_registration_apps() at main.c:1976)
DEBUG3 - 16:56:11.529676 [21776/21780]: UST app creating application for socket 23 (in ust_app_create() at ust-app.c:2938)
DEBUG3 - 16:56:11.529690 [21776/21780]: Created hashtable size 4 at 0x7fbf0c000a10 of type 2 (in lttng_ht_new() at hashtable.c:128)
DEBUG3 - 16:56:11.529708 [21776/21780]: Created hashtable size 4 at 0x7fbf0c001150 of type 1 (in lttng_ht_new() at hashtable.c:128)
DEBUG1 - 16:56:11.529721 [21776/21780]: Dispatching UST registration pid:21853 ppid:21833 uid:1000 gid:1000 sock:30 name:python3 (version 6.0) (in thread_dispatch_ust_registration() at main.c:1750)
DEBUG3 - 16:56:11.529728 [21776/21780]: UST app notify socket 30 is set (in thread_dispatch_ust_registration() at main.c:1807)
DEBUG1 - 16:56:11.529740 [21776/21780]: App registered with pid:21853 ppid:21833 uid:1000 gid:1000 sock:23 name:python3 notify_sock:30 (version 6.0) (in ust_app_add() at ust-app.c:3026)
DEBUG2 - 16:56:11.529784 [21776/21780]: UST app global update for app sock 23 for session id 0 (in ust_app_global_update() at ust-app.c:4263)
DEBUG2 - 16:56:11.529809 [21776/21780]: UST app pid: 21853 session id 0 not found, creating it (in create_ust_app_session() at ust-app.c:1847)
DEBUG3 - 16:56:11.529812 [21776/21783]: UST thread notify added sock 30 to pollset (in ust_thread_manage_notify() at ust-thread.c:138)
DEBUG3 - 16:56:11.529836 [21776/21783]: [ust-thread] Manage notify polling on 3 fds (in ust_thread_manage_notify() at ust-thread.c:69)
DEBUG3 - 16:56:11.529826 [21776/21780]: Created hashtable size 4 at 0x7fbf0c002970 of type 0 (in lttng_ht_new() at hashtable.c:128)
DEBUG2 - 16:56:11.529859 [21776/21780]: Shadow copy of session handle -1 (in shadow_copy_session() at ust-app.c:1603)
DEBUG2 - 16:56:11.529877 [21776/21780]: Channel channel0 not found on shadow session copy, creating it (in shadow_copy_session() at ust-app.c:1653)
DEBUG3 - 16:56:11.529884 [21776/21780]: Created hashtable size 4 at 0x7fbf0c0032f0 of type 1 (in lttng_ht_new() at hashtable.c:128)
DEBUG3 - 16:56:11.529891 [21776/21780]: Created hashtable size 4 at 0x7fbf0c003a30 of type 0 (in lttng_ht_new() at hashtable.c:128)
DEBUG3 - 16:56:11.529897 [21776/21780]: UST app channel channel0 allocated (in alloc_ust_app_channel() at ust-app.c:883)
DEBUG2 - 16:56:11.529906 [21776/21780]: UST app shadow copy of channel channel0 started (in shadow_copy_channel() at ust-app.c:1530)
DEBUG2 - 16:56:11.529914 [21776/21780]: UST event * not found on shadow copy channel (in shadow_copy_channel() at ust-app.c:1570)
DEBUG3 - 16:56:11.529929 [21776/21780]: UST app event * allocated (in alloc_ust_app_event() at ust-app.c:939)
DEBUG3 - 16:56:11.529937 [21776/21780]: UST app shadow copy of channel channel0 done (in shadow_copy_channel() at ust-app.c:1580)
DEBUG3 - 16:56:11.529944 [21776/21780]: Buffer registry per UID find id: 0, ABI: 64, uid: 1000 (in buffer_reg_uid_find() at buffer-registry.c:196)
DEBUG3 - 16:56:11.529953 [21776/21780]: Created hashtable size 4 at 0x7fbf0c004580 of type 2 (in lttng_ht_new() at hashtable.c:128)
DEBUG3 - 16:56:11.529960 [21776/21780]: Buffer registry per UID created id: 0, ABI: 64, uid: 1000, domain: 2 (in buffer_reg_uid_create() at buffer-registry.c:145)
DEBUG3 - 16:56:11.529967 [21776/21780]: Buffer registry per UID adding to global registry with id: 0 (in buffer_reg_uid_add() at buffer-registry.c:167)
DEBUG3 - 16:56:11.529975 [21776/21780]: Created hashtable size 4 at 0x7fbf0c004d60 of type 2 (in lttng_ht_new() at hashtable.c:128)
DEBUG3 - 16:56:11.530013 [21776/21780]: Append to metadata: "typealias integer { size = 8; align = 8; signed = false; } := uint8_t;
typealias integer { size = 16; align = 8; signed = false; } := uint16_t;
typealias integer { size = 32; align = 8; signed = false; } := uint32_t;
typealias integer { size = 64; align = 8; signed = false; } := uint64_t;
typealias integer { size = 64; align = 8; signed = false; } := unsigned long;
typealias integer { size = 5; align = 1; signed = false; } := uint5_t;
typealias integer { size = 27; align = 1; signed = false; } := uint27_t;

trace {
major = 1;
minor = 8;
uuid = "54b830c0-b308-416b-98b8-a1dbd24a5c6c";
byte_order = le;
packet.header := struct {
uint32_t magic;
uint8_t  uuid[16];
uint32_t stream_id;
};
};

" (in lttng_metadata_printf() at ust-metadata.c:152)
DEBUG3 - 16:56:11.530114 [21776/21780]: Append to metadata: "env {
hostname = "berta";
domain = "ust";
tracer_name = "lttng-ust";
tracer_major = 2;
tracer_minor = 6;
" (in lttng_metadata_printf() at ust-metadata.c:152)
DEBUG3 - 16:56:11.530164 [21776/21780]: Append to metadata: "};

" (in lttng_metadata_printf() at ust-metadata.c:152)
DEBUG3 - 16:56:11.530176 [21776/21780]: Append to metadata: "clock {
name = monotonic;
" (in lttng_metadata_printf() at ust-metadata.c:152)
DEBUG3 - 16:56:11.530214 [21776/21780]: Append to metadata: " uuid = "929f2bc9-1726-4628-a617-66b2a2d84c0b";
" (in lttng_metadata_printf() at ust-metadata.c:152)
DEBUG3 - 16:56:11.530235 [21776/21780]: Append to metadata: " description = "Monotonic Clock";
freq = 1000000000; /* Frequency, in Hz */
/* clock value offset from Epoch is: offset * (1/freq) */
offset = 1409415126878138691;
};

" (in lttng_metadata_printf() at ust-metadata.c:152)
DEBUG3 - 16:56:11.530272 [21776/21780]: Append to metadata: "typealias integer {
size = 27; align = 1; signed = false;
map = clock.monotonic.value;
} := uint27_clock_monotonic_t;

typealias integer {
size = 32; align = 8; signed = false;
map = clock.monotonic.value;
} := uint32_clock_monotonic_t;

typealias integer {
size = 64; align = 8; signed = false;
map = clock.monotonic.value;
} := uint64_clock_monotonic_t;

" (in lttng_metadata_printf() at ust-metadata.c:152)
DEBUG3 - 16:56:11.530337 [21776/21780]: Append to metadata: "struct packet_context {
uint64_clock_monotonic_t timestamp_begin;
uint64_clock_monotonic_t timestamp_end;
uint64_t content_size;
uint64_t packet_size;
unsigned long events_discarded;
uint32_t cpu_id;
};

" (in lttng_metadata_printf() at ust-metadata.c:152)
DEBUG3 - 16:56:11.530387 [21776/21780]: Append to metadata: "struct event_header_compact {
enum : uint5_t { compact = 0 ... 30, extended = 31 } id;
variant <id> {
struct {
uint27_clock_monotonic_t timestamp;
} compact;
struct {
uint32_t id;
uint64_clock_monotonic_t timestamp;
} extended;
} v;
} align(8);

struct event_header_large {
enum : uint16_t { compact = 0 ... 65534, extended = 65535 } id;
variant <id> {
struct {
uint32_clock_monotonic_t timestamp;
} compact;
struct {
uint32_t id;
uint64_clock_monotonic_t timestamp;
} extended;
} v;
} align(8);

" (in lttng_metadata_printf() at ust-metadata.c:152)
DEBUG3 - 16:56:11.530549 [21776/21780]: UST app buffer registry per UID created successfully (in setup_buffer_reg_uid() at ust-app.c:1809)
DEBUG2 - 16:56:11.530608 [21776/21780]: UST app session created successfully with handle 1 (in create_ust_app_session() at ust-app.c:1915)
DEBUG1 - 16:56:11.530626 [21776/21780]: UST app creating channel channel0 with per UID buffers (in create_channel_per_uid() at ust-app.c:2508)
DEBUG3 - 16:56:11.530635 [21776/21780]: Buffer registry per UID find id: 0, ABI: 64, uid: 1000 (in buffer_reg_uid_find() at buffer-registry.c:196)
DEBUG2 - 16:56:11.530642 [21776/21780]: UST app creating buffer registry channel for channel0 (in create_buffer_reg_channel() at ust-app.c:2361)
DEBUG3 - 16:56:11.530649 [21776/21780]: Buffer registry channel create with key: 0 (in buffer_reg_channel_create() at buffer-registry.c:327)
DEBUG3 - 16:56:11.530658 [21776/21780]: Created hashtable size 4 at 0x7fbf0c0055b0 of type 0 (in lttng_ht_new() at hashtable.c:128)
DEBUG2 - 16:56:11.530671 [21776/21780]: Asking UST consumer for channel (in ask_channel_creation() at ust-consumer.c:119)
DEBUG3 - 16:56:11.530682 [21776/21780]: mkdir() recursive /home/francis/lttng-traces/auto-20141127-165611/ust/uid/1000/64-bit with mode 504 for uid 1000 and gid 1000 (in run_as_mkdir_recursive() at runas.c:309)
DEBUG1 - 16:56:11.530691 [21776/21780]: Using run_as_clone (in run_as() at runas.c:292)
DEBUG3 - 16:56:11.531579 [21776/21780]: UST registry channel finding key 0 (in ust_registry_channel_find() at ust-registry.c:490)
DEBUG2 - 16:56:11.557620 [21776/21780]: UST ask channel 1 successfully done with 8 stream(s) (in ask_channel_creation() at ust-consumer.c:196)
DEBUG2 - 16:56:11.557724 [21776/21780]: UST app stream 1 received successfully (in ust_consumer_get_channel() at ust-consumer.c:312)
DEBUG2 - 16:56:11.557754 [21776/21780]: UST app stream 2 received successfully (in ust_consumer_get_channel() at ust-consumer.c:312)
DEBUG2 - 16:56:11.557776 [21776/21780]: UST app stream 3 received successfully (in ust_consumer_get_channel() at ust-consumer.c:312)
DEBUG2 - 16:56:11.557796 [21776/21780]: UST app stream 4 received successfully (in ust_consumer_get_channel() at ust-consumer.c:312)
DEBUG2 - 16:56:11.557816 [21776/21780]: UST app stream 5 received successfully (in ust_consumer_get_channel() at ust-consumer.c:312)
DEBUG2 - 16:56:11.557838 [21776/21780]: UST app stream 6 received successfully (in ust_consumer_get_channel() at ust-consumer.c:312)
DEBUG2 - 16:56:11.557853 [21776/21780]: UST app stream 7 received successfully (in ust_consumer_get_channel() at ust-consumer.c:312)
DEBUG2 - 16:56:11.557867 [21776/21780]: UST app stream 8 received successfully (in ust_consumer_get_channel() at ust-consumer.c:312)
DEBUG3 - 16:56:11.557882 [21776/21780]: UST app consumer has no more stream available (in ust_consumer_get_channel() at ust-consumer.c:295)
DEBUG2 - 16:56:11.557893 [21776/21780]: UST app setup buffer registry channel for channel0 (in setup_buffer_reg_channel() at ust-app.c:2409)
DEBUG2 - 16:56:11.557902 [21776/21780]: UST app setup buffer registry stream (in setup_buffer_reg_streams() at ust-app.c:2316)
DEBUG3 - 16:56:11.557910 [21776/21780]: Buffer registry creating stream (in buffer_reg_stream_create() at buffer-registry.c:357)
DEBUG3 - 16:56:11.557920 [21776/21780]: Buffer registry creating stream (in buffer_reg_stream_create() at buffer-registry.c:357)
DEBUG3 - 16:56:11.557927 [21776/21780]: Buffer registry creating stream (in buffer_reg_stream_create() at buffer-registry.c:357)
DEBUG3 - 16:56:11.557935 [21776/21780]: Buffer registry creating stream (in buffer_reg_stream_create() at buffer-registry.c:357)
DEBUG3 - 16:56:11.557944 [21776/21780]: Buffer registry creating stream (in buffer_reg_stream_create() at buffer-registry.c:357)
DEBUG3 - 16:56:11.557951 [21776/21780]: Buffer registry creating stream (in buffer_reg_stream_create() at buffer-registry.c:357)
DEBUG3 - 16:56:11.557959 [21776/21780]: Buffer registry creating stream (in buffer_reg_stream_create() at buffer-registry.c:357)
DEBUG3 - 16:56:11.557968 [21776/21780]: Buffer registry creating stream (in buffer_reg_stream_create() at buffer-registry.c:357)
DEBUG1 - 16:56:11.557976 [21776/21780]: UST app sending buffer registry channel to ust sock 23 (in send_channel_uid_to_ust() at ust-app.c:2445)
DEBUG2 - 16:56:11.557988 [21776/21780]: UST app send channel to sock 23 pid 21853 (name: channel0, key: 0) (in ust_consumer_send_channel_to_ust() at ust-consumer.c:416)
DEBUG2 - 16:56:11.558248 [21776/21780]: UST consumer send stream to app 23 (in ust_consumer_send_stream_to_ust() at ust-consumer.c:381)
DEBUG2 - 16:56:11.558342 [21776/21780]: UST consumer send stream to app 23 (in ust_consumer_send_stream_to_ust() at ust-consumer.c:381)
DEBUG2 - 16:56:11.558400 [21776/21780]: UST consumer send stream to app 23 (in ust_consumer_send_stream_to_ust() at ust-consumer.c:381)
DEBUG2 - 16:56:11.558449 [21776/21780]: UST consumer send stream to app 23 (in ust_consumer_send_stream_to_ust() at ust-consumer.c:381)
DEBUG2 - 16:56:11.558487 [21776/21780]: UST consumer send stream to app 23 (in ust_consumer_send_stream_to_ust() at ust-consumer.c:381)
DEBUG2 - 16:56:11.558529 [21776/21780]: UST consumer send stream to app 23 (in ust_consumer_send_stream_to_ust() at ust-consumer.c:381)
DEBUG2 - 16:56:11.558567 [21776/21780]: UST consumer send stream to app 23 (in ust_consumer_send_stream_to_ust() at ust-consumer.c:381)
DEBUG2 - 16:56:11.558604 [21776/21780]: UST consumer send stream to app 23 (in ust_consumer_send_stream_to_ust() at ust-consumer.c:381)
DEBUG2 - 16:56:11.558672 [21776/21780]: UST app event * created successfully for pid:21853 (in create_ust_event() at ust-app.c:1429)
DEBUG2 - 16:56:11.558703 [21776/21780]: UST app event * enabled successfully for app (pid: 21853) (in enable_ust_event() at ust-app.c:1341)
DEBUG1 - 16:56:11.558713 [21776/21780]: Starting tracing for ust app pid 21853 (in ust_app_start_trace() at ust-app.c:3832)
DEBUG3 - 16:56:11.558723 [21776/21780]: mkdir() recursive /home/francis/lttng-traces/auto-20141127-165611 with mode 504 for uid 1000 and gid 1000 (in run_as_mkdir_recursive() at runas.c:309)
DEBUG1 - 16:56:11.558733 [21776/21780]: Using run_as_clone (in run_as() at runas.c:292)
DEBUG3 - 16:56:11.559632 [21776/21780]: Buffer registry per UID find id: 0, ABI: 64, uid: 1000 (in buffer_reg_uid_find() at buffer-registry.c:196)
DEBUG3 - 16:56:11.559663 [21776/21780]: Created hashtable size 4 at 0x7fbf0c008ed0 of type 1 (in lttng_ht_new() at hashtable.c:128)
DEBUG3 - 16:56:11.559676 [21776/21780]: Created hashtable size 4 at 0x7fbf0c009800 of type 0 (in lttng_ht_new() at hashtable.c:128)
DEBUG3 - 16:56:11.559684 [21776/21780]: UST app channel metadata allocated (in alloc_ust_app_channel() at ust-app.c:883)
DEBUG2 - 16:56:11.559696 [21776/21780]: Asking UST consumer for channel (in ask_channel_creation() at ust-consumer.c:119)
DEBUG3 - 16:56:11.559710 [21776/21780]: mkdir() recursive /home/francis/lttng-traces/auto-20141127-165611/ust/uid/1000/64-bit with mode 504 for uid 1000 and gid 1000 (in run_as_mkdir_recursive() at runas.c:309)
DEBUG1 - 16:56:11.559720 [21776/21780]: Using run_as_clone (in run_as() at runas.c:292)
DEBUG2 - 16:56:11.561817 [21776/21780]: UST ask channel 2 successfully done with 1 stream(s) (in ask_channel_creation() at ust-consumer.c:196)
DEBUG2 - 16:56:11.561860 [21776/21780]: Consumer setup metadata channel key 2 (in consumer_setup_metadata() at consumer.c:1206)
DEBUG2 - 16:56:11.561916 [21776/21780]: UST metadata with key 2 created for app pid 21853 (in create_ust_app_metadata() at ust-app.c:2890)
DEBUG3 - 16:56:11.561932 [21776/21780]: UST app deleting channel metadata (in delete_ust_app_channel() at ust-app.c:375)
DEBUG3 - 16:56:11.562035 [21776/21777]: [ht-thread] Polling on 2 fds. (in thread_ht_cleanup() at ht-cleanup.c:65)
DEBUG3 - 16:56:11.562066 [21776/21777]: [ht-thread] Polling on 2 fds. (in thread_ht_cleanup() at ht-cleanup.c:65)
DEBUG3 - 16:56:11.562051 [21776/21783]: UST app receiving notify from sock 30 (in ust_app_recv_notify() at ust-app.c:4820)
DEBUG2 - 16:56:11.562103 [21776/21783]: UST app ustctl register channel received (in ust_app_recv_notify() at ust-app.c:4873)
DEBUG3 - 16:56:11.562118 [21776/21783]: Buffer registry per UID find id: 0, ABI: 64, uid: 1000 (in buffer_reg_uid_find() at buffer-registry.c:196)
DEBUG3 - 16:56:11.562131 [21776/21783]: UST registry channel finding key 0 (in ust_registry_channel_find() at ust-registry.c:490)
DEBUG3 - 16:56:11.562159 [21776/21783]: Append to metadata: "stream {
id = 0;
event.header := struct event_header_compact;
packet.context := struct packet_context;
" (in lttng_metadata_printf() at ust-metadata.c:152)
DEBUG3 - 16:56:11.562194 [21776/21783]: Append to metadata: "};

" (in lttng_metadata_printf() at ust-metadata.c:152)
DEBUG3 - 16:56:11.562209 [21776/21783]: UST app replying to register channel key 0 with id 0, type: 1, ret: 0 (in reply_ust_register_channel() at ust-app.c:4686)
DEBUG3 - 16:56:11.562223 [21776/21783]: [ust-thread] Manage notify polling on 3 fds (in ust_thread_manage_notify() at ust-thread.c:69)
DEBUG3 - 16:56:11.562265 [21776/21783]: UST app receiving notify from sock 30 (in ust_app_recv_notify() at ust-app.c:4820)
DEBUG2 - 16:56:11.562278 [21776/21783]: UST app ustctl register event received (in ust_app_recv_notify() at ust-app.c:4840)
DEBUG3 - 16:56:11.562296 [21776/21783]: Buffer registry per UID find id: 0, ABI: 64, uid: 1000 (in buffer_reg_uid_find() at buffer-registry.c:196)
DEBUG3 - 16:56:11.562306 [21776/21783]: UST registry channel finding key 0 (in ust_registry_channel_find() at ust-registry.c:490)
DEBUG3 - 16:56:11.562314 [21776/21783]: UST registry creating event with event: ust_baddr_statedump:soinfo, sig: struct lttng_session *, session, void *, baddr, const char*, sopath, int64_t, size, int64_t, mtime, id: 0, chan_objd: 2, sess_objd: 1, chan_id: 0 (in ust_registry_create_event() at ust-registry.c:299)
DEBUG3 - 16:56:11.562326 [21776/21783]: Append to metadata: "event {
name = "ust_baddr_statedump:soinfo";
id = 0;
stream_id = 0;
" (in lttng_metadata_printf() at ust-metadata.c:152)
DEBUG3 - 16:56:11.562360 [21776/21783]: Append to metadata: " loglevel = 13;
" (in lttng_metadata_printf() at ust-metadata.c:152)
DEBUG3 - 16:56:11.562378 [21776/21783]: Append to metadata: " fields := struct {
" (in lttng_metadata_printf() at ust-metadata.c:152)
DEBUG3 - 16:56:11.562397 [21776/21783]: Append to metadata: " integer { size = 64; align = 8; signed = 0; encoding = none; base = 16; } _baddr;
" (in lttng_metadata_printf() at ust-metadata.c:152)
DEBUG3 - 16:56:11.562418 [21776/21783]: Append to metadata: " string _sopath;
" (in lttng_metadata_printf() at ust-metadata.c:152)
DEBUG3 - 16:56:11.562439 [21776/21783]: Append to metadata: " integer { size = 64; align = 8; signed = 1; encoding = none; base = 10; } _size;
" (in lttng_metadata_printf() at ust-metadata.c:152)
DEBUG3 - 16:56:11.562460 [21776/21783]: Append to metadata: " integer { size = 64; align = 8; signed = 1; encoding = none; base = 10; } _mtime;
" (in lttng_metadata_printf() at ust-metadata.c:152)
DEBUG3 - 16:56:11.562480 [21776/21783]: Append to metadata: " };
};

" (in lttng_metadata_printf() at ust-metadata.c:152)
DEBUG3 - 16:56:11.562508 [21776/21783]: UST registry event ust_baddr_statedump:soinfo with id 0 added successfully (in add_event_ust_registry() at ust-app.c:4801)
DEBUG3 - 16:56:11.562518 [21776/21783]: [ust-thread] Manage notify polling on 3 fds (in ust_thread_manage_notify() at ust-thread.c:69)
DEBUG2 - 16:56:11.562570 [21776/21780]: UST trace started for app pid 21853 (in ust_app_global_update() at ust-app.c:4337)
DEBUG1 - 16:56:11.562633 [21776/21780]: Woken up but nothing in the UST command queue (in thread_dispatch_ust_registration() at main.c:1738)
DEBUG1 - 16:56:11.562645 [21776/21780]: Futex n to 1 wait done (in futex_nto1_wait() at futex.c:91)
DEBUG1 - 16:56:11.562656 [21776/21780]: Futex n to 1 prepare done (in futex_nto1_prepare() at futex.c:76)
DEBUG1 - 16:56:11.562667 [21776/21780]: Woken up but nothing in the UST command queue (in thread_dispatch_ust_registration() at main.c:1738)
DEBUG1 - 16:56:11.562648 [21776/21782]: Apps with sock 23 added to poll set (in thread_manage_apps() at main.c:1520)
DEBUG1 - 16:56:11.562703 [21776/21782]: Apps thread polling on 3 fds (in thread_manage_apps() at main.c:1459)

_______________________________________________
lttng-dev mailing list
lttng-dev <at> lists.lttng.org
http://lists.lttng.org/cgi-bin/mailman/listinfo/lttng-dev
Anand Neeli | 27 Nov 12:31 2014
Picon

not able to read 32-bit app traces running on a 64-bit system with relayd

Hi All,
I'm running both 32-bit and 64-bit app's on a 64-bit system.  I have consumerd's build for both 32-bit and 64-bits (followed http://lttng.org/docs/#doc-instrumenting-32-bit-app-on-64-bit-system)

I'm seeing problem in reading 32-bit app traces, although it is logging something and logfile size in lttng-traces/ is increasing.
I have compiled same app for 64-bit and it works fine.

One more point here is that, this happens only when relaying traces. Without using relayd and by using local tracing i dont see any issues.

Attached are the logs from 32-bit and 64-bit app's. There sizes are same except the files in index/

I'm using 2.4.1 lttng and tried 1.2.0 and 1.2.1 version of babeltrace. 

Can anyone please tell me how can i avoid this problem. 

Thanks,
Anand Neeli
_______________________________________________
lttng-dev mailing list
lttng-dev <at> lists.lttng.org
http://lists.lttng.org/cgi-bin/mailman/listinfo/lttng-dev
Philippe Proulx | 27 Nov 04:32 2014
Picon

[lttng-tools] Fix: channel name with '.' and '/' brings problems

This patch ensures:

  1. A channel name does not contain any '/' character, since
     relative paths may be injected in the channel name
     otherwise (knowing that the channel name is eventually
     part of a file name)
  2. A channel name does not start with a '.' character, since
     trace readers (Babeltrace is one of them) could interpret
     files starting with a dot as hidden files and ignore
     them when opening the CTF trace

Fixes: #751

Signed-off-by: Philippe Proulx <eeppeliteloop <at> gmail.com>
---
 src/bin/lttng/commands/enable_channels.c | 38 +++++++++++++++++++++++++++-----
 1 file changed, 33 insertions(+), 5 deletions(-)

diff --git a/src/bin/lttng/commands/enable_channels.c b/src/bin/lttng/commands/enable_channels.c
index f8272e9..e6cce49 100644
--- a/src/bin/lttng/commands/enable_channels.c
+++ b/src/bin/lttng/commands/enable_channels.c
 <at>  <at>  -275,11 +275,39  <at>  <at>  static int enable_channel(char *session_name)
 	/* Strip channel list (format: chan1,chan2,...) */
 	channel_name = strtok(opt_channels, ",");
 	while (channel_name != NULL) {
-		/* Copy channel name and normalize it */
+		/* Copy channel name, sanitize and normalize it */
 		strncpy(chan.name, channel_name, NAME_MAX);
 		chan.name[NAME_MAX - 1] = '\0';

-		DBG("Enabling channel %s", channel_name);
+		char *src, *dst;
+		int got_first = 0;
+
+		for (src = dst = chan.name; *src != '\0'; ++src) {
+			*dst = *src;
+
+			/*
+			 * Channel name could be used in file names, so remove
+			 * invalid '/'
+			 */
+			if (*dst != '/') {
+				/*
+				 * Remove starting dots since this could create
+				 * file names starting with dots, and trace
+				 * readers could interpret them as hidden files
+				 * and ignore them.
+				 */
+				if (*dst != '.') {
+					got_first = 1;
+					dst++;
+				} else if (got_first) {
+					dst++;
+				}
+			}
+		}
+
+		*dst = '\0';
+
+		DBG("Enabling channel %s", chan.name);

 		ret = lttng_enable_channel(handle, &chan);
 		if (ret < 0) {
 <at>  <at>  -288,19 +316,19  <at>  <at>  static int enable_channel(char *session_name)
 			case LTTNG_ERR_KERN_CHAN_EXIST:
 			case LTTNG_ERR_UST_CHAN_EXIST:
 			case LTTNG_ERR_CHAN_EXIST:
-				WARN("Channel %s: %s (session %s)", channel_name,
+				WARN("Channel %s: %s (session %s)", chan.name,
 						lttng_strerror(ret), session_name);
 				warn = 1;
 				break;
 			default:
-				ERR("Channel %s: %s (session %s)", channel_name,
+				ERR("Channel %s: %s (session %s)", chan.name,
 						lttng_strerror(ret), session_name);
 				error = 1;
 				break;
 			}
 		} else {
 			MSG("%s channel %s enabled for session %s",
-					get_domain_str(dom.type), channel_name, session_name);
+					get_domain_str(dom.type), chan.name, session_name);
 			success = 1;
 		}

--

-- 
2.1.3
Philippe Proulx | 26 Nov 22:50 2014
Picon

[lttng-ust] Fix: man: you can't link a lib with a static lib

Fixes: #825

Signed-off-by: Philippe Proulx <eeppeliteloop <at> gmail.com>
---
 doc/man/lttng-ust.3 | 14 +++++---------
 1 file changed, 5 insertions(+), 9 deletions(-)

diff --git a/doc/man/lttng-ust.3 b/doc/man/lttng-ust.3
index 0c8405f..3d52bc0 100644
--- a/doc/man/lttng-ust.3
+++ b/doc/man/lttng-ust.3
 <at>  <at>  -299,17 +299,13  <at>  <at>  There are 2 ways to compile the Tracepoint Provider with the
 application: either statically or dynamically. Please follow
 carefully:

-  1.1) Compile the Tracepoint provider with the application, either
-       directly or through a static library (.a):
-    - Into exactly one object of your application: define
+  1) Compile the Tracepoint Provider with the application, either
+     directly or through a static library (.a):
+    - Into exactly one object of your application, define
       "TRACEPOINT_DEFINE" and include the tracepoint provider.
     - Use "\-I." for the compilation unit containing the tracepoint
-      provider include (e.g. tp.c).
-    - Link application with "\-ldl".
-    - If building the provider directly into the application,
-      link the application with "\-llttng-ust".
-    - If building a static library for the provider, link the static
-      library with "\-llttng-ust".
+      provider include (e.g., tp.c).
+    - Link the application with "\-llttng-ust" and "\-ldl".
     - Include the tracepoint provider header into all C files using
       the provider.
     - Examples:
--

-- 
2.1.3
Philippe Proulx | 26 Nov 22:29 2014
Picon

[lttng-tools 0/2] Fix various polling loops when using poll()

When disabling epoll (--disable-epoll), poll() is used instead of
epoll_wait() thanks to the compat layer. While epoll_wait() only returns
the file descriptors that are ready, with poll() you need to check all
file descriptors and process only those which have revents flags.

This patchset fixes a few of those polling loops in LTTng-tools where
it is assumed that revents is not 0 (epoll_wait() behaviour).

Philippe Proulx (2):
  Fix: sessiond: revents may be 0 when using poll()
  Fix: relayd: revents may be 0 when using poll()

 src/bin/lttng-relayd/main.c         |  5 +++++
 src/bin/lttng-sessiond/ht-cleanup.c |  5 +++++
 src/bin/lttng-sessiond/main.c       | 10 ++++++++++
 src/bin/lttng-sessiond/ust-thread.c |  5 +++++
 4 files changed, 25 insertions(+)

--
2.1.3
Mathieu Desnoyers | 26 Nov 20:59 2014

[GIT PULL] out of memory handling fix branch

Hi Jérémie,

Please pull from:

https://github.com/compudj/lttng-tools-dev/tree/fix-oom-handling-pull

The top commit is:

commit e752224d5c12bdb52932989b0bce09f6971928a2

Thanks!

Mathieu

--

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

_______________________________________________
lttng-dev mailing list
lttng-dev <at> lists.lttng.org
http://lists.lttng.org/cgi-bin/mailman/listinfo/lttng-dev
Francis Giraldeau | 26 Nov 18:24 2014
Picon

lttng-modules addons stable (sort of)

After the LinuxCon event, some people were interested to install the addons for LTTng to perform active path analysis and virtual machine experiments. I did a clean rebase on master (with a linear log), and kept only stable features for this purpose. 

* Record part of TCPv4 header using netfilter hook
  * inet_sock_local_in
  * inet_sock_local_out

* Wake-up signal between task (tracepoint before the wakeup IPI)
  * sched_ttwu

* KVM virtual machine synchronization
  * vmsync_gh_guest
  * vmsync_gh_host
  * vmsync_hg_guest
  * vmsync_hg_host

Features *removed* from the addons stable branch: 
  * lttng_statedump_inet_sock: list of opened sockets at trace start
  * inet_sock_clone, inet_sock_create, inet_sock_delete: these were too hackish (required to overload the IPv4 socket family and a couple of kprobes)
  * syscall_entry (single event, with syscall id as the only field)
  * per-context callstack for user/kernel: unstable, requires more love (along with mmap_exec_file event)

I would like to thanks the following contributors: 
  * Mathieu Desnoyers: valuable advices and reviews
  * Mohamad Gebai: vmsync instrumentation
  * Geneviève Bastien: testing, fixes and improvements
  * François Doray: porting instrumentation to newer macros

Further development will occur in addons-staging, to keep the addons branch stable. If you find any issue with the addons, you can fill an issue on github. 


Cheers,

Francis
_______________________________________________
lttng-dev mailing list
lttng-dev <at> lists.lttng.org
http://lists.lttng.org/cgi-bin/mailman/listinfo/lttng-dev
fmahn | 26 Nov 17:59 2014
Picon

instrumenting "tutorial" and RTAI


Hello, right now I am reading the LTTng documentation and I am at the  
point with the "tutorial" for adding a tracepoint to the  
usb_probe_device(). I updated the files as instructed, rebuilt the  
kernel and bootet it, but the "/sys/kernel/debug/tracing/events/hello"  
directory wasnt created. It exists up to the debug directory, but the  
directory itself is empty. What could have gone wrong? Is this  
directory necessary? I still followed the other instructions and I was  
able to trace the USB event but I am curios about the directory.
Furthermore, I am planning to instrument an RTAI kernel (for my  
Bachelorthesis), so I can trace it with LTTng. Is it even possible  
with these methods?

Thank you for your time!

PS:
I am using an RTAI patched 2.6.38.8 linux kernel with debian

Gmane