Kostya Serebryany via llvm-dev
2016-May-28 04:26 UTC
[llvm-dev] [LibFuzzer] Recent performance regression due to r270942
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>
Dan Liew via llvm-dev
2016-May-28 06:50 UTC
[llvm-dev] [LibFuzzer] Recent performance regression due to r270942
On 27 May 2016 at 21:26, Kostya Serebryany <kcc at google.com> wrote:> Done. r271095Thanks that fixed the issue for me. But now ``fuzzer.test`` is failing for me. Specifically ``` not LLVMFuzzer-NullDerefTest -close_fd_mask=3 2>&1 | FileCheck %s --check-prefix=NullDerefTest ``` However it looks like this is to be expected because this test is relying on the symbol ``__sanitizer_set_report_fd`` to be defined however my version compiler-rt is a slightly too old and doesn't have this symbol. r271046 seems to add this so I will rebuild the version of clang I use to build LibFuzzer.
Kostya Serebryany via llvm-dev
2016-May-29 05:28 UTC
[llvm-dev] [LibFuzzer] Recent performance regression due to r270942
On Fri, May 27, 2016 at 11:50 PM, Dan Liew <dan at su-root.co.uk> wrote:> On 27 May 2016 at 21:26, Kostya Serebryany <kcc at google.com> wrote: > > Done. r271095 > > Thanks that fixed the issue for me. But now ``fuzzer.test`` is failing > for me. Specifically > > ``` > not LLVMFuzzer-NullDerefTest -close_fd_mask=3 2>&1 | FileCheck %s > --check-prefix=NullDerefTest > ``` > > However it looks like this is to be expected because this test is > relying on the symbol ``__sanitizer_set_report_fd`` to be defined > however my version compiler-rt is a slightly too old and doesn't have > this symbol. r271046 seems to add this so I will rebuild the version > of clang I use to build LibFuzzer. >This will happen periodically. libFuzzer tests are only expected to work with the same revision of clang+compiler-rt. We try to keep libFuzzer *mostly* compatible with the older versions of clang (thus the code is "if (weak_fun) weak_func()" and not just "weak_func()"), but the tests need freshest clang+asan --kcc -------------- next part -------------- An HTML attachment was scrubbed... URL: <http://lists.llvm.org/pipermail/llvm-dev/attachments/20160528/019a35c1/attachment.html>