Dan Liew via llvm-dev
2016-May-28 01:18 UTC
[llvm-dev] [LibFuzzer] Recent performance regression due to r270942
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>
Kostya Serebryany via llvm-dev
2016-May-28 02:55 UTC
[llvm-dev] [LibFuzzer] Recent performance regression due to r270942
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>
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>