Bug 10261 - Excessive filesystem access when inferior binary uses absolute path to sources
Summary: Excessive filesystem access when inferior binary uses absolute path to sources
Status: UNCONFIRMED
Alias: None
Product: gdb
Classification: Unclassified
Component: breakpoints (show other bugs)
Version: 6.8
: P2 normal
Target Milestone: 6.8
Assignee: Not yet assigned to anyone
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2009-06-11 01:56 UTC by Paul Pluzhnikov
Modified: 2012-07-08 19:32 UTC (History)
2 users (show)

See Also:
Host: x86_64-unknown-linux-gnu
Target: x86_64-unknown-linux-gnu
Build: x86_64-unknown-linux-gnu
Last reconfirmed:


Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description Paul Pluzhnikov 2009-06-11 01:56:19 UTC
Discovered this as extreme slowdown in debugging GCC, using
GNU gdb (GDB) 6.8.50.20090610-cvs

It appears that GDB performs bazillion of lstat() calls when sources are
compiled via absolute path.

I have two identical builds of gcc, except one was configured with

  ../configure

and the other with

  /abs/path/to/gcc-svn/configure

Results for "relative" build:
-----------------------------

time ./gdb -q -ex 'rbreak emit_' -ex run -ex quit --args 
/usr/local/gcc-svn-install/libexec/gcc/x86_64-unknown-linux-gnu/4.5.0/cc1 /dev/null
...
Breakpoint 47, init_emit_once (line_numbers=0) at ../../gcc/emit-rtl.c:5382
5382    {

real    0m2.050s
user    0m1.928s
sys     0m0.112s

strace -c ./gdb -q -ex 'rbreak emit_' -ex run -ex quit --args 
/usr/local/gcc-svn-install/libexec/gcc/x86_64-unknown-linux-gnu/4.5.0/cc1 /dev/null
...
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 83.99    0.043842          83       529           read
  8.90    0.004644         141        33        14 wait4
  6.85    0.003576        3576         1           clone
  0.11    0.000057           0      4092         1 ptrace
  0.07    0.000035           0       122           mmap
  0.05    0.000028           0       285           brk
  0.04    0.000020           0        41           pread
  0.00    0.000000           0       261           write
  0.00    0.000000           0       137        18 open
  0.00    0.000000           0       119           close
  0.00    0.000000           0        17         7 stat
  0.00    0.000000           0        49           fstat
  0.00    0.000000           0        48         2 lstat


Results for "absolute" build:
-----------------------------

time ./gdb -q -ex 'rbreak emit_' -ex run -ex quit --args 
/usr/local/gcc-svn-install-abspath/libexec/gcc/x86_64-unknown-linux-gnu/4.5.0/cc1 /dev/null
...
Breakpoint 47, init_emit_once (line_numbers=0) at
/home/ppluzhnikov/Archive/gcc-svn/gcc/emit-rtl.c:5382
5382    {

real    0m11.126s
user    0m3.108s
sys     0m7.908s

It's 5 times slower! Strace shows:


% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 38.99    0.051544           0   2881691         2 lstat
 31.62    0.041798          80       524           read
 16.44    0.021727           0    728617        18 open
  4.47    0.005903           0    728599           close
  3.85    0.005091         189        27        11 wait4
  3.03    0.004000        4000         1           clone
  0.78    0.001034           0     25093     23827 stat
  0.30    0.000393          79         5           mremap
  0.22    0.000295         295         1           execve
  0.18    0.000237           0      2425           readlink
  0.06    0.000084           0       261           write
  0.03    0.000037           0       622           brk
  0.02    0.000021           0        56           ioctl
  0.02    0.000021           1        15         2 access
  0.01    0.000010           0      4092         1 ptrace
  0.00    0.000000           0        49           fstat

Where did the extra 2.9 million calls to lstat(), 700K+ calls to open/close
come from?

This also becomes significantly more pronounced when the source is nested
more deeply, that is when the path to emit-rtl.c is something like
/usr/local/google/tmp/build-v13/gcc-4.4.0-glibc-2.3.6-grte/rpmbuild/BUILD/ppluzhnikov-gcc-4.4.0-glibc-2.3.6/i686-unknown-linux-gnu/gcc-4.4.0/gcc/emit-rtl.c

strace shows long chains like this:
...
write(1, "Breakpoint 1, init_emit_once (li"..., 115) = 115
stat("/usr/local/google/ppluzhnikov/Archive/gcc-svn/gcc/emit-rtl.c",
{st_mode=S_IFREG|0640, st_size=150634, ...}) = 0
open("/usr/local/google/ppluzhnikov/Archive/gcc-svn/gcc/emit-rtl.c", O_RDONLY) = 5
lstat("/usr", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
lstat("/usr/local", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
lstat("/usr/local/google", {st_mode=S_IFDIR|S_ISVTX|0777, st_size=4096, ...}) = 0
lstat("/usr/local/google/ppluzhnikov", {st_mode=S_IFDIR|0750, st_size=4096,
...}) = 0
lstat("/usr/local/google/ppluzhnikov/Archive", {st_mode=S_IFDIR|0755,
st_size=4096, ...}) = 0
lstat("/usr/local/google/ppluzhnikov/Archive/gcc-svn", {st_mode=S_IFDIR|0750,
st_size=4096, ...}) = 0
lstat("/usr/local/google/ppluzhnikov/Archive/gcc-svn/gcc",
{st_mode=S_IFDIR|0750, st_size=20480, ...}) = 0
fstat(5, {st_mode=S_IFREG|0640, st_size=150634, ...}) = 0
mmap(NULL, 151552, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) =
0x7f651bfce000
read(5, "/* Emit RTL for the GCC expander"..., 150634) = 150634
brk(0x10c1000)                          = 0x10c1000
brk(0x10bd000)                          = 0x10bd000
munmap(0x7f651bfce000, 151552)          = 0
brk(0x10bb000)                          = 0x10bb000
lseek(5, 140035, SEEK_SET)              = 140035
fcntl(5, F_GETFL)                       = 0x8000 (flags O_RDONLY|O_LARGEFILE)
fstat(5, {st_mode=S_IFREG|0640, st_size=150634, ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) =
0x7f651cedf000
lseek(5, 0, SEEK_CUR)                   = 140035
read(5, "{\n  int i;\n  enum machine_mode m"..., 4096) = 4096
write(1, "5382\t{\n", 7)                = 7
close(5)                                = 0
Comment 1 dje 2012-07-08 19:32:38 UTC
Note to self: I need to check whether the "basenames-may-differ" patch improves things here.