[lttng-dev] [PATCH lttng-ust 0/2] Shared object base address tracing

Woegerer, Paul Paul_Woegerer at mentor.com
Wed Nov 13 05:00:24 EST 2013 

On 11/12/2013 08:59 PM, Alexandre Montplaisir wrote:
> Hi Paul,
>
> I tried your patches. It seems to work quite well!

Glad to hear that :)

> - The events are called "ust_baddr:push" and "ust_baddr:pop". To be
> consistent with the other wrapper libraries in UST, perhaps they should
> be called "ust_dl:dlopen" and "ust_dl:dlclose" or similar?

I leave this up to Mathieu.
I don't mind changing the names to whatever makes most sense for LTTng.

> - Why does the "statedump" event seem to give many more libs than the
> "push" events? Could we be missing some dlopen's? For example, I traced
> glxgears by preloading liblttng-ust-dl.so: http://pastebin.com/HKVa9a4T

Since ust_baddr:push/pop is based on LD_PRELOAD'ing dlopen/dlclose it
can only tell you what shared libraries were opened/closed during the
time you are actually tracing the application. Whatever is
dlopen'ed/dlclose'ed before the tracing infrastructure that is part of
the userspace application (lttng-ust) is becoming fully functional
therefore cannot be captured as ust_baddr:push/pop events.

For that reason we have the statedump mechanism (*) that complements
shared object tracing by telling us what was happening (in respect to
shared library loading) *before* we started (or before we were able) to
trace calls to dlopen/dlclose. Only the two complementary approaches
combined together give you the full picture of shared library loading.

