[ltt-dev] Problem with metadata_0 file

Fri Sep 9 08:42:04 EDT 2011

Hello,

I am having a problem with the LTT UST/rcu tools on a PowerPC (440)
system and am hoping someone can help determine what may be wrong.

UST version is 0.15.
Userspace-rcu version is 0.6.4.

The main trouble seems to come from the resulting metadata_0 file being
essentially empty.  The header seems to be present, but the various
marker entries are absent.

I compiled UST and userspace-rcu natively on the PowerPC 440 target (gcc
4.2.4) and also natively on a Fedora 9 x86 host system (gcc 4.3.0-8),
both with the UST_DEBUG flag enabled.  Using the sample code as a
reference on both systems, the usttrace output is different (the PowerPC
case registers 3 ust_marker sections while the Fedora x86 case registers
6 around line 5 of each output):

>From the PowerPC system:

~/ltt/sample# usttrace ./foo
libust[28460/28460]: Tracectl constructor (in init() at tracectl.c:1288)
libust[28460/28462]: LISTENER (in listener_main() at tracectl.c:1095)
libust[28460/28460]: UST traces will not be synchronized with LTTng
traces (in init() at tracectl.c:1313)
libust[28460/28460]: just registered a tracepoints section from
0x10012130 and having 1 tracepoints (minus dummy tracepoints) (in
tracepoint_register_lib() at tracepoint.c:668)
libust[28460/28460]: just registered a ust_marker section from
0x10012124 and having 3 ust_marker (minus dummy ust_marker) (in
ust_marker_register_lib() at marker.c:1165)
libust[28460/28460]: Autoprobe enabled. (in init() at tracectl.c:1325)
libust[28460/28460]: now iterating on ust_marker already registered (in
init() at tracectl.c:1352)
libust[28460/28460]: now iterating on ust_marker myotherevent (in init()
at tracectl.c:1354)
libust[28460/28460]: auto connected ust_marker ust (addr: 0x10012138)
myotherevent to probe default (in auto_probe_connect() at
tracectl.c:1221)
libust[28460/28460]: now iterating on ust_marker myevent (in init() at
tracectl.c:1354)
libust[28460/28460]: auto connected ust_marker ust (addr: 0x10012164)
myevent to probe default (in auto_probe_connect() at tracectl.c:1221)
libust[28460/28460]: starting early tracing (in init() at
tracectl.c:1400)
libust[28460/28460]: Connecting to daemon_path
/tmp/ust-consumerd-sock-28448 (in connect_ustconsumer() at
tracectl.c:152)
libust[28460/28460]: Connected to ustconsumer (in
inform_consumer_daemon() at tracectl.c:216)
libust[28460/28462]: get_buffer_shmid_pipe_fd (in
get_buffer_shmid_pipe_fd() at tracectl.c:269)
libust[28460/28462]: get_subbuf_size (in get_subbuf_num_size() at
tracectl.c:301)
libust[28460/28462]: get_buffer_fd (in notify_buffer_mapped() at
tracectl.c:465)
libust[28460/28462]: decrementing buffers_to_export (in
notify_buffer_mapped() at tracectl.c:489)
libust[28460/28460]: just registered a trace_events section from
0x10012134 and having 1 trace_events (minus dummy trace_event) (in
trace_event_register_lib() at trace_event.c:175)
libust[28460/28460]: just registered a tracepoints section from
0x10012130 and having 1 tracepoints (minus dummy tracepoints) (in
tracepoint_register_lib() at tracepoint.c:668)
libust[28460/28460]: auto connected ust_marker ust (addr: 0x10012138)
myotherevent to probe default (in auto_probe_connect() at
tracectl.c:1221)
libust[28460/28460]: auto connected ust_marker ust (addr: 0x10012164)
myevent to probe default (in auto_probe_connect() at tracectl.c:1221)
libust[28460/28460]: just registered a ust_marker section from
0x10012124 and having 3 ust_marker (minus dummy ust_marker) (in
ust_marker_register_lib() at marker.c:1165)
libust[28460/28460]: commit_seq for channel ust_0, subbuf 0 is now 104
(in ltt_write_commit_counter() at buffers.h:551)
libust[28460/28460]: just commited event (ust/myevent) at offset 84 and
size 36 (in ltt_vtrace() at serialize.c:745)
libust[28460/28460]: commit_seq for channel ust_0, subbuf 0 is now 120
(in ltt_write_commit_counter() at buffers.h:551)
libust[28460/28460]: just commited event (ust/myotherevent) at offset
120 and size 16 (in ltt_vtrace() at serialize.c:745)
libust[28460/28460]: Keeping process alive for consumer daemon... (in
keepalive() at tracectl.c:1561)
libust[28460/28462]: get_buffer_shmid_pipe_fd (in
get_buffer_shmid_pipe_fd() at tracectl.c:269)
libust[28460/28462]: get_subbuf_size (in get_subbuf_num_size() at
tracectl.c:301)
libust[28460/28462]: get_buffer_fd (in notify_buffer_mapped() at
tracectl.c:465)
libust[28460/28462]: decrementing buffers_to_export (in
notify_buffer_mapped() at tracectl.c:489)
libust[28460/28460]: Finally dying... (in keepalive() at
tracectl.c:1572)
libust[28460/28460]: destructor stopping traces (in destroy_traces() at
tracectl.c:1479)
libust[28460/28460]: Switching (forced) metadata_0 (in
ltt_force_switch_lockless_slow() at buffers.c:841)
libust[28460/28462]: get_subbuf (in get_subbuffer() at tracectl.c:422)
libust[28460/28462]: Cannot find trace. It was likely destroyed by the
user. (in get_subbuffer() at tracectl.c:430)
libust[28460/28460]: commit_seq for channel metadata_0, subbuf 0 is now
1048576 (in ltt_write_commit_counter() at buffers.h:551)
libust[28460/28460]: Switching (forced) ust_0 (in
ltt_force_switch_lockless_slow() at buffers.c:841)
libust[28460/28460]: commit_seq for channel ust_0, subbuf 0 is now
1048576 (in ltt_write_commit_counter() at buffers.h:551) Waiting for
ust-consumerd to shutdown...
Trace was output in:
/home/root/.usttraces/mcb00-main-sju1426008h-20110908175451255956058

