From b6a2ac8e4e9801fd2d37de100060dd9fc488b795 Mon Sep 17 00:00:00 2001 From: marta-lokhova Date: Tue, 11 Aug 2026 11:02:15 -0700 Subject: [PATCH] Bring back medida::Timer now that CKMS compression is much faster --- docs/metrics.md | 13 +++---------- src/herder/TransactionQueue.cpp | 10 +++++----- src/herder/TransactionQueue.h | 12 +++++------- src/ledger/LedgerManagerImpl.cpp | 5 ++--- src/overlay/OverlayMetrics.cpp | 4 ++-- src/overlay/OverlayMetrics.h | 6 +----- src/overlay/test/OverlayTests.cpp | 14 ++++++-------- src/simulation/LoadGenerator.cpp | 14 ++++++++------ 8 files changed, 32 insertions(+), 46 deletions(-) diff --git a/docs/metrics.md b/docs/metrics.md index c538fbb413..facf1874e0 100644 --- a/docs/metrics.md +++ b/docs/metrics.md @@ -67,12 +67,8 @@ herder.pending[-soroban]-txs.age1 | counter | number of gen1 pending t herder.pending[-soroban]-txs.age2 | counter | number of gen2 pending transactions herder.pending[-soroban]-txs.age3 | counter | number of gen3 pending transactions herder.pending[-soroban]-txs.banned | counter | number of transactions that got banned -herder.pending[-soroban]-txs.sum | counter | sum of time (milliseconds) for transactions to be included in a ledger -herder.pending[-soroban]-txs.count | counter | number of transactions to be included in a ledger -herder.pending[-soroban]-txs.max | counter | largest time (milliseconds) for a transaction to be included in a ledger since last metrics call -herder.pending[-soroban]-txs.self-sum | counter | sum of time (milliseconds) for transactions submitted from this node to be included in a ledger -herder.pending[-soroban]-txs.self-count | counter | number of transactions submitted from this node to be included in a ledger -herder.pending[-soroban]-txs.self-max | counter | largest time (milliseconds) for a transaction submitted from this node to be included in a ledger since last metrics call +herder.pending[-soroban]-txs.delay | timer | time for transactions to be included in a ledger +herder.pending[-soroban]-txs.self-delay | timer | time for transactions submitted from this node to be included in a ledger herder.pending[-soroban]-txs.evicted-due-to-low-fee-count | counter | Count of transactions evicted by higher fee txs when queue is near its capacity. herder.pending[-soroban]-txs.evicted-due-to-age-count | counter | Count of transactions that had low fee for too long and have not been included into several ledgers in a row. herder.pending[-soroban]-txs.not-included-due-to-low-fee-count | counter | Count of transactions that were not included into queue because it is at capacity and the fee is too low to replace other txs. @@ -168,10 +164,7 @@ overlay.outbound.attempt | meter | outbound connection atte overlay.outbound.cancel | meter | outbound connection cancelled overlay.outbound.drop | meter | outbound connection dropped overlay.outbound.establish | meter | outbound connection established (added to pending) -overlay.recv. | timer | received message (except transaction) -overlay.recv-transaction.sum | counter | sum of time (microseconds) to receive transaction message -overlay.recv-transaction.count | counter | number of transaction messages received -overlay.recv-transaction.max | counter | maximum time (microseconds) to receive transaction message since last metrics call +overlay.recv. | timer | received message overlay.send. | meter | sent message overlay.timeout.idle | meter | idle peer timeout overlay.timeout.straggler | meter | straggler peer timeout diff --git a/src/herder/TransactionQueue.cpp b/src/herder/TransactionQueue.cpp index fd6bb963d9..fbf69841e2 100644 --- a/src/herder/TransactionQueue.cpp +++ b/src/herder/TransactionQueue.cpp @@ -144,8 +144,8 @@ ClassicTransactionQueue::ClassicTransactionQueue(Application& app, mQueueMetrics = std::make_unique( sizeByAge, app.getMetrics().NewCounter({"herder", "pending-txs", "banned"}), - app.getMetrics().NewSimpleTimer({"herder", "pending-txs"}), - app.getMetrics().NewSimpleTimer({"herder", "pending-txs", "self-"}), + app.getMetrics().NewTimer({"herder", "pending-txs", "delay"}), + app.getMetrics().NewTimer({"herder", "pending-txs", "self-delay"}), app.getMetrics().NewCounter( {"herder", "pending-txs", "evicted-due-to-low-fee-count"}), app.getMetrics().NewCounter( @@ -1112,9 +1112,9 @@ SorobanTransactionQueue::SorobanTransactionQueue( sizeByAge, app.getMetrics().NewCounter( {"herder", "pending-soroban-txs", "banned"}), - app.getMetrics().NewSimpleTimer({"herder", "pending-soroban-txs"}), - app.getMetrics().NewSimpleTimer( - {"herder", "pending-soroban-txs", "self-"}), + app.getMetrics().NewTimer({"herder", "pending-soroban-txs", "delay"}), + app.getMetrics().NewTimer( + {"herder", "pending-soroban-txs", "self-delay"}), app.getMetrics().NewCounter( {"herder", "pending-soroban-txs", "evicted-due-to-low-fee-count"}), app.getMetrics().NewCounter( diff --git a/src/herder/TransactionQueue.h b/src/herder/TransactionQueue.h index ef3a3247a3..c93a72e8d8 100644 --- a/src/herder/TransactionQueue.h +++ b/src/herder/TransactionQueue.h @@ -202,8 +202,8 @@ class TransactionQueue { QueueMetrics(std::vector sizeByAge, medida::Counter& bannedTransactionsCounter, - SimpleTimer& transactionsDelay, - SimpleTimer& transactionsSelfDelay, + medida::Timer& transactionsDelay, + medida::Timer& transactionsSelfDelay, medida::Counter& txsEvictedByHigherFeeTxCounter, medida::Counter& txsEvictedDueToAgeCounter, medida::Counter& txsNotAcceptedDueToLowFeeCounter, @@ -224,11 +224,9 @@ class TransactionQueue std::vector mSizeByAge; medida::Counter& mBannedTransactionsCounter; - // Keep track of time (in milliseconds) for transaction to be included - // in ledger using `SimpleTimer`s since medida `Timer`s are too - // expensive - SimpleTimer& mTransactionsDelay; - SimpleTimer& mTransactionsSelfDelay; + // Keep track of time for transaction to be included in ledger + medida::Timer& mTransactionsDelay; + medida::Timer& mTransactionsSelfDelay; // The following metrics provided more detailed insight into banned // transactions: mBannedTransactionsCounter includes all these, as well diff --git a/src/ledger/LedgerManagerImpl.cpp b/src/ledger/LedgerManagerImpl.cpp index dc703a2e8c..8a699f5384 100644 --- a/src/ledger/LedgerManagerImpl.cpp +++ b/src/ledger/LedgerManagerImpl.cpp @@ -240,9 +240,8 @@ LedgerManagerImpl::LedgerApplyMetrics::LedgerApplyMetrics( // different window from the e2e number we want to report (we want the time from // tx sub to meta emission, but the existing metric, for example, includes an // extra delay for a postOnMainThread when background apply is enabled). Fourth, -// as of writing, the metric is a SimpleTimer, so it is lacking most of the -// percentile data we want, but even if we switch it to be a full Timer, the -// 30-second medida windowing makes interpretation more difficult. +// even though the metric is a full Timer with percentiles, the 30-second +// medida windowing makes interpretation more difficult. LedgerManagerImpl::TxLatencyMetrics::TxLatencyMetrics(MetricsRegistry& registry) : mTxsSubmitted(registry.NewCounter({"loadgen", "tx-latency", "submitted"})) , mTxsExternalized( diff --git a/src/overlay/OverlayMetrics.cpp b/src/overlay/OverlayMetrics.cpp index 85bb88e0e0..49b89bcaa4 100644 --- a/src/overlay/OverlayMetrics.cpp +++ b/src/overlay/OverlayMetrics.cpp @@ -47,8 +47,8 @@ OverlayMetrics::OverlayMetrics(Application& app) , mRecvGetTxSetTimer( app.getMetrics().NewTimer({"overlay", "recv", "get-txset"})) , mRecvTxSetTimer(app.getMetrics().NewTimer({"overlay", "recv", "txset"})) - , mRecvTransactionTimer(app.getMetrics().NewSimpleTimer( - {"overlay", "recv-transaction", ""}, std::chrono::microseconds{1})) + , mRecvTransactionTimer( + app.getMetrics().NewTimer({"overlay", "recv", "transaction"})) , mRecvGetSCPQuorumSetTimer( app.getMetrics().NewTimer({"overlay", "recv", "get-scp-qset"})) , mRecvSCPQuorumSetTimer( diff --git a/src/overlay/OverlayMetrics.h b/src/overlay/OverlayMetrics.h index 933031fbe0..fa28606266 100644 --- a/src/overlay/OverlayMetrics.h +++ b/src/overlay/OverlayMetrics.h @@ -7,7 +7,6 @@ // This structure just exists to cache frequently-accessed, overlay-wide // (non-peer-specific) metrics. -#include "util/SimpleTimer.h" namespace medida { class Timer; @@ -50,10 +49,7 @@ struct OverlayMetrics medida::Timer& mRecvGetTxSetTimer; medida::Timer& mRecvTxSetTimer; - // For frequently occurring events, using medida timers can be very - // expensive, as we are constantly compressing and copying data to maintain - // histograms. So, we use a `SimpleTimer` of microseconds instead. - SimpleTimer& mRecvTransactionTimer; + medida::Timer& mRecvTransactionTimer; medida::Timer& mRecvGetSCPQuorumSetTimer; medida::Timer& mRecvSCPQuorumSetTimer; diff --git a/src/overlay/test/OverlayTests.cpp b/src/overlay/test/OverlayTests.cpp index 4092fcddb8..e9404c6bbb 100644 --- a/src/overlay/test/OverlayTests.cpp +++ b/src/overlay/test/OverlayTests.cpp @@ -378,8 +378,8 @@ TEST_CASE("flow control byte capacity", "[overlay][flowcontrol]") txtest::executeUpgrade(*app, txtest::makeConfigUpgrade(*res)); }; - auto& txsRecv = app2->getMetrics().NewCounter( - {"overlay", "recv-transaction", "count"}); + auto& txsRecv = + app2->getMetrics().NewTimer({"overlay", "recv", "transaction"}); auto start = txsRecv.count(); conn.getInitiator()->sendMessage(std::make_shared(tx1)); @@ -2861,7 +2861,7 @@ TEST_CASE("overlay pull mode", "[overlay][pullmode]") .count() == 2); REQUIRE(apps[2] ->getMetrics() - .NewCounter({"overlay", "recv-transaction", "count"}) + .NewTimer({"overlay", "recv", "transaction"}) .count() == 1); REQUIRE(getAdvertisedHashCount(apps[2]) == 0); } @@ -3286,9 +3286,7 @@ TEST_CASE("Queue purging after write completion", "[overlay][flowcontrol]") int const NUM_MESSAGES = 1000; auto initialTxCount = - n0->getMetrics() - .NewCounter({"overlay", "recv-transaction", "count"}) - .count(); + n0->getMetrics().NewTimer({"overlay", "recv", "transaction"}).count(); SECTION("p1 never reads") { @@ -3315,7 +3313,7 @@ TEST_CASE("Queue purging after write completion", "[overlay][flowcontrol]") REQUIRE(finalQueueDrops > initialQueueDrops); REQUIRE(finalQueueSize < NUM_MESSAGES); REQUIRE(n1->getMetrics() - .NewCounter({"overlay", "recv-transaction", "count"}) + .NewTimer({"overlay", "recv", "transaction"}) .count() == initialTxCount); } SECTION("p1 received all txs") @@ -3328,7 +3326,7 @@ TEST_CASE("Queue purging after write completion", "[overlay][flowcontrol]") s->crankForAtLeast(std::chrono::seconds(1), false); REQUIRE(n1->getMetrics() - .NewCounter({"overlay", "recv-transaction", "count"}) + .NewTimer({"overlay", "recv", "transaction"}) .count() == initialTxCount + NUM_MESSAGES); REQUIRE(p0->getFlowControl()->getQueuesForTesting()[1].size() == 0); // No new messages were dropped diff --git a/src/simulation/LoadGenerator.cpp b/src/simulation/LoadGenerator.cpp index 33c56fb667..2f59e24109 100644 --- a/src/simulation/LoadGenerator.cpp +++ b/src/simulation/LoadGenerator.cpp @@ -86,15 +86,17 @@ getTxCount(Application& app, bool isSoroban) { if (isSoroban) { - return app.getMetrics() - .NewCounter({"herder", "pending-soroban-txs", "self-count"}) - .count(); + return static_cast( + app.getMetrics() + .NewTimer({"herder", "pending-soroban-txs", "self-delay"}) + .count()); } else { - return app.getMetrics() - .NewCounter({"herder", "pending-txs", "self-count"}) - .count(); + return static_cast( + app.getMetrics() + .NewTimer({"herder", "pending-txs", "self-delay"}) + .count()); } }