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.
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
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.
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
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.
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!
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.
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.
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.
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)
- 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
- Status changed from Confirmed to Resolved
- % Done changed from 0 to 100
Also available in: Atom
PDF