[Bug sanitizer/91101] New: Possible performance regression in libasan with detect_stack_use_after_return=1

frantisek at sumsal dot cz gcc-bugzilla@gcc.gnu.org
Sat Jul 6 20:07:00 GMT 2019


https://gcc.gnu.org/bugzilla/show_bug.cgi?id=91101

            Bug ID: 91101
           Summary: Possible performance regression in libasan with
                    detect_stack_use_after_return=1
           Product: gcc
           Version: 9.1.0
            Status: UNCONFIRMED
          Severity: normal
          Priority: P3
         Component: sanitizer
          Assignee: unassigned at gcc dot gnu.org
          Reporter: frantisek at sumsal dot cz
                CC: dodji at gcc dot gnu.org, dvyukov at gcc dot gnu.org,
                    jakub at gcc dot gnu.org, kcc at gcc dot gnu.org, marxin at gcc dot gnu.org
  Target Milestone: ---

Hello,
in systemd we recently noticed[0], that certain CI's started timeouting after
upgrade to gcc 9.1.0 and 9.1.1. After a bit of investigation it seems that the
runtime of instrumented binaries with ASan is more than doubled. (The GitHub
thread contains claims about the performance issue being present even without
sanitizers, but that hasn't been confirmed yet, so please ignore it).

Also, I apologize if this report is useless for upstream, since it's not using
the trunk GCC, but I'd really like to know if we're doing something
fundamentally wrong or if this is an actual issue. The following report is from
Arch Linux with GCC 9.1.0, but I also managed to reproduce this on Fedora
Rawhide with GCC 9.1.1[1]. As this thread is without any response so far, I've
been trying to collect as much information as possible regarding this issue, as
testing systemd with bleeding-edge software is particularly important for us.

The following statistics provide comparison between two particular systemd test
cases compiled with GCC 8.3.0 (with and without ASan and UBSan) and the same
statistics for GCC 9.1.0:

----

[vagrant@arch build]$ pacman -Q gcc gcc-libs
gcc 8.3.0-1
gcc-libs 8.3.0-1
[vagrant@arch build]$ gcc -v
Using built-in specs.
COLLECT_GCC=gcc
COLLECT_LTO_WRAPPER=/usr/lib/gcc/x86_64-pc-linux-gnu/8.3.0/lto-wrapper
Target: x86_64-pc-linux-gnu
Configured with: /build/gcc/src/gcc/configure --prefix=/usr --libdir=/usr/lib
--libexecdir=/usr/lib --mandir=/usr/share/man --infodir=/usr/share/info
--with-bugurl=https://bugs.archlinux.org/
--enable-languages=c,c++,ada,fortran,go,lto,objc,obj-c++ --enable-shared
--enable-threads=posix --enable-libmpx --with-system-zlib --with-isl
--enable-__cxa_atexit --disable-libunwind-exceptions --enable-clocale=gnu
--disable-libstdcxx-pch --disable-libssp --enable-gnu-unique-object
--enable-linker-build-id --enable-lto --enable-plugin
--enable-install-libiberty --with-linker-hash-style=gnu
--enable-gnu-indirect-function --enable-multilib --disable-werror
--enable-checking=release --enable-default-pie --enable-default-ssp
--enable-cet=auto
Thread model: posix
gcc version 8.3.0 (GCC)

# Basically git clone https://github.com/systemd/systemd /build
[vagrant@arch build]$ meson build-gcc-8.3.0-sanitizers
-Db_sanitize=address,undefined
<...snip...>
[vagrant@arch build]$ meson build-gcc-8.3.0
<...snip...>
[vagrant@arch build]$ ninja -C build-gcc-8.3.0-sanitizers
<...snip...>
[vagrant@arch build]$ ninja -C build-gcc-8.3.0
<...snip...>

# Sanitizer-specific options
[vagrant@arch build]$ export
ASAN_OPTIONS=strict_string_checks=1:detect_stack_use_after_return=1:check_initialization_order=1:strict_init_order=1
[vagrant@arch build]$ export
UBSAN_OPTIONS=print_stacktrace=1:print_summary=1:halt_on_error=1

# WITHOUT sanitizers
[vagrant@arch build]$ /bin/time -v build-gcc-8.3.0/test-conf-parser >/dev/null
<...snip...>
    Command being timed: "build-gcc-8.3.0/test-conf-parser"
    User time (seconds): 1.25
    System time (seconds): 0.01
    Percent of CPU this job got: 99%
    Elapsed (wall clock) time (h:mm:ss or m:ss): 0:01.28
    Average shared text size (kbytes): 0
    Average unshared data size (kbytes): 0
    Average stack size (kbytes): 0
    Average total size (kbytes): 0
    Maximum resident set size (kbytes): 9944
    Average resident set size (kbytes): 0
    Major (requiring I/O) page faults: 0
    Minor (reclaiming a frame) page faults: 930
    Voluntary context switches: 12
    Involuntary context switches: 107
    Swaps: 0
    File system inputs: 0
    File system outputs: 0
    Socket messages sent: 0
    Socket messages received: 0
    Signals delivered: 0
    Page size (bytes): 4096
    Exit status: 0

[vagrant@arch build]$ cd build-gcc-8.3.0 && /bin/time -v ../test/hwdb-test.sh
>/dev/null
    Command being timed: "../test/hwdb-test.sh"
    User time (seconds): 0.40
    System time (seconds): 0.01
    Percent of CPU this job got: 98%
    Elapsed (wall clock) time (h:mm:ss or m:ss): 0:00.41
    Average shared text size (kbytes): 0
    Average unshared data size (kbytes): 0
    Average stack size (kbytes): 0
    Average total size (kbytes): 0
    Maximum resident set size (kbytes): 25752
    Average resident set size (kbytes): 0
    Major (requiring I/O) page faults: 0
    Minor (reclaiming a frame) page faults: 7264
    Voluntary context switches: 71
    Involuntary context switches: 30
    Swaps: 0
    File system inputs: 0
    File system outputs: 0
    Socket messages sent: 0
    Socket messages received: 0
    Signals delivered: 0
    Page size (bytes): 4096
    Exit status: 0

# WITH sanitizers
[vagrant@arch build]$ /bin/time -v build-gcc-8.3.0-sanitizers/test-conf-parser
>/dev/null
<...snip...>
    Command being timed: "build-gcc-8.3.0-sanitizers/test-conf-parser"
    User time (seconds): 3.05
    System time (seconds): 0.28
    Percent of CPU this job got: 92%
    Elapsed (wall clock) time (h:mm:ss or m:ss): 0:03.61
    Average shared text size (kbytes): 0
    Average unshared data size (kbytes): 0
    Average stack size (kbytes): 0
    Average total size (kbytes): 0
    Maximum resident set size (kbytes): 347056
    Average resident set size (kbytes): 0
    Major (requiring I/O) page faults: 16
    Minor (reclaiming a frame) page faults: 180270
    Voluntary context switches: 85
    Involuntary context switches: 395
    Swaps: 0
    File system inputs: 35568
    File system outputs: 0
    Socket messages sent: 0
    Socket messages received: 0
    Signals delivered: 0
    Page size (bytes): 4096
    Exit status: 0

[vagrant@arch build]$ cd build-gcc-8.3.0-sanitizers/ && /bin/time -v
../test/hwdb-test.sh >/dev/null
    Command being timed: "../test/hwdb-test.sh"
    User time (seconds): 40.08
    System time (seconds): 31.98
    Percent of CPU this job got: 99%
    Elapsed (wall clock) time (h:mm:ss or m:ss): 1:12.41
    Average shared text size (kbytes): 0
    Average unshared data size (kbytes): 0
    Average stack size (kbytes): 0
    Average total size (kbytes): 0
    Maximum resident set size (kbytes): 805060
    Average resident set size (kbytes): 0
    Major (requiring I/O) page faults: 3
    Minor (reclaiming a frame) page faults: 22857463
    Voluntary context switches: 97
    Involuntary context switches: 414
    Swaps: 0
    File system inputs: 288
    File system outputs: 0
    Socket messages sent: 0
    Socket messages received: 0
    Signals delivered: 0
    Page size (bytes): 4096
    Exit status: 0


# GCC upgrade
[vagrant@arch build]$ sudo pacman -Sy gcc gcc-libs
...
Packages (2) gcc-9.1.0-2  gcc-libs-9.1.0-2
...
[vagrant@arch build]$ gcc -v
Using built-in specs.
COLLECT_GCC=gcc
COLLECT_LTO_WRAPPER=/usr/lib/gcc/x86_64-pc-linux-gnu/9.1.0/lto-wrapper
Target: x86_64-pc-linux-gnu
Configured with: /build/gcc/src/gcc/configure --prefix=/usr --libdir=/usr/lib
--libexecdir=/usr/lib --mandir=/usr/share/man --infodir=/usr/share/info
--with-bugurl=https://bugs.archlinux.org/
--enable-languages=c,c++,ada,fortran,go,lto,objc,obj-c++ --enable-shared
--enable-threads=posix --with-system-zlib --with-isl --enable-__cxa_atexit
--disable-libunwind-exceptions --enable-clocale=gnu --disable-libstdcxx-pch
--disable-libssp --enable-gnu-unique-object --enable-linker-build-id
--enable-lto --enable-plugin --enable-install-libiberty
--with-linker-hash-style=gnu --enable-gnu-indirect-function --enable-multilib
--disable-werror --enable-checking=release --enable-default-pie
--enable-default-ssp --enable-cet=auto
Thread model: posix
gcc version 9.1.0 (GCC)


[vagrant@arch build]$ meson build-gcc-9.1.0-sanitizers
-Db_sanitize=address,undefined
<...snip...>
[vagrant@arch build]$ meson build-gcc-9.1.0
<...snip...>
[vagrant@arch build]$ ninja -C build-gcc-9.1.0-sanitizers
<...snip...>
[vagrant@arch build]$ ninja -C build-gcc-9.1.0
<...snip...>


# WITHOUT sanitizers
[vagrant@arch build]$ /bin/time -v build-gcc-9.1.0/test-conf-parser >/dev/null
<...snip...>
    Command being timed: "build-gcc-9.1.0/test-conf-parser"
    User time (seconds): 1.26
    System time (seconds): 0.00
    Percent of CPU this job got: 99%
    Elapsed (wall clock) time (h:mm:ss or m:ss): 0:01.28
    Average shared text size (kbytes): 0
    Average unshared data size (kbytes): 0
    Average stack size (kbytes): 0
    Average total size (kbytes): 0
    Maximum resident set size (kbytes): 10016
    Average resident set size (kbytes): 0
    Major (requiring I/O) page faults: 1
    Minor (reclaiming a frame) page faults: 928
    Voluntary context switches: 6
    Involuntary context switches: 111
    Swaps: 0
    File system inputs: 96
    File system outputs: 0
    Socket messages sent: 0
    Socket messages received: 0
    Signals delivered: 0
    Page size (bytes): 4096
    Exit status: 0

[vagrant@arch build]$ cd build-gcc-9.1.0 && /bin/time -v ../test/hwdb-test.sh
>/dev/null
    Command being timed: "../test/hwdb-test.sh"
    User time (seconds): 0.43
    System time (seconds): 0.03
    Percent of CPU this job got: 95%
    Elapsed (wall clock) time (h:mm:ss or m:ss): 0:00.49
    Average shared text size (kbytes): 0
    Average unshared data size (kbytes): 0
    Average stack size (kbytes): 0
    Average total size (kbytes): 0
    Maximum resident set size (kbytes): 25856
    Average resident set size (kbytes): 0
    Major (requiring I/O) page faults: 3
    Minor (reclaiming a frame) page faults: 7279
    Voluntary context switches: 108
    Involuntary context switches: 68
    Swaps: 0
    File system inputs: 1144
    File system outputs: 0
    Socket messages sent: 0
    Socket messages received: 0
    Signals delivered: 0
    Page size (bytes): 4096
    Exit status: 0

# WITH sanitizers
[vagrant@arch build]$ /bin/time -v build-gcc-9.1.0-sanitizers/test-conf-parser
>/dev/null
<...snip...>
    Command being timed: "build-gcc-9.1.0-sanitizers/test-conf-parser"
    User time (seconds): 30.03
    System time (seconds): 0.33
    Percent of CPU this job got: 99%
    Elapsed (wall clock) time (h:mm:ss or m:ss): 0:30.50
    Average shared text size (kbytes): 0
    Average unshared data size (kbytes): 0
    Average stack size (kbytes): 0
    Average total size (kbytes): 0
    Maximum resident set size (kbytes): 348972
    Average resident set size (kbytes): 0
    Major (requiring I/O) page faults: 17
    Minor (reclaiming a frame) page faults: 180473
    Voluntary context switches: 31
    Involuntary context switches: 160
    Swaps: 0
    File system inputs: 5200
    File system outputs: 0
    Socket messages sent: 0
    Socket messages received: 0
    Signals delivered: 0
    Page size (bytes): 4096
    Exit status: 0

[vagrant@arch build]$ cd build-gcc-9.1.0-sanitizers/ && /bin/time -v
../test/hwdb-test.sh >/dev/null
    Command being timed: "../test/hwdb-test.sh"
    User time (seconds): 129.53
    System time (seconds): 32.94
    Percent of CPU this job got: 99%
    Elapsed (wall clock) time (h:mm:ss or m:ss): 2:43.29
    Average shared text size (kbytes): 0
    Average unshared data size (kbytes): 0
    Average stack size (kbytes): 0
    Average total size (kbytes): 0
    Maximum resident set size (kbytes): 805868
    Average resident set size (kbytes): 0
    Major (requiring I/O) page faults: 6
    Minor (reclaiming a frame) page faults: 22858160
    Voluntary context switches: 118
    Involuntary context switches: 1136
    Swaps: 0
    File system inputs: 11640
    File system outputs: 0
    Socket messages sent: 0
    Socket messages received: 0
    Signals delivered: 0
    Page size (bytes): 4096
    Exit status: 0

----

Notice the huge difference in user/wall time in the ASan+UBsan run, which is
~10 times slower with GCC 9.1.x as opposed to GCC 8.3.0.

However, by switching the `detect_stack_use_after_return` option off, the
performance issue is much less noticeable:

----

[vagrant@arch build]$ export
ASAN_OPTIONS=strict_string_checks=1:check_initialization_order=1:strict_init_order=1:detect_stack_use_after_return=0

[vagrant@arch build]$ /bin/time -v build-gcc-9.1.0-sanitizers/test-conf-parser
>/dev/null
<...snip...>
/tmp/test-conf-parser.Q8S7gi:1: Continuation line too long
    Command being timed: "build-gcc-9.1.0-sanitizers/test-conf-parser"
    User time (seconds): 2.61
    System time (seconds): 0.23
    Percent of CPU this job got: 99%
    Elapsed (wall clock) time (h:mm:ss or m:ss): 0:02.87
    Average shared text size (kbytes): 0
    Average unshared data size (kbytes): 0
    Average stack size (kbytes): 0
    Average total size (kbytes): 0
    Maximum resident set size (kbytes): 347316
    Average resident set size (kbytes): 0
    Major (requiring I/O) page faults: 9
    Minor (reclaiming a frame) page faults: 179814
    Voluntary context switches: 22
    Involuntary context switches: 108
    Swaps: 0
    File system inputs: 1160
    File system outputs: 0
    Socket messages sent: 0
    Socket messages received: 0
    Signals delivered: 0
    Page size (bytes): 4096
    Exit status: 0

[vagrant@arch build]$ cd build-gcc-9.1.0-sanitizers/ && /bin/time -v
../test/hwdb-test.sh >/dev/null
    Command being timed: "../test/hwdb-test.sh"
    User time (seconds): 22.71
    System time (seconds): 32.06
    Percent of CPU this job got: 99%
    Elapsed (wall clock) time (h:mm:ss or m:ss): 0:55.11
    Average shared text size (kbytes): 0
    Average unshared data size (kbytes): 0
    Average stack size (kbytes): 0
    Average total size (kbytes): 0
    Maximum resident set size (kbytes): 802892
    Average resident set size (kbytes): 0
    Major (requiring I/O) page faults: 15
    Minor (reclaiming a frame) page faults: 22856894
    Voluntary context switches: 171
    Involuntary context switches: 657
    Swaps: 0
    File system inputs: 25384
    File system outputs: 0
    Socket messages sent: 0
    Socket messages received: 0
    Signals delivered: 0
    Page size (bytes): 4096
    Exit status: 0

---

So far I've failed to convince meson/ninja to build systemd and leave the GCC's
temporary files intact, so I'll provide them as soon as possible.

Thank you.


[0] https://github.com/systemd/systemd/pull/12856#issuecomment-504395847
[1] https://bugzilla.redhat.com/show_bug.cgi?id=1722949


More information about the Gcc-bugs mailing list