Repost: Inaccurate function parameter location in debug info with gcc 3.x and 4.0

Repost: Inaccurate function parameter location in debug info with gcc 3.x and 4.0

[Yi Feng]

This is a repost. I wonder if anybody tried compiling the kernel with
gcc 3.x and noticed the same problem. Thanks very much!


Hi,

I have encountered a problem with the DWARF debug info when compiling
the kernel with gcc 3.x and 4.0 with optimization flags of either -O1
or -O2. When looking at the parameter locations of, for example,
sys_read, the debug info says they are all in EAX while these
parameters are in fact only read into EAX temporarily in the function
body. Using this inaccurate information, SystemTap looks at EAX at the
function entry when it's told to instrument the function parameters.
Obviously the returned value is bogus.

I'm wondering if people have noticed this problem before. Using gcc
3.x/4.0 with -Os or gcc 4.1 (with either -O2 or -Os) would generate
accurate debug info which gives the correct stack locations of the
parameters. Therefore SystemTap works correctly to get the parameter value.

This happens with all the 2.6.1x kernels I've tested. Thanks very much
for any information you may have.


Yi Feng

Re: Repost: Inaccurate function parameter location in debug info with gcc 3.x and 4.0

[Frank Ch. Eigler]

"Yi Feng" <ericyifeng@gmail.com> writes:

> [...]  I have encountered a problem with the DWARF debug info when
> compiling the kernel with gcc 3.x and 4.0 with optimization flags of
> either -O1 or -O2. When looking at the parameter locations of, for
> example, sys_read, the debug info says they are all in EAX [...]

Something must be very odd about your build or systemtap script, since
in general parameter access is working all right.  We even have a
sys_open-related test in the pass-5 test suite, and it succeeds on a
variety of kernel and compiler versions.

If you can share more details about what you're seeing (relevant
chunks of dwarf readelf data, script, "stap -vvvv" type output) ... we
may be able to help.

- FChE

Re: Repost: Inaccurate function parameter location in debug info with gcc 3.x and 4.0

[Yi Feng]

On 15 May 2006 22:15:44 -0400, Frank Ch. Eigler <fche@redhat.com> wrote:
>
> Something must be very odd about your build or systemtap script, since
> in general parameter access is working all right.  We even have a
> sys_open-related test in the pass-5 test suite, and it succeeds on a
> variety of kernel and compiler versions.
>
> If you can share more details about what you're seeing (relevant
> chunks of dwarf readelf data, script, "stap -vvvv" type output) ... we
> may be able to help.
>

Below is the relevant debug info generated by "readelf -wi vmlinux".
The kernel is 2.6.14.7 and the compiler is gcc 3.4.4. The function of
interest is sys_read.

======================================
Debug info of sys_read when compiled with -O2

 <1><431c01>: Abbrev Number: 76 (DW_TAG_subprogram)
    DW_AT_sibling     : <431cd9>
    DW_AT_external    : 1
    DW_AT_name        : (indirect string, offset: 0x1ee17): sys_read
    DW_AT_decl_file   : 1
    DW_AT_decl_line   : 329
    DW_AT_prototyped  : 1
    DW_AT_type        : <42ae88>
    DW_AT_low_pc      : 0xc0157767
    DW_AT_high_pc     : 0xc01577dc
    DW_AT_frame_base  : 1 byte block: 55       (DW_OP_reg5)
 <2><431c1d>: Abbrev Number: 78 (DW_TAG_formal_parameter)
    DW_AT_name        : fd
    DW_AT_decl_file   : 1
    DW_AT_decl_line   : 328
    DW_AT_type        : <42a899>
    DW_AT_location    : 1 byte block: 50       (DW_OP_reg0)
 <2><431c2a>: Abbrev Number: 78 (DW_TAG_formal_parameter)
    DW_AT_name        : buf
    DW_AT_decl_file   : 1
    DW_AT_decl_line   : 328
    DW_AT_type        : <42addd>
    DW_AT_location    : 1 byte block: 50       (DW_OP_reg0)
 <2><431c38>: Abbrev Number: 77 (DW_TAG_formal_parameter)
    DW_AT_name        : (indirect string, offset: 0xdbc1): count
    DW_AT_decl_file   : 1
    DW_AT_decl_line   : 328
    DW_AT_type        : <42ae7d>
    DW_AT_location    : 1 byte block: 50       (DW_OP_reg0)

