Bug 556975 - Variables optimized out (python)
Summary: Variables optimized out (python)
Keywords:
Status: CLOSED EOL
Alias: None
Product: Fedora
Classification: Fedora
Component: gcc
Version: 19
Hardware: x86_64
OS: Linux
low
medium
Target Milestone: ---
Assignee: Jakub Jelinek
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard:
Depends On:
Blocks: 557772 558977 1187759
TreeView+ depends on / blocked
 
Reported: 2010-01-20 00:10 UTC by Dave Malcolm
Modified: 2015-02-18 13:25 UTC (History)
14 users (show)

Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Clone Of:
: 557772 1187759 (view as bug list)
Environment:
Last Closed: 2015-02-18 13:25:38 UTC
Type: ---
Embargoed:


Attachments (Terms of Use)
Postprocessed code via gcc -E (432.01 KB, text/plain)
2010-01-20 15:26 UTC, Dave Malcolm
no flags Details
parsetok.c.bz2 (32.40 KB, application/octet-stream)
2010-01-25 10:15 UTC, Jakub Jelinek
no flags Details
ceval.i.bz2 (49.89 KB, application/octet-stream)
2010-03-26 09:25 UTC, Jakub Jelinek
no flags Details
sdsdfd (1.47 MB, application/octet-stream)
2011-11-30 03:04 UTC, Duc
no flags Details

Description Dave Malcolm 2010-01-20 00:10:27 UTC
Description of problem:
The most significant function for debugging the Python runtime is probably "PyEval_EvalFrameEx", and the two most significant variables within it are the local "PyObject* co" and the parameter "PyFrameObject *f"  (this is a complicated function; see http://svn.python.org/view/python/trunk/Python/ceval.c?view=markup for the implementation).

In F-12 and earlier, these variables were queryable in gdb.

In rawhide, these variables are no longer queryable, and this makes it almost impossible to debug issues within the runtime (see e.g. bug 556584) - I need to be able to access these variables to determine what Python-level code is being executed.

I'm seeing similar behavior in a local rebuild of the Python rpm:

(gdb) frame 9
#9  PyEval_EvalFrameEx (f=<value optimized out>, throwflag=<value optimized out>) at Python/ceval.c:2389
2389				x = call_function(&sp, oparg);
(gdb) p co
$1 = <value optimized out>
(gdb) p f
$7 = <value optimized out>

local build of python-2.6.2-3.fc12.i386, built with gcc-4.4.2-20.fc12.i686; investigating with "eu-readelf -w /usr/lib/debug/usr/lib/libpython2.6.so.debug" shows:

 [ 9178a]    subprogram
             external             Yes
             name                 "PyEval_EvalFrameEx"
             decl_file            1
             decl_line            542
             prototyped           Yes
             type                 [ 8ee95]
             low_pc               +0x000bf410 <PyEval_EvalFrameEx>
             high_pc              +0x000c4e86
             frame_base                         [   0] call_frame_cfa
             sibling              [ 92543]
(snip)
 [ 917a6]      formal_parameter
               name                 "f"
               decl_file            1
               decl_line            542
               type                 [ 9046a]
               location             location list [ 5c893]
(snip)
 [ 918b2]      variable
               name                 "co"
               decl_file            1
               decl_line            562
               type                 [ 90219]

(no location in that last one)
f's location:
 [ 5c893]  +0x000012c0..+0x00001306 [   0] fbreg 0
           +0x00001ae7..+0x00001af4 [   0] fbreg 0

Any ideas what I can do to get visibility back on these variables?  Is there a way of hinting to the toolchain that a variable is important for debugging?  (I'd rather not turn down optimization if possible; this is a performance-critical part of the code).  Could this be a recent change in gcc?  I'm willing to do some experimental rebuilds if you can give me some pointers on other gcc versions.

This is blocking: https://fedoraproject.org/wiki/Features/Python3F13
See also http://sourceware.org/ml/archer/2009-q4/msg00129.html

Seen whilst debugging bug 556584: python-2.6.4-6.fc13: i686 build here: http://koji.fedoraproject.org/koji/taskinfo?taskID=1930187 
Buildroot components here: http://koji.fedoraproject.org/koji/rpmlist?buildrootID=693709&type=component
giving: gcc-4.4.2-20.fc13.i686.rpm

Version-Release number of selected component (if applicable):
gcc-4.4.2-20.fc13.i686.rpm

Comment 1 Dave Malcolm 2010-01-20 00:15:24 UTC
> This is blocking: https://fedoraproject.org/wiki/Features/Python3F13
Oops; this should have been:
https://fedoraproject.org/wiki/Features/EasierPythonDebugging

Comment 2 Jakub Jelinek 2010-01-20 00:16:30 UTC
Please attach preprocessed source and gcc options used to compile it, on which this can be investigated.
This could very well be http://gcc.gnu.org/PR42782 for which Alex posted yesterday
a patch: http://gcc.gnu.org/ml/gcc-patches/2010-01/msg01027.html

Comment 3 Dave Malcolm 2010-01-20 15:25:31 UTC
Thanks.

Looks like I'm getting "almost everything" optimized out in my builds.

[david@brick Python-2.6.2]$ rpm -q gcc
gcc-4.4.2-20.fc12.i686

Command line used in the build:
[david@brick Python-2.6.2]$ gcc -pthread -c -fno-strict-aliasing -DNDEBUG -O2 -g -pipe -Wall -Wp,-D_FORTIFY_SOURCE=2 -fexceptions -fstack-protector --param=ssp-buffer-size=4 -m32 -march=i386 -mtune=generic -fasynchronous-unwind-tables -D_GNU_SOURCE -fPIC  -I. -IInclude -I./Include -I/usr/lib/libffi-3.0.5/include   -fPIC -DPy_BUILD_CORE -o Python/ceval.o Python/ceval.c

Adding "-E" to front to as per "man gcc" (this is for my own reference, I had to look this one up):
       -E  Stop after the preprocessing stage; do not run the compiler proper.  The output is in the form of preprocessed source code, which
           is sent to the standard output.

[david@brick Python-2.6.2]$ gcc -E -pthread -c -fno-strict-aliasing -DNDEBUG -O2 -g -pipe -Wall -Wp,-D_FORTIFY_SOURCE=2 -fexceptions -fstack-protector --param=ssp-buffer-size=4 -m32 -march=i386 -mtune=generic -fasynchronous-unwind-tables -D_GNU_SOURCE -fPIC  -I. -IInclude -I./Include -I/usr/lib/libffi-3.0.5/include   -fPIC -DPy_BUILD_CORE -o Python/ceval.o Python/ceval.c

leading to Python/ceval.o being the postprocessed source, which I'll attach directly.

Comment 4 Dave Malcolm 2010-01-20 15:26:39 UTC
Created attachment 385701 [details]
Postprocessed code via gcc -E

Please let me know if there's any other information you need

Comment 5 Dave Malcolm 2010-01-20 15:32:33 UTC
(In reply to comment #3)
> Thanks.
> 
> Looks like I'm getting "almost everything" optimized out in my builds.

What I meant by this is that almost all of the parameters in the following backtrace read "<value optimized out>", and, within the frames, most locals appear to be "<value optimized out>" as well:

[david@brick Python-2.6.2]$ gdb ./python
GNU gdb (GDB) 7.0
  [  snip ]
(gdb) run
Starting program: /home/david/coding/cvs-fedora/python/F-12/Python-2.6.2/python 
[Thread debugging using libthread_db enabled]
Python 2.6.2 (r262:71600, Jan 17 2010, 11:06:21) 
[GCC 4.4.2 20091222 (Red Hat 4.4.2-20)] on linux2
Type "help", "copyright", "credits" or "license" for more information.
>>> 
Program received signal SIGINT, Interrupt.
0x001ec424 in __kernel_vsyscall ()

(gdb) bt
#0  0x001ec424 in __kernel_vsyscall ()
#1  0x00516ded in ___newselect_nocancel () at ../sysdeps/unix/syscall-template.S:82
#2  0x00977a4c in readline_until_enter_or_signal (sys_stdin=<value optimized out>, sys_stdout=<value optimized out>, prompt=<value optimized out>)
    at ./Modules/readline.c:864
#3  call_readline (sys_stdin=<value optimized out>, sys_stdout=<value optimized out>, prompt=<value optimized out>) at ./Modules/readline.c:958
#4  0x04efd6f0 in PyOS_Readline (sys_stdin=<value optimized out>, sys_stdout=<value optimized out>, prompt=<value optimized out>) at Parser/myreadline.c:208
#5  0x04efecda in tok_nextc (tok=<value optimized out>) at Parser/tokenizer.c:784
#6  0x04eff4a7 in tok_get (tok=<value optimized out>, p_start=<value optimized out>, p_end=<value optimized out>) at Parser/tokenizer.c:1131
#7  PyTokenizer_Get (tok=<value optimized out>, p_start=<value optimized out>, p_end=<value optimized out>) at Parser/tokenizer.c:1571
#8  0x04efa877 in parsetok (tok=<value optimized out>, g=<value optimized out>, start=<value optimized out>, err_ret=<value optimized out>, 
    flags=<value optimized out>) at Parser/parsetok.c:159
#9  0x04fba54c in PyParser_ASTFromFile (fp=<value optimized out>, filename=<value optimized out>, start=<value optimized out>, ps1=<value optimized out>, 
    ps2=<value optimized out>, flags=<value optimized out>, errcode=<value optimized out>, arena=<value optimized out>) at Python/pythonrun.c:1458
#10 0x04fbc434 in PyRun_InteractiveOneFlags (fp=<value optimized out>, filename=<value optimized out>, flags=<value optimized out>)
    at Python/pythonrun.c:820
#11 0x04fbc6ab in PyRun_InteractiveLoopFlags (fp=<value optimized out>, filename=<value optimized out>, flags=<value optimized out>)
    at Python/pythonrun.c:760
#12 0x04fbc7eb in PyRun_AnyFileExFlags (fp=<value optimized out>, filename=<value optimized out>, closeit=<value optimized out>, 
    flags=<value optimized out>) at Python/pythonrun.c:729
