LTTng » LTTng-tools

We're trying to reproduce the issue on our end.

Hi Jérémie,

Did you have a chance to looks into this issue ?
Thanks,
Tan

David has tried to reproduce the issue without success... However, we have identified another bug that may be related. We are still looking into it.
Could you run the sessiond under valgrind in "--leak-check=full" mode?

David has rebased a Valgrind-support patch on the current lttng-tools HEAD. It's available on his personal repository.

git@github.com:dgoulet/lttng-tools-dev.git
branch: valgrind

Hi Jeremie,

Unfortunately, I can not reproduce this with Valgrind. The reason is that when sessionD is running with Valgrind, it is too slow to reponse to the registration of the instrumented app causing too many "Error: Timed out waiting for lttng-sessiond", which in turns, causes the instrumented app to hang (ie: they can not execute their main even after the LTTNG_UST_REGISTER_TIMEOUT has elapsed). This new behaviour has been reported in bug-545.

I will try to rerun with a lower launch rate (ie: launch less number of instances of intr app per sec) and see
if I can see the increase of MEM usage from the "top" printout.
Regards,
Tan

Okay. Reproducing it under a lighter load will absolutely make it easier to debug... Keep me posted.
Thanks for reporting #545 too!

When trying with lower rate, problem did not happen.
ex:
  for a in $(seq 1 28800); do (for n in $(seq 1 100); do (/home/test_apps/TestApp_100perSecOnly 3 np > /dev/null &);\
       done; usleep 800000); done &

  I have ran the above for 8hrs, each 0.8sec, launch 100 instances. The "top" printout before and after
  the 8 hour run are pretty much the same (from RES and MEM column):
  [SC-1:Node16 Mon May 27 15:40:05/cluster/temp/tdlt] # top -b -n 1 | head -n 7 | tail -n 1; top -b -n 1 |grep -i sessiond
  PID USER      PR  NI  VIRT  RES  SHR S   %CPU %MEM    TIME+  COMMAND
  712 root      20   0  157m 6892  664 S      2  0.0   0:00.28 lttng-sessiond
  :
  [SC-1:Node16 Tue May 28 06:51:22/cluster/temp/tdlt] # top -b -n 1 | head -n 7 | tail -n 1; top -b -n 1 |grep -i sessiond
  PID USER      PR  NI  VIRT  RES  SHR S   %CPU %MEM    TIME+  COMMAND
  712 root      20   0  236m 8720  708 S      0  0.0   7:08.17 lttng-sessiond

When changing the rate to 100 instances per 0.2 sec, I see the value under RES increase to 12MB and stay there 
even after no more apps being launched (NOTE: there is no session defined, no session active):
ex:
    for a in $(seq 1 28800); do (for n in $(seq 1 100); do (/home/test_apps/TestApp_100perSecOnly 3 np > /dev/null &); \
       done; usleep 200000); done &

  <before launching apps>
  [SC-1:Node16 Tue May 28 06:51:22/cluster/temp/tdlt] # top -b -n 1 | head -n 7 | tail -n 1; top -b -n 1 |grep -i sessiond
    PID USER      PR  NI  VIRT  RES  SHR S   %CPU %MEM    TIME+  COMMAND
    712 root      20   0  236m 8720  708 S      0  0.0   7:08.17 lttng-sessiond
  :
  :
  <after launching apps>
  [SC-1:Node16 Tue May 28 06:52:45/cluster/temp/tdlt] # top -b -n 1 | head -n 7 | tail -n 1; top -b -n 1 |grep -i sessiond
  PID USER      PR  NI  VIRT  RES  SHR S   %CPU %MEM    TIME+  COMMAND
  712 root      20   0  235m  12m  708 S      7  0.1   7:08.52 lttng-sessiond

That's interesting. I'm betting on an error path that does not clean up memory when some limit is reached.

During those tests with a large number of applications, do you know if any errors occur like open file limit reached for instance ?

No, I did not observe any error while doing the test.

We've been running this use case (and variations) on a 16 cores machine for more than 50 minutes and we are unable to reproduce it.

So, can you confirm me that during this test there is NO session(s) created and the applications just register and unregister? Also, are you running health check during that time also.

I'm trying to find any "variables" that can change the state of the session daemon.

If none of the above apply, we'll have to come on site to help you guys. We have a small library that keeps track of the malloc/free and their call sites.

We confirm that during this test (as described earlier in this bug-report):
  _ Our TraceEA process performs the following at every 5 sec interval:
        1)_ Call the following APIs:
             lttng_health_check(LTTNG_HEALTH_CMD)
             lttng_health_check(LTTNG_HEALTH_APP_MANAGE)
             lttng_health_check(LTTNG_HEALTH_APP_REG)
             lttng_health_check(LTTNG_HEALTH_CONSUMER)
        2)_ Create a dummy session via the following API calls:
             lttng_create_session()
             lttng_destroy_session()

             (NOTE: no channel or event being enabled)

  _ However, when we turn off the above TraceEA process, the same thing
    is still observed (ie: after a few minutes run, we stop launching 
    the apps, the top or ps command printout indicate that the resident 
    memory for sessiond has increased by around 20 times its original 
    size.)

  _ Other than the above, only a bunch of instrumented application being
    launched and terminates. No real session (with enabled events) being 
    created and started.

 

Is this can be reproduce with the session daemon in -vvv ?

Actually, only "-v" will be of great help. If not, I'll come on site to help you hunt this one.

Well yes RSS is the resident size of the program. I can see in the log that it goes up to 100Mb... The head commit of tools does not show the fix I've provided (commit: adbbaabc265e354b7986b48815ee556f1a07769b). Is this because you might have forget it or you just applied the diff ?

Ouch !

My Bad....my verrrry bad !

I thought I just need the latest commit ..... didn't see the patch :-(
Applying the patch now ...will update you soon .

No problem. :)

If it is still visible after using the patch, I'll come on site hunt down this thing!

After loading lttng-tools v2.2.3 and lttng-ust 2.2.1, the above mem leak is no longer observed.
Many thanks for the great support.