Bug 440508 - Stack trace from ftrace bears no resemblance to reality
Summary: Stack trace from ftrace bears no resemblance to reality
Alias: None
Product: Fedora
Classification: Fedora
Component: frysk
Version: 9
Hardware: All
OS: Linux
Target Milestone: ---
Assignee: andrew.cagney
QA Contact: Fedora Extras Quality Assurance
Depends On:
TreeView+ depends on / blocked
Reported: 2008-04-03 20:56 UTC by Daniel Berrangé
Modified: 2008-10-27 22:35 UTC (History)
3 users (show)

Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Clone Of:
Last Closed: 2008-10-27 22:35:03 UTC
Type: ---

Attachments (Terms of Use)
6029-backport.patch (4.05 KB, patch)
2008-04-11 21:12 UTC, Mark Wielaard
no flags Details | Diff

System ID Private Priority Status Summary Last Updated
Sourceware 6029 0 None None None Never

Description Daniel Berrangé 2008-04-03 20:56:38 UTC
Description of problem:
I'm using ftrace to track calls to XOpenDisplay in an application, and asking it
to provide a stack trace showing the caller. The stack trace produced bears no
resemblance to reality. The neccessary -debuginfo RPMs are all installed, and
GDB is able to show full, correct stack traces.

Version-Release number of selected component (if applicable):

How reproducible:

Steps to Reproduce:
1. debuginfo-install gedit.x86_64
2. ftrace --dyn=XOpenDisplay --stack /usr/bin/gedit
Actual results:
10615.10615 attached /usr/bin/gedit
INFO: 00:00:00.067 10613.10613 frysk.ftrace.Ftrace: Request for tracing
INFO: 00:00:00.068 10613.10613 frysk.ftrace.Ftrace: Will trace `XOpenDisplay' at
10615.10615 call libX11.so.6->XOpenDisplay(0x0, 0x7f9c1a3ca890, 0x0, 0x0, 0x0,
10615.10615  dumping stack trace:
#0 0x00007f9c20a64411 in _XimProtoGetICValues () from /usr/lib64/libX11.so.6.2.0
#1 0x00007f9c23443328 in gdk_colormap_alloc_colors () from
#2 0x00007f9c23bb83c1 in gtk_option_menu_item_state_changed_cb () from
#3 0x00007f9c21798b90 in [unknown] from /lib64/libglib-2.0.so.0.1600.2
10615.10615 leave XOpenDisplay = 11096592

Expected results:
This trace from GDB shows expected stack trace information

# gdb /usr/bin/gedit
(gdb) break XOpenDisplay
Function "XOpenDisplay" not defined.
Make breakpoint pending on future shared library load? (y or [n]) y
Breakpoint 1 (XOpenDisplay) pending.
(gdb) run
Starting program: /usr/bin/gedit 
[Thread debugging using libthread_db enabled]
[New Thread 0x7f15bb9187b0 (LWP 10606)]
[Switching to Thread 0x7f15bb9187b0 (LWP 10606)]

Breakpoint 1, XOpenDisplay (display=0x0) at OpenDis.c:94
94      {
Missing separate debuginfos, use: debuginfo-install esound.x86_64 keyutils.x86_64
(gdb) bt
#0  XOpenDisplay (display=0x0) at OpenDis.c:94
#1  0x00007f15c49bc60c in IA__gdk_display_open (display_name=0x0) at
#2  0x00007f15c4991328 in IA__gdk_display_open_default_libgtk_only () at gdk.c:288
#3  0x00007f15c51063c1 in post_parse_hook (context=0x10d48a0, group=0x10e8b50,
data=0x10e7080, error=0x7fffcee2d170) at gtkmain.c:725
#4  0x00007f15c2ce6b90 in IA__g_option_context_parse (context=0x10d48a0,
argc=0x7fffcee2d17c, argv=0x7fffcee2d168, 
    error=0x7fffcee2d170) at goption.c:1796
#5  0x00007f15c63413d2 in gnome_program_parse_args (program=0x10e3050) at
#6  0x00007f15c6342543 in gnome_program_init_common (type=17688272,
app_id=0x481de1 "gedit", app_version=0x4773ca "2.22.0", 
    module_info=<value optimized out>, argc=1, argv=0x7fffcee2d4a8,
first_property_name=0x4773ba "goption-context", 
    args=0x7fffcee2d240, nparams=-1, params=0x0) at gnome-program.c:2069
#7  0x00007f15c63427cd in gnome_program_initv (type=0, app_id=0x7f15bb918890
"\001", app_version=0x0, module_info=0x0, argc=0, 
    argv=0x22206b7467203a20, first_property_name=0x4773ba "goption-context",
args=0x7fffcee2d240) at gnome-program.c:2107
#8  0x00007f15c63428c4 in gnome_program_init (app_id=0x481de1 "gedit",
app_version=0x4773ca "2.22.0", module_info=0xeef1e0, argc=1, 
    argv=0x7fffcee2d4a8, first_property_name=0x4773ba "goption-context") at
#9  0x000000000042508d in main (argc=1, argv=0x7fffcee2d4a8) at gedit.c:471

Additional info:

Comment 1 Mark Wielaard 2008-04-11 21:11:35 UTC
On x86 you wouldn't even get a backtrace because of upstream bug 6029. With a
(backported) patch I now get:

$ ~/src/frysk-obj/frysk-core/frysk/bindir/ftrace -dyn XOpenDisplay --stack
3695.3695 attached /usr/bin/gedit
3695.3695 call libX11.so.6->XOpenDisplay(0x0, 0x18, 0xbfb21508, 0x3058d8, 0x1,
3695.3695  dumping stack trace:
Task #3695
#0 0x0397cce0 in XOpenDisplay ()
#1 0x06ee2269 in gdk_display_open ()
#2 0x06eb75b2 in gdk_display_open_default_libgtk_only ()
#3 0x02dd3ea2 in post_parse_hook ()
#4 0x03695980 in g_option_context_parse ()
#5 0x00174985 in gnome_program_parse_args ()
#6 0x001779ed in gnome_program_init_common ()
#7 0x00177d21 in gnome_program_init ()
#8 0x080666e1 in main ()
#9 0x001f1390 in __libc_start_main ()
3695.3695 leave XOpenDisplay = 152252224

Unfortunately ftrace has been completely rewritten upstream and the -dyn option
has been removed. Petr, could you take a look at replicating the above with the
new ftrace? I have attached a backported (to April 1 - commit
73baf44bbc8df85147fc09136607a327e2c9eeb3) patch.

I'll try to replicate on x86_64 next.

Comment 2 Mark Wielaard 2008-04-11 21:12:54 UTC
Created attachment 302171 [details]

Comment 3 Mark Wielaard 2008-04-11 21:14:22 UTC
Petr, please see comment #1

Comment 4 Mark Wielaard 2008-04-11 21:29:50 UTC
I cannot replicate the issue on my x86_64 install, even without the patch:

$ ftrace --dyn=XOpenDisplay --stack /usr/bin/gedit
3559.3559 attached /usr/bin/gedit
INFO: 00:00:00.386 3557.3557 frysk.ftrace.Ftrace: Request for tracing `XOpenDisplay'
INFO: 00:00:00.386 3557.3557 frysk.ftrace.Ftrace: Will trace `XOpenDisplay' at
3559.3559 call libX11.so.6->XOpenDisplay(0x0, 0x0, 0x0, 0x1, 0x6b7a70, 0x20)\
3559.3559  dumping stack trace:
#0 0x00000034e4033531 in XOpenDisplay () from /usr/lib64/libX11.so.6.2.0
#1 0x00000034e164667a in gdk_display_open () from
#2 0x00000034e161a7e9 in gdk_display_open_default_libgtk_only () from
#3 0x00000034deb9c74f in post_parse_hook () from
#4 0x000000358e03bac2 in g_option_context_parse () from
#5 0x0000003575e0b908 in gnome_program_parse_args () from
#6 0x0000003575e0e640 in gnome_program_init_common () from
#7 0x0000003575e0e8cd in gnome_program_initv () from
#8 0x0000003575e0e9c4 in gnome_program_init () from
#9 0x0000000000427425 in main () from /usr/bin/gedit
#10 0x0000003a1681e074 in __libc_start_main () from /lib64/libc-2.7.so
#11 0x0000000000426bb9 in _start () from /usr/bin/gedit
3559.3559 leave XOpenDisplay = 7174544

But this is most likely just luck. If you compare the address that ftrace says
it will trace:
Will trace `XOpenDisplay' at 0x34e4033530

