[llvm-dev] [LibFuzzer] Recent performance regression due to r270942

[Dan Liew via llvm-dev]

Hi,

This started as an off hand comment in [1] but this appears to be a
real issue so I'm moving the discussion to the mailing list.

In r270942 the time taken to run LibFuzzer's test became noticeably
longer. I am building on

* Arch Linux (4.5.4-1-ARCH #1 SMP PREEMPT Wed May 11 22:21:28 CEST
2016 x86_64 GNU/Linux)
* I am building libFuzzer and running its tests like so

```
CC=<new_clang> CXX=<new_clang++> cmake -DLLVM_USE_SANITIZE_COVERAGE=1
-DLLVM_USE_SANITIZER=Address -DCMAKE_BUILD_TYPE=RELEASE ../src/ &&
make check-fuzzer -j8
```

where ``<new_clang>`` and ``<new_clang++>`` point to a recently built
clang (llvm: r270960 , clang: r270962 , compiler-rt: r270949) which
itself was compiled using gcc 6.1.1.

In r270937 (prior commit) the time to run the tests was ~25 seconds on
my machine but for the subsequent commit ( r270942 ) the tests took
~78 seconds.

If I run the tests

```
cd lib/Fuzzer/test
python2 ../../../bin/llvm-lit -v --time-tests -j1 .
```

then I can observe the time it is taking to run the tests.

# For r270942

```

Slowest Tests:

--------------------------------------------------------------------------

0.06s: LLVMFuzzer :: fuzzer-trunc.test

0.06s: LLVMFuzzer :: merge.test

0.07s: LLVMFuzzer-Unittest :: LLVMFuzzer-Unittest/FuzzerMutate.ShuffleBytes1

0.10s: LLVMFuzzer-Unittest :: LLVMFuzzer-Unittest/FuzzerMutate.InsertByte2

0.10s: LLVMFuzzer-Unittest :: LLVMFuzzer-Unittest/FuzzerMutate.ChangeByte2

0.11s: LLVMFuzzer :: fuzzer-ubsan.test

0.11s: LLVMFuzzer-Unittest :: LLVMFuzzer-Unittest/Fuzzer.CrossOver

0.14s: LLVMFuzzer-Unittest :: LLVMFuzzer-Unittest/FuzzerMutate.ChangeBit2

0.24s: LLVMFuzzer-Unittest :: LLVMFuzzer-Unittest/FuzzerMutate.ShuffleBytes2

0.38s: LLVMFuzzer :: fuzzer-dfsan.test

1.04s: LLVMFuzzer :: fuzzer-dict.test

1.08s: LLVMFuzzer :: fuzzer-oom.test

1.25s: LLVMFuzzer-Unittest :: LLVMFuzzer-Unittest/Corpus.Distribution

3.90s: LLVMFuzzer :: fuzzer-trace-pc.test

5.33s: LLVMFuzzer :: fuzzer-drill.test

9.85s: LLVMFuzzer :: fuzzer-leak.test

13.30s: LLVMFuzzer :: fuzzer-threaded.test

19.22s: LLVMFuzzer :: fuzzer-traces.test

58.83s: LLVMFuzzer :: fuzzer.test

66.28s: LLVMFuzzer :: fuzzer-timeout.test

```

# For r270937

```

Slowest Tests:

--------------------------------------------------------------------------

0.04s: LLVMFuzzer-Unittest :: LLVMFuzzer-Unittest/FuzzerMutate.ChangeBit1

0.05s: LLVMFuzzer :: fuzzer-ubsan.test

0.06s: LLVMFuzzer :: fuzzer-trunc.test

0.06s: LLVMFuzzer-Unittest :: LLVMFuzzer-Unittest/FuzzerMutate.InsertByte2

0.06s: LLVMFuzzer :: merge.test

0.10s: LLVMFuzzer-Unittest :: LLVMFuzzer-Unittest/Fuzzer.CrossOver

0.11s: LLVMFuzzer-Unittest :: LLVMFuzzer-Unittest/FuzzerMutate.ChangeBit2

0.11s: LLVMFuzzer-Unittest :: LLVMFuzzer-Unittest/FuzzerMutate.ChangeByte2

0.17s: LLVMFuzzer-Unittest :: LLVMFuzzer-Unittest/FuzzerMutate.ShuffleBytes2

0.39s: LLVMFuzzer :: fuzzer-dfsan.test

1.06s: LLVMFuzzer :: fuzzer-dict.test

1.09s: LLVMFuzzer :: fuzzer-oom.test

1.24s: LLVMFuzzer-Unittest :: LLVMFuzzer-Unittest/Corpus.Distribution

3.55s: LLVMFuzzer :: fuzzer.test

3.82s: LLVMFuzzer :: fuzzer-trace-pc.test

5.38s: LLVMFuzzer :: fuzzer-drill.test

6.20s: LLVMFuzzer :: fuzzer-timeout.test

10.21s: LLVMFuzzer :: fuzzer-leak.test

13.28s: LLVMFuzzer :: fuzzer-threaded.test

18.85s: LLVMFuzzer :: fuzzer-traces.test

```

You can see that in r270942 that ``fuzzer.test`` and
``fuzzer-timeout.test`` are taking much longer to run.

I'm still not quite sure what happened in r270942 because the changes
look benign but something definitely is going wrong.

I'm currently looking at ``fuzzer-timeout.test`` at the following
command is behaving very suspiciously

```
not LLVMFuzzer-TimeoutTest -timeout=1 %S/hi.txt 2>&1 | FileCheck %s
--check-prefix=SingleInputTimeoutTest
```

When I run ``LLVMFuzzer-TimeoutTest -timeout=1 /path/to/hi.txt`` ASan
is firing with same stack trace over and over again (piping the output
to file a results in a file that is 259 MiB). I've attached the
compressed log.

Hopefully this will be a useful starting point in determining the
issue. At a glance it looks like we are derefencing a nullptr
somewhere in ``fuzzer::PrintHexArray()`` which ASan then catches but
then the handler for the ASan detected nullptr derefence calls
``fuzzer::PrintHexArray()`` again and so we get stuck in a loop. Some
how we are managing to break out of this loop but I'm guessing this
probably racey which would probably also explain the very variable
timings I've been seeing for test execution.


[1] http://reviews.llvm.org/D20706

Dan.
-------------- next part --------------
A non-text attachment was scrubbed...
Name: crash-log.txt.xz
Type: application/octet-stream
Size: 41200 bytes
Desc: not available
URL: <http://lists.llvm.org/pipermail/llvm-dev/attachments/20160527/c2f54ebb/attachment.obj>