#13 0x04fc9212 in Py_Main (argc=<value optimized out>, argv=<value optimized out>) at Modules/main.c:599
#14 0x080485c7 in main (argc=<value optimized out>, argv=<value optimized out>) at ./Modules/python.c:23

Comment 6 Jakub Jelinek 2010-01-21 15:20:47 UTC
Please try gcc-4.4.2-28.fc12 (in koji).

Comment 7 Dave Malcolm 2010-01-21 18:01:09 UTC
Thanks.

Having done a "make clean; make" with gcc-4.4.2-28.fc12.i686 there is a slight improvement in the case given in comment #5, but unfortunately the case described in comment #0 still optimizes away the critical variables.

Specifically (re comment #5: starting the rebuilt "python" in interactive mode then breaking into gdb), the gdb backtrace contains more variables with queryable values than in comment #5, although many are still "<variable optimized out>":
(gdb) bt
#0  0x002e5424 in __kernel_vsyscall ()
#1  0x00516ded in ___newselect_nocancel () at ../sysdeps/unix/syscall-template.S:82
#2  0x0011ea4c in readline_until_enter_or_signal (sys_stdin=0x5b5420, sys_stdout=0x5b54c0, prompt=0xb7f495f4 ">>> ") at ./Modules/readline.c:864
#3  call_readline (sys_stdin=0x5b5420, sys_stdout=0x5b54c0, prompt=0xb7f495f4 ">>> ") at ./Modules/readline.c:958
#4  0x04efd6f0 in PyOS_Readline (sys_stdin=<value optimized out>, sys_stdout=<value optimized out>, prompt=<value optimized out>) at Parser/myreadline.c:208
#5  0x04efecda in tok_nextc (tok=<value optimized out>) at Parser/tokenizer.c:784
#6  0x04eff4a7 in tok_get (tok=<value optimized out>, p_start=<value optimized out>, p_end=<value optimized out>) at Parser/tokenizer.c:1131
#7  PyTokenizer_Get (tok=<value optimized out>, p_start=<value optimized out>, p_end=<value optimized out>) at Parser/tokenizer.c:1571
#8  0x04efa877 in parsetok (tok=<value optimized out>, g=<value optimized out>, start=<value optimized out>, err_ret=<value optimized out>, flags=<value optimized out>) at Parser/parsetok.c:159
#9  0x04fba54c in PyParser_ASTFromFile (fp=<value optimized out>, filename=<value optimized out>, start=<value optimized out>, ps1=<value optimized out>, ps2=<value optimized out>, flags=<value optimized out>, 
    errcode=<value optimized out>, arena=<value optimized out>) at Python/pythonrun.c:1458
