Bug 4621

Summary:	lttng userspace trace is not created
Product:	[Yocto Project Subprojects] ADT	Reporter:	Alexandru Georgescu <alexandru.c.georgescu>
Component:	kernel analysis	Assignee:	Tom Zanussi <tom.zanussi>
Status:	VERIFIED FIXED	QA Contact:
Severity:	normal
Priority:	Medium	CC:	dvhart, sgw, yp.sdk.watcher, yp.watcher
Version:	1.5
Target Milestone:	1.5
Hardware:	x86
OS:	Multiple
Whiteboard:
OS type for building Yocto:	---	Type of Regression:	---
Verified:		Documentation change:	Don't know

Description Alexandru Georgescu 2013-06-06 13:35:44 UTC

poky:a62aed41f2d8f874f7ae24d0e5be5dbc66ea2199
QEMU: http://autobuilder.yoctoproject.org/pub/nightly/20130604-5/machines/qemu/qemux86-64/

STEPS TO REPRODUCE

1. Boot a core-image-sato-sdk image (e.g. qemux86-64)
2. Perform an userspace trace with lttng and view the trace

EXPECTED RESULTS:
2. Trace is created and can be viewed:

root@crownbay:~# lttng view
[02:31:14.906146544] (+?.?????????) hello:1424 ust_tests_hello:tptest: { cpu_id = 1 }, { intfield = 0, intfield2 = 0x0, longfield = 0, netintfield = 0, netintfieldhex = 0x0, arrfield1 = [ [0] = 1, [1] = 2, [2] = 3 ], arrfield2 = "test", _seqfield1_length = 4, seqfield1 = [ [0] = 116, [1] = 101, [2] = 115, [3] = 116 ], _seqfield2_length = 4,  seqfield2 = "test", stringfield = "test", floatfield = 2222, doublefield = 2, boolfield = 1 }
[02:31:14.906170360] (+0.000023816) hello:1424 ust_tests_hello:tptest: { cpu_id = 1 }, { intfield = 1, intfield2 = 0x1, longfield = 1, netintfield = 1, netintfieldhex = 0x1, arrfield1 = [ [0] = 1, [1] = 2, [2] = 3 ], arrfield2 = "test", _seqfield1_length = 4, seqfield1 = [ [0] = 116, [1] = 101, [2] = 115, [3] = 116 ], _seqfield2_length = 4, seqfield2 = "test", stringfield = "test", floatfield = 2222, doublefield = 2, boolfield = 1 }
[02:31:14.906183140] (+0.000012780) hello:1424 ust_tests_hello:tptest: { cpu_id = 1 }, { intfield = 2, intfield2 = 0x2, longfield = 2, netintfield = 2, netintfieldhex = 0x2, arrfield1 = [ [0] = 1, [1] = 2, [2] = 3 ], arrfield2 = "test", _seqfield1_length = 4, seqfield1 = [ [0] = 116, [1] = 101, [2] = 115, [3] = 116 ], _seqfield2_length = 4, seqfield2 = "test", stringfield = "test", floatfield = 2222, doublefield = 2, boolfield = 1 }
[02:31:14.906194385] (+0.000011245) hello:1424 ust_tests_hello:tptest: { cpu_id = 1 }, { intfield = 3, intfield2 = 0x3, longfield = 3, netintfield = 3, netintfieldhex = 0x3, arrfield1 = [ [0] = 1, [1] = 2, [2] = 3 ], arrfield2 = "test", _seqfield1_length = 4, seqfield1 = [ [0] = 116, [1] = 101, [2] = 115, [3] = 116 ], _seqfield2_length = 4, seqfield2 = "test", stringfield = "test", floatfield = 2222, doublefield = 2, boolfield = 1 }
.
.
.

ACTUAL RESULTS
2. trace is not created:



root@qemux86-64:~# lttng create
Session auto-20130606-132154 created.
Traces will be written in /home/root/lttng-traces/auto-20130606-132154
root@qemux86-64:~# lttng enable-event --userspace --all
All UST events are enabled in channel channel0
root@qemux86-64:~# lttng start
Tracing started for session auto-20130606-132154
root@qemux86-64:~# ./a.out 
Hello, World!
root@qemux86-64:~# lttng stop
Waiting for data availability
Tracing stopped for session auto-20130606-132154
root@qemux86-64:~# lttng view
Trace directory: /home/root/lttng-traces/auto-20130606-132154