>From the Fedora 9 system:
[Luccisa at torlxemb15 sample]$ usttrace ./ustsample
libust[18229/18229]: Tracectl constructor (in init() at tracectl.c:1288)
libust[18229/18230]: LISTENER (in listener_main() at tracectl.c:1095)
libust[18229/18229]: UST traces will not be synchronized with LTTng
traces (in init() at tracectl.c:1313)
libust[18229/18229]: just registered a tracepoints section from 0x1cd8cc
and having 1 tracepoints (minus dummy tracepoints) (in
tracepoint_register_lib() at tracepoint.c:668)
libust[18229/18229]: just registered a ust_marker section from 0x1cd73c
and having 6 ust_marker (minus dummy ust_marker) (in
ust_marker_register_lib() at marker.c:1165)
libust[18229/18229]: Autoprobe enabled. (in init() at tracectl.c:1325)
libust[18229/18229]: now iterating on ust_marker already registered (in
init() at tracectl.c:1352)
libust[18229/18229]: now iterating on ust_marker core_marker_format (in
init() at tracectl.c:1354)
libust[18229/18229]: auto connected ust_marker metadata (addr: 0x1cd760)
core_marker_format to probe default (in auto_probe_connect() at
tracectl.c:1221)
libust[18229/18229]: now iterating on ust_marker core_marker_format (in
init() at tracectl.c:1354)
libust[18229/18229]: auto connected ust_marker metadata (addr: 0x1cd7a0)
core_marker_format to probe default (in auto_probe_connect() at
tracectl.c:1221)
libust[18229/18229]: now iterating on ust_marker core_marker_id (in
init() at tracectl.c:1354)
libust[18229/18229]: auto connected ust_marker metadata (addr: 0x1cd7e0)
core_marker_id to probe default (in auto_probe_connect() at
tracectl.c:1221)
libust[18229/18229]: now iterating on ust_marker core_marker_format (in
init() at tracectl.c:1354)
libust[18229/18229]: auto connected ust_marker metadata (addr: 0x1cd820)
core_marker_format to probe default (in auto_probe_connect() at
tracectl.c:1221)
libust[18229/18229]: now iterating on ust_marker core_marker_id (in
init() at tracectl.c:1354)
libust[18229/18229]: auto connected ust_marker metadata (addr: 0x1cd860)
core_marker_id to probe default (in auto_probe_connect() at
tracectl.c:1221)
libust[18229/18229]: now iterating on ust_marker potential_exec (in
init() at tracectl.c:1354)
libust[18229/18229]: auto connected ust_marker ust (addr: 0x1cd8a0)
potential_exec to probe default (in auto_probe_connect() at
tracectl.c:1221)
libust[18229/18229]: starting early tracing (in init() at
tracectl.c:1400)
libust[18229/18229]: commit_seq for channel metadata_0, subbuf 0 is now
110 (in ltt_write_commit_counter() at buffers.h:551)
libust[18229/18229]: just commited event (metadata/core_marker_id) at
offset 84 and size 42 (in ltt_vtrace() at serialize.c:745)
libust[18229/18229]: commit_seq for channel metadata_0, subbuf 0 is now
147 (in ltt_write_commit_counter() at buffers.h:551)
libust[18229/18229]: just commited event (metadata/core_marker_format)
at offset 126 and size 37 (in ltt_vtrace() at serialize.c:745)
libust[18229/18229]: commit_seq for channel metadata_0, subbuf 0 is now
198 (in ltt_write_commit_counter() at buffers.h:551)
libust[18229/18229]: just commited event (metadata/core_marker_id) at
offset 163 and size 51 (in ltt_vtrace() at serialize.c:745)
libust[18229/18229]: commit_seq for channel metadata_0, subbuf 0 is now
271 (in ltt_write_commit_counter() at buffers.h:551)
libust[18229/18229]: just commited event (metadata/core_marker_format)
at offset 214 and size 73 (in ltt_vtrace() at serialize.c:745)
libust[18229/18229]: commit_seq for channel metadata_0, subbuf 0 is now
318 (in ltt_write_commit_counter() at buffers.h:551)
libust[18229/18229]: just commited event (metadata/core_marker_id) at
offset 287 and size 47 (in ltt_vtrace() at serialize.c:745)
libust[18229/18229]: commit_seq for channel metadata_0, subbuf 0 is now
458 (in ltt_write_commit_counter() at buffers.h:551)
libust[18229/18229]: just commited event (metadata/core_marker_format)
at offset 334 and size 140 (in ltt_vtrace() at serialize.c:745)
libust[18229/18229]: Connecting to daemon_path
/tmp/ust-consumerd-sock-18217 (in connect_ustconsumer() at
tracectl.c:152)
libust[18229/18229]: Connected to ustconsumer (in
inform_consumer_daemon() at tracectl.c:216)
libust[18229/18230]: get_buffer_shmid_pipe_fd (in
get_buffer_shmid_pipe_fd() at tracectl.c:269)
libust[18229/18229]: commit_seq for channel metadata_0, subbuf 0 is now
498 (in ltt_write_commit_counter() at buffers.h:551)
libust[18229/18229]: just commited event (metadata/core_marker_id) at
offset 474 and size 40 (in ltt_vtrace() at serialize.c:745)
libust[18229/18229]: commit_seq for channel metadata_0, subbuf 0 is now
533 (in ltt_write_commit_counter() at buffers.h:551)
libust[18229/18229]: just commited event (metadata/core_marker_format)
at offset 514 and size 35 (in ltt_vtrace() at serialize.c:745)
libust[18229/18229]: auto connected ust_marker ust (addr: 0x8049b60)
myotherevent to probe default (in auto_probe_connect() at
tracectl.c:1221)
libust[18229/18230]: get_subbuf_size (in get_subbuf_num_size() at
tracectl.c:301)
libust[18229/18230]: get_buffer_fd (in notify_buffer_mapped() at
tracectl.c:465)
libust[18229/18230]: decrementing buffers_to_export (in
notify_buffer_mapped() at tracectl.c:489)
libust[18229/18230]: get_buffer_shmid_pipe_fd (in
get_buffer_shmid_pipe_fd() at tracectl.c:269)
libust[18229/18230]: get_subbuf_size (in get_subbuf_num_size() at
tracectl.c:301)
libust[18229/18230]: get_buffer_fd (in notify_buffer_mapped() at
tracectl.c:465)
libust[18229/18230]: decrementing buffers_to_export (in
notify_buffer_mapped() at tracectl.c:489)
libust[18229/18229]: commit_seq for channel metadata_0, subbuf 0 is now
568 (in ltt_write_commit_counter() at buffers.h:551)
libust[18229/18229]: just commited event (metadata/core_marker_id) at
offset 549 and size 35 (in ltt_vtrace() at serialize.c:745)
libust[18229/18229]: commit_seq for channel metadata_0, subbuf 0 is now
621 (in ltt_write_commit_counter() at buffers.h:551)
libust[18229/18229]: just commited event (metadata/core_marker_format)
at offset 584 and size 53 (in ltt_vtrace() at serialize.c:745)
libust[18229/18229]: auto connected ust_marker ust (addr: 0x8049ba0)
myevent to probe default (in auto_probe_connect() at tracectl.c:1221)
libust[18229/18229]: just registered a ust_marker section from 0x8049b34
and having 3 ust_marker (minus dummy ust_marker) (in
ust_marker_register_lib() at marker.c:1165)
libust[18229/18229]: just registered a tracepoints section from
0x8049b40 and having 1 tracepoints (minus dummy tracepoints) (in
tracepoint_register_lib() at tracepoint.c:668)
libust[18229/18229]: just registered a trace_events section from
0x8049b44 and having 1 trace_events (minus dummy trace_event) (in
trace_event_register_lib() at trace_event.c:175)
libust[18229/18229]: commit_seq for channel ust_0, subbuf 0 is now 102
(in ltt_write_commit_counter() at buffers.h:551)
libust[18229/18229]: just commited event (ust/myevent) at offset 84 and
size 34 (in ltt_vtrace() at serialize.c:745)
libust[18229/18229]: commit_seq for channel ust_0, subbuf 0 is now 118
(in ltt_write_commit_counter() at buffers.h:551)
libust[18229/18229]: just commited event (ust/myotherevent) at offset
118 and size 16 (in ltt_vtrace() at serialize.c:745)
libust[18229/18229]: destructor stopping traces (in destroy_traces() at
tracectl.c:1479)
libust[18229/18229]: Switching (forced) metadata_0 (in
ltt_force_switch_lockless_slow() at buffers.c:841)
libust[18229/18230]: get_subbuf (in get_subbuffer() at tracectl.c:422)
libust[18229/18230]: Cannot find trace. It was likely destroyed by the
user. (in get_subbuffer() at tracectl.c:430)
libust[18229/18229]: commit_seq for channel metadata_0, subbuf 0 is now
1048576 (in ltt_write_commit_counter() at buffers.h:551)
libust[18229/18229]: Switching (forced) ust_0 (in
ltt_force_switch_lockless_slow() at buffers.c:841)
libust[18229/18230]: get_subbuf (in get_subbuffer() at tracectl.c:422)
libust[18229/18230]: Cannot find trace. It was likely destroyed by the
user. (in get_subbuffer() at tracectl.c:430)
libust[18229/18229]: commit_seq for channel ust_0, subbuf 0 is now
1048576 (in ltt_write_commit_counter() at buffers.h:551) Waiting for
ust-consumerd to shutdown...
Trace was output in:
/home/Luccisa/.usttraces/torlxemb15.cisco.com-20110908135746874823225

In looking through the code, it is obvious that
ust_marker_register_lib() is called with __start__ust_marker_ptrs as an
argument, and this is where I'm thinking there may be a difference
between x86 and PowerPC.  I do not understand how
__start__ust_marker_ptrs is populated/generated.

Can anyone help point me in the right direction to determine why the
metadata_0 file is not being generated correctly and if the differences
above are related to that problem?

Regards,
Alex Luccisano