Project

General

Profile

Actions

Bug #487

closed

Per UID buffer: Can not see any data being logged

Added by Tan le tran about 11 years ago. Updated about 11 years ago.

Status:
Resolved
Priority:
Critical
Target version:
-
Start date:
03/27/2013
Due date:
% Done:

100%

Estimated time:

Description

Problem Description:
====================
 * After the session is activated and instrumented app launched, no
   log can be obtained. Only metadata file contain "seem to be valid" data.
   Babeltrace the session directory gives nothing.

Is problem reproducible ?
=========================
  * yes 100%

How to reproduce (if reproducible):
===================================
  1)_
      export TC=ses1
      ps -ef |egrep 'lttng'
      netstat -etanp | head -n 2 ; netstat -etanp |egrep lttng
      lttng-relayd  -C tcp://0.0.0.0:53000 -D tcp://0.0.0.0:53001  -o /cluster/temp/log/$TC &
      netstat -etanp | head -n 2 ; netstat -etanp |egrep lttng
      time lttng list
      time lttng create $TC -U net://192.168.0.1:53000:53001/./
      time lttng list
      sleep 1
      time lttng enable-channel -u --buffers-uid chan1
      sleep 1
      time lttng enable-event -s $TC "com*"  -u -c chan1
      sleep 1
      time lttng list $TC
       sleep 1
       time lttng start;
       sleep 1
       time lttng list
  2)_ Launch the application 
       /home/test_apps/TestApp_type1 50000 np &
       lttng list -u
           #-- shows that the instr app has registered and sessionD sees all their tracepoints
           #   all tracepoints start with com_....
  3)_ dir ses1/SC-1/ust/uid/0/64-bit/   (current directory is : /cluster/temp/log/)
        total 0
        -rwxr-xr-x 1 root root 0 Mar 26 17:54 metadata
        -rwxr-xr-x 1 root root 0 Mar 26 17:54 chan1_3
        -rwxr-xr-x 1 root root 0 Mar 26 17:54 chan1_2
        -rwxr-xr-x 1 root root 0 Mar 26 17:54 chan1_1
        -rwxr-xr-x 1 root root 0 Mar 26 17:54 chan1_0

      Repeat the above command  again and again, but still see all filesize 0.
      The above instr app should produce about 10000 events per sec, and
      we are expecting to get about 600KB/s of data.

  4)_ lttng stop
      lttng destroy
      pkill relayd

  5)_ dir ses1/SC-1/ust/uid/0/64-bit/
        total 44
        -rwxr-xr-x 1 root root 12288 Mar 26 17:55 metadata
        -rwxr-xr-x 1 root root  8192 Mar 26 17:55 chan1_3
        -rwxr-xr-x 1 root root  8192 Mar 26 17:55 chan1_2
        -rwxr-xr-x 1 root root  8192 Mar 26 17:55 chan1_1
        -rwxr-xr-x 1 root root  8192 Mar 26 17:55 chan1_0

   6)_ more ses1/SC-1/ust/uid/0/64-bit/metadata    #-- shows that the tracepoints are present

   7)_ babeltrace ses1/SC-1/ust/uid/0/64-bit/
       babeltrace ses1/SC-1/ust/uid/0/64-bit/
       babeltrace ses1/SC-1/ust/uid/0/
       babeltrace ses1/SC-1/ust/
       babeltrace ses1/SC-1/
       babeltrace ses1/

       #--- get nothing in printout

Commit used:
============
  userspace   : d107390 (HEAD, origin/master, origin/HEAD, globalBuffer) Add tab to output in ...
  lttng-ust   : e2ad3b4 (HEAD, origin/master, origin/HEAD, globalBuffer) Add demo README
  lttng-tools : 9f9ee9c (HEAD, origin/master, origin/HEAD, globalBuffer) Fix: UST context activation
  babeltrace  : c99b191 (HEAD, tag: v1.1.0) Version 1.1.0

Any other information:
======================
- The above terminal log are attached.
- The corresponding session directory is also attached


Files

Terminal.log (38.2 KB) Terminal.log Terminal log when TC is executed Tan le tran, 03/27/2013 11:46 AM
ses1.tar (1.94 KB) ses1.tar ses1 directory after the session has been destroyed Tan le tran, 03/27/2013 11:46 AM
ses9_terminal_log.log (21.2 KB) ses9_terminal_log.log log file for session "ses9" Tan le tran, 03/27/2013 03:20 PM
ses9_sessionD_verbose.log (141 KB) ses9_sessionD_verbose.log Corresponding "sessiond -vvv" while ses9 is run Tan le tran, 03/27/2013 03:20 PM
TestApp_type1.tar (790 KB) TestApp_type1.tar Tarball of TestApp_type1 Tan le tran, 03/27/2013 03:20 PM
ses13_withUST_DEBUG.log (40.8 KB) ses13_withUST_DEBUG.log terminal log Tan le tran, 03/27/2013 05:44 PM
ses13_sessionD_consumerD_verbose.log (1.21 MB) ses13_sessionD_consumerD_verbose.log Output of sessiond -vvv --verbose-consumer Tan le tran, 03/27/2013 05:44 PM
Actions #1

