[Bug translator/4915] New: Incorrect code for accessing function argument

[Bug translator/4915] New: Incorrect code for accessing function argument

[wcohen at redhat dot com]

On RHEL4 machines the a number of the tests from
testsuite/systemtap.syscall/syscall.exp fail on i686 machine when
running the nightly test runs based on a checkout from cvs and using a
elfutils 0.127. Looking through the tests results a number of the
syscall functions seem to be getting bogus arguments producing
"<unknown>" as one of the systemcall arguments. The same tests failed
regardless using the linux-2.6.9-55.0.2.ELsmp or the 2.6.23-rc2
kernels. On the RHEL4 system the following systemcalls had bogus
arguments:

access
chdir
chmod
chown
lchown
open
pwrite
readlink
statfs
swapoff
swapon


It was noted that the failure did not occur on the RHEL5 i386
machine. Thus, the 2.6.23-rc2 kernel was built on both RHEL4 and RHEL5
i386 machines and a stripped down script, open.stp, were used to
compare the differences between working RHEL5 and problem RHEL4.  One
possible cause of the problem is the compiler generating bogus
debugging information. The machines have the following compilers:

rhel4: gcc version 3.4.6 20060404 (Red Hat 3.4.6-8)
rhel5: gcc version 4.1.1 20070105 (Red Hat 4.1.1-52)

The code for the sys_open function being instrumented looks to be identical.
The place that probes are places on the code are marked below.


RHEL4
c017384f <sys_open>:
c017384f:	51                   	push   %ecx		<--retprobe
c0173850:	8b 44 24 10          	mov    0x10(%esp),%eax <---entry probe
c0173854:	8b 54 24 08          	mov    0x8(%esp),%edx
c0173858:	8b 4c 24 0c          	mov    0xc(%esp),%ecx
c017385c:	89 04 24             	mov    %eax,(%esp)
c017385f:	b8 9c ff ff ff       	mov    $0xffffff9c,%eax
c0173864:	e8 26 ff ff ff       	call   c017378f <do_sys_open>
c0173869:	5a                   	pop    %edx
c017386a:	c3                   	ret    

RHEL5
c046ca3b <sys_open>:
c046ca3b:	83 ec 04             	sub    $0x4,%esp <---both probes here
c046ca3e:	8b 44 24 10          	mov    0x10(%esp),%eax
c046ca42:	8b 54 24 08          	mov    0x8(%esp),%edx
c046ca46:	8b 4c 24 0c          	mov    0xc(%esp),%ecx
c046ca4a:	89 04 24             	mov    %eax,(%esp)
c046ca4d:	b8 9c ff ff ff       	mov    $0xffffff9c,%eax
c046ca52:	e8 07 ff ff ff       	call   c046c95e <do_sys_open>
c046ca57:	5a                   	pop    %edx
c046ca58:	c3                   	ret    


Below are the functions for obtaining file name generated on the RHEL4
and RHEL5 machines. The one for the RHEL4 machine doe not look
correct. The argument is still on the stack. It isn't in a register
yet.

RHEL4 code for getting the filename:

void function__dwarf_tvar_get_filename_3 (struct context* __restrict__ c) {
  struct function__dwarf_tvar_get_filename_3_locals *  __restrict__ l =
    & c->locals[c->nesting].function__dwarf_tvar_get_filename_3;
  (void) l;
  #define CONTEXT c
  #define THIS l
  if (0) goto out;
  l->__retvalue = 0;
  {
    {
  {
    uint32_t addr;
    { // DWARF expression: 0x52
    { uint32_t value = fetch_register (2);addr = value; }
    }
    THIS->__retvalue = addr;
  }
  goto out;
if (0) goto deref_fault;
deref_fault:
  c->last_error = "pointer dereference fault";
  goto out;
}
/* pure */
  }
out:
  ;
  #undef CONTEXT
  #undef THIS
}


RHEL5 code for getting filename:

