[lttng-dev] Python tracef() jams the interpreter on registration

Thu Nov 27 16:55:00 EST 2014

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

http://git.dorsal.polymtl.ca/~fgiraldeau?p=python-profile-ust.git;a=summary

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)
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.lttng.org/pipermail/lttng-dev/attachments/20141127/37ced112/attachment-0001.html>