#10 0x04fbc434 in PyRun_InteractiveOneFlags (fp=<value optimized out>, filename=<value optimized out>, flags=<value optimized out>) at Python/pythonrun.c:820
#11 0x04fbc6ab in PyRun_InteractiveLoopFlags (fp=<value optimized out>, filename=<value optimized out>, flags=<value optimized out>) at Python/pythonrun.c:760
#12 0x04fbc7eb in PyRun_AnyFileExFlags (fp=<value optimized out>, filename=<value optimized out>, closeit=<value optimized out>, flags=<value optimized out>) at Python/pythonrun.c:729
#13 0x04fc9212 in Py_Main (argc=<value optimized out>, argv=<value optimized out>) at Modules/main.c:599
#14 0x080485c7 in main (argc=1, argv=0xbffff374) at ./Modules/python.c:23


However, upon (e.g. debugging a PyGTK app) the PyEval_EvalFrameEx function is still optimizing away the critical "co" and "f" variables:
(gdb) bt
#0  0x004cb424 in __kernel_vsyscall ()
#1  0x001dfe0b in __poll (fds=<value optimized out>, nfds=<value optimized out>, timeout=<value optimized out>) at ../sysdeps/unix/sysv/linux/poll.c:83
#2  0x00691a0c in IA__g_poll (fds=<value optimized out>, nfds=<value optimized out>, timeout=<value optimized out>) at gpoll.c:127
#3  0x00684883 in g_main_context_poll (context=<value optimized out>, block=<value optimized out>, dispatch=<value optimized out>, self=<value optimized out>) at gmain.c:2904
#4  g_main_context_iterate (context=<value optimized out>, block=<value optimized out>, dispatch=<value optimized out>, self=<value optimized out>) at gmain.c:2586
#5  0x00684ebf in IA__g_main_loop_run (loop=<value optimized out>) at gmain.c:2799
#6  0x06c31ac9 in IA__gtk_main () at gtkmain.c:1218
#7  0x010eec49 in _wrap_gtk_main (self=0x0) at ./gtk.override:1241
#8  0x04f9d723 in call_function (f=<value optimized out>, throwflag=<value optimized out>) at Python/ceval.c:3690
#9  PyEval_EvalFrameEx (f=<value optimized out>, throwflag=<value optimized out>) at Python/ceval.c:2389
#10 0x04f9eb79 in fast_function (f=<value optimized out>, throwflag=<value optimized out>) at Python/ceval.c:3792
#11 call_function (f=<value optimized out>, throwflag=<value optimized out>) at Python/ceval.c:3727
#12 PyEval_EvalFrameEx (f=<value optimized out>, throwflag=<value optimized out>) at Python/ceval.c:2389
#13 0x04f9f642 in PyEval_EvalCodeEx (co=<value optimized out>, globals=<value optimized out>, locals=<value optimized out>, args=<value optimized out>, argcount=<value optimized out>, kws=<value optimized out>, 
    kwcount=<value optimized out>, defs=<value optimized out>, defcount=<value optimized out>, closure=<value optimized out>) at Python/ceval.c:2968
#14 0x04f9f7a3 in PyEval_EvalCode (co=<value optimized out>, globals=<value optimized out>, locals=<value optimized out>) at Python/ceval.c:522
#15 0x04fba94b in run_mod (mod=<value optimized out>, filename=<value optimized out>, globals=<value optimized out>, locals=<value optimized out>, flags=<value optimized out>, arena=<value optimized out>) at Python/pythonrun.c:1335
#16 0x04fbaa12 in PyRun_FileExFlags (fp=<value optimized out>, filename=<value optimized out>, start=<value optimized out>, globals=<value optimized out>, locals=<value optimized out>, closeit=<value optimized out>, 
    flags=<value optimized out>) at Python/pythonrun.c:1321
#17 0x04fbbf9c in PyRun_SimpleFileExFlags (fp=<value optimized out>, filename=<value optimized out>, closeit=<value optimized out>, flags=<value optimized out>) at Python/pythonrun.c:931
#18 0x04fbc822 in PyRun_AnyFileExFlags (fp=<value optimized out>, filename=<value optimized out>, closeit=<value optimized out>, flags=<value optimized out>) at Python/pythonrun.c:735
#19 0x04fc9212 in Py_Main (argc=<value optimized out>, argv=<value optimized out>) at Modules/main.c:599
#20 0x080485c7 in main (argc=2, argv=0xbffff364) at ./Modules/python.c:23


(gdb) frame 12
#12 PyEval_EvalFrameEx (f=<value optimized out>, throwflag=<value optimized out>) at Python/ceval.c:2389
2389				x = call_function(&sp, oparg);
(gdb) p co
$1 = <value optimized out>
(gdb) p f
$2 = <value optimized out>


I notice with the above that glibc and GTK are also showing all parameters as "<value optimized out>", so perhaps this is a gdb bug, or perhaps simply that those rpms were built with a toolchain that optimizes the vars away.

For what it's worth this is with:
gcc-4.4.2-28.fc12.i686
gdb-7.0.1-26.fc12.i686
gtk2-2.18.3-21.fc12.i686

Is there any other information that would be useful in tracking this down?

