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

Fri May 27 19:55:48 PDT 2016

Reproduced, should be easy to fix. Will do it.
And thanks for noticing, on my machine this fails very fast and the test
passes because it sees everything it wants to see.

--kcc

On Fri, May 27, 2016 at 6:18 PM, Dan Liew <dan at su-root.co.uk> wrote:

> 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 --------------
An HTML attachment was scrubbed...
URL: <http://lists.llvm.org/pipermail/llvm-dev/attachments/20160527/6ca40ab8/attachment.html>