[error] Cannot open any trace for reading.

[error] opening trace "/home/root/lttng-traces/auto-20130606-132154" for reading.

[error] none of the specified trace paths could be opened.

root@qemux86-64:~# lttng destroy
Session auto-20130606-132154 destroyed
root@qemux86-64:~# ls
a.out  hello.c
root@qemux86-64:~#

Comment 1 Tom Zanussi 2013-06-06 19:29:41 UTC

Please check maintainers.inc when assigning bugs:

RECIPE_MAINTAINER_pn-lttng-ust = "Bogdan Marinescu <bogdan.a.marinescu@intel.com>"

Comment 2 Saul Wold 2013-06-28 19:08:57 UTC

Tom: I am explictly re-assinging this back to you as Bogdan has left and you 
are the tracing person.

Comment 3 Tom Zanussi 2013-07-02 18:05:18 UTC

There doesn't seem to be a problem here.


Build Configuration:
BB_VERSION        = "1.19.1"
BUILD_SYS         = "x86_64-linux"
NATIVELSBSTRING   = "Fedora-17"
TARGET_SYS        = "i586-poky-linux"
MACHINE           = "crownbay"
DISTRO            = "poky"
DISTRO_VERSION    = "1.4+snapshot-20130701"
TUNE_FEATURES     = "m32 core2"
TARGET_FPU        = ""
meta              
meta-yocto        
meta-yocto-bsp    = "master0:80b263430453896189b704d0997943642eec6fef"
meta-intel        
meta-crownbay     = "master0:e0d6134ed2e2687ff9f2ee77701666447842bf33"


