From 4730bf39cdc6e3788423d54d30dcb9621e96f335 Mon Sep 17 00:00:00 2001 From: canepat <16927169+canepat@users.noreply.github.com> Date: Fri, 13 Dec 2024 23:35:27 +0100 Subject: [PATCH 1/3] node: replace incremental with full mode in InterHashes stage --- .../stagedsync/stages/stage_interhashes.cpp | 64 ++++++++----------- .../stagedsync/stages/stage_interhashes.hpp | 6 +- 2 files changed, 31 insertions(+), 39 deletions(-) diff --git a/silkworm/node/stagedsync/stages/stage_interhashes.cpp b/silkworm/node/stagedsync/stages/stage_interhashes.cpp index f6857fc5ba..2d67b8fdfc 100644 --- a/silkworm/node/stagedsync/stages/stage_interhashes.cpp +++ b/silkworm/node/stagedsync/stages/stage_interhashes.cpp @@ -91,7 +91,10 @@ Stage::Result InterHashes::forward(RWTxn& txn) { ret = regenerate_intermediate_hashes(txn, &expected_state_root); } else { // Incremental update - ret = increment_intermediate_hashes(txn, previous_progress, hashstate_stage_progress, &expected_state_root); + // TODO(canepat) debug_unwind block 4'000'000 step 1 fails with kWrongStateRoot in incremental mode + // ret = increment_intermediate_hashes(txn, previous_progress, hashstate_stage_progress, &expected_state_root); + SILK_TRACE_M(log_prefix_, {"function", std::string(__FUNCTION__), "algo", "full rather than incremental"}); + ret = regenerate_intermediate_hashes(txn, &expected_state_root); } if (ret == Stage::Result::kWrongStateRoot) { @@ -106,20 +109,16 @@ Stage::Result InterHashes::forward(RWTxn& txn) { txn.commit_and_renew(); } catch (const StageError& ex) { - log::Error(log_prefix_, - {"function", std::string(__FUNCTION__), "exception", std::string(ex.what())}); + SILK_ERROR_M(log_prefix_, {"function", std::string(__FUNCTION__), "exception", std::string(ex.what())}); ret = static_cast(ex.err()); } catch (const mdbx::exception& ex) { - log::Error(log_prefix_, - {"function", std::string(__FUNCTION__), "exception", std::string(ex.what())}); + SILK_ERROR_M(log_prefix_, {"function", std::string(__FUNCTION__), "exception", std::string(ex.what())}); ret = Stage::Result::kDbError; } catch (const std::exception& ex) { - log::Error(log_prefix_, - {"function", std::string(__FUNCTION__), "exception", std::string(ex.what())}); + SILK_ERROR_M(log_prefix_, {"function", std::string(__FUNCTION__), "exception", std::string(ex.what())}); ret = Stage::Result::kUnexpectedError; } catch (...) { - log::Error(log_prefix_, - {"function", std::string(__FUNCTION__), "exception", "unexpected and undefined"}); + SILK_ERROR_M(log_prefix_, {"function", std::string(__FUNCTION__), "exception", "unexpected and undefined"}); ret = Stage::Result::kUnexpectedError; } @@ -175,7 +174,10 @@ Stage::Result InterHashes::unwind(RWTxn& txn) { ret = regenerate_intermediate_hashes(txn, &expected_state_root); } else { // Incremental update - ret = increment_intermediate_hashes(txn, previous_progress, to, &expected_state_root); + // TODO(canepat) debug_unwind block 4'000'000 step 1 fails with kWrongStateRoot in incremental mode + // ret = increment_intermediate_hashes(txn, previous_progress, to, &expected_state_root); + SILK_TRACE_M(log_prefix_, {"function", std::string(__FUNCTION__), "algo", "full rather than incremental"}); + ret = regenerate_intermediate_hashes(txn, &expected_state_root); } success_or_throw(ret); @@ -184,20 +186,16 @@ Stage::Result InterHashes::unwind(RWTxn& txn) { txn.commit_and_renew(); } catch (const StageError& ex) { - log::Error(log_prefix_, - {"function", std::string(__FUNCTION__), "exception", std::string(ex.what())}); + SILK_ERROR_M(log_prefix_, {"function", std::string(__FUNCTION__), "exception", std::string(ex.what())}); ret = static_cast(ex.err()); } catch (const mdbx::exception& ex) { - log::Error(log_prefix_, - {"function", std::string(__FUNCTION__), "exception", std::string(ex.what())}); + SILK_ERROR_M(log_prefix_, {"function", std::string(__FUNCTION__), "exception", std::string(ex.what())}); ret = Stage::Result::kDbError; } catch (const std::exception& ex) { - log::Error(log_prefix_, - {"function", std::string(__FUNCTION__), "exception", std::string(ex.what())}); + SILK_ERROR_M(log_prefix_, {"function", std::string(__FUNCTION__), "exception", std::string(ex.what())}); ret = Stage::Result::kUnexpectedError; } catch (...) { - log::Error(log_prefix_, - {"function", std::string(__FUNCTION__), "exception", "unexpected and undefined"}); + SILK_ERROR_M(log_prefix_, {"function", std::string(__FUNCTION__), "exception", "unexpected and undefined"}); ret = Stage::Result::kUnexpectedError; } @@ -460,6 +458,7 @@ Stage::Result InterHashes::regenerate_intermediate_hashes(RWTxn& txn, const evmc log_lck.unlock(); const evmc::bytes32 computed_root{trie_loader_->calculate_root()}; + SILK_TRACE_M(log_prefix_, {"function", std::string(__FUNCTION__), "computed_root", to_hex(computed_root.bytes)}); // Fail if not what expected if (expected_root != nullptr && computed_root != *expected_root) { @@ -475,20 +474,16 @@ Stage::Result InterHashes::regenerate_intermediate_hashes(RWTxn& txn, const evmc flush_collected_nodes(txn); } catch (const StageError& ex) { - log::Error(log_prefix_, - {"function", std::string(__FUNCTION__), "exception", std::string(ex.what())}); + SILK_ERROR_M(log_prefix_, {"function", std::string(__FUNCTION__), "exception", std::string(ex.what())}); ret = static_cast(ex.err()); } catch (const mdbx::exception& ex) { - log::Error(log_prefix_, - {"function", std::string(__FUNCTION__), "exception", std::string(ex.what())}); + SILK_ERROR_M(log_prefix_, {"function", std::string(__FUNCTION__), "exception", std::string(ex.what())}); ret = Stage::Result::kDbError; } catch (const std::exception& ex) { - log::Error(log_prefix_, - {"function", std::string(__FUNCTION__), "exception", std::string(ex.what())}); + SILK_ERROR_M(log_prefix_, {"function", std::string(__FUNCTION__), "exception", std::string(ex.what())}); ret = Stage::Result::kUnexpectedError; } catch (...) { - log::Error(log_prefix_, - {"function", std::string(__FUNCTION__), "exception", "unexpected and undefined"}); + SILK_ERROR_M(log_prefix_, {"function", std::string(__FUNCTION__), "exception", "unexpected and undefined"}); ret = Stage::Result::kUnexpectedError; } @@ -524,6 +519,7 @@ Stage::Result InterHashes::increment_intermediate_hashes(RWTxn& txn, BlockNum fr log_lck.unlock(); const evmc::bytes32 computed_root{trie_loader_->calculate_root()}; + SILK_TRACE_M(log_prefix_, {"function", std::string(__FUNCTION__), "computed_root", to_hex(computed_root.bytes)}); // Fail if not what expected if (expected_root != nullptr && computed_root != *expected_root) { @@ -532,28 +528,23 @@ Stage::Result InterHashes::increment_intermediate_hashes(RWTxn& txn, BlockNum fr account_collector_.reset(); // Will invoke dtor which causes all flushed files (if any) to be deleted storage_collector_.reset(); // Will invoke dtor which causes all flushed files (if any) to be deleted log_lck.unlock(); - log::Error("Wrong trie root", - {"expected", to_hex(*expected_root, true), "got", to_hex(computed_root, true)}); + SILK_ERROR_M("Wrong trie root", {"expected", to_hex(*expected_root, true), "got", to_hex(computed_root, true)}); return Stage::Result::kWrongStateRoot; } flush_collected_nodes(txn); } catch (const StageError& ex) { - log::Error(log_prefix_, - {"function", std::string(__FUNCTION__), "exception", std::string(ex.what())}); + SILK_ERROR_M(log_prefix_, {"function", std::string(__FUNCTION__), "exception", std::string(ex.what())}); ret = static_cast(ex.err()); } catch (const mdbx::exception& ex) { - log::Error(log_prefix_, - {"function", std::string(__FUNCTION__), "exception", std::string(ex.what())}); + SILK_ERROR_M(log_prefix_, {"function", std::string(__FUNCTION__), "exception", std::string(ex.what())}); ret = Stage::Result::kDbError; } catch (const std::exception& ex) { - log::Error(log_prefix_, - {"function", std::string(__FUNCTION__), "exception", std::string(ex.what())}); + SILK_ERROR_M(log_prefix_, {"function", std::string(__FUNCTION__), "exception", std::string(ex.what())}); ret = Stage::Result::kUnexpectedError; } catch (...) { - log::Error(log_prefix_, - {"function", std::string(__FUNCTION__), "exception", "unexpected and undefined"}); + SILK_ERROR_M(log_prefix_, {"function", std::string(__FUNCTION__), "exception", "unexpected and undefined"}); ret = Stage::Result::kUnexpectedError; } @@ -623,4 +614,5 @@ std::vector InterHashes::get_log_progress() { } return ret; } + } // namespace silkworm::stagedsync diff --git a/silkworm/node/stagedsync/stages/stage_interhashes.hpp b/silkworm/node/stagedsync/stages/stage_interhashes.hpp index f810c15020..176fd737ac 100644 --- a/silkworm/node/stagedsync/stages/stage_interhashes.hpp +++ b/silkworm/node/stagedsync/stages/stage_interhashes.hpp @@ -54,17 +54,17 @@ class InterHashes final : public Stage { trie::PrefixSet collect_storage_changes(db::RWTxn& txn, BlockNum from, BlockNum to, absl::btree_map& hashed_addresses); - //! \brief Erigon's RegenerateIntermediateHashes + //! \brief Erigon RegenerateIntermediateHashes //! \remarks might throw WrongRoot //! \return the state root Stage::Result regenerate_intermediate_hashes( db::RWTxn& txn, const evmc::bytes32* expected_root = nullptr); - //! \brief Erigon's IncrementIntermediateHashes + //! \brief Erigon IncrementIntermediateHashes //! \remarks might throw //! \return the state root - Stage::Result increment_intermediate_hashes( + [[maybe_unused]] Stage::Result increment_intermediate_hashes( db::RWTxn& txn, BlockNum from, BlockNum to, From f9f0f8fa4dcdd4a31fb2e0714eda333772f70927 Mon Sep 17 00:00:00 2001 From: canepat <16927169+canepat@users.noreply.github.com> Date: Fri, 13 Dec 2024 23:36:24 +0100 Subject: [PATCH 2/3] demote log in Headers stage --- silkworm/node/stagedsync/stages/stage_headers.cpp | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/silkworm/node/stagedsync/stages/stage_headers.cpp b/silkworm/node/stagedsync/stages/stage_headers.cpp index 7086c698fe..77bdc32f1c 100644 --- a/silkworm/node/stagedsync/stages/stage_headers.cpp +++ b/silkworm/node/stagedsync/stages/stage_headers.cpp @@ -100,7 +100,7 @@ HeadersStage::HeadersStage( const auto stop_at_block = Environment::get_stop_at_block(); if (stop_at_block.has_value()) { forced_target_block_ = stop_at_block; - log::Info(log_prefix_) << "env var STOP_AT_BLOCK set, target block=" << forced_target_block_.value(); + SILK_DEBUG_M(log_prefix_, {"target=", std::to_string(*forced_target_block_)}) << " env var STOP_AT_BLOCK set"; } } From 2a99d046f84fc09b11e9e39c61919d783c6c0cfd Mon Sep 17 00:00:00 2001 From: canepat <16927169+canepat@users.noreply.github.com> Date: Fri, 13 Dec 2024 23:36:55 +0100 Subject: [PATCH 3/3] improve logs in pipeline --- .../node/stagedsync/execution_pipeline.cpp | 19 ++++++++++--------- 1 file changed, 10 insertions(+), 9 deletions(-) diff --git a/silkworm/node/stagedsync/execution_pipeline.cpp b/silkworm/node/stagedsync/execution_pipeline.cpp index 64c1f66b46..3ec0655595 100644 --- a/silkworm/node/stagedsync/execution_pipeline.cpp +++ b/silkworm/node/stagedsync/execution_pipeline.cpp @@ -171,21 +171,22 @@ Stage::Result ExecutionPipeline::forward(db::RWTxn& cycle_txn, BlockNum target_b const auto stage_result = current_stage_->second->forward(cycle_txn); if (stage_result != Stage::Result::kSuccess) { /* clang-format off */ - auto result_description = std::string(magic_enum::enum_name(stage_result)); - log::Error(get_log_prefix(current_stage_name), {"op", "Forward", "returned", result_description}); - SILK_ERROR_M("ExecutionPipeline") << "Forward interrupted due to stage " << current_stage_->first << " failure"; + const auto result_description = std::string(magic_enum::enum_name(stage_result)); + SILK_ERROR_M(get_log_prefix(current_stage_name), {"op", "Forward", "failure", result_description}); return stage_result; } /* clang-format on */ - auto stage_head_number = read_stage_progress(cycle_txn, current_stage_name.data()); - if (!stop_at_block && stage_head_number != target_block_num) { - throw std::logic_error("Sync pipeline: stage returned success with an block_num different from target=" + - to_string(target_block_num) + " reached= " + to_string(stage_head_number)); + const auto stage_head_number = read_stage_progress(cycle_txn, current_stage_name.data()); + if (!stop_at_block && stage_head_number != target_block_num && current_stage_name != kTriggersStageKey) { + SILK_ERROR_M(get_log_prefix(current_stage_name), + {"op", "Forward", "target", to_string(target_block_num), "reached", to_string(stage_head_number)}); + throw std::logic_error("stage returned success with an block_num different from target=" + + to_string(target_block_num) + " reached=" + to_string(stage_head_number)); } - auto [_, stage_duration] = stages_stop_watch.lap(); + const auto [_, stage_duration] = stages_stop_watch.lap(); if (stage_duration > kStageDurationThresholdForLog) { - log::Info(get_log_prefix(current_stage_name), {"op", "Forward", "done", StopWatch::format(stage_duration)}); + SILK_INFO_M(get_log_prefix(current_stage_name), {"op", "Forward", "done", StopWatch::format(stage_duration)}); } }