Project

General

Profile

Actions
Copy link

Bug #142

closed

Python application freeze when registering to sessiond

Added by Yannick Brosseau almost 13 years ago. Updated almost 13 years ago.

Status:
Resolved
Priority:
Critical
Assignee:
Mathieu Desnoyers
Target version:
LTTng - 2.0 stable
Start date:
03/01/2012
Due date:
% Done:

0%

Estimated time:

Description

A python application freeze when we try to start it.

We get the following error message on the console:
libust[11028/11028]: Error: Timed out waiting for ltt-sessiond (in lttng_ust_init() at lttng-ust-comm.c:873)

The corresponding output of lttng-sessiond -vvv:

DEBUG1: Accepting client command ... [in thread_manage_clients() at main.c:3627]
DEBUG1: UST registration received with pid:11028 ppid:11027 uid:0 gid:0 sock:19 name:python (version 2.0) [in thread_registration_apps() at main.c:1392]
DEBUG1: Futex n to 1 wake done [in futex_nto1_wake() at futex.c:101]
DEBUG1: Accepting application registration [in thread_registration_apps() at main.c:1322]
DEBUG1: Futex n to 1 wait done [in futex_nto1_wait() at futex.c:88]
DEBUG1: Futex n to 1 prepare done [in futex_nto1_prepare() at futex.c:74]
DEBUG1: Dispatching UST registration pid:11028 ppid:11027 uid:0 gid:0 sock:19 name:python (version 2.0) [in thread_dispatch_ust_registration() at main.c:1245]
DEBUG1: Woken up but nothing in the UST command queue [in thread_dispatch_ust_registration() at main.c:1233]
DEBUG3: Created hashtable size 4 at 0x21ba4b0 of type 1 [in lttng_ht_new() at hashtable.c:96]
DEBUG1: App registered with pid:11028 ppid:11027 uid:0 gid:0 sock:19 name:python (version 2.0) [in ust_app_register() at ust-app.c:1317]
DEBUG2: UST app PID 11028 is compatible with major version 2 (supporting <= 2) [in ust_app_validate_version() at ust-app.c:2562]
DEBUG2: UST app global update for app sock 19 for session id 1 [in ust_app_global_update() at ust-app.c:2232]
DEBUG2: UST app pid: 11028 session id 1 not found, creating it [in create_ust_app_session() at ust-app.c:855]
DEBUG3: Created hashtable size 4 at 0x21bb7b0 of type 0 [in lttng_ht_new() at hashtable.c:96]
DEBUG2: Shadow copy of session handle -1 [in shadow_copy_session() at ust-app.c:766]
DEBUG2: Channel channel0 not found on shadow session copy, creating it [in shadow_copy_session() at ust-app.c:795]
DEBUG3: Created hashtable size 4 at 0x21bc5c0 of type 1 [in lttng_ht_new() at hashtable.c:96]
DEBUG3: Created hashtable size 4 at 0x21bc860 of type 0 [in lttng_ht_new() at hashtable.c:96]
DEBUG3: UST app channel channel0 allocated [in alloc_ust_app_channel() at ust-app.c:281]
DEBUG2: UST app shadow copy of channel channel0 started [in shadow_copy_channel() at ust-app.c:706]
DEBUG2: UST event * not found on shadow copy channel [in shadow_copy_channel() at ust-app.c:733]
DEBUG3: Created hashtable size 4 at 0x21bce90 of type 1 [in lttng_ht_new() at hashtable.c:96]
DEBUG3: UST app event * allocated [in alloc_ust_app_event() at ust-app.c:316]
DEBUG3: UST app shadow copy of channel channel0 done [in shadow_copy_channel() at ust-app.c:743]

Files

Download all files
sample_tracepoint_python.c (736 Bytes) sample_tracepoint_python.c Yannick Brosseau, 03/01/2012 10:43 AM
sample.py (97 Bytes) sample.py Yannick Brosseau, 03/01/2012 10:43 AM
setup.py (384 Bytes) setup.py Yannick Brosseau, 03/01/2012 10:43 AM
sample_tracepoint.h (709 Bytes) sample_tracepoint.h Yannick Brosseau, 03/01/2012 10:43 AM
Actions
Copy link Download all files
 #1

Updated by Yannick Brosseau almost 13 years ago

To compile and install the python module:
python setup.py build
python setup.py install

and run the sample.py script

Actions
Copy link
 #2

Updated by Yannick Brosseau almost 13 years ago

Voila l'ouput LTTNG_UST_DEBUG=1 de l'application:

LTTNG_UST_DEBUG=1 python sample.py 
libust[11936/11936]: LTT : ltt ring buffer client init
 (in ltt_ring_buffer_metadata_client_init() at ltt-ring-buffer-metadata-client.h:318)
libust[11936/11936]: LTT : ltt ring buffer client init
 (in ltt_ring_buffer_client_overwrite_init() at ltt-ring-buffer-client.h:575)
libust[11936/11936]: LTT : ltt ring buffer client init
 (in ltt_ring_buffer_client_discard_init() at ltt-ring-buffer-client.h:575)
