LTTng » LTTng-tools

Hi Micke,

thanks for the bug report. In the first case you demonstrate: when you say hang, do you mean an indefinite hang? I haven't been able to reproduce that with 2.13.13, stable-2.13, or master.

thanks,
kienan

I think in the original report the sequence was repeated twice in order to actually reach a visible hang and a remote lttng-relayd was used, but I was able to deduce from the logs that the hang actually occurs during the destroy of the first session. The call sequence I received was embedded with the verbose logs from the session daemon, so it wasn't available for copy paste and it was like 2 months or something since I worked on this but right before opening the ticket I tested the sequence I reported.

If you run the lttng-session with logs enabled like "-vvv --verbose-consumer" you should see that the logging never settles and that the live timer keeps on running for ever. In the normal case logging will eventually stop even though it may take 1-2 minutes due to the latency. This is how I reproduced the issue.

I don't think I was ever able to reproduce it without a second user running an app with tracing enabled. Not sure why that was needed but this was something I picked up from the original logs. Before that, things just worked whatever I tried.

I guess you could also test using a remote relay daemon, but I am pretty sure I reproduced the issue using a local relay daemon. Possibly I should have emphasized the fact that you either need to check the verbose logging or run the sequence twice.

Anyway, as far as I could tell the live timer rt signal would always arrive before the monitor signal was processed, always putting itself first in the queue. After creating the patch, I even wrote a C test program to prove this. I think I even created a variant using separate threads for the signals which would not hang.

Hello Kienan!

Let me have a look at your reproducer and results but I vaguely remember that I couldn't reproduce the issue on a dual core system but on systems with more cores it was 100%.

Micke

I think reproduction is fine using your script but you can't shut down the session daemon or delete the netem delay as you will not see the logs then.

Maybe if you do:
...
echo -e "$TRACED_APPS_COUNT\t$QDISC_DELAY\t$START\t$END\t$(bc <<< "$END - $START")" >> results

1. >>> ADDED THIS LINE <<<
   tail -f "${SESSIOND_LOG_FILE}"

1. Cleanup
   stop_sessiond
   ...

And then from another shell after some time you can do:
tc qdisc del dev lo root

Or whatever way you want to do it but you need to observe the logs from the session daemon after the destroy call has finished.

It should look something like this:
DBG1 - 15:02:30.638588687 [4510/4522]: Live timer for channel 1 (in live_timer() at ../../../../git/src/common/consumer/consumer-timer.c:291)
DBG1 - 15:02:30.638617535 [4510/4522]: Stream 58 empty, sending beacon (in consumer_flush_ust_index() at ../../../../git/src/common/consumer/consumer-timer.c:257)
DBG1 - 15:02:30.638633460 [4510/4522]: Relayd sending index for stream ID 70 (in relayd_send_index() at ../../../../git/src/common/relayd/relayd.c:1101)
DBG3 - 15:02:30.638647933 [4510/4522]: Relayd sending command 13 of size 104 (in send_command() at ../../../../git/src/common/relayd/relayd.c:90)
...
over and over again.