binaryen icon indicating copy to clipboard operation
binaryen copied to clipboard

Fuzzer iteration takes over an hour

Open tlively opened this issue 2 years ago • 1 comments

At commit 0d3c2eeb634913643f2cade4b5d738962b2308c2 I'm getting this:

$ time ./scripts/fuzz_opt.py --auto-initial-contents 2795924036512128284
<...>
real    87m56.269s
user    87m55.172s
sys     0m1.603s

tlively avatar Aug 31 '23 21:08 tlively

Perf data:

  14.61%  wasm-ctor-eval  libbinaryen.so        [.] wasm::HeapType::isBottom                                                                                                                  
  12.56%  wasm-ctor-eval  libbinaryen.so        [.] wasm::Type::getHeapType                                                                                                                   
  11.51%  wasm-ctor-eval  libbinaryen.so        [.] wasm::Literal::~Literal                                                                                                                   
  10.26%  wasm-ctor-eval  libbinaryen.so        [.] wasm::Type::isRef                                                                                                                         
   9.04%  wasm-ctor-eval  libbinaryen.so        [.] wasm::Literal::Literal                                                                                                                    
   4.87%  wasm-ctor-eval  libbinaryen.so        [.] wasm::Type::isRef@plt                                                                                                                     
   4.81%  wasm-ctor-eval  libbinaryen.so        [.] std::_Hashtable<std::reference_wrapper<wasm::(anonymous namespace)::TypeInfo const>, std::pair<std::reference_wrapper<wasm::(anonymous nam
   3.83%  wasm-ctor-eval  libbinaryen.so        [.] wasm::ExpressionRunner<wasm::PrecomputingExpressionRunner>::visitArrayNewFixed                                                            
   3.25%  wasm-ctor-eval  libbinaryen.so        [.] wasm::Type::Type                                                                                                                          
   2.73%  wasm-ctor-eval  libc.so.6             [.] __GI___pthread_mutex_unlock_usercnt                                                                                                       
   2.70%  wasm-ctor-eval  libc.so.6             [.] pthread_mutex_lock@@GLIBC_2.2.5                                                                                                           
   2.28%  wasm-ctor-eval  libbinaryen.so        [.] wasm::Type::getHeapType@plt                                                                                                               

and main stack traces are

-   97.63%     0.00%  wasm-ctor-eval  libc.so.6             [.] __libc_start_call_main                                                                                                       ◆
     __libc_start_call_main                                                                                                                                                                  ▒
   - main                                                                                                                                                                                    ▒
      - 97.63% (anonymous namespace)::evalCtors                                                                                                                                              ▒
         - 95.48% wasm::PassRunner::runOnFunction                                                                                                                                            ▒
            - wasm::PassRunner::runPassOnFunction                                                                                                                                            ▒
               - 95.48% wasm::WalkerPass<wasm::PostWalker<wasm::Precompute, wasm::UnifiedExpressionVisitor<wasm::Precompute, void> > >::runOnFunction                                        ▒
                    wasm::Precompute::visitExpression                                                                                                                                        ▒
                    wasm::Precompute::precomputeExpression                                                                                                                                   ▒
                    wasm::Visitor<wasm::PrecomputingExpressionRunner, wasm::Flow>::visit                                                                                                     ▒
                    wasm::ExpressionRunner<wasm::PrecomputingExpressionRunner>::visit                                                                                                        ▒
                    wasm::Visitor<wasm::PrecomputingExpressionRunner, wasm::Flow>::visit                                                                                                     ▒
                    wasm::ExpressionRunner<wasm::PrecomputingExpressionRunner>::visitArrayNewFixed                                                                                           ▒

I've seen before cases where an array creation of a massive size caused such a slowdown, but here"

 (global $global$11 arrayref (array.new_fixed $2 0))
    (array.new_fixed $2 0)
    (array.new_fixed $2 0)
    (array.new_fixed $2 0)
        (array.new_fixed $2 0)
     (array.new_fixed $2 0)
  (array.new_fixed $2 0)
           (array.new_fixed $2 0)

Those are all of size 0. So we must be creating very many of them... perhaps the fuzzer happened to generate an Ackermann function :thinking:

We could perhaps add a time limit to wasm-ctor-eval somehow if this is common.

kripken avatar Aug 31 '23 22:08 kripken