Comment 8 Jakub Jelinek 2010-01-21 20:04:59 UTC
I see
 <1><2d04>: Abbrev Number: 34 (DW_TAG_subprogram)
    <2d05>   DW_AT_name        : (indirect string, offset: 0x1c85): call_function       
    <2d09>   DW_AT_decl_file   : 1      
    <2d0a>   DW_AT_decl_line   : 3665   
    <2d0c>   DW_AT_prototyped  : 1      
    <2d0d>   DW_AT_type        : <0x6d2>        
    <2d11>   DW_AT_inline      : 1      (inlined)
    <2d12>   DW_AT_sibling     : <0x2de1>       
 <2><2d16>: Abbrev Number: 35 (DW_TAG_formal_parameter)
    <2d17>   DW_AT_name        : (indirect string, offset: 0x17b7): pp_stack    
    <2d1b>   DW_AT_decl_file   : 1      
    <2d1c>   DW_AT_decl_line   : 3665   
    <2d1e>   DW_AT_type        : <0x1d66>       
 <2><2d22>: Abbrev Number: 35 (DW_TAG_formal_parameter)
    <2d23>   DW_AT_name        : (indirect string, offset: 0x855): oparg        
    <2d27>   DW_AT_decl_file   : 1      
    <2d28>   DW_AT_decl_line   : 3665   
    <2d2a>   DW_AT_type        : <0x5a> 
...
 <1><30ea>: Abbrev Number: 45 (DW_TAG_subprogram)
    <30eb>   DW_AT_external    : 1      
    <30ec>   DW_AT_name        : (indirect string, offset: 0x14c6): PyEval_EvalFrameEx  
    <30f0>   DW_AT_decl_file   : 1      
    <30f1>   DW_AT_decl_line   : 542    
    <30f3>   DW_AT_prototyped  : 1      
    <30f4>   DW_AT_type        : <0x6d2>        
    <30f8>   DW_AT_low_pc      : 0x1270 
    <30fc>   DW_AT_high_pc     : 0x6ac6 
    <3100>   DW_AT_frame_base  : 0x1159 (location list)
    <3104>   DW_AT_sibling     : <0x3f1d>       
 <2><3108>: Abbrev Number: 47 (DW_TAG_formal_parameter)
    <3109>   DW_AT_name        : f      
    <310b>   DW_AT_decl_file   : 1      
    <310c>   DW_AT_decl_line   : 542    
    <310e>   DW_AT_type        : <0x1e5e>       
    <3112>   DW_AT_location    : 2 byte block: 91 0     (DW_OP_fbreg: 0)
 <2><3115>: Abbrev Number: 46 (DW_TAG_formal_parameter)
    <3116>   DW_AT_name        : (indirect string, offset: 0x1c54): throwflag   
    <311a>   DW_AT_decl_file   : 1      
    <311b>   DW_AT_decl_line   : 542    
    <311d>   DW_AT_type        : <0x5a> 
    <3121>   DW_AT_location    : 2 byte block: 91 4     (DW_OP_fbreg: 4)
...
 <3><3913>: Abbrev Number: 66 (DW_TAG_inlined_subroutine)
    <3914>   DW_AT_abstract_origin: <0x2d04>    
    <3918>   DW_AT_entry_pc    : 0x34fe 
    <391c>   DW_AT_ranges      : 0x7d0  
    <3920>   DW_AT_call_file   : 1      
    <3921>   DW_AT_call_line   : 2389   
 <4><3923>: Abbrev Number: 68 (DW_TAG_formal_parameter)
    <3924>   DW_AT_abstract_origin: <0x2d22>    
 <4><3928>: Abbrev Number: 67 (DW_TAG_formal_parameter)
    <3929>   DW_AT_abstract_origin: <0x2d16>    
    <392d>   DW_AT_location    : 0x488d (location list)

which means that PyEval_EvalFrameEx's both arguments should be available through the whole lifetime of the function and call_function (and fast_function too) are inlined and definitely have different arguments from those printed in the (virtual) backtrace.  call_function's pp_stack argument has some location list, so is valid at least in some places.

Comment 9 Jakub Jelinek 2010-01-22 09:18:27 UTC
gcc-4.4.3-1.fc13 is now in dist-f13, perhaps best would be if you could do a dist-f13 python rebuild, then we can look all at the same binaries and the same debug info.

Comment 10 Jan Kratochvil 2010-01-22 11:20:51 UTC
Sorry, those parameters of inlined functions was a regression of Fedora GDB against FSF GDB by me, fixed (disabled break-by-name on inlined functions, non-backtrace debugging of inlined code still does not work well anyway):
gdb-7.0.50.20100121-5.fc13

gcc-4.4.3-1.fc13 rebuilt python:

#0  0x00956430 in __kernel_vsyscall ()
#1  0x004cb79d in ___newselect_nocancel () at ../sysdeps/unix/syscall-template.S:82
#2  0x002a3a8d in readline_until_enter_or_signal (sys_stdin=0x56e420, sys_stdout=0x56e4c0, prompt=0x80a1f74 ">>> ") at Modules/readline.c:864
#3  call_readline (sys_stdin=0x56e420, sys_stdout=0x56e4c0, prompt=0x80a1f74 ">>> ") at Modules/readline.c:958
#4  0x001338d8 in PyOS_Readline (sys_stdin=0x56e420, sys_stdout=0x56e4c0, prompt=0x80a1f74 ">>> ") at Parser/myreadline.c:208
#5  0x00134ebf in tok_nextc (tok=0x8107e78) at Parser/tokenizer.c:784
#6  0x00135687 in tok_get (tok=0x8107e78, p_start=0xffffc28c, p_end=0xffffc288) at Parser/tokenizer.c:1131
#7  PyTokenizer_Get (tok=0x8107e78, p_start=0xffffc28c, p_end=0xffffc288) at Parser/tokenizer.c:1571
#8  0x00130a2b in parsetok (tok=<value optimized out>, g=<value optimized out>, start=256, err_ret=0xffffc2ec, flags=0xffffc308) at Parser/parsetok.c:159
#9  0x001f1c9d in PyParser_ASTFromFile (fp=0x56e420, filename=0x238d9d "<stdin>", start=256, ps1=0x80a1f74 ">>> ", ps2=0x80a5314 "... ", flags=0xffffc4dc, errcode=0xffffc36c, arena=0x804da68) at Python/pythonrun.c:1458
#10 0x001f3b95 in PyRun_InteractiveOneFlags (fp=0x56e420, filename=0x238d9d "<stdin>", flags=0xffffc4dc) at Python/pythonrun.c:820
#11 0x001f3e23 in PyRun_InteractiveLoopFlags (fp=0x56e420, filename=0x238d9d "<stdin>", flags=0xffffc4dc) at Python/pythonrun.c:760
#12 0x001f3f6f in PyRun_AnyFileExFlags (fp=0x56e420, filename=0x238d9d "<stdin>", closeit=0, flags=0xffffc4dc) at Python/pythonrun.c:729
#13 0x00200a45 in Py_Main (argc=1, argv=0xffffc5d4) at Modules/main.c:599
#14 0x080485c8 in main (argc=1, argv=0xffffc5d4) at Modules/python.c:23

