[lttng-dev] Endless waiting for data availability.

[Ruslan Uvashev]

Thanks for email, David!
Bug #770 has been opened :
http://bugs.lttng.org/issues/770


-------------------------------------
Best regards,
Ruslan Uvashev




On Mon, Mar 24, 2014 at 8:01 AM, <dgoulet at efficios.com> wrote:

> 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 --------------
An HTML attachment was scrubbed...
URL: <http://lists.lttng.org/pipermail/lttng-dev/attachments/20140324/17a4a8f6/attachment.html>