<div dir="ltr">Reproduced, should be easy to fix. Will do it.<div>And thanks for noticing, on my machine this fails very fast and the test passes because it sees everything it wants to see. </div><div><br></div><div>--kcc </div></div><div class="gmail_extra"><br><div class="gmail_quote">On Fri, May 27, 2016 at 6:18 PM, Dan Liew <span dir="ltr"><<a href="mailto:dan@su-root.co.uk" target="_blank">dan@su-root.co.uk</a>></span> wrote:<br><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex">Hi,<br>
<br>
This started as an off hand comment in [1] but this appears to be a<br>
real issue so I'm moving the discussion to the mailing list.<br>
<br>
In r270942 the time taken to run LibFuzzer's test became noticeably<br>
longer. I am building on<br>
<br>
* Arch Linux (4.5.4-1-ARCH #1 SMP PREEMPT Wed May 11 22:21:28 CEST<br>
2016 x86_64 GNU/Linux)<br>
* I am building libFuzzer and running its tests like so<br>
<br>
```<br>
CC=<new_clang> CXX=<new_clang++> cmake -DLLVM_USE_SANITIZE_COVERAGE=1<br>
-DLLVM_USE_SANITIZER=Address -DCMAKE_BUILD_TYPE=RELEASE ../src/ &&<br>
make check-fuzzer -j8<br>
```<br>
<br>
where ``<new_clang>`` and ``<new_clang++>`` point to a recently built<br>
clang (llvm: r270960 , clang: r270962 , compiler-rt: r270949) which<br>
itself was compiled using gcc 6.1.1.<br>
<br>
In r270937 (prior commit) the time to run the tests was ~25 seconds on<br>
my machine but for the subsequent commit ( r270942 ) the tests took<br>
~78 seconds.<br>
<br>
If I run the tests<br>
<br>
```<br>
cd lib/Fuzzer/test<br>
python2 ../../../bin/llvm-lit -v --time-tests -j1 .<br>
```<br>
<br>
then I can observe the time it is taking to run the tests.<br>
<br>
# For r270942<br>
<br>
```<br>
<br>
Slowest Tests:<br>
<br>
--------------------------------------------------------------------------<br>
<br>
0.06s: LLVMFuzzer :: fuzzer-trunc.test<br>
<br>
0.06s: LLVMFuzzer :: merge.test<br>
<br>
0.07s: LLVMFuzzer-Unittest :: LLVMFuzzer-Unittest/FuzzerMutate.ShuffleBytes1<br>
<br>
0.10s: LLVMFuzzer-Unittest :: LLVMFuzzer-Unittest/FuzzerMutate.InsertByte2<br>
<br>
0.10s: LLVMFuzzer-Unittest :: LLVMFuzzer-Unittest/FuzzerMutate.ChangeByte2<br>
<br>
0.11s: LLVMFuzzer :: fuzzer-ubsan.test<br>
<br>
0.11s: LLVMFuzzer-Unittest :: LLVMFuzzer-Unittest/Fuzzer.CrossOver<br>
<br>
0.14s: LLVMFuzzer-Unittest :: LLVMFuzzer-Unittest/FuzzerMutate.ChangeBit2<br>
<br>
0.24s: LLVMFuzzer-Unittest :: LLVMFuzzer-Unittest/FuzzerMutate.ShuffleBytes2<br>
<br>
0.38s: LLVMFuzzer :: fuzzer-dfsan.test<br>
<br>
1.04s: LLVMFuzzer :: fuzzer-dict.test<br>
<br>
1.08s: LLVMFuzzer :: fuzzer-oom.test<br>
<br>
1.25s: LLVMFuzzer-Unittest :: LLVMFuzzer-Unittest/Corpus.Distribution<br>
<br>
3.90s: LLVMFuzzer :: fuzzer-trace-pc.test<br>
<br>
5.33s: LLVMFuzzer :: fuzzer-drill.test<br>
<br>
9.85s: LLVMFuzzer :: fuzzer-leak.test<br>
<br>
13.30s: LLVMFuzzer :: fuzzer-threaded.test<br>
<br>
19.22s: LLVMFuzzer :: fuzzer-traces.test<br>
<br>
58.83s: LLVMFuzzer :: fuzzer.test<br>
<br>
66.28s: LLVMFuzzer :: fuzzer-timeout.test<br>
<br>
```<br>
<br>
# For r270937<br>
<br>
```<br>
<br>
Slowest Tests:<br>
<br>
--------------------------------------------------------------------------<br>
<br>
0.04s: LLVMFuzzer-Unittest :: LLVMFuzzer-Unittest/FuzzerMutate.ChangeBit1<br>
<br>
0.05s: LLVMFuzzer :: fuzzer-ubsan.test<br>
<br>
0.06s: LLVMFuzzer :: fuzzer-trunc.test<br>
<br>
0.06s: LLVMFuzzer-Unittest :: LLVMFuzzer-Unittest/FuzzerMutate.InsertByte2<br>
<br>
0.06s: LLVMFuzzer :: merge.test<br>
<br>
0.10s: LLVMFuzzer-Unittest :: LLVMFuzzer-Unittest/Fuzzer.CrossOver<br>
<br>
0.11s: LLVMFuzzer-Unittest :: LLVMFuzzer-Unittest/FuzzerMutate.ChangeBit2<br>
<br>
0.11s: LLVMFuzzer-Unittest :: LLVMFuzzer-Unittest/FuzzerMutate.ChangeByte2<br>
<br>
0.17s: LLVMFuzzer-Unittest :: LLVMFuzzer-Unittest/FuzzerMutate.ShuffleBytes2<br>
<br>
0.39s: LLVMFuzzer :: fuzzer-dfsan.test<br>
<br>
1.06s: LLVMFuzzer :: fuzzer-dict.test<br>
<br>
1.09s: LLVMFuzzer :: fuzzer-oom.test<br>
<br>
1.24s: LLVMFuzzer-Unittest :: LLVMFuzzer-Unittest/Corpus.Distribution<br>
<br>
3.55s: LLVMFuzzer :: fuzzer.test<br>
<br>
3.82s: LLVMFuzzer :: fuzzer-trace-pc.test<br>
<br>
5.38s: LLVMFuzzer :: fuzzer-drill.test<br>
<br>
6.20s: LLVMFuzzer :: fuzzer-timeout.test<br>
<br>
10.21s: LLVMFuzzer :: fuzzer-leak.test<br>
<br>
13.28s: LLVMFuzzer :: fuzzer-threaded.test<br>
<br>
18.85s: LLVMFuzzer :: fuzzer-traces.test<br>
<br>
```<br>
<br>
You can see that in r270942 that ``fuzzer.test`` and<br>
``fuzzer-timeout.test`` are taking much longer to run.<br>
<br>
I'm still not quite sure what happened in r270942 because the changes<br>
look benign but something definitely is going wrong.<br>
<br>
I'm currently looking at ``fuzzer-timeout.test`` at the following<br>
command is behaving very suspiciously<br>
<br>
```<br>
not LLVMFuzzer-TimeoutTest -timeout=1 %S/hi.txt 2>&1 | FileCheck %s<br>
--check-prefix=SingleInputTimeoutTest<br>
```<br>
<br>
When I run ``LLVMFuzzer-TimeoutTest -timeout=1 /path/to/hi.txt`` ASan<br>
is firing with same stack trace over and over again (piping the output<br>
to file a results in a file that is 259 MiB). I've attached the<br>
compressed log.<br>
<br>
Hopefully this will be a useful starting point in determining the<br>
issue. At a glance it looks like we are derefencing a nullptr<br>
somewhere in ``fuzzer::PrintHexArray()`` which ASan then catches but<br>
then the handler for the ASan detected nullptr derefence calls<br>
``fuzzer::PrintHexArray()`` again and so we get stuck in a loop. Some<br>
how we are managing to break out of this loop but I'm guessing this<br>
probably racey which would probably also explain the very variable<br>
timings I've been seeing for test execution.<br>
<br>
<br>
[1] <a href="http://reviews.llvm.org/D20706" rel="noreferrer" target="_blank">http://reviews.llvm.org/D20706</a><br>
<span class="HOEnZb"><font color="#888888"><br>
Dan.<br>
</font></span></blockquote></div><br></div>