(*) The statedump mechanism iterates the currently open shared objects
with dl_iterate_phdr (see: http://linux.die.net/man/3/dl_iterate_phdr).

BTW, I get a slight different result when I trace glxgears (see attached
glxgears_baddr.txt). I wonder what the reason is.

> - As Matthew suggested, we could also hijack dlsym(), and with its
> parameters we could match a symbol name to an address. This becomes
> immensely useful when coupled with the ust-cyg-profile instrumentation,
> so we can get information about about function names directly in the
> trace! (but ironically, only for the dlopened libraries, and not the
> main binary). What do you think of this approach?

IMHO, hijacking dlsym() is not helping. The only thing you would know is
that somewhere in your code for some reason the address for some symbol
was requested via dlsym(). This will not help you to get symbol
resolution for ust-cyg-profile instrumentation.

In fact, the solution I present already contains all the information
needed to provide full symbol resolution for any address during the
whole lifetime of the traced application. To prove that I have attached
a dump of our trace viewer that shows all the symbols resolved for a
small forking web server example (traced with ust-cyg-profile and custom
tracepoints + ip context enabled) . See attached server_sample.csv and
server_sample_resolved.csv.

> In any case, it's quite interesting!

Thanks!

--
Paul

>
> Cheers,
> Alexandre
>
>
>
> On 13-11-11 10:28 AM, Paul Woegerer wrote:
>> The following two patches implement https://bugs.lttng.org/issues/474
>>
>> The first patch provides tracing of dlopen/dlclose calls with the use of an
>> LD_PRELOAD library (liblttng-ust-dl.so) using the following events:
>>
>>  ust_baddr:push(void *baddr, const char*sopath, int64_t size, int64_t mtime)
>>  ust_baddr:pop(void *baddr)
>>
>> The second patch adds support for tracing the whole state of currently loaded
>> shared objects at session-enable time. The corresponding events are only
>> emitted into the session that got enabled. The following event is used: 
>>
>>  ust_baddr_statedump (same args as ust_baddr:push)
>>
>>
>> Paul Woegerer (2):
>>   Base-address tracing for dlopen and dlclose
>>   Implement base-address-state tracing
>>
>>  Makefile.am                              |   2 +
>>  configure.ac                             |   2 +
>>  include/Makefile.am                      |   1 +
>>  include/lttng/tracepoint.h               |  12 +--
>>  include/lttng/ust-dl.h                   |  54 ++++++++++++
>>  include/lttng/ust-tracepoint-event.h     |  14 +++
>>  liblttng-ust-baddr/Makefile.am           |  20 +++++
>>  liblttng-ust-baddr/lttng-ust-baddr.c     | 111 ++++++++++++++++++++++++
>>  liblttng-ust-baddr/ust_baddr.c           |  20 +++++
>>  liblttng-ust-baddr/ust_baddr.h           |  66 ++++++++++++++
>>  liblttng-ust-baddr/ust_baddr_statedump.c |  21 +++++
>>  liblttng-ust-baddr/ust_baddr_statedump.h |  60 +++++++++++++
>>  liblttng-ust-dl/Makefile.am              |  17 ++++
>>  liblttng-ust-dl/ustdl.c                  | 144 +++++++++++++++++++++++++++++++
>>  liblttng-ust/lttng-events.c              |  10 +++
>>  liblttng-ust/lttng-tracer-core.h         |   2 +
>>  liblttng-ust/lttng-ust-comm.c            |  52 +++++++++++
>>  17 files changed, 603 insertions(+), 5 deletions(-)
>>  create mode 100644 include/lttng/ust-dl.h
>>  create mode 100644 liblttng-ust-baddr/Makefile.am
>>  create mode 100644 liblttng-ust-baddr/lttng-ust-baddr.c
>>  create mode 100644 liblttng-ust-baddr/ust_baddr.c
>>  create mode 100644 liblttng-ust-baddr/ust_baddr.h
>>  create mode 100644 liblttng-ust-baddr/ust_baddr_statedump.c
>>  create mode 100644 liblttng-ust-baddr/ust_baddr_statedump.h
>>  create mode 100644 liblttng-ust-dl/Makefile.am
>>  create mode 100644 liblttng-ust-dl/ustdl.c
>>


-- 
Paul Woegerer, SW Development Engineer
Sourcery Analyzer <http://go.mentor.com/sourceryanalyzer>
Mentor Graphics, Embedded Software Division

-------------- next part --------------
pwoegere at atv-pwoegere-l3:~> lttng create
Session auto-20131113-092537 created.
Traces will be written in /home/pwoegere/lttng-traces/auto-20131113-092537
pwoegere at atv-pwoegere-l3:~> lttng enable-event -u -a
All UST events are enabled in channel channel0
pwoegere at atv-pwoegere-l3:~> lttng start
Tracing started for session auto-20131113-092537
pwoegere at atv-pwoegere-l3:~> LD_PRELOAD=liblttng-ust-dl.so /usr/bin/glxgears
Running synchronized to the vertical refresh.  The framerate should be
approximately the same as the monitor refresh rate.
301 frames in 5.0 seconds = 60.060 FPS
XIO:  fatal IO error 11 (Resource temporarily unavailable) on X server ":0"
      after 1515 requests (1515 known processed) with 0 events remaining.
pwoegere at atv-pwoegere-l3:~> lttng stop
Waiting for data availability.
Tracing stopped for session auto-20131113-092537
pwoegere at atv-pwoegere-l3:~> lttng view
Trace directory: /home/pwoegere/lttng-traces/auto-20131113-092537

[warning] Skipping directory 'index' found in trace
[09:27:04.774912693] (+?.?????????) atv-pwoegere-l3.atv.mentorg.com ust_baddr_statedump:soinfo: { cpu_id = 5 }, { baddr = 0x400000, sopath = "/usr/lib64/mesa-demos/xdemos/glxgears", size = 23360, mtime = 1381596745 }
[09:27:04.774922939] (+0.000010246) atv-pwoegere-l3.atv.mentorg.com ust_baddr_statedump:soinfo: { cpu_id = 5 }, { baddr = 0x7FFF8A1DD000, sopath = "[linux-vdso.so.1]", size = 0, mtime = -1 }
[09:27:04.774930406] (+0.000007467) atv-pwoegere-l3.atv.mentorg.com ust_baddr_statedump:soinfo: { cpu_id = 5 }, { baddr = 0x7F8E2AA4E000, sopath = "/home/pwoegere/MGC/lttng2_stack_latest_install/lib64/liblttng-ust-dl.so.0.0.0", size = 21500, mtime = 1384181281 }
[09:27:04.774936424] (+0.000006018) atv-pwoegere-l3.atv.mentorg.com ust_baddr_statedump:soinfo: { cpu_id = 5 }, { baddr = 0x7F8E2A7F0000, sopath = "/usr/lib64/libGL.so.1.2.0", size = 380976, mtime = 1382866191 }
[09:27:04.774940192] (+0.000003768) atv-pwoegere-l3.atv.mentorg.com ust_baddr_statedump:soinfo: { cpu_id = 5 }, { baddr = 0x7F8E2A4F2000, sopath = "/lib64/libm-2.17.so", size = 1109606, mtime = 1379513990 }
[09:27:04.774945488] (+0.000005296) atv-pwoegere-l3.atv.mentorg.com ust_baddr_statedump:soinfo: { cpu_id = 5 }, { baddr = 0x7F8E2A1B6000, sopath = "/usr/lib64/libX11.so.6.3.0", size = 1294064, mtime = 1380577077 }
[09:27:04.774948793] (+0.000003305) atv-pwoegere-l3.atv.mentorg.com ust_baddr_statedump:soinfo: { cpu_id = 5 }, { baddr = 0x7F8E29E08000, sopath = "/lib64/libc-2.17.so", size = 1996294, mtime = 1379513989 }
[09:27:04.774955069] (+0.000006276) atv-pwoegere-l3.atv.mentorg.com ust_baddr_statedump:soinfo: { cpu_id = 5 }, { baddr = 0x7F8E29BBF000, sopath = "/home/pwoegere/MGC/lttng2_stack_latest_install/lib64/liblttng-ust.so.0.0.0", size = 1611934, mtime = 1384181281 }
[09:27:04.774961151] (+0.000006082) atv-pwoegere-l3.atv.mentorg.com ust_baddr_statedump:soinfo: { cpu_id = 5 }, { baddr = 0x7F8E299A5000, sopath = "/home/pwoegere/MGC/lttng2_stack_latest_install/lib64/liblttng-ust-tracepoint.so.0.0.0", size = 138864, mtime = 1384181280 }
[09:27:04.774964667] (+0.000003516) atv-pwoegere-l3.atv.mentorg.com ust_baddr_statedump:soinfo: { cpu_id = 5 }, { baddr = 0x7F8E2979D000, sopath = "/lib64/librt-2.17.so", size = 42706, mtime = 1379513990 }
[09:27:04.774967809] (+0.000003142) atv-pwoegere-l3.atv.mentorg.com ust_baddr_statedump:soinfo: { cpu_id = 5 }, { baddr = 0x7F8E29599000, sopath = "/lib64/libdl-2.17.so", size = 19016, mtime = 1379513990 }
[09:27:04.774973714] (+0.000005905) atv-pwoegere-l3.atv.mentorg.com ust_baddr_statedump:soinfo: { cpu_id = 5 }, { baddr = 0x7F8E29392000, sopath = "/home/pwoegere/MGC/lttng2_stack_latest_install/lib64/liburcu-bp.so.2.0.0", size = 108574, mtime = 1381992197 }
[09:27:04.774979504] (+0.000005790) atv-pwoegere-l3.atv.mentorg.com ust_baddr_statedump:soinfo: { cpu_id = 5 }, { baddr = 0x7F8E2918A000, sopath = "/home/pwoegere/MGC/lttng2_stack_latest_install/lib64/liburcu-cds.so.2.0.0", size = 162940, mtime = 1381992197 }
[09:27:04.774985314] (+0.000005810) atv-pwoegere-l3.atv.mentorg.com ust_baddr_statedump:soinfo: { cpu_id = 5 }, { baddr = 0x7F8E28F86000, sopath = "/home/pwoegere/MGC/lttng2_stack_latest_install/lib64/liburcu-common.so.2.0.0", size = 86456, mtime = 1381992197 }
[09:27:04.774988677] (+0.000003363) atv-pwoegere-l3.atv.mentorg.com ust_baddr_statedump:soinfo: { cpu_id = 5 }, { baddr = 0x7F8E28D6A000, sopath = "/lib64/libpthread-2.17.so", size = 131133, mtime = 1379513990 }
[09:27:04.774992806] (+0.000004129) atv-pwoegere-l3.atv.mentorg.com ust_baddr_statedump:soinfo: { cpu_id = 5 }, { baddr = 0x7F8E28B44000, sopath = "/usr/lib64/libglapi.so.0.0.0", size = 150016, mtime = 1382866195 }
[09:27:04.774996621] (+0.000003815) atv-pwoegere-l3.atv.mentorg.com ust_baddr_statedump:soinfo: { cpu_id = 5 }, { baddr = 0x7F8E28932000, sopath = "/usr/lib64/libXext.so.6.4.0", size = 73864, mtime = 1380578949 }
[09:27:04.775000324] (+0.000003703) atv-pwoegere-l3.atv.mentorg.com ust_baddr_statedump:soinfo: { cpu_id = 5 }, { baddr = 0x7F8E2872F000, sopath = "/usr/lib64/libXdamage.so.1.1.0", size = 10424, mtime = 1380582326 }
[09:27:04.775004059] (+0.000003735) atv-pwoegere-l3.atv.mentorg.com ust_baddr_statedump:soinfo: { cpu_id = 5 }, { baddr = 0x7F8E28529000, sopath = "/usr/lib64/libXfixes.so.3.1.0", size = 22736, mtime = 1380579302 }
[09:27:04.775008109] (+0.000004050) atv-pwoegere-l3.atv.mentorg.com ust_baddr_statedump:soinfo: { cpu_id = 5 }, { baddr = 0x7F8E28327000, sopath = "/usr/lib64/libX11-xcb.so.1.0.0", size = 6160, mtime = 1380577076 }
[09:27:04.775013524] (+0.000005415) atv-pwoegere-l3.atv.mentorg.com ust_baddr_statedump:soinfo: { cpu_id = 5 }, { baddr = 0x7F8E2810F000, sopath = "/usr/lib64/libxcb-glx.so.0.0.0", size = 96464, mtime = 1382344054 }
[09:27:04.775017240] (+0.000003716) atv-pwoegere-l3.atv.mentorg.com ust_baddr_statedump:soinfo: { cpu_id = 5 }, { baddr = 0x7F8E27F0A000, sopath = "/usr/lib64/libxcb-dri2.so.0.0.0", size = 18656, mtime = 1382344054 }
[09:27:04.775022385] (+0.000005145) atv-pwoegere-l3.atv.mentorg.com ust_baddr_statedump:soinfo: { cpu_id = 5 }, { baddr = 0x7F8E27CEA000, sopath = "/usr/lib64/libxcb.so.1.1.0", size = 129920, mtime = 1382344056 }
[09:27:04.775026302] (+0.000003917) atv-pwoegere-l3.atv.mentorg.com ust_baddr_statedump:soinfo: { cpu_id = 5 }, { baddr = 0x7F8E27AE4000, sopath = "/usr/lib64/libXxf86vm.so.1.0.0", size = 22912, mtime = 1380582136 }
[09:27:04.775030152] (+0.000003850) atv-pwoegere-l3.atv.mentorg.com ust_baddr_statedump:soinfo: { cpu_id = 5 }, { baddr = 0x7F8E278D8000, sopath = "/usr/lib64/libdrm.so.2.4.0", size = 47696, mtime = 1382865247 }
[09:27:04.775033421] (+0.000003269) atv-pwoegere-l3.atv.mentorg.com ust_baddr_statedump:soinfo: { cpu_id = 5 }, { baddr = 0x7F8E2AC51000, sopath = "/lib64/ld-2.17.so", size = 163493, mtime = 1379513989 }
[09:27:04.775037205] (+0.000003784) atv-pwoegere-l3.atv.mentorg.com ust_baddr_statedump:soinfo: { cpu_id = 5 }, { baddr = 0x7F8E276D4000, sopath = "/usr/lib64/libXau.so.6.0.0", size = 14640, mtime = 1380536554 }
[09:27:04.775042540] (+0.000005335) atv-pwoegere-l3.atv.mentorg.com ust_baddr_statedump:soinfo: { cpu_id = 5 }, { baddr = 0x7F8E26100000, sopath = "/home/pwoegere/MGC/lttng2_stack_latest_install/lib64/liblttng-ust-baddr.so.0.0.0", size = 77469, mtime = 1384181281 }
[09:27:04.776345452] (+0.001302912) atv-pwoegere-l3.atv.mentorg.com ust_baddr:push: { cpu_id = 4 }, { baddr = 0x7F8E2A7F0000, sopath = "/usr/lib64/libGL.so.1.2.0", size = 380976, mtime = 1382866191 }
[09:27:04.795393509] (+0.019048057) atv-pwoegere-l3.atv.mentorg.com ust_baddr:push: { cpu_id = 4 }, { baddr = 0x7F8E256DD000, sopath = "/usr/lib64/dri/r600_dri.so", size = 6560344, mtime = 1382866182 }
[09:27:04.795397917] (+0.000004408) atv-pwoegere-l3.atv.mentorg.com ust_baddr:pop: { cpu_id = 4 }, { baddr = 0x7F8E2A7F0000 }
pwoegere at atv-pwoegere-l3:~> lttng destroy
Session auto-20131113-092537 destroyed

-------------- next part --------------
A non-text attachment was scrubbed...
Name: server_sample.csv
Type: text/csv
Size: 34540 bytes
Desc: not available
URL: <http://lists.lttng.org/pipermail/lttng-dev/attachments/20131113/ece892e2/attachment-0002.csv>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: server_sample_resolved.csv
Type: text/csv
Size: 35382 bytes
Desc: not available
URL: <http://lists.lttng.org/pipermail/lttng-dev/attachments/20131113/ece892e2/attachment-0003.csv>

More information about the lttng-dev mailing list