[lttng-dev] Endless waiting for data availability.

[Ruslan Uvashev]

Hello lttng developers,

While looking at UST example in  "lttng-ust/doc/examples/easy-ust" i
noticed that waiting for data availability never ends if tracing has never
been started for UST.

I would like to ask you if it is an issue/bug and if it is need to be fixed?

Steps:
1) create session
2) enable UST event
3) DO NOT start tracing
4) start application and then stop it
5) stop tracing <<< here tracing will never stop.

Thoughts:
This is valid only for UST.
Kernel is ok because it seems that kernel trace files are opened after
tracing is started while UST trace files are opened during application
registration.

/*
 * An empty output file is not valid. We need at least one packet
 * generated per stream, even if it contains no event, so it
 * contains at least one packet header.
 */
if (stream->output_written == 0) {
pthread_mutex_unlock(&stream->lock);
goto data_pending;
}



logs showing issue:

rusty at u:~/code/lttng-tools$ lttng -V

lttng (LTTng Trace Control) 2.4.0-rc2 - Époque Opaque

rusty at u:~/code/lttng-tools$ lttng create
Session auto-20140323-202015 created.
Traces will be written in /home/rusty/lttng-traces/auto-20140323-202015
rusty at u:~/code/lttng-tools$ lttng enable-event sample_component:message -u
UST event sample_component:message created in channel channel0
rusty at u:~/code/lttng-tools$ ../lttng-ust/doc/examples/easy-ust/sample
^C
rusty at u:~/code/lttng-tools$ lttng stop
Waiting for data
availability.................................................^C



I added a few printouts to lttng and consumer to understand the issue
better.

traces UST:

rusty at u:~/code/lttng-tools$ lttng create
Session auto-20140323-201048 created.
Traces will be written in /home/rusty/lttng-traces/auto-20140323-201048
rusty at u:~/code/lttng-tools$ lttng enable-event sample_component:message -u
UST event sample_component:message created in channel channel0
rusty at u:~/code/lttng-tools$ ../lttng-ust/doc/examples/easy-ust/sample
^C
rusty at u:~/code/lttng-tools$ lttng stop
llm.ret_code = 81
Waiting for data availabilityllm.ret_code = 1
.llm.ret_code = 1
.llm.ret_code = 1
^C


traces UST from daemon:

DEBUG1 [6362/6465]: Processing client command 24 (in process_client_msg()
at main.c:2703)
DEBUG1 [6362/6465]: Getting session auto-20140323-201048 by name (in
process_client_msg() at main.c:2782)
DEBUG2 [6362/6465]: Trying to find session by name auto-20140323-201048 (in
session_find_by_name() at session.c:169)
DEBUG3 [6362/6465]: Consumer data pending for id 1 (in
consumer_is_data_pending() at consumer.c:1083)
DEBUG1 [6495/6501]: Incoming command on sock (in
consumer_thread_sessiond_poll() at consumer.c:3068)
DEBUG1 [6495/6501]: UST consumer data pending command for id 1 (in
lttng_ustconsumer_recv_cmd() at ust-consumer.c:1177)
DEBUG1 [6495/6501]: Consumer data pending command on session id 1 (in
consumer_data_pending() at consumer.c:3491)
DEBUG1 [6495/6501]: >>> Go over stream_list_ht <<< (in
consumer_data_pending() at consumer.c:3525)
DEBUG1 [6495/6501]: >>> stream_try_lock(stream) ret = 1 <<< (in
consumer_data_pending() at consumer.c:3532)
DEBUG1 [6495/6501]: >>> cds_lfht_is_node_deleted(&stream->node.node) ret =
0 <<< (in consumer_data_pending() at consumer.c:3545)
DEBUG1 [6495/6501]: >>> !!! stream->output_written == 0 !!! <<< (in
consumer_data_pending() at consumer.c:3553)
DEBUG1 [6495/6501]: received command on sock (in
consumer_thread_sessiond_poll() at consumer.c:3084)
DEBUG1 [6362/6465]: Consumer data is  pending for session id 1 (in
consumer_is_data_pending() at consumer.c:1119)
DEBUG1 [6362/6465]: Sending response (size: 16, retcode: Unknown error
code) (in thread_manage_clients() at main.c:3975)




traces kernel:

rusty at u:~/code/lttng-tools$ lttng create
Session auto-20140323-201349 created.
Traces will be written in /home/rusty/lttng-traces/auto-20140323-201349
rusty at u:~/code/lttng-tools$ lttng enable-event -a -k
All Kernel events are enabled in channel channel0
rusty at u:~/code/lttng-tools$ lttng stop
llm.ret_code = 81
Waiting for data availabilityllm.ret_code = 0

Warning: Tracing already stopped for session auto-20140323-201349


traces kernel from daemon:

DEBUG1 [6362/6465]: Processing client command 24 (in process_client_msg()
at main.c:2703)
DEBUG1 [6362/6465]: Getting session auto-20140323-201349 by name (in
process_client_msg() at main.c:2782)
DEBUG2 [6362/6465]: Trying to find session by name auto-20140323-201349 (in
session_find_by_name() at session.c:169)
DEBUG3 [6362/6465]: Consumer data pending for id 2 (in
consumer_is_data_pending() at consumer.c:1083)
DEBUG1 [6576/6582]: Incoming command on sock (in
consumer_thread_sessiond_poll() at consumer.c:3068)
DEBUG1 [6576/6582]: Kernel consumer data pending command for id 2 (in
lttng_kconsumer_recv_cmd() at kernel-consumer.c:850)
DEBUG1 [6576/6582]: Consumer data pending command on session id 2 (in
consumer_data_pending() at consumer.c:3491)
DEBUG1 [6576/6582]: >>> Go over stream_list_ht <<< (in
consumer_data_pending() at consumer.c:3525)
DEBUG1 [6576/6582]: received command on sock (in
consumer_thread_sessiond_poll() at consumer.c:3084)
DEBUG1 [6362/6465]: Consumer data is NOT pending for session id 2 (in
consumer_is_data_pending() at consumer.c:1119)
DEBUG1 [6362/6465]: Sending response (size: 16, retcode: Unknown error
code) (in thread_manage_clients() at main.c:3975)



Thank you.

-------------------------------------
Best regards,
Ruslan Uvashev
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.lttng.org/pipermail/lttng-dev/attachments/20140323/4b07d5c1/attachment.html>