LTTng » LTTng-tools

Are you sure you are running the right lttng-tools version?

The commit given is currently the HEAD of stable-2.1 but it does not fit the log you sent. Can you double check because this debug statement for instance is not on line 127 anymore. It is on 2.1.1 but not on the current HEAD of stable-2.1.

DEBUG1: Health state current 61644, last 61644, ret 0 [in health_check_state() at health.c:127]

Furthermore, we can see one of the health check checking for three different counters which was the consumer threads testing all three possible consumer (ust32, ust64 and kernel).

DEBUG1: Receiving data from client for health... [in thread_manage_health() at main.c:3041]
DEBUG1: Health state current 1, last 1, ret 0 [in health_check_state() at health.c:127]
DEBUG1: Health state current 1, last 1, ret 0 [in health_check_state() at health.c:127]
DEBUG1: Health state current 15, last 15, ret 0 [in health_check_state() at health.c:127]

This is definitely a log NOT from git head with the health TLS patch.

Thanks!

Hi David,

Here are new logs.

I didn't put the entire log because it got around 35 000 lines, so i put cut it to get the part were the failure happened. If you need more, i attached the entire log file.

Thanks Mathieu! I'll flag this back to Confirmed since it is clearly happening to your use case.

Can you try this. It should help. This makes the connect() to the relayd in a poll execution state for the health.

Here are some new logs

Ok, so in this case, everything is still fine but the command triggering the bad health state is due to the fact that the session list lock is taken by the application registration update process and it appears it takes more than 20 seconds until the lock is released.

I'll provide you a patch for that and will try to find more possible blocking calls in this thread since you've hit at least two as of now so they might be more.

Thanks!

This should help. I've added a bunch of health code update through out the client command susbsytem and some poll entry/exit at potential blocking callsite such as the recv() from the consumer, session and session list locking.

This should at least fix the issues observed in the attached logs. Apply this patch on top of stable-2.1 HEAD.

I hope to have covered every possible long blocking call that could trigger the BAD health state even though it's not.

Let me know! Thanks.

Ok, Mathieu, can you try that on stable-2.1 HEAD and tell us if it helps/fixes the problem.

Thanks!

Hi David,

Due to the overhead we had on our side, we could not continue working
on this bug until yesterday.

Unfortunately, the problem are still there (in lesser frequency than before, maybe 1 health check failure per 15min instead of 1 per 10min as before).
The failures that we have seen so far are: LTTNG_HEALTH_APP_MANAGE and LTTNG_HEALTH_CMD .

The scenario is still the same as described in this bug report.

I have not tried to combined all the logs together into a singer file like Mathieu did. But I hope the data collected are still analyzable. 

The commits used for this time was:
===================================
lttng-ust:    d480871 (HEAD, origin/stable-2.1) Fix package: don't distribute generated headers
lttng-tools:  ed22248 (HEAD, temp_bug429_bug433_patches) Apply patches for bug429 and 433
              b325dc7 (origin/stable-2.1) Fix: put session list lock around the app registration
userspace  :  da9bed2 (HEAD, tag: v0.7.6) Version 0.7.6

The general overview of the log:
================================
User2:   Mon Feb 25 17:35:58 EST 2013: Activate Profile again (2nd) 
User2:   Mon Feb 25 17:36:04 EST 2013: 2nd Activate completed, sleep for 10 sec. 
                   ~17:36:06           launch 20 TestApp_Mini (each has lifetime = 5 sec) 
User2:   Mon Feb 25 17:36:07 EST 2013: Deactivate Profile 
User2:   Mon Feb 25 17:36:07 EST 2013: Cancel during DEACTIVATE   (invoke lttng_list_session)
User1:   Mon Feb 25 17:36:08 EST 2013: Deactivate ...(invoke lttng_list_session)

         Feb 25 17:36:41 SC-1 TraceEa: SessionD healthcheck failed: LTTNG_HEALTH_APP_MANAGE !
         Feb 25 17:36:42 SC-1 TraceEa: sessiond faulted - Trying to Stop LTTNG
         Feb 25 17:36:42 SC-1 logger: lttng-sessiond is stopped

Enclosed are 2 logs:
====================
"bug433_saflog_SC1_1736pm.log"  containing the log from our system.
                                "TraceP_SC-1" is the interface towards sessionD.
                                All api call/reply to and from this process are logged.

"combined_APP_MANAGE_1736pm.log" contains the output from "lttng-sessiond -vvv" .
                                 A timestamp is inserted at every second.
                                 it shows that the health check was still good at 17:36:36.

Please, let us know if further info are needed.

Having a backtrace of all sessiond threads when the health issue is detected would be helpful here: it would allow us to know exactly what the sessiond was doing that took so long (without having health state report).

Thanks,

Mathieu