Updated by David Goulet about 11 years ago

This works well here. After the stop, you should get your data.

Note that in your case you use "*" as a wild card but with double quotes. That may cause your shell to replace the star with some unwanted input.

$ lttng enable-event -s $TC "com*" -u -c chan1

That would explain why the trace is valid but does not have anything in it. If not, let me know.

Actions #2

Updated by Mathieu Desnoyers about 11 years ago

The proper usage for wildcard is to use single quote, not double,
indeed.

'*' rather than "*".

Thanks,

Mathieu

--
Mathieu Desnoyers
EfficiOS Inc.
http://www.efficios.com

Actions #3

Updated by Tan le tran about 11 years ago

Negative !

The reason I used "com*" is to get a quick file size increase.
The problem has been spotted when using a single specific tracepoint:
com_ericsson_cba_trace_testapp_lowtraf:OnePerSecB

Can we safely assume that "com*" has been interpreted properly
by lttng because the corresponding tracepoints are shown in the
metadata file ? Otherwise, none of the tracepoints should be
present in that file, isn't it ?

I tried with 'com*' anyway and same problem. no Data .

Will try to run again with verbose mode... will update later.

Actions #4

Updated by David Goulet about 11 years ago

Can I have the TestApp (tarball) so I can test the same exact use case because I'm unable to have an empty trace here with the exact command you are using.

Thanks!

Updated by Tan le tran about 11 years ago

We have rerun the scenario with "sessionD -vvv".

The following files are attached:
"ses9_terminal_log.log"
Terminal log file when session "ses9" is being created, start, stop, destroy.
"ses9_sessionD_verbose.log"
Corresponding sessiond -vvv output
"TestApp_type1.tar" the requested tarball of TestApp_type1 used in the test.

Actions #6

Updated by Tan le tran about 11 years ago

I have rerun the case using the "hello" program under "lttng-ust/tests/hello-static-lib"
with the instructions steps below and the problem is still the same. I could not get
any log data. Only metadata.

export TC=ses102
ps -ef |egrep 'lttng'
lttng-relayd -C tcp://0.0.0.0:53000 -D tcp://0.0.0.0:53001 -o /cluster/temp/log/$TC &
lttng create $TC -U net://192.168.0.1:53000:53001/./
lttng list
sleep 1
lttng enable-channel chan1 -u --buffers-uid
sleep 1
lttng enable-event -s $TC -u -c chan1 ust_tests_hello:tptest_sighandler
sleep 1
lttng list $TC
sleep 1
lttng start;
sleep 1
lttng list $TC
sleep 1
netstat -etanp | head -n 2 ; netstat -etanp |egrep 'lttng'
sleep 1
lttng list -u
sleep 1
/cluster/temp/tdlt/hello 20 &
sleep 1
lttng list -u
dir -R /cluster/temp/log/$TC
sleep 22
dir -R /cluster/temp/log/$TC
lttng stop
sleep 1
dir -R $TC/SC-1/ust/uid/0/64-bit
lttng destroy $TC
sleep 1
dir -R $TC/SC-1/ust/uid/0/64-bit
pkill relayd
ps -ef |egrep 'lttng'
pkill TestApp
lttng list -u
babeltrace $TC/SC-1/ust/uid/0/64-bit

I am still using the same set of lttng commits indicated at the beginning of this report.

Actions #7

Updated by David Goulet about 11 years ago

I can't get an empty trace here... I used "com*" and after only "com_ericsson_cba_trace_testapp_lowtraf:OnePerSecB:" with the application started before and after the lttng commands and I'm unable to get an empty trace. (at the same commit as you are in all projects).

Is your system 32 bit?

Second thing, can you set the application in debug mode using LTTNG_UST_DEBUG=1 ./TestApp_type1 .... (or simply hello). Also, add "--verbose-consumer" to the session daemon logs so we can look if the consumer is the problem.

Updated by Tan le tran about 11 years ago

We are using a 64 bit system.

I have run a new session with the info you requested (ses13).
Logs are attached.

From the consumer output, there are plenty of complaints about:
Reserving sub buffer failed (everything is normal, it is due to concurrency) [ret: -11] (in lttng_ustconsumer_read_subbuffer() at ust-consumer.c:1188)

Actions #9

Updated by Mathieu Desnoyers about 11 years ago

  • Project changed from LTTng-tools to LTTng-UST
  • Status changed from New to Confirmed
  • Assignee set to Mathieu Desnoyers
  • Priority changed from Normal to Critical
Actions #10

Updated by Mathieu Desnoyers about 11 years ago

  • Status changed from Confirmed to Resolved
  • % Done changed from 0 to 100
Actions

Also available in: Atom PDF