======================================
Debug info of sys_read when compiled with -Os

 <1><432a89>: Abbrev Number: 76 (DW_TAG_subprogram)
    DW_AT_sibling     : <432b67>
    DW_AT_external    : 1
    DW_AT_name        : (indirect string, offset: 0x1ee17): sys_read
    DW_AT_decl_file   : 1
    DW_AT_decl_line   : 329
    DW_AT_prototyped  : 1
    DW_AT_type        : <42bd17>
    DW_AT_low_pc      : 0xc0148d36
    DW_AT_high_pc     : 0xc0148d97
    DW_AT_frame_base  : 1 byte block: 55       (DW_OP_reg5)
 <2><432aa5>: Abbrev Number: 78 (DW_TAG_formal_parameter)
    DW_AT_name        : fd
    DW_AT_decl_file   : 1
    DW_AT_decl_line   : 328
    DW_AT_type        : <42b728>
    DW_AT_location    : 1 byte block: 50       (DW_OP_reg0)
 <2><432ab2>: Abbrev Number: 78 (DW_TAG_formal_parameter)
    DW_AT_name        : buf
    DW_AT_decl_file   : 1
    DW_AT_decl_line   : 328
    DW_AT_type        : <42bc6c>
    DW_AT_location    : 2 byte block: 91 c     (DW_OP_fbreg: 12)
 <2><432ac1>: Abbrev Number: 77 (DW_TAG_formal_parameter)
    DW_AT_name        : (indirect string, offset: 0xdbc1): count
    DW_AT_decl_file   : 1
    DW_AT_decl_line   : 328
    DW_AT_type        : <42bd0c>
    DW_AT_location    : 2 byte block: 91 10    (DW_OP_fbreg: 16)

============================================================
Difference in stap_xxxx.c for the two cases when reading "count" in sys_read

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

========================
The original systemtap script

/* rwblock.stp
  This is a simple get count the number of read and write operations and
  accumulate the number of bytes for each.

  Will Cohen
*/

global count_sys_read
global count_sys_write
global sys_read_bytes
global sys_write_bytes

probe kernel.function("sys_read")
{
       ++count_sys_read;
       sys_read_bytes += $count;
}

probe kernel.function("sys_write")
{
       ++count_sys_write;
       sys_write_bytes += $count;
}

probe begin { log("starting probe") }

probe end
{
       log("ending probe")
       log(string(sys_read_bytes) . " bytes read with "
       . string(count_sys_read) . " calls to sys_read(), avg size of read "
       . string(sys_read_bytes/count_sys_read) );
       log(string(sys_write_bytes) . " bytes written with "
       . string(count_sys_write) . " calls to sys_write(), avg size of write "
       . string(sys_write_bytes/count_sys_write) );
}


In both cases, systemtap "succeeds" executing the script except the
numbers it reports with the -O2 kernel are bogus (because it reads
"count" from the wrong location / at the wrong time).

In my system, this is very easily reproducible. You just need to
compile the kernel using gcc 3.x with -O2 and -Os.

Please help me verify if this is just my build system's problem or it
is a common problem affecting all users. Thank you very much!


Yi Feng

Re: Repost: Inaccurate function parameter location in debug info with gcc 3.x and 4.0

[Roland McGrath]

We have come across some bugs in gcc's DWARF generation in the course of
systemtap development.  We mostly pay attention to the current compiler
versions (now gcc 4.1), but we have also had some fixes backported to the
3.4-based version used in RHEL4.  Frank might have a list of the gcc or
redhat bugzilla items reported about these things.  I don't have one off
hand.  To figure out if your issues are affected by those changes, you
might try a gcc build from the sources in this branch:
svn://gcc.gnu.org/svn/gcc/branches/redhat/gcc-3_4-branch

I'm not sure that anyone working on systemtap is using kernels built with
gcc 3 any longer, except for RHEL4 kernels, which are built with a compiler
from this branch.


Thanks,
Roland

Re: Repost: Inaccurate function parameter location in debug info with gcc 3.x and 4.0

[bibo,mao]

There is one method to check whether parameter location is right. Checking
translated systemtap script, including both probed function's ip address and 
function location, and compare them with assembly language of this function.
you can get this function's assembly language by "objdump -DS vmlinux" command.


Thanks
bibo,mao

