diff --git a/docs/apply-load-benchmark-sac.cfg b/docs/apply-load-benchmark-sac.cfg index ecede87549..78f6faaa64 100644 --- a/docs/apply-load-benchmark-sac.cfg +++ b/docs/apply-load-benchmark-sac.cfg @@ -7,6 +7,11 @@ APPLY_LOAD_MODE="benchmark" APPLY_LOAD_MODEL_TX="sac" +# Which timing path to use: "apply" preserves the historical apply-only +# benchmark, while "txset-validation-and-apply" simulates a non-leader receiving +# and validating a tx set before applying it. Tx-set creation is not measured. +APPLY_LOAD_TIMING_PHASES = "apply" + # Whether to time the write part of the apply stage. This can be # disabled to get less noisy results for non-write related changes, # but should be enabled to get more comprehensive e2e numbers. @@ -62,4 +67,4 @@ NODE_SEED="SDQVDISRYN2JXBS7ICL7QJAEKB3HWBJFP2QECXG7GZICAHBK4UNJCWK2 self" [QUORUM_SET] THRESHOLD_PERCENT=100 -VALIDATORS=["$self"] \ No newline at end of file +VALIDATORS=["$self"] diff --git a/docs/metrics.md b/docs/metrics.md index c538fbb413..4d93d03bfe 100644 --- a/docs/metrics.md +++ b/docs/metrics.md @@ -62,6 +62,7 @@ crypto.verify.miss | meter | number of signature cach crypto.verify.total | meter | sum of both hits and misses crypto.verify.tx-valid-hit | meter | signature cache hits that occurred while validating transactions (outside of background signature validation) crypto.verify.tx-valid-total | meter | sum of both hits and misses during transaction validation (outside of background signature validation) +herder.txset.validate | timer | time spent turning a received tx set into an applicable tx set and validating it on a validity-cache miss; Tracy labels the enclosing call as a cache hit or miss herder.pending[-soroban]-txs.age0 | counter | number of gen0 pending transactions herder.pending[-soroban]-txs.age1 | counter | number of gen1 pending transactions herder.pending[-soroban]-txs.age2 | counter | number of gen2 pending transactions diff --git a/docs/software/commands.md b/docs/software/commands.md index 66033880c2..33851db66f 100644 --- a/docs/software/commands.md +++ b/docs/software/commands.md @@ -20,9 +20,11 @@ Common options can be placed at any place in the command line. Command options can only by placed after command. * **apply-load**: Benchmarks Soroban transaction application time using - synthetic transactions. The benchmark is isolated to mostly just executing - the transactions and thus it omits a lot of the supporting mechanisms - (such as overlay, SCP, mempool etc). This command will generate enough + synthetic transactions. The benchmark omits the overlay and mempool, but + each iteration reconstructs the tx set from serialized bytes and runs real + consensus with the node as its own single-validator quorum. It does not + simulate network transport, peer fetching, or multi-node timing. + This command will generate enough transactions to fill up a synthetic transaction queue (it's just a list of transactions with the same limits as the real queue), and then create a transaction set off of that to apply. This can also be used to record the @@ -36,6 +38,20 @@ Command options can only by placed after command. consisting only of fast SAC transfer. - `APPLY_LOAD_MODE="benchmark"`: benchmarks a fixed-size ledger of model transactions. Use `APPLY_LOAD_MODEL_TX` to select the model transaction. + * `APPLY_LOAD_TIMING_PHASES` selects one of two timing paths: + - `"apply"`: the default historical apply-only benchmark. Its close helper + still calls `checkValid`, but that happens before the recorded ledger-close + timer and leaves the caches warm, as consensus validation would on a live + node. Output remains in the historical format. + - `"txset-validation-and-apply"`: simulates a non-leader receiving the tx + set over the wire, validating it through local consensus, and then applying + it. It reports validation, ledger close, and end-to-end time. Leader-side + tx-set creation and signing happen before the measured span. The signature + verification cache is cleared before validation, then retained so apply + sees the warm cache produced by validation. + `"txset-validation-and-apply"` is not supported with + `APPLY_LOAD_MODE="max-sac-tps"`; that search retains its historical + apply-only timing objective. * Load generation is configured in the Core config file. The relevant settings all begin with `APPLY_LOAD_`. See full example configurations with per-setting documentation in the `docs` directory diff --git a/src/herder/HerderSCPDriver.cpp b/src/herder/HerderSCPDriver.cpp index 69654085ba..117add57fe 100644 --- a/src/herder/HerderSCPDriver.cpp +++ b/src/herder/HerderSCPDriver.cpp @@ -76,6 +76,8 @@ HerderSCPDriver::SCPMetrics::SCPMetrics(Application& app) {"scp", "timing", "self-to-others-externalize-lag"})) , mBallotBlockedOnTxSet(app.getMetrics().NewTimer( {"scp", "timing", "ballot-blocked-on-txset"})) + , mTxSetValidation( + app.getMetrics().NewTimer({"herder", "txset", "validate"})) , mEmptyTxSetExternalized( app.getMetrics().NewCounter({"scp", "empty-tx-set", "externalized"})) , mEmptyTxSetValueReplaced(app.getMetrics().NewCounter( @@ -1859,12 +1861,18 @@ HerderSCPDriver::checkAndCacheTxSetValid(TxSetXDRFrame const& txSet, LedgerHeaderHistoryEntry const& lcl, uint64_t closeTimeOffset) const { + ZoneScoped; + auto key = TxSetValidityKey{lcl.hash, txSet.getContentsHash(), closeTimeOffset, closeTimeOffset}; bool* pRes = mTxSetValidCache.maybeGet(key); if (pRes == nullptr) { + std::string zoneTxt("miss"); + ZoneText(zoneTxt.c_str(), zoneTxt.size()); + auto validationTime = mSCPMetrics.mTxSetValidation.TimeScope(); + // The invariant here is that we only validate tx sets nominated // to be applied to the current ledger state. However, in case // if we receive a bad SCP value for the current state, we still @@ -1895,6 +1903,8 @@ HerderSCPDriver::checkAndCacheTxSetValid(TxSetXDRFrame const& txSet, } else { + std::string zoneTxt("hit"); + ZoneText(zoneTxt.c_str(), zoneTxt.size()); return *pRes; } } diff --git a/src/herder/HerderSCPDriver.h b/src/herder/HerderSCPDriver.h index 81f9114e4e..d4906b64db 100644 --- a/src/herder/HerderSCPDriver.h +++ b/src/herder/HerderSCPDriver.h @@ -268,6 +268,9 @@ class HerderSCPDriver : public SCPDriver // download medida::Timer& mBallotBlockedOnTxSet; + // Timer tracking time to check and cache a tx set + medida::Timer& mTxSetValidation; + // Tracks how many ledgers we externalized an empty-tx-set value. medida::Counter& mEmptyTxSetExternalized; diff --git a/src/main/Config.cpp b/src/main/Config.cpp index ec5725e6d3..b71ea3e377 100644 --- a/src/main/Config.cpp +++ b/src/main/Config.cpp @@ -464,6 +464,23 @@ parseApplyLoadModelTx(ConfigItem const& item) "invalid 'APPLY_LOAD_MODEL_TX', expected one of: sac, custom_token, " "soroswap"); } + +ApplyLoadTimingPhases +parseApplyLoadTimingPhases(ConfigItem const& item) +{ + auto phases = readString(item); + if (phases == "apply") + { + return ApplyLoadTimingPhases::APPLY_ONLY; + } + if (phases == "txset-validation-and-apply") + { + return ApplyLoadTimingPhases::TX_SET_VALIDATION_AND_APPLY; + } + throw std::invalid_argument( + "invalid 'APPLY_LOAD_TIMING_PHASES', expected one of: apply, " + "txset-validation-and-apply"); +} #endif template @@ -1866,6 +1883,11 @@ Config::processConfig(std::shared_ptr t) }}, {"APPLY_LOAD_TIME_WRITES", [&]() { APPLY_LOAD_TIME_WRITES = readBool(item); }}, + {"APPLY_LOAD_TIMING_PHASES", + [&]() { + APPLY_LOAD_TIMING_PHASES = + parseApplyLoadTimingPhases(item); + }}, #endif // BUILD_TESTS {"GENESIS_TEST_ACCOUNT_COUNT", [&]() { diff --git a/src/main/Config.h b/src/main/Config.h index 3f6b6b4c9e..ee4965219c 100644 --- a/src/main/Config.h +++ b/src/main/Config.h @@ -83,6 +83,13 @@ enum class ApplyLoadModelTx CUSTOM_TOKEN, SOROSWAP }; + +// Which apply-load timing path to use. +enum class ApplyLoadTimingPhases +{ + APPLY_ONLY, + TX_SET_VALIDATION_AND_APPLY +}; #endif class Config : public std::enable_shared_from_this @@ -425,6 +432,10 @@ class Config : public std::enable_shared_from_this // If set to true, database writes will count towards TPS calculation. // Otherwise, BucketList writes will not be counted. bool APPLY_LOAD_TIME_WRITES = true; + + // Which apply-load timing path to use. + ApplyLoadTimingPhases APPLY_LOAD_TIMING_PHASES = + ApplyLoadTimingPhases::APPLY_ONLY; #endif // BUILD_TESTS // Waits for merges to complete before applying transactions during catchup diff --git a/src/simulation/ApplyLoad.cpp b/src/simulation/ApplyLoad.cpp index 80bc2aaa63..37f19009c4 100644 --- a/src/simulation/ApplyLoad.cpp +++ b/src/simulation/ApplyLoad.cpp @@ -12,8 +12,10 @@ #include "bucket/BucketListSnapshot.h" #include "bucket/BucketManager.h" #include "bucket/test/BucketTestUtils.h" +#include "crypto/SecretKey.h" #include "herder/Herder.h" #include "herder/HerderImpl.h" +#include "herder/TxSetFrame.h" #include "ledger/ImmutableLedgerView.h" #include "ledger/InMemorySorobanState.h" #include "ledger/LedgerManager.h" @@ -77,6 +79,40 @@ interpolatePercentile(std::vector const& sortedValues, return sortedValues[lo] * (1.0 - weight) + sortedValues[hi] * weight; } +void +nominateAndClose(Application& app, TxSetXDRFrameConstPtr txSet, + StellarValue const& value) +{ + auto& herder = static_cast(app.getHerder()); + auto const& lcl = app.getLedgerManager().getLastClosedLedgerHeader(); + auto const ledgerSeq = lcl.header.ledgerSeq + 1; + herder.getPendingEnvelopes().putTxSet(txSet->getContentsHash(), ledgerSeq, + txSet); + herder.getHerderSCPDriver().nominate(ledgerSeq, value, txSet, + lcl.header.scpValue); + + auto const deadline = + std::chrono::steady_clock::now() + std::chrono::seconds(60); + size_t cranks = 0; + while (app.getLedgerManager().getLastClosedLedgerNum() < ledgerSeq && + std::chrono::steady_clock::now() < deadline) + { + app.getClock().crank(true); + ++cranks; + } + if (app.getLedgerManager().getLastClosedLedgerNum() < ledgerSeq) + { + throw std::runtime_error(fmt::format( + FMT_STRING("nominateAndClose: SCP did not externalize ledger {} " + "within 60s ({} cranks); close time {} is {}s from the " + "wall clock (slip limit {}s)"), + ledgerSeq, cranks, value.closeTime, + static_cast(value.closeTime) - + static_cast(app.timeNow()), + Herder::MAX_TIME_SLIP_SECONDS.count())); + } +} + template void throwIfResourceIsZero(T resourceVal, char const* resourceName) @@ -627,6 +663,7 @@ ApplyLoad::ApplyLoad(Application& app) , mMode(app.getConfig().APPLY_LOAD_MODE) , mModelTx(app.getConfig().APPLY_LOAD_MODEL_TX) , mLimitsBasedTxProfile(deriveLimitBasedTxProfile(mMode, app.getConfig())) + , mTimingPhases(app.getConfig().APPLY_LOAD_TIMING_PHASES) , mTotalHotArchiveEntries( calculateRequiredHotArchiveEntries(app.getConfig())) , mTxCountUtilization( @@ -680,7 +717,12 @@ ApplyLoad::ApplyLoad(Application& app) // enough samples for statistics to be meaningful. if (mMode == ApplyLoadMode::MAX_SAC_TPS) { - + if (measuresTxSetValidation()) + { + throw std::runtime_error( + "APPLY_LOAD_TIMING_PHASES=txset-validation-and-apply is not " + "supported with APPLY_LOAD_MODE=max-sac-tps"); + } if (config.APPLY_LOAD_NUM_LEDGERS < 30) { throw std::runtime_error( @@ -846,48 +888,142 @@ ApplyLoad::setup() } } +void +ApplyLoad::logPhaseStats(std::string const& label, + std::vector const& samplesMs) +{ + releaseAssert(!samplesMs.empty()); + + double mean = std::accumulate(samplesMs.begin(), samplesMs.end(), 0.0) / + samplesMs.size(); + + double varianceMsSq = 0.0; + for (auto const& sample : samplesMs) + { + double delta = sample - mean; + varianceMsSq += delta * delta; + } + varianceMsSq /= samplesMs.size(); + + std::vector sortedSamples = samplesMs; + std::sort(sortedSamples.begin(), sortedSamples.end()); + + CLOG_WARNING(Perf, "mean {}: {} ms", label, mean); + CLOG_WARNING(Perf, "p25 {}: {} ms", label, + interpolatePercentile(sortedSamples, 25.0)); + CLOG_WARNING(Perf, "p50 {}: {} ms", label, + interpolatePercentile(sortedSamples, 50.0)); + CLOG_WARNING(Perf, "p75 {}: {} ms", label, + interpolatePercentile(sortedSamples, 75.0)); + CLOG_WARNING(Perf, "p95 {}: {} ms", label, + interpolatePercentile(sortedSamples, 95.0)); + CLOG_WARNING(Perf, "p99 {}: {} ms", label, + interpolatePercentile(sortedSamples, 99.0)); + CLOG_WARNING(Perf, "{} stddev: {} ms", label, std::sqrt(varianceMsSq)); +} + +void +ApplyLoad::logConfiguredPhaseStats() const +{ + if (!measuresTxSetValidation()) + { + return; + } + + CLOG_WARNING(Perf, "================================================"); + logPhaseStats("txset validation", mPhaseValidationMs); + + // Expect one cold check per tx + one StellarValue check per ledger. + auto const ledgerCount = static_cast(mPhaseValidationMs.size()); + auto const txCount = static_cast(mBenchmarkTxCount); + CLOG_WARNING( + Perf, + "sig cache hits/misses: {}/{} (expected {} misses = {} tx sigs + {} " + "value sigs)", + mLedgerSigCacheHits, mLedgerSigCacheMisses, txCount + ledgerCount, + txCount, ledgerCount); + if (txCount > 0) + { + CLOG_WARNING( + Perf, + "tx signature cache misses per transaction: {:.4f} (expect 1.0)", + static_cast(static_cast(mLedgerSigCacheMisses) - + ledgerCount) / + static_cast(txCount)); + } + // Expect one cold tx set validation per ledger. + auto const validations = + mApp.getMetrics().NewTimer({"herder", "txset", "validate"}).count(); + CLOG_WARNING(Perf, "txset validations per ledger: {:.2f}", + static_cast(validations) / + static_cast(ledgerCount)); + + logPhaseStats("ledger close", mPhaseLedgerCloseMs); + logPhaseStats("end-to-end txset+apply", mPhaseEndToEndMs); + + double validationSum = std::accumulate(mPhaseValidationMs.begin(), + mPhaseValidationMs.end(), 0.0); + double ledgerCloseSum = std::accumulate(mPhaseLedgerCloseMs.begin(), + mPhaseLedgerCloseMs.end(), 0.0); + double e2eSum = std::accumulate(mPhaseEndToEndMs.begin(), + mPhaseEndToEndMs.end(), 0.0); + if (e2eSum > 0.0) + { + CLOG_WARNING(Perf, "txset validation share of end-to-end: {:.2f}%", + validationSum / e2eSum * 100.0); + CLOG_WARNING(Perf, "ledger close share of end-to-end: {:.2f}%", + ledgerCloseSum / e2eSum * 100.0); + CLOG_WARNING(Perf, + "other receive/consensus/externalize overhead share " + "of end-to-end: {:.2f}%", + (e2eSum - validationSum - ledgerCloseSum) / e2eSum * + 100.0); + } + CLOG_WARNING(Perf, "================================================"); +} + +void +ApplyLoad::recordSorobanUtilization(ApplicableTxSetFrame const& txSet, + uint32_t ledgerVersion) +{ + auto ledgerResources = mApp.getLedgerManager().maxLedgerResources(true); + auto txSetResources = + txSet.getPhases() + .at(static_cast(TxSetPhase::SOROBAN)) + .getTotalResources(ledgerVersion) + .value(); + auto updateUtilization = [&](medida::Histogram& histogram, + Resource::Type resource) { + histogram.Update(txSetResources.getVal(resource) * 1.0 / + ledgerResources.getVal(resource) * 100000.0); + }; + updateUtilization(mTxCountUtilization, Resource::Type::OPERATIONS); + updateUtilization(mInstructionUtilization, Resource::Type::INSTRUCTIONS); + updateUtilization(mTxSizeUtilization, Resource::Type::TX_BYTE_SIZE); + updateUtilization(mDiskReadByteUtilization, + Resource::Type::DISK_READ_BYTES); + updateUtilization(mWriteByteUtilization, Resource::Type::WRITE_BYTES); + updateUtilization(mDiskReadEntryUtilization, + Resource::Type::READ_LEDGER_ENTRIES); + updateUtilization(mWriteEntryUtilization, + Resource::Type::WRITE_LEDGER_ENTRIES); + CLOG_INFO(Perf, "generated tx set resources: {}/{}", + txSetResources.toString(), ledgerResources.toString()); +} + void ApplyLoad::closeLedger(std::vector const& txs, xdr::xvector const& upgrades, - bool recordSorobanUtilization) + bool recordUtilization) { auto txSet = makeTxSetFromTransactions(txs, mApp, 0, 0); - if (recordSorobanUtilization) - { - auto ledgerResources = mApp.getLedgerManager().maxLedgerResources(true); - auto txSetResources = - txSet.second->getPhases() - .at(static_cast(TxSetPhase::SOROBAN)) - .getTotalResources(mApp.getLedgerManager() - .getLastClosedLedgerHeader() - .header.ledgerVersion) - .value(); - mTxCountUtilization.Update( - txSetResources.getVal(Resource::Type::OPERATIONS) * 1.0 / - ledgerResources.getVal(Resource::Type::OPERATIONS) * 100000.0); - mInstructionUtilization.Update( - txSetResources.getVal(Resource::Type::INSTRUCTIONS) * 1.0 / - ledgerResources.getVal(Resource::Type::INSTRUCTIONS) * 100000.0); - mTxSizeUtilization.Update( - txSetResources.getVal(Resource::Type::TX_BYTE_SIZE) * 1.0 / - ledgerResources.getVal(Resource::Type::TX_BYTE_SIZE) * 100000.0); - mDiskReadByteUtilization.Update( - txSetResources.getVal(Resource::Type::DISK_READ_BYTES) * 1.0 / - ledgerResources.getVal(Resource::Type::DISK_READ_BYTES) * 100000.0); - mWriteByteUtilization.Update( - txSetResources.getVal(Resource::Type::WRITE_BYTES) * 1.0 / - ledgerResources.getVal(Resource::Type::WRITE_BYTES) * 100000.0); - mDiskReadEntryUtilization.Update( - txSetResources.getVal(Resource::Type::READ_LEDGER_ENTRIES) * 1.0 / - ledgerResources.getVal(Resource::Type::READ_LEDGER_ENTRIES) * - 100000.0); - mWriteEntryUtilization.Update( - txSetResources.getVal(Resource::Type::WRITE_LEDGER_ENTRIES) * 1.0 / - ledgerResources.getVal(Resource::Type::WRITE_LEDGER_ENTRIES) * - 100000.0); - CLOG_INFO(Perf, "generated tx set resources: {}/{}", - txSetResources.toString(), ledgerResources.toString()); + if (recordUtilization) + { + recordSorobanUtilization( + *txSet.second, + mApp.getLedgerManager().getLastClosedLedgerHeader().header + .ledgerVersion); } auto sv = mApp.getHerder().makeStellarValue(txSet.first->getContentsHash(), 1, @@ -896,10 +1032,105 @@ ApplyLoad::closeLedger(std::vector const& txs, stellar::txtest::closeLedger(mApp, txs, /* strictOrder */ false, upgrades); } +void +ApplyLoad::closeLedgerViaConsensus( + std::vector const& txs, + bool recordUtilization) +{ + releaseAssert(!txs.empty()); + auto& herder = mApp.getHerder(); + auto const& lcl = mApp.getLedgerManager().getLastClosedLedgerHeader(); + + uint64_t const closeTime = lcl.header.scpValue.closeTime + 1; + auto txSet = makeTxSetFromTransactions(txs, mApp, 1, 1); + + if (recordUtilization) + { + recordSorobanUtilization(*txSet.second, lcl.header.ledgerVersion); + } + + // We want to simulate a non-leader node receiving a TX set off the wire, + // so we build and sign outside the measured receiver-side span. + GeneralizedTransactionSet xdrTxSet; + txSet.first->toXDR(xdrTxSet); + auto const wireBytes = xdr::xdr_to_opaque(xdrTxSet); + auto const nominatedValue = + herder.makeStellarValue(txSet.first->getContentsHash(), closeTime, {}, + mApp.getConfig().NODE_SEED); + // Do not retain leader-side frames during the measured work. + xdrTxSet = GeneralizedTransactionSet{}; + txSet.first.reset(); + txSet.second.reset(); + + // Validation should see cold signatures and leave them warm for apply. + PubKeyUtils::clearVerifySigCache(); + // Exclude signature checks performed while building the set. + mApp.syncOwnMetrics(); + auto& metrics = mApp.getMetrics(); + auto& sigHitMeter = + metrics.NewMeter({"crypto", "verify", "hit"}, "signature"); + auto& sigMissMeter = + metrics.NewMeter({"crypto", "verify", "miss"}, "signature"); + auto const sigHitsBefore = sigHitMeter.count(); + auto const sigMissesBefore = sigMissMeter.count(); + + auto& validationTimer = metrics.NewTimer({"herder", "txset", "validate"}); + // ledger.close includes apply-side prepareForApply. + auto& ledgerCloseTimer = metrics.NewTimer({"ledger", "ledger", "close"}); + double const validationBefore = validationTimer.sum(); + double const ledgerCloseBefore = ledgerCloseTimer.sum(); + + auto const e2eStart = std::chrono::steady_clock::now(); + + // Decode into a fresh frame as the overlay receive path does. + GeneralizedTransactionSet receivedXdr; + xdr::xdr_from_opaque(wireBytes, receivedXdr); + auto receivedTxSet = TxSetXDRFrame::makeFromWire(receivedXdr); + + // Nomination through externalization and apply use production SCP paths. + nominateAndClose(mApp, receivedTxSet, nominatedValue); + + auto const e2eEnd = std::chrono::steady_clock::now(); + double const ledgerCloseMs = ledgerCloseTimer.sum() - ledgerCloseBefore; + mPhaseValidationMs.emplace_back(validationTimer.sum() - validationBefore); + mPhaseLedgerCloseMs.emplace_back(ledgerCloseMs); + mPhaseEndToEndMs.emplace_back( + std::chrono::duration(e2eEnd - e2eStart).count()); + mApp.syncOwnMetrics(); + mLedgerSigCacheHits += sigHitMeter.count() - sigHitsBefore; + mLedgerSigCacheMisses += sigMissMeter.count() - sigMissesBefore; + mBenchmarkTxCount += txs.size(); +} + +void +ApplyLoad::closeBenchmarkLedger( + std::vector const& txs, + bool recordUtilization) +{ + if (measuresTxSetValidation()) + { + closeLedgerViaConsensus(txs, recordUtilization); + } + else + { + closeLedger(txs, {}, recordUtilization); + } +} + void ApplyLoad::execute() { logExecutionEnvironmentSnapshot(mApp.getConfig()); + if (measuresTxSetValidation()) + { + mApp.getMetrics().NewTimer({"herder", "txset", "validate"}).Clear(); + mPhaseValidationMs.clear(); + mPhaseLedgerCloseMs.clear(); + mPhaseEndToEndMs.clear(); + mLedgerSigCacheHits = 0; + mLedgerSigCacheMisses = 0; + mBenchmarkTxCount = 0; + } switch (mMode) { @@ -1450,6 +1681,8 @@ ApplyLoad::benchmarkLimits() getWriteEntryUtilization().max() / 1000.0); CLOG_INFO(Perf, "Tx Success Rate: {:f}%", successRate() * 100); + + logConfiguredPhaseStats(); } double @@ -1562,9 +1795,8 @@ ApplyLoad::benchmarkLimitsIteration() mApp.getMetrics().NewTimer({"ledger", "ledger", "close"}); double timeBefore = ledgerCloseTime.sum(); - closeLedger(txs, {}, /* recordSorobanUtilization */ true); + closeBenchmarkLedger(txs, /* recordSorobanUtilization */ true); double timeAfter = ledgerCloseTime.sum(); - double closeTime = timeAfter - timeBefore; CLOG_INFO(Perf, "Limits benchmark time: {:.2f}ms", closeTime); return closeTime; @@ -1754,38 +1986,15 @@ ApplyLoad::benchmarkModelTx() releaseAssert(!closeTimes.empty()); - double avgCloseTimeMs = - std::accumulate(closeTimes.begin(), closeTimes.end(), 0.0) / - closeTimes.size(); - - double varianceMsSq = 0.0; - for (auto const& closeTime : closeTimes) - { - double delta = closeTime - avgCloseTimeMs; - varianceMsSq += delta * delta; - } - varianceMsSq /= closeTimes.size(); - - std::vector sortedCloseTimes = closeTimes; - std::sort(sortedCloseTimes.begin(), sortedCloseTimes.end()); - CLOG_WARNING(Perf, "================================================"); - CLOG_WARNING( - Perf, "Model tx benchmark stats ({} ledgers, {} tx per ledger):", - config.APPLY_LOAD_NUM_LEDGERS, config.APPLY_LOAD_MAX_SOROBAN_TX_COUNT); - CLOG_WARNING(Perf, "mean close time: {} ms", avgCloseTimeMs); - CLOG_WARNING(Perf, "p25 close time: {} ms", - interpolatePercentile(sortedCloseTimes, 25.0)); - CLOG_WARNING(Perf, "p50 close time: {} ms", - interpolatePercentile(sortedCloseTimes, 50.0)); - CLOG_WARNING(Perf, "p75 close time: {} ms", - interpolatePercentile(sortedCloseTimes, 75.0)); - CLOG_WARNING(Perf, "p95 close time: {} ms", - interpolatePercentile(sortedCloseTimes, 95.0)); - CLOG_WARNING(Perf, "p99 close time: {} ms", - interpolatePercentile(sortedCloseTimes, 99.0)); - CLOG_WARNING(Perf, "close time stddev: {} ms", std::sqrt(varianceMsSq)); + CLOG_WARNING(Perf, + "Model tx benchmark stats ({} ledgers, {} tx per ledger):", + config.APPLY_LOAD_NUM_LEDGERS, + config.APPLY_LOAD_MAX_SOROBAN_TX_COUNT); + logPhaseStats("close time", closeTimes); CLOG_WARNING(Perf, "================================================"); + + logConfiguredPhaseStats(); } double @@ -1835,7 +2044,7 @@ ApplyLoad::benchmarkModelTxTpsSingleLedger(ApplyLoadModelTx modelTx, releaseAssert( mApp.getBucketManager().getHotArchiveBucketList().futuresAllResolved()); double timeBefore = totalTxApplyTimer.sum(); - closeLedger(txs); + closeBenchmarkLedger(txs, /* recordSorobanUtilization */ false); double timeAfter = totalTxApplyTimer.sum(); double closeTime = timeAfter - timeBefore; diff --git a/src/simulation/ApplyLoad.h b/src/simulation/ApplyLoad.h index 66f7c25130..944436271b 100644 --- a/src/simulation/ApplyLoad.h +++ b/src/simulation/ApplyLoad.h @@ -22,7 +22,8 @@ class ApplyLoad // of values is [0,1.0]. double successRate(); - // Closes a ledger with the given transactions and optional upgrades. + // Closes a ledger through the historical direct-externalization path. + // checkValid runs before the ledger-close timer, leaving its caches warm. // `recordSorobanUtilization` indicates whether to record utilization of // Soroban resources in transaction set, this should only be necessary for // the benchmark runs. @@ -48,6 +49,30 @@ class ApplyLoad uint32_t getTotalHotArchiveEntries() const; private: + bool + measuresTxSetValidation() const + { + return mTimingPhases == + ApplyLoadTimingPhases::TX_SET_VALIDATION_AND_APPLY; + } + + // Simulates a non-leader receiving a tx set over the wire, then closes it + // through local consensus. Tx-set creation is outside the measured span. + void + closeLedgerViaConsensus(std::vector const& txs, + bool recordUtilization); + void closeBenchmarkLedger( + std::vector const& txs, + bool recordUtilization); + void recordSorobanUtilization(ApplicableTxSetFrame const& txSet, + uint32_t ledgerVersion); + + // Logs the distribution of per-ledger samples for one timing phase. + // Passing "close time" preserves the historical output format. + static void logPhaseStats(std::string const& label, + std::vector const& samplesMs); + void logConfiguredPhaseStats() const; + uint32_t calculateRequiredHotArchiveEntries(Config const& cfg); void setup(); @@ -140,6 +165,20 @@ class ApplyLoad ApplyLoadMode mMode; ApplyLoadModelTx mModelTx; ApplyLoadTxProfile mLimitsBasedTxProfile; + ApplyLoadTimingPhases mTimingPhases; + + // A phase is a timed portion of one ledger's receiver-side processing. We + // track cold tx-set validation, ledger close/application, and end-to-end + // time from wire decoding through the completed ledger close. Ledger close + // includes apply-side prepareForApply. + std::vector mPhaseValidationMs; + std::vector mPhaseLedgerCloseMs; + std::vector mPhaseEndToEndMs; + + // Signature cache totals and the transaction count used to interpret them. + uint64_t mLedgerSigCacheHits = 0; + uint64_t mLedgerSigCacheMisses = 0; + uint64_t mBenchmarkTxCount = 0; uint32_t mTotalHotArchiveEntries;