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@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 _______________________________________________ ltt-dev mailing list [email protected] http://lists.casi.polymtl.ca/cgi-bin/mailman/listinfo/ltt-dev