Yi Feng wrote:
> On 15 May 2006 22:15:44 -0400, Frank Ch. Eigler <fche@redhat.com> wrote:
>>
>> Something must be very odd about your build or systemtap script, since
>> in general parameter access is working all right.  We even have a
>> sys_open-related test in the pass-5 test suite, and it succeeds on a
>> variety of kernel and compiler versions.
>>
>> If you can share more details about what you're seeing (relevant
>> chunks of dwarf readelf data, script, "stap -vvvv" type output) ... we
>> may be able to help.
>>
> 
> Below is the relevant debug info generated by "readelf -wi vmlinux".
> The kernel is 2.6.14.7 and the compiler is gcc 3.4.4. The function of
> interest is sys_read.
> 
> ======================================
> Debug info of sys_read when compiled with -O2
> 
> <1><431c01>: Abbrev Number: 76 (DW_TAG_subprogram)
>    DW_AT_sibling     : <431cd9>
>    DW_AT_external    : 1
>    DW_AT_name        : (indirect string, offset: 0x1ee17): sys_read
>    DW_AT_decl_file   : 1
>    DW_AT_decl_line   : 329
>    DW_AT_prototyped  : 1
>    DW_AT_type        : <42ae88>
>    DW_AT_low_pc      : 0xc0157767
>    DW_AT_high_pc     : 0xc01577dc
>    DW_AT_frame_base  : 1 byte block: 55       (DW_OP_reg5)
> <2><431c1d>: Abbrev Number: 78 (DW_TAG_formal_parameter)
>    DW_AT_name        : fd
>    DW_AT_decl_file   : 1
>    DW_AT_decl_line   : 328
>    DW_AT_type        : <42a899>
>    DW_AT_location    : 1 byte block: 50       (DW_OP_reg0)
> <2><431c2a>: Abbrev Number: 78 (DW_TAG_formal_parameter)
>    DW_AT_name        : buf
>    DW_AT_decl_file   : 1
>    DW_AT_decl_line   : 328
>    DW_AT_type        : <42addd>
>    DW_AT_location    : 1 byte block: 50       (DW_OP_reg0)
> <2><431c38>: Abbrev Number: 77 (DW_TAG_formal_parameter)
>    DW_AT_name        : (indirect string, offset: 0xdbc1): count
>    DW_AT_decl_file   : 1
>    DW_AT_decl_line   : 328
>    DW_AT_type        : <42ae7d>
>    DW_AT_location    : 1 byte block: 50       (DW_OP_reg0)
> 
> ======================================
> Debug info of sys_read when compiled with -Os
> 
> <1><432a89>: Abbrev Number: 76 (DW_TAG_subprogram)
>    DW_AT_sibling     : <432b67>
>    DW_AT_external    : 1
>    DW_AT_name        : (indirect string, offset: 0x1ee17): sys_read
>    DW_AT_decl_file   : 1
>    DW_AT_decl_line   : 329
>    DW_AT_prototyped  : 1
>    DW_AT_type        : <42bd17>
>    DW_AT_low_pc      : 0xc0148d36
>    DW_AT_high_pc     : 0xc0148d97
>    DW_AT_frame_base  : 1 byte block: 55       (DW_OP_reg5)
> <2><432aa5>: Abbrev Number: 78 (DW_TAG_formal_parameter)
>    DW_AT_name        : fd
>    DW_AT_decl_file   : 1
>    DW_AT_decl_line   : 328
>    DW_AT_type        : <42b728>
>    DW_AT_location    : 1 byte block: 50       (DW_OP_reg0)
> <2><432ab2>: Abbrev Number: 78 (DW_TAG_formal_parameter)
>    DW_AT_name        : buf
>    DW_AT_decl_file   : 1
>    DW_AT_decl_line   : 328
>    DW_AT_type        : <42bc6c>
>    DW_AT_location    : 2 byte block: 91 c     (DW_OP_fbreg: 12)
> <2><432ac1>: Abbrev Number: 77 (DW_TAG_formal_parameter)
>    DW_AT_name        : (indirect string, offset: 0xdbc1): count
>    DW_AT_decl_file   : 1
>    DW_AT_decl_line   : 328
>    DW_AT_type        : <42bd0c>
>    DW_AT_location    : 2 byte block: 91 10    (DW_OP_fbreg: 16)
> 
> ============================================================
> Difference in stap_xxxx.c for the two cases when reading "count" in 
> sys_read
> 
> void function__dwarf_tvar_get_count_0 (struct context* __restrict__ c) {
>  struct function__dwarf_tvar_get_count_0_locals *  __restrict__ l =
>    & c->locals[c->nesting].function__dwarf_tvar_get_count_0;
>  (void) l;
>  #define CONTEXT c
>  #define THIS l
>  if (0) goto out;
>  l->__retvalue = 0;
>  {
>    {
>  {
> -    THIS->__retvalue = fetch_register (0);
> +    intptr_t addr;
> +  intptr_t frame_base;
> +  { // DWARF expression: 0x55
> +    frame_base = fetch_register (5);
> +  }
> +    { // DWARF expression: 0x91(16)
> +      {
> +        intptr_t s0;
> +        s0 = frame_base + 16L;
> +        addr = s0;
> +      }
> +    }
> +    THIS->__retvalue = deref (4, addr);
>  }
>  goto out;
> if (0) goto deref_fault;
> deref_fault:
>  c->last_error = "pointer dereference fault";
>  goto out;
> }
> /* pure */
>  }
> out:
>  ;
>  #undef CONTEXT
>  #undef THIS
> }
> 
> ========================
> The original systemtap script
> 
> /* rwblock.stp
>  This is a simple get count the number of read and write operations and
>  accumulate the number of bytes for each.
> 
>  Will Cohen
> */
> 
> global count_sys_read
> global count_sys_write
> global sys_read_bytes
> global sys_write_bytes
> 
> probe kernel.function("sys_read")
> {
>       ++count_sys_read;
>       sys_read_bytes += $count;
> }
> 
> probe kernel.function("sys_write")
> {
>       ++count_sys_write;
>       sys_write_bytes += $count;
> }
> 
> probe begin { log("starting probe") }
> 
> probe end
> {
>       log("ending probe")
>       log(string(sys_read_bytes) . " bytes read with "
>       . string(count_sys_read) . " calls to sys_read(), avg size of read "
>       . string(sys_read_bytes/count_sys_read) );
>       log(string(sys_write_bytes) . " bytes written with "
>       . string(count_sys_write) . " calls to sys_write(), avg size of 
> write "
>       . string(sys_write_bytes/count_sys_write) );
> }
> 
> 
> In both cases, systemtap "succeeds" executing the script except the
> numbers it reports with the -O2 kernel are bogus (because it reads
> "count" from the wrong location / at the wrong time).
> 
> In my system, this is very easily reproducible. You just need to
> compile the kernel using gcc 3.x with -O2 and -Os.
> 
> Please help me verify if this is just my build system's problem or it
> is a common problem affecting all users. Thank you very much!
> 
> 
> Yi Feng
> 

