Record e2e measurement through tx set instead of meta (#5359)

Update to #5356. Changes how we get the transactions that have been
externalized from using the generated meta to using the externalized tx
set so that we can support overlay-only mode. Also, moves when the call
to `recordTxMetaEmissionLatency` happens: now, it happens after the
simulated sleep. For the overlay-only simulated delay, this is the best
time to call it. Unfortunately, this lengthens the time for the
real-delay case.

Author: marta-lokhova

src/ledger/LedgerManager.h

@@ -302,11 +302,11 @@ class LedgerManager
 
     // Records the submission time of a self-submitted transaction for the
     // tx-latency metrics. No-op unless
-    // Config::LOADGEN_MEASURE_TX_LATENCY_FOR_TESTING is set.
+    // Config::LOADGEN_MEASURE_TX_E2E_LATENCY_FOR_TESTING is set.
     virtual void recordTxSubmission(Hash const& contentsHash) = 0;
 
     // Begins/ends a load-generation latency measurement window. No-op unless
-    // Config::LOADGEN_MEASURE_TX_LATENCY_FOR_TESTING is set.
+    // Config::LOADGEN_MEASURE_TX_E2E_LATENCY_FOR_TESTING is set.
     virtual void beginTxLatencyMeasurement(uint32_t expectedTxCount) = 0;
     virtual void finalizeTxLatencyMeasurement() = 0;
 #endif

src/ledger/LedgerManagerImpl.cpp

@@ -1362,47 +1362,33 @@ LedgerManagerImpl::recordTxSubmission(Hash const& contentsHash)
 }
 
 void
-LedgerManagerImpl::recordTxMetaEmissionLatency(LedgerCloseMeta const& lcm)
+LedgerManagerImpl::recordTxE2eLatency(ApplicableTxSetFrame const& txSet)
 {
     if (!mApp.getConfig().LOADGEN_MEASURE_TX_E2E_LATENCY_FOR_TESTING)
     {
         return;
     }
-    VirtualClock::time_point const emitTime = mApp.getClock().now();
+    VirtualClock::time_point const applyEndTime = mApp.getClock().now();
     MutexLocker guard(mTxLatencyMetrics.mMutex);
-    auto probe =
-        [&](auto const& txProcessing) REQUIRES(mTxLatencyMetrics.mMutex) {
-            for (auto const& txp : txProcessing)
+    for (auto const& phase : txSet.getPhases())
+    {
+        for (auto const& tx : phase)
+        {
+            if (auto submitted = mTxLatencyMetrics.mTxSubmitTimes.find(
+                    tx->getContentsHash());
+                submitted != mTxLatencyMetrics.mTxSubmitTimes.end())
             {
-                if (auto submitted = mTxLatencyMetrics.mTxSubmitTimes.find(
-                        txp.result.transactionHash);
-                    submitted != mTxLatencyMetrics.mTxSubmitTimes.end())
-                {
-                    auto const latency = emitTime - submitted->second;
-                    mTxLatencyMetrics.mTxsExternalized.inc();
-                    int64_t const ms =
-                        std::chrono::duration_cast<std::chrono::milliseconds>(
-                            latency)
-                            .count();
-                    mTxLatencyMetrics.mSamples.push_back(std::clamp<int64_t>(
-                        ms, 0, std::numeric_limits<uint32_t>::max()));
-                    mTxLatencyMetrics.mTxSubmitTimes.erase(submitted);
-                }
+                auto const latency = applyEndTime - submitted->second;
+                mTxLatencyMetrics.mTxsExternalized.inc();
+                int64_t const ms =
+                    std::chrono::duration_cast<std::chrono::milliseconds>(
+                        latency)
+                        .count();
+                mTxLatencyMetrics.mSamples.push_back(std::clamp<int64_t>(
+                    ms, 0, std::numeric_limits<uint32_t>::max()));
+                mTxLatencyMetrics.mTxSubmitTimes.erase(submitted);
             }
-        };
-    switch (lcm.v())
-    {
-    case 0:
-        probe(lcm.v0().txProcessing);
-        break;
-    case 1:
-        probe(lcm.v1().txProcessing);
-        break;
-    case 2:
-        probe(lcm.v2().txProcessing);
-        break;
-    default:
-        releaseAssert(false);
+        }
     }
 }
 
@@ -1951,7 +1937,6 @@ LedgerManagerImpl::applyLedger(LedgerCloseData const& ledgerData,
             appliedLedgerState->getLastClosedLedgerHeader();
         // Copy this before we move it into mNextMetaToEmit below
         mLastLedgerCloseMeta = *ledgerCloseMeta;
-        recordTxMetaEmissionLatency(ledgerCloseMeta->getXDR());
     }
 #endif
 
@@ -2056,6 +2041,7 @@ LedgerManagerImpl::applyLedger(LedgerCloseData const& ledgerData,
 #ifdef BUILD_TESTS
     maybeSimulateSleep(mApp.getConfig(), txSet->sizeOpTotalForLogging(),
                        applyLedgerTime, mApplySleepRng);
+    recordTxE2eLatency(*applicableTxSet);
 #endif
 
     // Steps 6, 7, 8 are done in `advanceLedgerStateAndPublish`

src/ledger/LedgerManagerImpl.h

@@ -457,15 +457,15 @@ class LedgerManagerImpl : public LedgerManager
         ANNOTATED_MUTEX(mMutex);
         UnorderedMap<Hash, VirtualClock::time_point>
             mTxSubmitTimes GUARDED_BY(mMutex);
-        // Each recorded submission -> meta-emission latency in ms
+        // Each recorded submission -> post-apply latency in ms
         std::vector<uint32_t> mSamples GUARDED_BY(mMutex);
 
         TxLatencyMetrics(MetricsRegistry& registry);
     } mTxLatencyMetrics;
 
-    // End point of the tx-latency metric: matches the ledger-close meta's
-    // txProcessing entries against mTxSubmitTimes and records each latency.
-    void recordTxMetaEmissionLatency(LedgerCloseMeta const& lcm);
+    // End point of the tx-latency metric: records the submission to post-apply
+    // latency for each externalized transaction.
+    void recordTxE2eLatency(ApplicableTxSetFrame const& txSet);
 #endif
 
     void setState(State s);