Bring back medida::Timer now that CKMS compression is much faster

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.<X>                          | timer     | received message <X> (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.<X>                          | timer     | received message <X>
 overlay.send.<X>                          | meter     | sent message <X>
 overlay.timeout.idle                      | meter     | idle peer timeout
 overlay.timeout.straggler                 | meter     | straggler peer timeout

src/herder/TransactionQueue.cpp

@@ -144,8 +144,8 @@ ClassicTransactionQueue::ClassicTransactionQueue(Application& app,
     mQueueMetrics = std::make_unique<QueueMetrics>(
         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(

src/herder/TransactionQueue.h

@@ -202,8 +202,8 @@ class TransactionQueue
     {
         QueueMetrics(std::vector<medida::Counter*> 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<medida::Counter*> 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

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(

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(

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;

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<StellarMessage>(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

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<uint32_t>(
+            app.getMetrics()
+                .NewTimer({"herder", "pending-soroban-txs", "self-delay"})
+                .count());
     }
     else
     {
-        return app.getMetrics()
-            .NewCounter({"herder", "pending-txs", "self-count"})
-            .count();
+        return static_cast<uint32_t>(
+            app.getMetrics()
+                .NewTimer({"herder", "pending-txs", "self-delay"})
+                .count());
     }
 }