Why the first time I execute an action I get "Error 3080006: transaction took too long"?

Question

WHAT I WANT

Call an action and see it succeed at the first execution.

WHAT IS NOT WORKING

The function, which I am executing, the first time fails with error:

Error 3080006: Transaction took too long

Error Details: deadline exceeded

pending console output:

WHAT IS WORKING

The second time the transaction completes in 7784 us!!!

CLEOS

cleos push action mycontract action1 '[]' -p mycontract@active

Answer 1

The execution time is based on many factors in each execution.

It could be the cache missing or process management could blocks the nodeos process and makes the execution time exceeds the max-transaction-time.

The max-transaction-time set by nodeos on startup or in the config file controls the time to throw the Error 3080006. The default value is 30ms. Trying to set a greater value on max-transaction-time would help.

Answer 2

I think, it may related with cache (as twksos commented).

https://github.com/EOSIO/eos/blob/11c25394b6dd05cc3c97f0b7471a84f3d7cfbca3/libraries/chain/include/eosio/chain/wasm_interface_private.hpp#L58

 auto it = instantiation_cache.find(code_id);
 if(it == instantiation_cache.end()) {
    auto timer_pause = fc::make_scoped_exit([&](){
       trx_context.resume_billing_timer();
    });
    trx_context.pause_billing_timer();                            // see this

and https://github.com/EOSIO/eos/blob/11c25394b6dd05cc3c97f0b7471a84f3d7cfbca3/libraries/chain/transaction_context.cpp#L467

void transaction_context::pause_billing_timer() {
      if( explicit_billed_cpu_time || pseudo_start == fc::time_point() ) return; // either irrelevant or already paused

      auto now = fc::time_point::now();
      billed_time = now - pseudo_start;
      deadline_exception_code = deadline_exception::code_value;   // see this
      pseudo_start = fc::time_point();
   }

and deadline_exception is

  FC_DECLARE_DERIVED_EXCEPTION( deadline_exception, resource_exhausted_exception,
                                3080006, "Transaction took too long" )

Answer 3

Due to its subjective nature, transaction execution time is likely to vary each time it is executed. It would take longer time to execute on a slower machine while short time to execute on a faster machine. However, the maximum time a transaction is allowed to execute is 30ms. So if a node can't execute your transaction within 30ms, your transaction is considered failed and will not be broadcast to the network. You can either:

1. Push the same transaction multiple times, hoping somehow it can be finished within 30ms.

2. (recommended) Optimize your code, given the fact that EOS transfer action can be done in around 0.1ms.