libust[11936/11937]: Info: sessiond not accepting connections to local apps socket (in ust_listener_thread() at lttng-ust-comm.c:688)
libust[11936/11937]: Waiting for local apps sessiond (in wait_for_sessiond() at lttng-ust-comm.c:610)
libust[11936/11938]: message received
 (in ust_listener_thread() at lttng-ust-comm.c:755)
libust[11936/11938]: message successfully sent (in send_reply() at lttng-ust-comm.c:201)
libust[11936/11938]: message received
 (in ust_listener_thread() at lttng-ust-comm.c:755)
libust[11936/11936]: Error: Timed out waiting for ltt-sessiond (in lttng_ust_init() at lttng-ust-comm.c:873)
Actions
Copy link
 #3

Updated by Yannick Brosseau almost 13 years ago

Output d'un strace:

access("/etc/ld.so.nohwcap", F_OK) = -1 ENOENT (No such file or directory)
open("/usr/local/lib/liburcu-common.so.1", O_RDONLY) = 4
read(4, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\200\10\0\0\0\0\0\0"..., 832) = 832
fstat(4, {st_mode=S_IFREG|0755, st_size=21927, ...}) = 0
mmap(NULL, 2101928, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 4, 0) = 0x7f406b03a000
mprotect(0x7f406b03c000, 2093056, PROT_NONE) = 0
mmap(0x7f406b23b000, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 4, 0x1000) = 0x7f406b23b000
close(4) = 0
mprotect(0x7f406b43f000, 4096, PROT_READ) = 0
mprotect(0x7f406b84d000, 4096, PROT_READ) = 0
mprotect(0x7f406be82000, 4096, PROT_READ) = 0
getuid() = 1000
geteuid() = 1000
mmap(NULL, 8392704, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_STACK, -1, 0) = 0x7f406a839000
mprotect(0x7f406a839000, 4096, PROT_NONE) = 0
clone(child_stack=0x7f406b038ff0, flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID, parent_tidptr=0x7f406b0399d0, tls=0x7f406b039700, child_tidptr=0x7f406b0399d0) = 12013
mmap(NULL, 8392704, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_STACK, -1, 0) = 0x7f406a038000
mprotect(0x7f406a038000, 4096, PROT_NONE) = 0
clone(child_stack=0x7f406a837ff0, flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID, parent_tidptr=0x7f406a8389d0, tls=0x7f406a838700, child_tidptr=0x7f406a8389d0) = 12014
futex(0x7f406bc80600, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 0, {1330617358, 497533513}, ffffffff) = -1 ETIMEDOUT (Connection timed out)
gettid() = 12012
write(2, "libust[12012/12012]: Error: Time"..., 109libust[12012/12012]: Error: Timed out waiting for ltt-sessiond (in lttng_ust_init() at lttng-ust-comm.c:873)
) = 109
futex(0x7f406bc806a0, FUTEX_WAIT_PRIVATE, 2, NULL^C <unfinished ...>

Actions
Copy link
 #4

Updated by Mathieu Desnoyers almost 13 years ago

  • Status changed from New to Resolved
  • Assignee set to Mathieu Desnoyers

Fixed by commits:

commit b834deadbfa8a78ae1d00440fd91c41dfd351eba
Author: Mathieu Desnoyers <>
Date: Thu Mar 1 12:15:34 2012 -0500

Fix effect: update README about dlopen()
Signed-off-by: Mathieu Desnoyers &lt;&gt;

commit 4158a15a59fc6efbbbc99d66107fb4e1f27f9664
Author: Mathieu Desnoyers <>
Date: Thu Mar 1 12:13:47 2012 -0500

Fix: fixup vtid TLS
Signed-off-by: Mathieu Desnoyers &lt;&gt;
Conflicts:
liblttng-ust/lttng-context-vtid.c

commit f645cfa794fc481dff6cb30ea56e93f825b3d423
Author: Mathieu Desnoyers <>
Date: Thu Mar 1 12:09:40 2012 -0500

Fix: fixup ringbuffer tls at constructor by forcing read
Signed-off-by: Mathieu Desnoyers &lt;&gt;
Conflicts:
liblttng-ust/lttng-ust-comm.c
        libringbuffer/ring_buffer_frontend.c

commit eddd8d5d1a04887d1979417f1aca6c2f109bfe50
Author: Mathieu Desnoyers <>
Date: Thu Mar 1 12:00:04 2012 -0500

Fix: fix deadlock with dlopen() lttng-ust
Pre-"fault" the libuuid TLS outside of the ust lock to ensure that we
    never deadlock with the linker mutex in libc. This mutex is held both
    for TLS fixup of dlopen'd libs, and across execution of all
    constructors. We therefore have a reverse use of this mutex wrt ust
    lock, that we fix by forcing the TLS fixup to happen very early in the
    lttng-ust constructor.
[fixed merge from dev branch]
Signed-off-by: Mathieu Desnoyers &lt;&gt;
Actions
Copy link

Also available in: Atom PDF