Extremely slow optimizer performance when including large array of strings

[joshtriplett]

Consider the following test program:

fn main() {
    let words = include!("num_array.rs");
    let mut l = 0;
    for word in words.into_iter() {
        l += word.len();
    }
    println!("{}", l);
}

num_array.rs contains an array of 250k strings:

$ (echo '['; seq 1 250000 | sed 's/.*/"&",/' ; echo ']') > num_array.rs
$ head -n 5 num_array.rs 
[
"1",
"2",
"3",
"4",
$ tail -n 5 num_array.rs 
"249997",
"249998",
"249999",
"250000",
]

Compiling this in debug mode took about 45 seconds; long, and potentially a good test case for compiler profiling, but not completely ridiculous.

Compiling this in release mode showed no signs of finishing after 45 minutes. stracing rustc showed two threads, one blocked in a futex and the other repeatedly allocating and freeing a memory buffer:

mmap(0x7fb665a00000, 2097152, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fb637400000
munmap(0x7fb637400000, 2097152)         = 0
mmap(0x7fb665a00000, 2097152, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fb637400000
munmap(0x7fb637400000, 2097152)         = 0
madvise(0x7fb66531a000, 659456, MADV_DONTNEED) = 0
madvise(0x7fb6653da000, 139264, MADV_DONTNEED) = 0
madvise(0x7fb66540c000, 1576960, MADV_DONTNEED) = 0
madvise(0x7fb665a0c000, 2043904, MADV_DONTNEED) = 0
madvise(0x7fb665600000, 4194304, MADV_DONTNEED) = 0
madvise(0x7fb63e600000, 12582912, MADV_DONTNEED) = 0
madvise(0x7fb661000000, 25165824, MADV_DONTNEED) = 0
madvise(0x7fb66531a000, 659456, MADV_DONTNEED) = 0
madvise(0x7fb6653da000, 139264, MADV_DONTNEED) = 0
madvise(0x7fb66540c000, 1576960, MADV_DONTNEED) = 0
madvise(0x7fb665a0c000, 2043904, MADV_DONTNEED) = 0
madvise(0x7fb667a00000, 10485760, MADV_DONTNEED) = 0
madvise(0x7fb646000000, 100663296, MADV_DONTNEED) = 0
mmap(0x7fb665a00000, 2097152, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fb637400000
munmap(0x7fb637400000, 2097152)         = 0
mmap(0x7fb665a00000, 2097152, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fb637400000
munmap(0x7fb637400000, 2097152)         = 0
madvise(0x7fb66531a000, 659456, MADV_DONTNEED) = 0
madvise(0x7fb6653da000, 139264, MADV_DONTNEED) = 0
madvise(0x7fb66540c000, 1576960, MADV_DONTNEED) = 0
madvise(0x7fb665a0c000, 2043904, MADV_DONTNEED) = 0
madvise(0x7fb665600000, 4194304, MADV_DONTNEED) = 0
madvise(0x7fb63e600000, 12582912, MADV_DONTNEED) = 0
madvise(0x7fb661000000, 25165824, MADV_DONTNEED) = 0
madvise(0x7fb66531a000, 659456, MADV_DONTNEED) = 0
madvise(0x7fb6653da000, 139264, MADV_DONTNEED) = 0
madvise(0x7fb66540c000, 1576960, MADV_DONTNEED) = 0
madvise(0x7fb665a0c000, 2043904, MADV_DONTNEED) = 0
madvise(0x7fb667a00000, 10485760, MADV_DONTNEED) = 0
madvise(0x7fb646000000, 100663296, MADV_DONTNEED) = 0

By way of comparison, an analogous C program compiled with GCC takes 4.6s to compile without optimization, or 5.6s with optimization. Python parses and runs an analogous program in 1.2s. So, 45s seems excessive for an unoptimized compile, and 45m+ seems wildly excessive for an optimized compile.

Complete test case (ready to cargo run or cargo run --release): testcase.tar.gz

[brson]

Great writeup. Thanks!

[nagisa]

Parts of timings for non-optimised build:

time: 0.000; rss: 52MB	parsing
time: 0.693; rss: 159MB	expansion
time: 3.174; rss: 233MB	item-bodies checking
time: 0.164; rss: 244MB	const checking
time: 0.181; rss: 263MB	MIR dump
time: 0.453; rss: 263MB	borrow checking
time: 2.685; rss: 622MB	translation
  time: 9.955; rss: 533MB	codegen passes [0]
time: 10.560; rss: 533MB	LLVM passes
time: 3.200; rss: 144MB	linking
    Finished dev [unoptimized + debuginfo] target(s) in 22.49 secs

So the guess wrt parsing is wrong. Timings for optimised build are pretty much the same with exception of LLVM passes:

  time: 2.194; rss: 549MB	llvm function passes [0]
  time: ∞; rss: ∞	        llvm module passes [0]
  time: ∞; rss: ∞	        codegen passes [0]
  time: ∞; rss: ∞	        codegen passes [0]

so this is basically yet another super-linear case in the Super-Linear Optimisation Engine.

---

Notable differences in IR between clang (takes no time at all) and rustc are linkage type of string constants. clang specifies private unnamed_addr whereas rustc specifies internal.

Main function has 250k instances of

  %749955 = getelementptr inbounds [250000 x %str_slice], [250000 x %str_slice]* %words, i32 0, i32 249985
  %749956 = getelementptr inbounds %str_slice, %str_slice* %749955, i32 0, i32 0
  store i8* getelementptr inbounds ([6 x i8], [6 x i8]* @str.1321, i32 0, i32 0), i8** %749956
  %749957 = getelementptr inbounds %str_slice, %str_slice* %749955, i32 0, i32 1
  store i64 6, i64* %749957

generated to produce the on-stack array, whereas clang produces a constant and memcpys it instead. That almost guaranteed is the reason here.

[nagisa]

Potentially fixed by having rvalue static promotion implemented.

[nagisa]

So, even if we fixed this particular case of completely static array, there’s still the same issue when the array is not exactly fully static:

[ ..., "100000", some_var, "100001", ...]

I constructed a program like above in C and made clang compile it without optimisations. It still haven’t finished.

EDIT: it has finished (keep in mind, this is not optimised build):

   ---User Time---   --System Time--   --User+System--   ---Wall Time---  --- Name ---
  2190.9531 ( 99.9%)   0.3600 ( 77.1%)  2191.3131 ( 99.9%)  2192.0474 ( 99.9%)  X86 DAG->DAG Instruction Selection

Which sounds right about where I’d expect the time be spent.

[joshtriplett]

@nagisa Interesting. I can reproduce that result with clang with or without optimization, but gcc has no problem with such a program when not optimizing. When optimizing, it too doesn't show any signs of finishing.

The test code I used, for reference:

#include <string.h>
#include <stdio.h>

int main(int argc, char *argv[]) {
    char *array[] = {
#include "num_array.h"
        argv[0],
    };
    size_t sum = 0;
    for (int i = 0; i < sizeof(array)/sizeof(*array); i++) {
        sum += strlen(array[i]);
    }
    printf("%zu\n", sum);
    return 0;
}

To generate num_array.h, use seq 1 250000 | sed 's/.*/"&",/' > num_array.h .

[joshtriplett]

I reported this test case as a GCC bug: https://gcc.gnu.org/bugzilla/show_bug.cgi?id=79266

[semarie]

I would just point that the llvm embedded version missed two commits (present in 3.9.1) that could be related to this bug:

• llvm-mirror/llvm@7e79c45
• llvm-mirror/llvm@e0af6c9

[nox]

Cc @rust-lang/wg-compiler-performance