root@crownbay:~# lttng create
Spawning a session daemon
Warning: No tracing group detected
Session auto-20130701-224222 created.
Traces will be written in /home/root/lttng-traces/auto-20130701-224222
root@crownbay:~# lttng enable-event --userspace --all 
All UST events are enabled in channel channel0
root@crownbay:~# lttng start
Tracing started for session auto-20130701-224222
root@crownbay:~# ./hello
Hello, World!
Tracing...  done.
root@crownbay:~# lttng stop
Waiting for data availability...............................
Tracing stopped for session auto-20130701-224222
root@crownbay:~# lttng view
[23:45:24.249558061] (+0.000005587) crownbay:hello:1236 ust_tests_hello:tptest: { cpu_id = 1 }, { intfield = 3295, intfield2 = 0xCDF, longfield = 3295, netintfield = 3295, netintfieldhex = 0xCDF, arrfield1 = [ [0] = 1, [1] = 2, [2] = 3 ], arrfield2 = "test", _seqfield1_length = 4, seqfield1 = [ [0] = 116, [1] = 101, [2] = 115, [3] = 116 ], _seqfield2_length = 4, seqfield2 = "test", stringfield = "test", floatfield = 2222, doublefield = 2, boolfield = 1 }
[23:45:24.249563648] (+0.000005587) crownbay:hello:1236 ust_tests_hello:tptest: { cpu_id = 1 }, { intfield = 3296, intfield2 = 0xCE0, longfield = 3296, netintfield = 3296, netintfieldhex = 0xCE0, arrfield1 = [ [0] = 1, [1] = 2, [2] = 3 ], arrfield2 = "test", _seqfield1_length = 4, seqfield1 = [ [0] = 116, [1] = 101, [2] = 115, [3] = 116 ], _seqfield2_length = 4, seqfield2 = "test", stringfield = "test", floatfield = 2222, doublefield = 2, boolfield = 1 }
[23:45:24.249569236] (+0.000005588) crownbay:hello:1236 ust_tests_hello:tptest: { cpu_id = 1 }, { intfield = 3297, intfield2 = 0xCE1, longfield = 3297, netintfield = 3297, netintfieldhex = 0xCE1, arrfield1 = [ [0] = 1, [1] = 2, [2] = 3 ], arrfield2 = "test", _seqfield1_length = 4, seqfield1 = [ [0] = 116, [1] = 101, [2] = 115, [3] = 116 ], _seqfield2_length = 4, seqfield2 = "test", stringfield = "test", floatfield = 2222, doublefield = 2, boolfield = 1 }
[23:45:24.249574823] (+0.000005587) crownbay:hello:1236 ust_tests_hello:tptest: { cpu_id = 1 }, { intfield = 3298, intfield2 = 0xCE2, longfield = 3298, netintfield = 3298, netintfieldhex = 0xCE2, arrfield1 = [ [0] = 1, [1] = 2, [2] = 3 ], arrfield2 = "test", _seqfield1_length = 4, seqfield1 = [ [0] = 116, [1] = 101, [2] = 115, [3] = 116 ], _seqfield2_length = 4, seqfield2 = "test", stringfield = "test", floatfield = 2222, doublefield = 2, boolfield = 1 }
[23:45:24.249580410] (+0.000005587) crownbay:hello:1236 ust_tests_hello:tptest: { cpu_id = 1 }, { intfield = 3299, intfield2 = 0xCE3, longfield = 3299, netintfield = 3299, netintfieldhex = 0xCE3, arrfield1 = [ [0] = 1, [1] = 2, [2] = 3 ],

Comment 4 Tom Zanussi 2013-07-02 22:05:57 UTC

Also tried with a qemux86-64 core-image-sato-sdk build and it worked fine too, so closing this.

Comment 5 Alexandru Georgescu 2013-08-02 10:57:31 UTC

Hi Tom,
I am sorry but I have to reopen this. I have tried on real HW, crownbay-noemgd and on qemux86 & qemux86-64 sato-sdk images.

It reproduces on both machines (qemu and real hw) with the same error I mentioned from above.


poky: 9de0ad47462c13ac4a2d73e12e92be6c1b4e0415
crownbay: http://autobuilder03.jf.intel.com/pub/nightly-meta-intel/20130731-3/machines/crownbay-noemgd/core-image-sato-sdk-crownbay-noemgd.hddimg

I really don't know why it doesn't happen to you but seems that on my machines it reproduces.

Comment 6 Tom Zanussi 2013-08-15 19:52:47 UTC

I think your problem is that you're not actually running anything that will produce a trace.  Apparently lttng-ust doesn't produce the file it says it does unless something is actually traced and 'lttng view' will produce  the error you see if nothing has been traced and therefore the file doesn't really exist:

lttng create
Spawning a session daemon
Warning: No tracing group detected
Session auto-20130801-095552 created.
Traces will be written in /home/root/lttng-traces/auto-20130801-095552
root@crownbay-noemgd:~# lttng enable-event --userspace --all
All UST events are enabled in channel channel0
root@crownbay-noemgd:~# lttng start
Tracing started for session auto-20130801-095552
root@crownbay-noemgd:~# lttng stop
Waiting for data availability
Tracing stopped for session auto-20130801-095552
root@crownbay-noemgd:~# lttng view
Trace directory: /home/root/lttng-traces/auto-20130801-095552

[error] Cannot open any trace for reading.

[error] opening trace "/home/root/lttng-traces/auto-20130801-095552" for reading.

[error] none of the specified trace paths could be opened.

root@crownbay-noemgd:~# lttng start
Tracing started for session auto-20130801-095552


If you repeat the test but actually run the hello application that will generate a trace, you get:

root@crownbay-noemgd:~# lttng start
Tracing started for session auto-20130801-095552
root@crownbay-noemgd:~# /media/sdb/lttng-ust-hello 
Hello, World!
Tracing...  done.
root@crownbay-noemgd:~# lttng stop
Waiting for data availability
Tracing stopped for session auto-20130801-095552
root@crownbay-noemgd:~# lttng view
Trace directory: /home/root/lttng-traces/auto-20130801-095552

[09:56:50.080838531] (+?.?????????) crownbay-noemgd:lttng-ust-hello:1107 ust_tests_hello:tptest: { cpu_id = 1 }, { intfield = 0, intfield2 = 0x0, longfield = 0, netintfield = 0, netintfieldhex = 0x0, arrfield1 = [ [0] = 1, [1] = 2, [2] = 3 ], arrfield2 = "test", _seqfield1_length = 4, seqfield1 = [ [0] = 116, [1] = 101

You can find a 'hello' program that you can use for testing in:

build/tmp/work/core2-poky-linux/lttng-ust/2_2.2.0-r0/build/tests/hello/.libs/hello

Comment 7 Alexandru Georgescu 2013-08-27 07:26:55 UTC

with the sample indicated by Tom, the trace can be viewed.