void function__dwarf_tvar_get_filename_3 (struct context* __restrict__ c) {
  struct function__dwarf_tvar_get_filename_3_locals *  __restrict__ l =
    & c->locals[c->nesting].function__dwarf_tvar_get_filename_3;
  (void) l;
  #define CONTEXT c
  #define THIS l
  if (0) goto out;
  l->__retvalue = 0;
  {
    {
  {
    intptr_t addr;
  intptr_t frame_base;
  { // DWARF expression: 0x74(4)
    {
      intptr_t s0;
        s0 = fetch_register (4) + 4L;
      frame_base = s0;
    }
  }
    { // DWARF expression: 0x91
      {
        intptr_t s0;
        s0 = frame_base + 0L;
        addr = s0;
      }
    }
    { // synthesized
    { uint32_t value = deref (4, addr);addr = value; }
    }
    THIS->__retvalue = addr;
  }
  goto out;
if (0) goto deref_fault;
deref_fault:
  c->last_error = "pointer dereference fault";
  goto out;
}
/* pure */
  }
out:
  ;
  #undef CONTEXT
  #undef THIS
}

-- 
           Summary: Incorrect code for accessing function argument
           Product: systemtap
           Version: unspecified
            Status: NEW
          Severity: normal
          Priority: P2
         Component: translator
        AssignedTo: systemtap at sources dot redhat dot com
        ReportedBy: wcohen at redhat dot com
  GCC host triplet: i386


http://sourceware.org/bugzilla/show_bug.cgi?id=4915

------- You are receiving this mail because: -------
You are the assignee for the bug, or are watching the assignee.

[Bug translator/4915] Incorrect code for accessing function argument

[wcohen at redhat dot com]

