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

Fri May 27 21:26:27 PDT 2016

Done. r271095

On Fri, May 27, 2016 at 7:55 PM, Kostya Serebryany <kcc at google.com> wrote:

> 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/30970785/attachment.html>