[lttng-dev] Endless waiting for data availability.

Mon Mar 24 11:01:24 EDT 2014

On 23 Mar (20:45:01), Ruslan Uvashev wrote:
> Hello lttng developers,

Hi Ruslan,

I have to say that you found quite a nice and important bug! :) I can
reproduce it here in no time so can you please open an issue on
bugs.lttng.org in the lttng-tools project and flag it high?

You basically just need to add the steps to reproduce and the version of
tools you are using. I'll link this email in the archive to the issue
you will open.

Big thanks!
David

> 
> 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

> _______________________________________________
> lttng-dev mailing list
> lttng-dev at lists.lttng.org
> http://lists.lttng.org/cgi-bin/mailman/listinfo/lttng-dev

-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 603 bytes
Desc: Digital signature
URL: <http://lists.lttng.org/pipermail/lttng-dev/attachments/20140324/98bc9ed3/attachment.pgp>