------- Additional Comments From wcohen at redhat dot com  2007-08-10 20:23 -------
Created an attachment (id=1959)
 --> (http://sourceware.org/bugzilla/attachment.cgi?id=1959&action=view)
script that probes sys_open and uses the filename argument


-- 


http://sourceware.org/bugzilla/show_bug.cgi?id=4915

------- You are receiving this mail because: -------
You are the assignee for the bug, or are watching the assignee.

[Bug translator/4915] Incorrect code for accessing function argument

[fche at redhat dot com]

------- Additional Comments From fche at redhat dot com  2007-08-10 20:23 -------
Is your systemtap build for RHEL4 using/implying -P for prologue searching?
What does stap -vvvv say about figuring out that argument?

-- 
           What    |Removed                     |Added
----------------------------------------------------------------------------
            Summary|Incorrect code for accessing|Incorrect code for accessing
                   |function argument           |function argument


http://sourceware.org/bugzilla/show_bug.cgi?id=4915

------- You are receiving this mail because: -------
You are the assignee for the bug, or are watching the assignee.

[Bug translator/4915] Incorrect code for accessing function argument

[wcohen at redhat dot com]

------- Additional Comments From wcohen at redhat dot com  2007-08-10 20:23 -------
Created an attachment (id=1960)
 --> (http://sourceware.org/bugzilla/attachment.cgi?id=1960&action=view)
output of translator from rhel4 system


-- 


http://sourceware.org/bugzilla/show_bug.cgi?id=4915

------- You are receiving this mail because: -------
You are the assignee for the bug, or are watching the assignee.

[Bug translator/4915] Incorrect code for accessing function argument

[wcohen at redhat dot com]

------- Additional Comments From wcohen at redhat dot com  2007-08-10 20:24 -------
Created an attachment (id=1961)
 --> (http://sourceware.org/bugzilla/attachment.cgi?id=1961&action=view)
output of translator from rhel5 system


-- 


http://sourceware.org/bugzilla/show_bug.cgi?id=4915

------- You are receiving this mail because: -------
You are the assignee for the bug, or are watching the assignee.

[Bug translator/4915] Incorrect code for accessing function argument

[wcohen at redhat dot com]

------- Additional Comments From wcohen at redhat dot com  2007-08-10 20:35 -------
Looking through the obj/config.h:

/* make -P prologue-searching default */
#define ENABLE_PROLOGUES 

grepping the output of the "stap -vvvv ~/open.stp" results.

$ grep filename ~/open_results.txt 
finding location for local 'filename' near address c0173850, module bias 0
finding location for local 'filename' near address c0173850, module bias 0
finding location for local 'filename' near address c0173850, module bias 0
finding location for local 'filename' near address c0173850, module bias 0
Eliding assignment to filename at operator '=' at /home/wcohen/open.stp:8:11
Eliding unused function _dwarf_tvar_get_filename_0
Eliding unused local variable filename in probe_1557
Changing _dwarf_tvar_get_filename_5 reference to _dwarf_tvar_get_filename_3
reference
Changing _dwarf_tvar_get_filename_6 reference to _dwarf_tvar_get_filename_3
reference


-- 


http://sourceware.org/bugzilla/show_bug.cgi?id=4915

------- You are receiving this mail because: -------
You are the assignee for the bug, or are watching the assignee.

[Bug translator/4915] Incorrect code for accessing function argument

[fche at redhat dot com]

-- 
           What    |Removed                     |Added
----------------------------------------------------------------------------
Attachment #1960 is|0                           |1
           obsolete|                            |


http://sourceware.org/bugzilla/show_bug.cgi?id=4915

------- You are receiving this mail because: -------
You are the assignee for the bug, or are watching the assignee.

[Bug translator/4915] Incorrect code for accessing function argument

[wcohen at redhat dot com]

------- Additional Comments From wcohen at redhat dot com  2007-08-10 21:43 -------
Got the raw dwarf information using the following commands:

readelf --debug-dump  /tmp/stap_rhel4/vmlinux-2.6.23-rc2 >
/tmp/stap_rhel4/vmlinux-2.6.23-rc2.debug_info
readelf --debug-dump /boot/vmlinux-2.6.23-rc2  >
/tmp/stap_rhel5/vmlinux-2.6.23-rc2.debug_info

It looks like the RHEL4 gcc compiler is generating some questionable debuginfo.

RHEL4 version
 <1><61d544>: Abbrev Number: 83 (DW_TAG_subprogram)
     DW_AT_sibling     : <61d59c>
     DW_AT_external    : 1
     DW_AT_name        : (indirect string, offset: 0x393cc): sys_open
     DW_AT_decl_file   : 1
     DW_AT_decl_line   : 1048
     DW_AT_prototyped  : 1
     DW_AT_type        : <610a64>
     DW_AT_low_pc      : 0xc017384f
     DW_AT_high_pc     : 0xc017386b
     DW_AT_frame_base  : 2 byte block: 74 4     (DW_OP_breg4: 4)
 <2><61d561>: Abbrev Number: 84 (DW_TAG_formal_parameter)
     DW_AT_name        : (indirect string, offset: 0x510e3): filename
     DW_AT_decl_file   : 1
     DW_AT_decl_line   : 1047
     DW_AT_type        : <61121a>
     DW_AT_location    : 1 byte block: 52       (DW_OP_reg2)
 <2><61d56f>: Abbrev Number: 84 (DW_TAG_formal_parameter)
     DW_AT_name        : (indirect string, offset: 0xcdf17): flags
     DW_AT_decl_file   : 1
     DW_AT_decl_line   : 1047
     DW_AT_type        : <610a35>
     DW_AT_location    : 1 byte block: 51       (DW_OP_reg1)
 <2><61d57d>: Abbrev Number: 84 (DW_TAG_formal_parameter)
     DW_AT_name        : (indirect string, offset: 0x5c9): mode
     DW_AT_decl_file   : 1
     DW_AT_decl_line   : 1047
     DW_AT_type        : <610a35>
     DW_AT_location    : 1 byte block: 50       (DW_OP_reg0)
 <2><61d58b>: Abbrev Number: 91 (DW_TAG_variable)
     DW_AT_name        : ret
     DW_AT_decl_file   : 1
     DW_AT_decl_line   : 1049
     DW_AT_type        : <610a64>
     DW_AT_location    : 0xa6de1        (location list)


RHEL5
 <1><65ecd8>: Abbrev Number: 83 (DW_TAG_subprogram)
     DW_AT_sibling     : <65ed34>
     DW_AT_external    : 1
     DW_AT_name        : (indirect string, offset: 0x3982d): sys_open
     DW_AT_decl_file   : 1
     DW_AT_decl_line   : 1048
     DW_AT_prototyped  : 1
     DW_AT_type        : <652c64>
     DW_AT_low_pc      : 0xc046ca3b
     DW_AT_high_pc     : 0xc046ca59
     DW_AT_frame_base  : 0x9402e        (location list)
 <2><65ecf6>: Abbrev Number: 89 (DW_TAG_formal_parameter)
     DW_AT_name        : (indirect string, offset: 0x51af4): filename
     DW_AT_decl_file   : 1
     DW_AT_decl_line   : 1047
     DW_AT_type        : <6533b6>
     DW_AT_location    : 2 byte block: 91 0     (DW_OP_fbreg: 0)
 <2><65ed05>: Abbrev Number: 89 (DW_TAG_formal_parameter)
     DW_AT_name        : (indirect string, offset: 0xd60b6): flags
     DW_AT_decl_file   : 1
     DW_AT_decl_line   : 1047
     DW_AT_type        : <652c35>
     DW_AT_location    : 2 byte block: 91 4     (DW_OP_fbreg: 4)
 <2><65ed14>: Abbrev Number: 89 (DW_TAG_formal_parameter)
     DW_AT_name        : (indirect string, offset: 0x836d): mode
     DW_AT_decl_file   : 1
     DW_AT_decl_line   : 1047
     DW_AT_type        : <652c35>
     DW_AT_location    : 2 byte block: 91 8     (DW_OP_fbreg: 8)
 <2><65ed23>: Abbrev Number: 95 (DW_TAG_variable)
     DW_AT_name        : ret
     DW_AT_decl_file   : 1
     DW_AT_decl_line   : 1049
     DW_AT_type        : <652c64>
     DW_AT_location    : 0x9404e        (location list)



-- 


http://sourceware.org/bugzilla/show_bug.cgi?id=4915

------- You are receiving this mail because: -------
You are the assignee for the bug, or are watching the assignee.

[Bug translator/4915] Incorrect code for accessing function argument

[fche at redhat dot com]

------- Additional Comments From fche at redhat dot com  2007-08-11 01:52 -------
(In reply to comment #5)
> Looking through the obj/config.h:
> /* make -P prologue-searching default */
> #define ENABLE_PROLOGUES 

OK.

> grepping the output of the "stap -vvvv ~/open.stp" results.

That point is too late.  The question is why the prologue-searching
heuristic ends up choosing 0xc0173850.  CVS systemtap on 2.6.9-55.ELsmp
gives me the correct instruction.  Grep the bunch of lines before/after
'prologue'.

If the problem ends up being solely that the RHEL4 gcc building bleeding
edge kernels gives poor results, this may not be worth fixing.


-- 
           What    |Removed                     |Added
----------------------------------------------------------------------------
             Status|NEW                         |WAITING


http://sourceware.org/bugzilla/show_bug.cgi?id=4915

------- You are receiving this mail because: -------
You are the assignee for the bug, or are watching the assignee.

[Bug translator/4915] Incorrect code for accessing function argument

[wcohen at redhat dot com]

------- Additional Comments From wcohen at redhat dot com  2007-08-13 14:26 -------
Isn't 2.6.9-55.ELsmp an older kernel? Current RHEL4 is 2.6.9-55.0.2.EL. Does the
debug information for the sys_open function look correct for that kernel?

Looking through the RHEL4 system output for -vvvv see the follow output related
to the generation of the probe points for the 2.6.23-rc2 kernel built with the
RHEL 4 gcc (gcc version 3.4.6 20060404 (Red Hat 3.4.6-8)):

control symbols: kts: 0xc0315b98 kte: 0xc03184b2 stext: 0xc01012dc
parsed 'sys_open' -> func 'sys_open'
pattern 'kernel' matches module 'kernel'
focused on module 'kernel = [0xc0100000-0xc0708000, bias 0x0] file
/boot/vmlinux-2.6.23-rc2 ELF machine i?86 (code 3)
pattern 'sys_open' matches function 'sys_open'
selected function sys_open
prologue searching function 'sys_open' 0xc017384f-0xc017386b@fs/open.c:1048
checking line record 0xc017384f@fs/open.c:1048
checking line record 0xc0173850@fs/open.c:1054
prologue found function 'sys_open' = 0xc0173850
probe sys_open@fs/open.c:1048 kernel section=.text pc=0xc0173850
finding location for local 'filename' near address c0173850, module bias 0
finding location for local 'flags' near address c0173850, module bias 0
finding location for local 'mode' near address c0173850, module bias 0
finding location for local 'filename' near address c0173850, module bias 0
finding location for local 'mode' near address c0173850, module bias 0
finding location for local 'filename' near address c0173850, module bias 0
finding location for local 'filename' near address c0173850, module bias 0
control symbols: kts: 0xc0315b98 kte: 0xc03184b2 stext: 0xc01012dc
parsed 'sys_open' -> func 'sys_open'
pattern 'kernel' matches module 'kernel'
focused on module 'kernel = [0xc0100000-0xc0708000, bias 0x0] file
/boot/vmlinux-2.6.23-rc2 ELF machine i?86 (code 3)
pattern 'sys_open' matches function 'sys_open'
selected function sys_open
prologue searching function 'sys_open' 0xc017384f-0xc017386b@fs/open.c:1048
checking line record 0xc017384f@fs/open.c:1048
checking line record 0xc0173850@fs/open.c:1054
prologue found function 'sys_open' = 0xc0173850
probe sys_open@fs/open.c:1048 kernel section=.text pc=0xc017384f

-- 


http://sourceware.org/bugzilla/show_bug.cgi?id=4915

------- You are receiving this mail because: -------
You are the assignee for the bug, or are watching the assignee.

[Bug translator/4915] Incorrect code for accessing function argument

[fche at redhat dot com]

------- Additional Comments From fche at redhat dot com  2007-08-13 18:48 -------
(In reply to comment #8)
> Isn't 2.6.9-55.ELsmp an older kernel? Current RHEL4 is 2.6.9-55.0.2.EL. Does the
> debug information for the sys_open function look correct for that kernel?

Yes, all looks fine on my 2.6.9-55.0.2ELsmp and non-smp i686 installation.
In each case, the first two instructions are skipped (those with line
record fs/open.c:964), and the subsequent one (:971) gets working data.

Are you positive that you've seen this fail on an RHEL4 official kernel?
There may be ABI differences (regparms?) between your old and new kernel
configs, and the RHEL4 compiler may not be up to the latter.


-- 


http://sourceware.org/bugzilla/show_bug.cgi?id=4915

------- You are receiving this mail because: -------
You are the assignee for the bug, or are watching the assignee.

[Bug translator/4915] Incorrect code for accessing function argument

[wcohen at redhat dot com]

------- Additional Comments From wcohen at redhat dot com  2007-08-13 20:11 -------
Yes, the 2.6.9-55.0.2 kernels are official kernels installed from RPMs. The
debuginfo is publically available from:

ftp://ftp.redhat.com/pub/redhat/linux/updates/enterprise/4AS/en/os/Debuginfo/i386/RPMS

Here are the related RPMs installed on the machine:

$ rpm -qa |grep kernel|grep 2.6.9-55.0.2
kernel-smp-2.6.9-55.0.2.EL
kernel-devel-2.6.9-55.0.2.EL
kernel-hugemem-devel-2.6.9-55.0.2.EL
kernel-2.6.9-55.0.2.EL
kernel-smp-devel-2.6.9-55.0.2.EL
kernel-doc-2.6.9-55.0.2.EL
kernel-debuginfo-2.6.9-55.0.2.EL

This open.stp example in the bugzilla appears to be working in this case.
However, many of the systemtap.systemcall calls still fail. Are the tests
passing when running something like the following?

 runtest --tool_opts install --tool systemtap --srcdir
/home/wcohen/stap_testing_200708131335/src/testsuite systemtap.syscall/*.exp 

There are still many failures in the systemtap.log for 2.6.9-55.0.2.EL kernel.

Looking through the many "<uknown>" arguments in place of strings. So the tests
are running correctly on the RHEL4 i686 machine there? The question is what is
different between the environments? Same kernel rpms? Same gcc and elfutils?

Could this be a result of using elfutils 0.127 vs. 0.128? The elfutils source is
being extracted from the devel elfutils rpm.


-- 


http://sourceware.org/bugzilla/show_bug.cgi?id=4915

------- You are receiving this mail because: -------
You are the assignee for the bug, or are watching the assignee.

[Bug translator/4915] Incorrect code for accessing function argument

[wcohen at redhat dot com]

------- Additional Comments From wcohen at redhat dot com  2007-08-13 20:13 -------
Created an attachment (id=1962)
 --> (http://sourceware.org/bugzilla/attachment.cgi?id=1962&action=view)
Run of the systemtap.syscall/*.exp on 2.6.9-55.0.2.EL kernel

The output shows many of the tests failing on this machine due to "<unknown>"
arguments.

-- 


http://sourceware.org/bugzilla/show_bug.cgi?id=4915

------- You are receiving this mail because: -------
You are the assignee for the bug, or are watching the assignee.

[Bug translator/4915] imperfect prologue searching heuristics for inlined functions

[fche at redhat dot com]

------- Additional Comments From fche at redhat dot com  2007-08-14 17:22 -------
I'm seeing some debugging info errors for sys_open and sys_access on
2.6.9-55.0.2.EL[smp].  They don't fit quite into the current "trouble cases"
for the prologue searcher (resolve_prologue_endings), in that what seems
to be happening is that a small function without a prologue calls an inlined
friend that does have a real prologue.  The gcc-emitted debugging info appears
to be valid (or at least plausible) for an int parameter, but a char* sibling
is invalid until the inlined prologue of the second function.

I don't know whether it's worth trying to improve the systemtap-side heuristics,
or beat on the old compiler.  Or neither?  Opinions please?


-- 
           What    |Removed                     |Added
----------------------------------------------------------------------------
            Summary|Incorrect code for accessing|imperfect prologue searching
                   |function argument           |heuristics for inlined
                   |                            |functions


http://sourceware.org/bugzilla/show_bug.cgi?id=4915

------- You are receiving this mail because: -------
You are the assignee for the bug, or are watching the assignee.

[Bug translator/4915] imperfect prologue searching heuristics for inlined functions

[fche at redhat dot com]

------- Additional Comments From fche at redhat dot com  2010-05-21 19:44 -------
Chances are we won't hack more on the prologue heuristics, with new compilers
generating good debuginfo for arguments.  Old distributions may need to suffer
with probe placement complications; at worst, .statement(...) probes instead of
.function() ones.


-- 
           What    |Removed                     |Added
----------------------------------------------------------------------------
             Status|WAITING                     |RESOLVED
         Resolution|                            |WONTFIX


http://sourceware.org/bugzilla/show_bug.cgi?id=4915

------- You are receiving this mail because: -------
You are the assignee for the bug, or are watching the assignee.