And compare it with the address of the first frame:
#0 0x00000034e4033531 in XOpenDisplay () from /usr/lib64/libX11.so.6.2.0

You see that there is an off-by-one. The same thing holds for the address and
first frame address of the original bug report.

This is exactly what the attached patch addresses. So I expect that the same fix
also holds for x86_64.

Comment 5 Mark Wielaard 2008-04-11 21:36:38 UTC
Confirmed, frame zero on x86_64 on my machine with patch is:
#0 0x00000034e4033530 in XOpenDisplay ()

Comment 6 Petr Machata 2008-04-14 08:54:57 UTC
Use -sym instead of -dyn.  -dyn was variant of -sym for cases where you only had
a dynamic symbol table in the binary.  Now that ftrace uses libdwfl to handle
symbol tables, it is no longer necessary.  On my x86 box, I see this:

$ ./frysk-core/frysk/bindir/ftrace -sym=XOpenDisplay -stack -- /usr/bin/gedit
12427.12427 attached /usr/bin/gedit
12427.12427 call #libX11.so.6#XOpenDisplay(0x0, 0x7714218, 0xbffaab28,
0x7693b54, 0x9c9bcc0, 0xb7b120)\
12427.12427  dumping stack trace:
Task #12427
#0 0x00c17ce0 in XOpenDisplay ()
#1 0x00291269 in gdk_display_open ()
#2 0x002665b2 in gdk_display_open_default_libgtk_only ()
#3 0x078a6ea2 in [unknown]
#4 0x07684980 in g_option_context_parse ()
#5 0x003ca985 in gnome_program_parse_args ()
#6 0x003cd9ed in [unknown]
#7 0x003cdd21 in gnome_program_init ()
#8 0x080666e1 in main ()
#9 0x00a3b390 in __libc_start_main ()
12427.12427 leave #libX11.so.6#XOpenDisplay = 0

(Note that XOpenDisplay gives me NULL, this is a bug that I've just discovered
and filed upstream as #6397)

Comment 7 Mark Wielaard 2008-04-20 14:30:35 UTC
(In reply to comment #6)
> (Note that XOpenDisplay gives me NULL, this is a bug that I've just discovered
> and filed upstream as #6397)

Upstream bug http://sourceware.org/bugzilla/show_bug.cgi?id=6397 has been resolved.

Comment 8 Bug Zapper 2008-05-14 08:38:36 UTC
Changing version to '9' as part of upcoming Fedora 9 GA.
More information and reason for this action is here:

Comment 9 andrew.cagney 2008-10-27 22:35:03 UTC
This is an upstream problem; and has been fixed there.  Look out for the next import.

Note You need to log in before you can comment on or make changes to this bug.