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
