Bug #487
closedPer UID buffer: Can not see any data being logged
100%
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
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.
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
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.
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
- File ses9_terminal_log.log ses9_terminal_log.log added
- File ses9_sessionD_verbose.log ses9_sessionD_verbose.log added
- File TestApp_type1.tar TestApp_type1.tar added
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.
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.
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
- File ses13_withUST_DEBUG.log ses13_withUST_DEBUG.log added
- File ses13_sessionD_consumerD_verbose.log ses13_sessionD_consumerD_verbose.log added
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)
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
Updated by Mathieu Desnoyers about 11 years ago
- Status changed from Confirmed to Resolved
- % Done changed from 0 to 100
Applied in changeset 46c881a7d6839761e3371a93ba29e7a0202bcd03.