Re: Repost: Inaccurate function parameter location in debug info with gcc 3.x and 4.0

[Frank Ch. Eigler]

Hi -

> [...]  Below is the relevant debug info generated by "readelf -wi
> vmlinux".  The kernel is 2.6.14.7 and the compiler is gcc 3.4.4. The
> function of interest is sys_read.  [...]

(Thanks for the eu-readelf information, though it is not by itself
enough to diagnose the problem.  One might need more bits like a
disassembly of the probed function, address-related excerpts from
"stap -vvvv" output.)

> In my system, this is very easily reproducible. You just need to
> compile the kernel using gcc 3.x with -O2 and -Os.

Red Hat originated kernels are built with -Os, but, importantly, use
newer compilers that include fixes related to debugging information.

> Please help me verify if this is just my build system's problem or
> it is a common problem affecting all users. [...]

It is not a common problem.  We have a standard example in the test
suite (iotask*.stp) that, although we don't run it automatically for
some reason (no .exp file), it does work when run by hand.

- FChE

RE: Repost: Inaccurate function parameter location in debug info with gcc 3.x and 4.0

[Mao, Bibo]

There are two different function probe point, one is function entry point, and the other is prologue end point. Function parameter location is different between these two probe points.
Currrently systemtap uses prologue end point as function probe point, there is one test case sysopen.stp, you can check translated c file, and the probe point value about sys_open is different with that in file/proc/kallsyms.

Bibo,mao

>-----Original Message-----
>From: systemtap-owner@sourceware.org [mailto:systemtap-owner@sourceware.org]
>On Behalf Of Yi Feng
>Sent: 2006年5月16日 1:55
>To: systemtap@sources.redhat.com
>Subject: Repost: Inaccurate function parameter location in debug info with gcc
>3.x and 4.0
>
>This is a repost. I wonder if anybody tried compiling the kernel with
>gcc 3.x and noticed the same problem. Thanks very much!
>
>
>Hi,
>
>I have encountered a problem with the DWARF debug info when compiling
>the kernel with gcc 3.x and 4.0 with optimization flags of either -O1
>or -O2. When looking at the parameter locations of, for example,
>sys_read, the debug info says they are all in EAX while these
>parameters are in fact only read into EAX temporarily in the function
>body. Using this inaccurate information, SystemTap looks at EAX at the
>function entry when it's told to instrument the function parameters.
>Obviously the returned value is bogus.
>
>I'm wondering if people have noticed this problem before. Using gcc
>3.x/4.0 with -Os or gcc 4.1 (with either -O2 or -Os) would generate
>accurate debug info which gives the correct stack locations of the
>parameters. Therefore SystemTap works correctly to get the parameter value.
>
>This happens with all the 2.6.1x kernels I've tested. Thanks very much
>for any information you may have.
>
>
>Yi Feng