This is the mail archive of the systemtap@sourceware.org mailing list for the systemtap project.


Index Nav: [Date Index] [Subject Index] [Author Index] [Thread Index]
Message Nav: [Date Prev] [Date Next] [Thread Prev] [Thread Next]
Other format: [Raw text]

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


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



Index Nav: [Date Index] [Subject Index] [Author Index] [Thread Index]
Message Nav: [Date Prev] [Date Next] [Thread Prev] [Thread Next]