From 3a3977e8f8182bd2027a445d98c86c36abef3813 Mon Sep 17 00:00:00 2001 From: Daniel Larimer Date: Fri, 24 Nov 2017 11:20:16 -0500 Subject: [PATCH 1/4] Refactor block production to have limited execution time and block size --- libraries/chain/chain_controller.cpp | 143 ++++++++------------------- 1 file changed, 39 insertions(+), 104 deletions(-) diff --git a/libraries/chain/chain_controller.cpp b/libraries/chain/chain_controller.cpp index 9e9d9a8c934..52caa0abfea 100644 --- a/libraries/chain/chain_controller.cpp +++ b/libraries/chain/chain_controller.cpp @@ -241,6 +241,8 @@ processed_transaction chain_controller::_push_transaction(const signed_transacti if (!_pending_tx_session.valid()) _pending_tx_session = _db.start_undo_session(true); + FC_ASSERT( _pending_transactions.size() < 1000, "too many pending transactions, try again later" ); + auto temp_session = _db.start_undo_session(true); validate_referenced_accounts(trx); check_transaction_authorization(trx); @@ -308,114 +310,49 @@ signed_block chain_controller::_generate_block( _pending_tx_session.reset(); _pending_tx_session = _db.start_undo_session(true); - const auto& generated = _db.get_index().equal_range(generated_transaction_object::PENDING); - - vector pending; - std::set invalid_pending; - pending.reserve(std::distance(generated.first, generated.second) + _pending_transactions.size()); - for (auto iter = generated.first; iter != generated.second; ++iter) { - const auto& gt = *iter; - pending.emplace_back(std::reference_wrapper {gt.trx}); - } - - for(const auto& st: _pending_transactions) { - pending.emplace_back(std::reference_wrapper {st}); - } + deque pending; - auto schedule = scheduler(pending, get_global_properties()); + auto start = fc::time_point::now(); signed_block pending_block; - pending_block.cycles.reserve(schedule.cycles.size()); - - size_t invalid_transaction_count = 0; - size_t valid_transaction_count = 0; - - for (const auto &c : schedule.cycles) { - cycle block_cycle; - block_cycle.reserve(c.size()); - - for (const auto &t : c) { - thread block_thread; - block_thread.user_input.reserve(t.transactions.size()); - block_thread.generated_input.reserve(t.transactions.size()); - for (const auto &trx : t.transactions) { - try - { - auto temp_session = _db.start_undo_session(true); - if (trx.contains>()) { - const auto& t = trx.get>().get(); - validate_referenced_accounts(t); - check_transaction_authorization(t); - auto processed = apply_transaction(t); - block_thread.user_input.emplace_back(processed); - } else if (trx.contains>()) { - const auto& t = trx.get>().get(); - auto processed = apply_transaction(t); - block_thread.generated_input.emplace_back(processed); - } else { - FC_THROW_EXCEPTION(tx_scheduling_exception, "Unknown transaction type in block_schedule"); - } - - temp_session.squash(); - valid_transaction_count++; - } - catch ( const fc::exception& e ) - { - // Do nothing, transaction will not be re-applied - elog( "Transaction was not processed while generating block due to ${e}", ("e", e) ); - if (trx.contains>()) { - const auto& t = trx.get>().get(); - wlog( "The transaction was ${t}", ("t", t ) ); - invalid_pending.emplace(t.id()); - } else if (trx.contains>()) { - wlog( "The transaction was ${t}", ("t", trx.get>().get()) ); - } - invalid_transaction_count++; - } - } - - if (!(block_thread.generated_input.empty() && block_thread.user_input.empty())) { - block_thread.generated_input.shrink_to_fit(); - block_thread.user_input.shrink_to_fit(); - block_cycle.emplace_back(std::move(block_thread)); - } - } - - if (!block_cycle.empty()) { - pending_block.cycles.emplace_back(std::move(block_cycle)); - } - } + const auto& gprops = get_global_properties(); + + uint32_t pending_block_size = fc::raw::pack_size( pending_block ); + if( _pending_transactions.size() ) { + pending_block.cycles.resize(1); + pending_block.cycles[0].resize(1); // single thread + + for( const auto& pending_trx : _pending_transactions ) { + idump((pending_trx.id())); + if( (fc::time_point::now() - start) > fc::milliseconds(200) || + pending_block_size > gprops.configuration.max_blk_size) + { + pending.push_back(pending_trx); + continue; + } + try { + auto temp_session = _db.start_undo_session(true); + validate_referenced_accounts(pending_trx); + check_transaction_authorization(pending_trx); + auto processed = apply_transaction(pending_trx); - size_t postponed_tx_count = pending.size() - valid_transaction_count - invalid_transaction_count; - if( postponed_tx_count > 0 ) - { - wlog( "Postponed ${n} transactions due to block size limit", ("n", postponed_tx_count) ); - } + pending_block_size += fc::raw::pack_size(processed); - if( invalid_transaction_count > 0 ) - { - wlog( "Postponed ${n} transactions errors when processing", ("n", invalid_transaction_count) ); - - // remove pending transactions determined to be bad during scheduling - if (invalid_pending.size() > 0) { - for (auto itr = _pending_transactions.begin(); itr != _pending_transactions.end(); ) { - auto& tx = *itr; - if (invalid_pending.find(tx.id()) != invalid_pending.end()) { - itr = _pending_transactions.erase(itr); - } else { - ++itr; + if( pending_block_size > gprops.configuration.max_blk_size) { + pending.push_back( pending_trx ); + continue; } + + temp_session.squash(); + pending_block.cycles[0][0].user_input.emplace_back( processed ); + } catch ( const fc::exception& e ) { + edump((e.to_detail_string())); } } } - _pending_tx_session.reset(); + _pending_transactions = move( pending ); - // We have temporarily broken the invariant that - // _pending_tx_session is the result of applying _pending_tx, as - // _pending_transactions now consists of the set of postponed transactions. - // However, the push_block() call below will re-create the - // _pending_tx_session. pending_block.previous = head_block_id(); pending_block.timestamp = when; @@ -429,16 +366,14 @@ signed_block chain_controller::_generate_block( pending_block.producer_changes = get_global_properties().active_producers - new_schedule; } + auto end = fc::time_point::now(); + ilog( "generation took ${x} ms", ("x", (end-start).count()/1000) ); + FC_ASSERT( end - start < fc::milliseconds( 250 ), "block took too long to build" ); + if( !(skip & skip_producer_signature) ) pending_block.sign( block_signing_private_key ); - // TODO: Move this to _push_block() so session is restored. - /* - if( !(skip & skip_block_size_check) ) - { - FC_ASSERT( fc::raw::pack_size(pending_block) <= get_global_properties().parameters.maximum_block_size ); - } - */ + _pending_tx_session.reset(); // push_block( pending_block, skip ); From 297746e142c69e9007173c03774fe20eead8d1be Mon Sep 17 00:00:00 2001 From: Daniel Larimer Date: Fri, 24 Nov 2017 11:59:33 -0500 Subject: [PATCH 2/4] restore proper state of pending trx --- libraries/chain/chain_controller.cpp | 13 ++++++++++--- 1 file changed, 10 insertions(+), 3 deletions(-) diff --git a/libraries/chain/chain_controller.cpp b/libraries/chain/chain_controller.cpp index 52caa0abfea..973a0fd65f7 100644 --- a/libraries/chain/chain_controller.cpp +++ b/libraries/chain/chain_controller.cpp @@ -323,7 +323,6 @@ signed_block chain_controller::_generate_block( pending_block.cycles[0].resize(1); // single thread for( const auto& pending_trx : _pending_transactions ) { - idump((pending_trx.id())); if( (fc::time_point::now() - start) > fc::milliseconds(200) || pending_block_size > gprops.configuration.max_blk_size) { @@ -351,8 +350,8 @@ signed_block chain_controller::_generate_block( } } - _pending_transactions = move( pending ); - + if( pending.size() ) + wlog( "${x} pending transactions postponed to future block", ("x", pending.size()) ); pending_block.previous = head_block_id(); pending_block.timestamp = when; @@ -375,6 +374,14 @@ signed_block chain_controller::_generate_block( _pending_tx_session.reset(); + _pending_transactions.clear(); + for( const auto& t : pending ) { + try { + push_transaction( t ); + } catch ( ... ) { + } + } + // push_block( pending_block, skip ); return pending_block; From 75294f19876b16f4e958cc8c00da0ccad63bc8fd Mon Sep 17 00:00:00 2001 From: Kevin Heifner Date: Fri, 24 Nov 2017 12:13:13 -0600 Subject: [PATCH 3/4] Only report block generation time if >10ms. --- libraries/chain/chain_controller.cpp | 9 ++++++--- 1 file changed, 6 insertions(+), 3 deletions(-) diff --git a/libraries/chain/chain_controller.cpp b/libraries/chain/chain_controller.cpp index 973a0fd65f7..927963c6bb7 100644 --- a/libraries/chain/chain_controller.cpp +++ b/libraries/chain/chain_controller.cpp @@ -365,9 +365,12 @@ signed_block chain_controller::_generate_block( pending_block.producer_changes = get_global_properties().active_producers - new_schedule; } - auto end = fc::time_point::now(); - ilog( "generation took ${x} ms", ("x", (end-start).count()/1000) ); - FC_ASSERT( end - start < fc::milliseconds( 250 ), "block took too long to build" ); + const auto end = fc::time_point::now(); + const auto gen_time = end - start; + if( gen_time > fc::milliseconds(10) ) { + ilog("generation took ${x} ms", ("x", gen_time.count() / 1000)); + FC_ASSERT(gen_time < fc::milliseconds(250), "block took too long to build"); + } if( !(skip & skip_producer_signature) ) pending_block.sign( block_signing_private_key ); From a78f8c9bdf1947c8a539a060b2a993a50c9d8367 Mon Sep 17 00:00:00 2001 From: Kevin Heifner Date: Fri, 24 Nov 2017 13:17:16 -0600 Subject: [PATCH 4/4] Modify limit tests to work under 1000 pending trn limit. --- tests/slow_tests/slow_tests.cpp | 11 +++- tests/tests/wasm_tests/wasm_tests.cpp | 79 ++++++++++++++++++--------- 2 files changed, 60 insertions(+), 30 deletions(-) diff --git a/tests/slow_tests/slow_tests.cpp b/tests/slow_tests/slow_tests.cpp index dee9e14ebdb..cd37dc622b4 100644 --- a/tests/slow_tests/slow_tests.cpp +++ b/tests/slow_tests/slow_tests.cpp @@ -314,7 +314,12 @@ void WithdrawCurrency( testing_blockchain& chain, account_name from, account_nam //Test account script processing BOOST_FIXTURE_TEST_CASE(create_script, testing_fixture) { try { - chain_controller::txn_msg_limits rate_limit = { fc::time_point_sec(10), 100000, fc::time_point_sec(10), 100000 }; + + chain_controller::txn_msg_limits rate_limit = { + .per_auth_account_txn_msg_rate_time_frame_sec = fc::time_point_sec(10), + .per_auth_account_txn_msg_rate = 100000, + .per_code_account_txn_msg_rate_time_frame_sec = fc::time_point_sec(10), + .per_code_account_txn_msg_rate = 100000 }; Make_Blockchain(chain, ::eosio::chain_plugin::default_transaction_execution_time, ::eosio::chain_plugin::default_received_block_transaction_execution_time, ::eosio::chain_plugin::default_create_block_transaction_execution_time, rate_limit); @@ -345,7 +350,7 @@ BOOST_FIXTURE_TEST_CASE(create_script, testing_fixture) auto start = fc::time_point::now(); - for (uint32_t i = 0; i < 10000; ++i) + for (uint32_t i = 0; i < 500; ++i) { eosio::chain::signed_transaction trx; trx.scope = sort_names({"currency","inita"}); @@ -358,7 +363,7 @@ BOOST_FIXTURE_TEST_CASE(create_script, testing_fixture) chain.push_transaction(trx); } auto end = fc::time_point::now(); - idump((10000*1000000.0 / (end-start).count())); + idump((500*1000000.0 / (end-start).count())); chain.produce_blocks(10); diff --git a/tests/tests/wasm_tests/wasm_tests.cpp b/tests/tests/wasm_tests/wasm_tests.cpp index 7d7fca2b287..c28f3a36e16 100644 --- a/tests/tests/wasm_tests/wasm_tests.cpp +++ b/tests/tests/wasm_tests/wasm_tests.cpp @@ -17,7 +17,12 @@ BOOST_AUTO_TEST_SUITE(wasm_tests) //Test rate limiting with single authority BOOST_FIXTURE_TEST_CASE(rate_limit_single_authority_test, testing_fixture) { try { - chain_controller::txn_msg_limits rate_limit = { fc::time_point_sec(18), 1800, fc::time_point_sec(18), 18000 }; + uint32_t auth_txn_msg_limit = 400; + chain_controller::txn_msg_limits rate_limit = { + .per_auth_account_txn_msg_rate_time_frame_sec = fc::time_point_sec(18), + .per_auth_account_txn_msg_rate = auth_txn_msg_limit, + .per_code_account_txn_msg_rate_time_frame_sec = fc::time_point_sec(18), + .per_code_account_txn_msg_rate = 900 }; Make_Blockchain(chain, 18000, 72000, 18000, rate_limit); chain.produce_blocks(10); Make_Account(chain, currency); @@ -71,10 +76,10 @@ BOOST_FIXTURE_TEST_CASE(rate_limit_single_authority_test, testing_fixture) txn2.expiration = chain.head_block_time() + 100; transaction_set_reference_block(txn2, chain.head_block_id()); - // sending 1800 transaction messages for 2 authorization accounts, which is the rate limit for this second + // sending auth_txn_msg_limit transaction messages for 2 authorization accounts, which is the rate limit for this second // since there were no previous messages before this uint32_t i = 0; - for (; i < 1800; ++i) + for (; i < auth_txn_msg_limit; ++i) { txn.messages.clear(); transaction_emplace_message(txn, "currency", @@ -122,7 +127,13 @@ BOOST_FIXTURE_TEST_CASE(rate_limit_single_authority_test, testing_fixture) //Test rate limiting with multiple authorities BOOST_FIXTURE_TEST_CASE(rate_limit_multi_authority_test, testing_fixture) { try { - chain_controller::txn_msg_limits rate_limit = { fc::time_point_sec(18), 1800, fc::time_point_sec(18), 18000 }; + uint32_t auth_txn_msg_limit = 100; + uint32_t code_txn_msg_limit = 900; + chain_controller::txn_msg_limits rate_limit = { + .per_auth_account_txn_msg_rate_time_frame_sec = fc::time_point_sec(18), + .per_auth_account_txn_msg_rate = auth_txn_msg_limit, + .per_code_account_txn_msg_rate_time_frame_sec = fc::time_point_sec(18), + .per_code_account_txn_msg_rate = code_txn_msg_limit}; Make_Blockchain(chain, 18000, 72000, 18000, rate_limit); chain.produce_blocks(10); Make_Account(chain, currency); @@ -153,7 +164,6 @@ BOOST_FIXTURE_TEST_CASE(rate_limit_multi_authority_test, testing_fixture) Make_Account(chain, test45); chain.produce_blocks(1); - types::setcode handler; handler.account = "currency"; @@ -216,6 +226,8 @@ BOOST_FIXTURE_TEST_CASE(rate_limit_multi_authority_test, testing_fixture) } + uint32_t total = 0; + // setup transactions eosio::chain::signed_transaction txn; txn.scope = sort_names({"test1","test2"}); @@ -232,33 +244,32 @@ BOOST_FIXTURE_TEST_CASE(rate_limit_multi_authority_test, testing_fixture) txn3.expiration = chain.head_block_time() + 100; transaction_set_reference_block(txn3, chain.head_block_id()); - // looping 900 times to put some accounts (test1 and test2) at 1800 rate limit - for (uint32_t i = 0; i < 900; ++i) + BOOST_TEST_CHECKPOINT("Before auth_txn_msg_limit/2 loop"); + + // looping auth_txn_msg_limit/2 times to put some accounts (test1 and test2) at auth_txn_msg_limit rate limit + for (uint32_t i = 0; i < auth_txn_msg_limit/2; ++i) { txn.messages.clear(); transaction_emplace_message(txn, "test1", vector{ {"test1","active"},{"test2","active"} }, "transfer", types::transfer{"test1", "test2", i+1, ""}); chain.push_transaction(txn); + ++total; txn2.messages.clear(); transaction_emplace_message(txn2, "test1", vector{ {"test2","active"},{"test3","active"} }, "transfer", types::transfer{"test2", "test3", i+1, ""}); chain.push_transaction(txn2); + ++total; txn3.messages.clear(); transaction_emplace_message(txn3, "test1", vector{ {"test1","active"},{"test4","active"} }, "transfer", types::transfer{"test1", "test4", i+1, ""}); chain.push_transaction(txn3); - + ++total; } - // auth test1 - 1800 transaction messages - // auth test2 - 1800 transaction messages - // auth test3 - 900 transaction messages - // auth test4 - 900 transaction messages - // code test1 - 5400 transaction messages // test1 at rate limit, should be rejected try @@ -270,6 +281,7 @@ BOOST_FIXTURE_TEST_CASE(rate_limit_multi_authority_test, testing_fixture) "transfer", types::transfer{"test1", "test4", 1000,""}); chain.push_transaction(txn); BOOST_FAIL("Should have gotten tx_msgs_auth_exceeded exception."); + ++total; } catch (const tx_msgs_auth_exceeded& ex) { @@ -286,6 +298,7 @@ BOOST_FIXTURE_TEST_CASE(rate_limit_multi_authority_test, testing_fixture) "transfer", types::transfer{"test2", "test3", 1000,""}); chain.push_transaction(txn2); BOOST_FAIL("Should have gotten tx_msgs_auth_exceeded exception."); + ++total; } catch (const tx_msgs_auth_exceeded& ex) { @@ -297,22 +310,17 @@ BOOST_FIXTURE_TEST_CASE(rate_limit_multi_authority_test, testing_fixture) txn4.expiration = chain.head_block_time() + 100; transaction_set_reference_block(txn4, chain.head_block_id()); - - // looping 900 times to put remaining accounts at 1800 rate limit - for (uint32_t i = 0; i < 900; ++i) + BOOST_TEST_CHECKPOINT("Before auth_txn_msg_limit/2 loop 2"); + // looping auth_txn_msg_limit/2 times to put remaining accounts at auth_txn_msg_limit rate limit + for (uint32_t i = 0; i < auth_txn_msg_limit/2; ++i) { txn4.messages.clear(); transaction_emplace_message(txn4, "test1", vector{ {"test3","active"},{"test4","active"} }, "transfer", types::transfer{"test3", "test4", i+1, ""}); chain.push_transaction(txn4); - + ++total; } - // auth test1 - 1800 transaction messages - // auth test2 - 1800 transaction messages - // auth test3 - 1800 transaction messages - // auth test4 - 1800 transaction messages - // code test1 - 7200 transaction messages // test3 at rate limit, should be rejected @@ -325,6 +333,7 @@ BOOST_FIXTURE_TEST_CASE(rate_limit_multi_authority_test, testing_fixture) "transfer", types::transfer{"test3", "test5", 1000,""}); chain.push_transaction(txn); BOOST_FAIL("Should have gotten tx_msgs_auth_exceeded exception."); + ++total; } catch (const tx_msgs_auth_exceeded& ex) { @@ -341,6 +350,7 @@ BOOST_FIXTURE_TEST_CASE(rate_limit_multi_authority_test, testing_fixture) "transfer", types::transfer{"test4", "test5", 1000,""}); chain.push_transaction(txn2); BOOST_FAIL("Should have gotten tx_msgs_auth_exceeded exception."); + ++total; } catch (const tx_msgs_auth_exceeded& ex) { @@ -397,74 +407,85 @@ BOOST_FIXTURE_TEST_CASE(rate_limit_multi_authority_test, testing_fixture) txn25.expiration = chain.head_block_time() + 100; transaction_set_reference_block(txn25, chain.head_block_id()); - // looping 1440 times with 10 different transactions to get to the 18000 code account rate limit for test1 + ilog("total push_transaction ${t}", ("t", total)); + BOOST_TEST_CHECKPOINT("Before code_txn_msg_limit/10 loop"); + // looping code_txn_msg_limit/10 times with 10 different transactions to get to the code_txn_msg_limit code account rate limit for test1 + const uint32_t prev_total = total; uint32_t i = 0; - for (; i < 1440; ++i) + for (; i < (code_txn_msg_limit - prev_total)/10; ++i) { txn11.messages.clear(); transaction_emplace_message(txn11, "test1", vector{ {"test11","active"},{"test31","active"} }, "transfer", types::transfer{"test11", "test31", i+1, ""}); chain.push_transaction(txn11); + ++total; txn12.messages.clear(); transaction_emplace_message(txn12, "test1", vector{ {"test12","active"},{"test32","active"} }, "transfer", types::transfer{"test12", "test32", i+1, ""}); chain.push_transaction(txn12); + ++total; txn13.messages.clear(); transaction_emplace_message(txn13, "test1", vector{ {"test13","active"},{"test33","active"} }, "transfer", types::transfer{"test13", "test33", i+1, ""}); chain.push_transaction(txn13); + ++total; txn14.messages.clear(); transaction_emplace_message(txn14, "test1", vector{ {"test14","active"},{"test34","active"} }, "transfer", types::transfer{"test14", "test34", i+1, ""}); chain.push_transaction(txn14); + ++total; txn15.messages.clear(); transaction_emplace_message(txn15, "test1", vector{ {"test15","active"},{"test35","active"} }, "transfer", types::transfer{"test15", "test35", i+1, ""}); chain.push_transaction(txn15); + ++total; txn21.messages.clear(); transaction_emplace_message(txn21, "test1", vector{ {"test21","active"},{"test41","active"} }, "transfer", types::transfer{"test21", "test41", i+1, ""}); chain.push_transaction(txn21); + ++total; txn22.messages.clear(); transaction_emplace_message(txn22, "test1", vector{ {"test22","active"},{"test42","active"} }, "transfer", types::transfer{"test22", "test42", i+1, ""}); chain.push_transaction(txn22); + ++total; txn23.messages.clear(); transaction_emplace_message(txn23, "test1", vector{ {"test23","active"},{"test43","active"} }, "transfer", types::transfer{"test23", "test43", i+1, ""}); chain.push_transaction(txn23); + ++total; txn24.messages.clear(); transaction_emplace_message(txn24, "test1", vector{ {"test24","active"},{"test44","active"} }, "transfer", types::transfer{"test24", "test44", i+1, ""}); chain.push_transaction(txn24); + ++total; txn25.messages.clear(); transaction_emplace_message(txn25, "test1", vector{ {"test25","active"},{"test45","active"} }, "transfer", types::transfer{"test25", "test45", i+1, ""}); chain.push_transaction(txn25); - + ++total; } - // code test1 - 18000 transaction messages - + ilog("total push_transaction ${t}", ("t", total)); // reached rate limit, should be rejected try { @@ -474,6 +495,7 @@ BOOST_FIXTURE_TEST_CASE(rate_limit_multi_authority_test, testing_fixture) "transfer", types::transfer{"test11", "test21", i+1, ""}); chain.push_transaction(txn11); BOOST_FAIL("Should have gotten tx_msgs_code_exceeded exception."); + ++total; } catch (const tx_msgs_code_exceeded& ex) { @@ -485,6 +507,7 @@ BOOST_FIXTURE_TEST_CASE(rate_limit_multi_authority_test, testing_fixture) vector{ {"test11","active"},{"test31","active"} }, "transfer", types::transfer{"test11", "test31", i+1, ""}); chain.push_transaction(txn11); + ++total; // still should be rejected @@ -496,6 +519,7 @@ BOOST_FIXTURE_TEST_CASE(rate_limit_multi_authority_test, testing_fixture) "transfer", types::transfer{"test11", "test21", i+1, ""}); chain.push_transaction(txn11); BOOST_FAIL("Should have gotten tx_msgs_code_exceeded exception."); + ++total; } catch (const tx_msgs_code_exceeded& ex) { @@ -509,6 +533,7 @@ BOOST_FIXTURE_TEST_CASE(rate_limit_multi_authority_test, testing_fixture) vector{ {"test11","active"},{"test21","active"} }, "transfer", types::transfer{"test11", "test21", i+1, ""}); chain.push_transaction(txn11); + ++total; } FC_LOG_AND_RETHROW() }