Fedora was displaying now:
#2  0x002a3a8d in readline_until_enter_or_signal (signal=<value optimized out>, prompt=<value optimized out>) at Modules/readline.c:864

Comment 11 Dave Malcolm 2010-01-22 16:26:03 UTC
(In reply to comment #9)
> gcc-4.4.3-1.fc13 is now in dist-f13, perhaps best would be if you could do a
> dist-f13 python rebuild, then we can look all at the same binaries and the same
> debug info.    

Rebuilt as python-2.6.4-8:
  - http://koji.fedoraproject.org/koji/taskinfo?taskID=1939018
  - x86-64 built using: gcc-4.4.3-1.fc13.x86_64.rpm 
    (buildroot: http://koji.fedoraproject.org/koji/rpmlist?buildrootID=697195&type=component )
  - i686 built using: gcc-4.4.3-1.fc13.i686.rpm
(buildroot: http://koji.fedoraproject.org/koji/rpmlist?buildrootID=697196&type=component )

(In reply to comment #10)
> Sorry, those parameters of inlined functions was a regression of Fedora GDB
> against FSF GDB by me, fixed (disabled break-by-name on inlined functions,
> non-backtrace debugging of inlined code still does not work well anyway):
> gdb-7.0.50.20100121-5.fc13
> 
> gcc-4.4.3-1.fc13 rebuilt python:
[snip]

Sorry, but I'm now confused; is this a bug in GDB, in GCC, or both?  

If this is a GCC bug, to what extent is it likely to affect the entire distribution? (and is a full rebuilt warranted?)

(Sorry for my ignorance here)

Comment 12 Jan Kratochvil 2010-01-22 18:41:49 UTC
(In reply to comment #11)
> Sorry, but I'm now confused; is this a bug in GDB, in GCC, or both?  

In the "virtual" frames for inlined functions it was a GDB bug.  It is not visible from a single backtrace whether a frame is for inlined function or not - that is printed in `info frame'.

The other cases were a GCC bug.

The single remaining one in Comment 10:
#8  0x00130a2b in parsetok (tok=<value optimized out>, ...
is not a GDB bug; I did not investigate more if it is a GCC VTA suboptimal case or not.

Comment 13 Jakub Jelinek 2010-01-25 10:07:26 UTC
parsetok is not necessarily a GCC bug either, the value really might not be available at all.
GCC chose to use a regparm(2) calling convention for the static function, and with that calling convention the argument is not necessarily live through the whole function.

That said, in this case I'd say tok should be live.  At the beginning of function
%eax (the incoming tok register) is copied to %esi and var-tracking correctly says that tok is live in %esi.  But then there is barrier and code in it uses %esi for a different variable (str), which var-tracking also correctly notes.
The code later on moves %esi to %edx and notes that str is live in %edx, but fails to notice that tok is now live again in %esi (restored from spill slot):

(note 531 345 375 6 (var_location tok (expr_list:REG_DEP_TRUE (reg/v/f:SI 4 si [orig:81 tok ] [81])
    (const_int 0 [0x0]))) NOTE_INSN_VAR_LOCATION)

(insn 375 531 391 6 (set (mem/c:SI (plus:SI (reg/f:SI 6 bp)
                (const_int -44 [0xffffffd4])) [0 %sfp+-20 S4 A32])
        (reg/v/f:SI 4 si [orig:81 tok ] [81])) 41 {*movsi_1} (expr_list:REG_DEAD (reg/v/f:SI 4 si [orig:81 tok ] [81])
        (nil)))
...
(note 585 186 379 19 (var_location str (expr_list:REG_DEP_TRUE (reg/v/f:SI 4 si [orig:67 str ] [67])
    (const_int 0 [0x0]))) NOTE_INSN_VAR_LOCATION)

(insn 379 585 380 19 (set (reg/v/f:SI 1 dx [orig:67 str ] [67])
        (reg/v/f:SI 4 si [orig:67 str ] [67])) 41 {*movsi_1} (expr_list:REG_DEAD (reg/v/f:SI 4 si [orig:67 str ] [67])
        (nil)))

(insn:TI 380 379 586 19 (set (reg/v/f:SI 4 si [orig:81 tok ] [81])
        (mem/c:SI (plus:SI (reg/f:SI 6 bp)
                (const_int -44 [0xffffffd4])) [0 %sfp+-20 S4 A32])) 41 {*movsi_1} (nil))

(note 586 380 187 19 (var_location str (expr_list:REG_DEP_TRUE (reg/v/f:SI 1 dx [orig:67 str ] [67])
    (const_int 0 [0x0]))) NOTE_INSN_VAR_LOCATION)

I guess the issue is that we don't track values in the spill slots (%sfp+X) slots since http://gcc.gnu.org/PR37447 change.  At least in the easy cases where one spill slot is used solely for one variable this shouldn't be terribly difficult (that's the case here), we'd just have to map the various sfp offsets to actual decls using some hash table.  For the easy case we'd just clear it when we see it used for more than one different value.  And, if we track anything in the %sfp slots, we should never consider those MEMs to die at call - I believe spill slots can't ever have their address taken in the original program sense, so mem_dies_at_call, though perhaps may_be_aliased already handles that case well.

Comment 14 Jakub Jelinek 2010-01-25 10:15:37 UTC
Created attachment 386582 [details]
parsetok.c.bz2

Corresponding preprocessed source with dg-options to compile.
Similar problem exists also in the trunk, just it is not %esi, but %ebx, but anyway, while the tok argument clearly has to live at least till the PyTokenizer_Free call immediately before returning, there are several places in the code where var-tracking thinks it isn't live anywhere.

Comment 15 Dave Malcolm 2010-01-26 20:54:12 UTC
Just to clarify, from my perspective, the most important function for python debuggability is PyEval_EvalFrameEx, and the vars "co" and "f" (see comment #0).

A reproducer to investigate this is:
$ gdb --args python -c "pass"
(gdb) break PyEval_EvalFrameEx
(gdb) run

Starting program: /usr/bin/python -c pass
[Thread debugging using libthread_db enabled]

Breakpoint 1, PyEval_EvalFrameEx (f=0x8063b0c, throwflag=0) at Python/ceval.c:543
543	{
(gdb) p f
$1 = (PyFrameObject *) 0x8063b0c
(gdb) p co
$2 = <value optimized out>

(this is as seen on my F-12 with a local build of python).

Ideally both "f" and "co" should be printable; co == f->f_code, so co being unprintable isn't a disaster, though it makes it that much harder to implement gdb-archer prettyprinting code if vars aren't available.

(gdb) p f->f_lineno
$4 = 59
(gdb) p f->f_code
$5 = (PyCodeObject *) 0xb7fd1068
(gdb) p (char*)(((PyStringObject*)f->f_code->co_name)->ob_sval)
$6 = 0xb7fcbf34 "<module>"
(gdb) p (char*)(((PyStringObject*)f->f_code->co_filename)->ob_sval)
$7 = 0xb7fadedc "/usr/lib/python2.6/site.py"

(i.e. in this case, the do-nothing "pass" case is executing the code in site.py, as expected; hopefully this illustrates the idea)

Comment 16 Jakub Jelinek 2010-01-28 09:35:50 UTC
gcc-4.4.3-4.{fc12,fc13,el6} should fix even the incomplete location coverage of the tok argument in parsetok.

Comment 17 Dave Malcolm 2010-03-25 22:02:41 UTC
Reopening, alas.

I've been testing:
https://fedoraproject.org/wiki/Features/EasierPythonDebugging
and am running into the symptoms described in comment #0, specifically that parameter "f" to "PyEval_EvalFrameEx" is showing up in gdb as "variable optimized out".

Unfortunately this code and variable are very important: the function is the central python bytecode execution loop, and "f" is the frame information on what python code we're using.

I'm assigning this to component "gdb", but obviously I could be wrong on this.

This is on a Fedora 13 x86_64 machine with:

gdb-7.0.50.20100203-15.fc13.x86_64

[david@f13 ~]$ rpm -q python python-libs python-debuginfo
python-2.6.4-23.fc13.x86_64
python-libs-2.6.4-23.fc13.x86_64
python-debuginfo-2.6.4-23.fc13.x86_64

but I've seen this on other recent builds of python.

To reproduce, I've been doing:
$ sudo yum update
CTRL-Z 
$ sudo gdb attach $(pidof -x yum)
(gdb) bt
and then looking at PyEval_EvalFrameEx frames

Looking at the DWARF data:

[david@f13 ~]$ eu-readelf -w /usr/lib/debug/usr/lib64/libpython2.6.so.debug |less
(and search for "PyEval_EvalFrameEx")

[ 9bd4e]    subprogram
             external             Yes
             name                 "PyEval_EvalFrameEx"
             decl_file            1
             decl_line            595
             prototyped           Yes
             type                 [ 9926a]
             low_pc               +0x00000000000d8510 <PyEval_EvalFrameEx>
             high_pc              +0x00000000000deb19
             frame_base                         [   0] call_frame_cfa
             sibling              [ 9ce31]
 [ 9bd72]      formal_parameter
               name                 "f"
               decl_file            1
               decl_line            595
               type                 [ 9a8be]
               location             location list [ ee66d]
 [ 9bd80]      formal_parameter
               name                 "throwflag"
               decl_file            1
               decl_line            595
               type                 [ 98c70]
               location             location list [ ee6ef]
(snip)

 [ 9be86]      variable
               name                 "co"
               decl_file            1
               decl_line            615
               type                 [ 9a68b]
               location             location list [ f539c]

(snip)

and the location for "f" shows up later in the eu-readelf output as:

 [ ee66d]  +0x0000000000001070..+0x00000000000010b6 [   0] reg5
           +0x00000000000010b6..+0x000000000000118b [   0] reg6
           +0x000000000000128a..+0x00000000000012c5 [   0] reg6
           +0x0000000000001307..+0x0000000000001408 [   0] reg6
           +0x0000000000001a8a..+0x0000000000001a97 [   0] reg5
           +0x0000000000001a97..+0x0000000000001ab5 [   0] reg6

So if I'm reading this right, I believe "f" ought to be visible (in reg5 or reg6?)  (or are those PC ranges in which it lives in that register? maybe that's the issue?)

Looking at:
(gdb) info registers
rax            0x442457b	71452027
rbx            0x5	5
rcx            0x34	52
rdx            0x13e	318
rsi            0x440a401	71345153
rdi            0x8	8
rbp            0x3be96d0	0x3be96d0
rsp            0x7fffed1a5030	0x7fffed1a5030
r8             0x4454a48	71649864
r9             0x40b	1035
r10            0x8	8
r11            0x440a4e0	71345376
r12            0x174f0a0	24440992
r13            0x7fbfcaadf144	140461715878212
r14            0x6	6
r15            0xffffffff	4294967295
rip            0x355eedd78c	0x355eedd78c <PyEval_EvalFrameEx+21116>
eflags         0x202	[ IF ]
cs             0x33	51
ss             0x2b	43
ds             0x0	0
es             0x0	0
fs             0x0	0
gs             0x0	0
fctrl          0x37f	895
fstat          0x0	0
ftag           0xffff	65535
fiseg          0x0	0
fioff          0xd527a1c8	-718822968
foseg          0x0	0
fooff          0xed1a5bc8	-317039672
fop            0x55c	1372
mxcsr          0x1fa0	[ PE IM DM ZM OM UM PM ]

and counting down from r9, r8, I guessed "rbp"="reg6", and:
(gdb) p (PyFrameObject*)$rbp
seems to contain a credible value for f

So it looks like the data's there in the "rbp" register, just not being picked up by gdb (does that DWARF data look complete and correct?)

Any ideas?  Let me know if there's anything I can do to help fix this: I'm very keen on getting this fixed, as without this variable it's significantly harder to debug python.  Thanks.

Comment 18 Dave Malcolm 2010-03-25 22:15:49 UTC
The specific python build I've been testing with is:
http://koji.fedoraproject.org/koji/buildinfo?buildID=163534

on x86_64, which was built with this buildroot: http://koji.fedoraproject.org/koji/buildrootinfo?buildrootID=747495

which had: gcc-4.4.3-8.fc13.x86_64.rpm

Comment 19 Jan Kratochvil 2010-03-26 00:28:53 UTC
(In reply to comment #17)
> and the location for "f" shows up later in the eu-readelf output as:
> 
>  [ ee66d]  +0x0000000000001070..+0x00000000000010b6 [   0] reg5
>            +0x00000000000010b6..+0x000000000000118b [   0] reg6
>            +0x000000000000128a..+0x00000000000012c5 [   0] reg6
>            +0x0000000000001307..+0x0000000000001408 [   0] reg6
>            +0x0000000000001a8a..+0x0000000000001a97 [   0] reg5
>            +0x0000000000001a97..+0x0000000000001ab5 [   0] reg6
>
> So if I'm reading this right, I believe "f" ought to be visible (in reg5 or
> reg6?)  (or are those PC ranges in which it lives in that register? maybe
> that's the issue?)

Yes, you would have to know also the PC to choose the right line.

Tried to rebuild python with gcc-4.4.3-12.fc13.x86_64 but the problem remains.

#6  0x00007f85dd56e1b5 in PyEval_EvalFrameEx (f=<value optimized out>, throwflag=<value optimized out>) at Python/ceval.c:2305
PC = 0xd91b5

 <1><9c578>: Abbrev Number: 47 (DW_TAG_subprogram)
    <9c57a>   DW_AT_name        : (indirect string, offset: 0x10941): PyEval_EvalFrameEx
    <9c586>   DW_AT_low_pc      : 0xd8510
    <9c58e>   DW_AT_high_pc     : 0xdeb19
 <2><9c59c>: Abbrev Number: 56 (DW_TAG_formal_parameter)
    <9c59d>   DW_AT_name        : f
    <9c5a6>   DW_AT_location    : 0xf875e       (location list)

    000f875e 00000000000d8510 00000000000d8556 (DW_OP_reg5)
    000f875e 00000000000d8556 00000000000d862b (DW_OP_reg6)
    000f875e 00000000000d872a 00000000000d8765 (DW_OP_reg6)
    000f875e 00000000000d87a7 00000000000d88a8 (DW_OP_reg6)
    000f875e 00000000000d8f2a 00000000000d8f37 (DW_OP_reg5)
    000f875e 00000000000d8f37 00000000000d8f55 (DW_OP_reg6)
    000f875e <End of list>

Comment 20 Jan Kratochvil 2010-03-26 00:34:31 UTC
(In reply to comment #17)
> and counting down from r9, r8, I guessed "rbp"="reg6", and:

Besides there is no indication it is in reg5/reg6 still you had a luck.
You would have to check:
http://www.x86-64.org/documentation/abi.pdf
Figure 3.36: DWARF Register Number Mapping
Register Name                 Number  Abbreviation
General Purpose Register RDI  5       %rdi
Frame Pointer Register RBP    6       %rbp

GDB cannot directly print the internal DWARF number of a register.

Comment 21 Jakub Jelinek 2010-03-26 09:25:25 UTC
Created attachment 402775 [details]
ceval.i.bz2

Well, now you are talking about a different architecture, which has completely different ABI.  Unlike i?86 where if the f argument isn't modified, you can always find it in the incoming argument stack slot, here the variable is passed in register (%rdi), which is shortly afterwards clobbered.  While the variable is copied into %rbp, apparently f isn't the only thing that is kept in %rbp, in some places this register holds e.g. pos instead and in those locations f isn't available anywhere.  So I believe it is correct that gcc says f isn't available everywhere in the function, it is certainly not available where %rbp holds pos, and in places which are reachable either from the locations where %rbp holds f, but also reachable from locations where %rbp holds pos we can't say f lives in %rbp either - while you might see %rbp containing expected value of f in there, it would be because you arrived there through location where f was known to live in %rbp, but the same code could be reached when %rbp would hold some previous pos value.

Attached is preprocessed source, here are command line options.
-dA -fverbose-asm -fno-strict-aliasing -O2 -g -fexceptions -fstack-protector 
--param ssp-buffer-size=4 -m64 -mtune=generic -fPIC -o ceval.s ceval.i

I guess if you said what exact location do you care about in the function, I could look in more detail whether it isn't some var-tracking bug rather than simply the sad state of things in the optimized huge function.

That said, as f isn't really modified in the function, this would be a perfect example where DW_OP_entry_value/DW_TAG_call_site stuff we've been discussing would help, but we still need to discuss it, then propose to DWARF, get some agreement on it and then actually implement it, so that's at least a year away from now.

Comment 22 Dave Malcolm 2010-03-26 18:53:51 UTC
(In reply to comment #21)
> Well, now you are talking about a different architecture, which has completely
> different ABI.  Unlike i?86 where if the f argument isn't modified, you can

Aha; please forgive me here - yes, I'm seeing this issue on x86_64.

I've doublechecked, and it's working nicely on i686 - I've tested:
  python-2.6.4-20.fc13.i686
  python-2.6.4-23.fc13.i686
  python-2.6.4-24.fc13.i686
and the value of "f" is visible in gdb with all of them.

So yes, this is affecting x86_64 only at this point.  Am investigating...

Comment 23 Bug Zapper 2011-06-02 16:49:36 UTC
This message is a reminder that Fedora 13 is nearing its end of life.
Approximately 30 (thirty) days from now Fedora will stop maintaining
and issuing updates for Fedora 13.  It is Fedora's policy to close all
bug reports from releases that are no longer maintained.  At that time
this bug will be closed as WONTFIX if it remains open with a Fedora 
'version' of '13'.

Package Maintainer: If you wish for this bug to remain open because you
plan to fix it in a currently maintained version, simply change the 'version' 
to a later Fedora version prior to Fedora 13's end of life.

Bug Reporter: Thank you for reporting this issue and we are sorry that 
we may not be able to fix it before Fedora 13 is end of life.  If you 
would still like to see this bug fixed and are able to reproduce it 
against a later version of Fedora please change the 'version' of this 
bug to the applicable version.  If you are unable to change the version, 
please add a comment here and someone will do it for you.

Although we aim to fix as many bugs as possible during every release's 
lifetime, sometimes those efforts are overtaken by events.  Often a 
more recent Fedora release includes newer upstream software that fixes 
bugs or makes them obsolete.

The process we are following is described here: 
http://fedoraproject.org/wiki/BugZappers/HouseKeeping

Comment 24 Jakub Jelinek 2011-06-08 20:44:39 UTC
gcc-4.6.0-10.fc16 has DW_OP_GNU_entry_value support (and typed DWARF stack support), so when F16 gdb gets corresponding support, some of these problems might go away.

Comment 25 Duc 2011-11-30 03:04:46 UTC
Created attachment 538379 [details]
sdsdfd

dsad

Comment 26 Fedora End Of Life 2013-04-03 20:04:44 UTC
This bug appears to have been reported against 'rawhide' during the Fedora 19 development cycle.
Changing version to '19'.

(As we did not run this process for some time, it could affect also pre-Fedora 19 development
cycle bugs. We are very sorry. It will help us with cleanup during Fedora 19 End Of Life. Thank you.)

More information and reason for this action is here:
https://fedoraproject.org/wiki/BugZappers/HouseKeeping/Fedora19

Comment 27 Tom Tromey 2013-06-05 19:36:13 UTC
FWIW this is still an issue on x86-64 Fedora 18.
Now, the 'f' variable in ceval.c:fast_function is optimized away.
This prevents "py-bt" from working (and in the future will
prevent a python frame filter from working).

(top-gdb) down
#3  0x00000035264dcef1 in fast_function (nk=<optimized out>, na=0, 
    n=<optimized out>, pp_stack=0x7fffffffdd28, func=
    <function at remote 0x21bf9b0>)
    at /usr/src/debug/Python-2.7.3/Python/ceval.c:4184
(top-gdb) p f
$4 = <optimized out>

One idea was to force this variable to be kept around using an asm.

I'd prefer a fix in gcc, I think, but if that is not possible,
perhaps this could be reassigned to Python and someone could provide
the asm patch.

Comment 28 Jan Kratochvil 2013-06-05 19:46:30 UTC
        retval = PyEval_EvalFrameEx(f,0);
$pc ->  ++tstate->recursion_depth;
        Py_DECREF(f);

   0x3e27cdcee4: mov   %rdx,%rdi
   0x3e27cdcee7: mov   %rdx,0x38(%rsp)
   0x3e27cdceec: callq 0x3e27c3c490 <PyEval_EvalFrameEx@plt>
=> 0x3e27cdcef1: addl  $0x1,0x18(%r14)
   0x3e27cdcef6: mov   %rax,%r15
   0x3e27cdcef9: mov   0x38(%rsp),%rdx
   0x3e27cdcefe: subq  $0x1,(%rdx)
   0x3e27cdcf02: jne   0x3e27cdcf0e <PyEval_EvalFrameEx+22046>

(gdb) info addr f
Symbol "f" is multi-location:
  Range 0x3e27cdcea1-0x3e27cdceb7: a variable in $rax
  Range 0x3e27cdceb7-0x3e27cdcef0: a variable in $rdx
  Range 0x3e27cdcf36-0x3e27cdcf3e: a variable in $rax
.

So 'f' is stored at 0x38(%rsp) at $pc == 0x3e27cdcef1 .

Comment 29 Tom Tromey 2014-01-20 18:05:35 UTC
I'd like to ping this bug again.

This bug prevents us from writing a decent gdb frame filter
for Python.  I would appreciate a fix for it.

In an earlier discussion someone (perhaps Jakub, I forget)
brought up the issue that such bugs can always reappear,
because they are dependent on changes in the optimizers.
That is true in general, but in this particular case, if
we can write a frame filter, we'll also write a test for
it, and this at least will let us detect regressions (perhaps
at some distance, after a Python rebuild with a new gcc --
but better than nothing).

Comment 30 Fedora End Of Life 2015-01-09 21:42:12 UTC
This message is a notice that Fedora 19 is now at end of life. Fedora 
has stopped maintaining and issuing updates for Fedora 19. It is 
Fedora's policy to close all bug reports from releases that are no 
longer maintained. Approximately 4 (four) weeks from now this bug will
be closed as EOL if it remains open with a Fedora 'version' of '19'.

Package Maintainer: If you wish for this bug to remain open because you
plan to fix it in a currently maintained version, simply change the 'version' 
to a later Fedora version.

Thank you for reporting this issue and we are sorry that we were not 
able to fix it before Fedora 19 is end of life. If you would still like 
to see this bug fixed and are able to reproduce it against a later version 
of Fedora, you are encouraged  change the 'version' to a later Fedora 
version prior this bug is closed as described in the policy above.

Although we aim to fix as many bugs as possible during every release's 
lifetime, sometimes those efforts are overtaken by events. Often a 
more recent Fedora release includes newer upstream software that fixes 
bugs or makes them obsolete.

Comment 33 Fedora End Of Life 2015-02-18 13:25:38 UTC
Fedora 19 changed to end-of-life (EOL) status on 2015-01-06. Fedora 19 is
no longer maintained, which means that it will not receive any further
security or bug fix updates. As a result we are closing this bug.

If you can reproduce this bug against a currently maintained version of
Fedora please feel free to reopen this bug against that version. If you
are unable to reopen this bug, please file a new report against the
current release. If you experience problems, please add a comment to this
bug.

Thank you for reporting this bug and we are sorry it could not be fixed.


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