Add module cache metrics and another test that checks costs.

stellar · Jan 31, 2025 · 88f6387 · 88f6387
1 parent cd8cda3
commit 88f6387
Show file tree

Hide file tree

Showing 8 changed files with 128 additions and 11 deletions.
diff --git a/docs/metrics.md b/docs/metrics.md
@@ -238,4 +238,8 @@ soroban.config.ledger-max-read-entry         | counter   | soroban config settin
 soroban.config.ledger-max-read-ledger-byte   | counter   | soroban config setting `ledger_max_read_bytes`
 soroban.config.ledger-max-write-entry        | counter   | soroban config setting `ledger_max_write_ledger_entries`
 soroban.config.ledger-max-write-ledger-byte  | counter   | soroban config setting `ledger_max_write_bytes`
-soroban.config.bucket-list-target-size-byte  | counter   | soroban config setting `bucket_list_target_size_bytes`
+soroban.config.bucket-list-target-size-byte  | counter   | soroban config setting `bucket_list_target_size_bytes`
+soroban.module-cache.num-entries             | counter   | current number of entries in module cache
+soroban.module-cache.compilation-time        | timer     | times each contract compilation when adding to module cache
+soroban.module-cache.rebuild-time            | timer     | times each rebuild of module cache (including all compilations)
+soroban.module-cache.rebuild-bytes           | counter   | bytes of WASM bytecode compiled in last rebuild of module cache
diff --git a/src/ledger/LedgerManagerImpl.cpp b/src/ledger/LedgerManagerImpl.cpp
@@ -616,7 +616,12 @@ LedgerManagerImpl::finishAnyPendingCompilation()
     if (mCompiler)
     {
         auto newCache = mCompiler->wait();
-        mLastBytesCompiled = mCompiler->getBytesCompiled();
+        mSorobanMetrics.mModuleCacheRebuildBytes.set_count(
+            (int64)mCompiler->getBytesCompiled());
+        mSorobanMetrics.mModuleCacheNumEntries.set_count(
+            (int64)mCompiler->getContractsCompiled());
+        mSorobanMetrics.mModuleCacheRebuildTime.Update(
+            mCompiler->getCompileTime());
         mModuleCache.swap(newCache);
         mCompiler.reset();
         mApp.getAppConnector().setModuleCache(mModuleCache->shallow_clone());
@@ -696,7 +701,8 @@ LedgerManagerImpl::maybeRebuildModuleCache(uint32_t minLedgerVersion)
         auto const& param = memParams[(size_t)stellar::VmInstantiation];
         linearTerm = param.linearTerm;
     }
-    uint64_t limit = 2 * mLastBytesCompiled * linearTerm / scale;
+    auto lastBytesCompiled = mSorobanMetrics.mModuleCacheRebuildBytes.count();
+    uint64_t limit = 2 * lastBytesCompiled * linearTerm / scale;
     if (mModuleCache->get_mem_bytes_consumed() > limit)
     {
         CLOG_DEBUG(Ledger,
@@ -2067,6 +2073,7 @@ LedgerManagerImpl::evictFromModuleCache(uint32_t ledgerVersion,
             CLOG_DEBUG(Ledger, "evicting {} from module cache", binToHex(hash));
             ::rust::Slice<uint8_t const> slice{hash.data(), hash.size()};
             mModuleCache->evict_contract_code(slice);
+            mSorobanMetrics.mModuleCacheNumEntries.dec();
         }
     }
 }
@@ -2084,8 +2091,14 @@ LedgerManagerImpl::addAnyContractsToModuleCache(
                 if (v >= ledgerVersion)
                 {
                     auto const& wasm = e.data.contractCode().code;
+                    CLOG_DEBUG(Ledger,
+                               "compiling wasm {} for protocol {} module cache",
+                               binToHex(sha256(wasm)), v);
                     auto slice =
                         rust::Slice<const uint8_t>(wasm.data(), wasm.size());
+                    mSorobanMetrics.mModuleCacheNumEntries.inc();
+                    auto timer =
+                        mSorobanMetrics.mModuleCompilationTime.TimeScope();
                     mModuleCache->compile(v, slice);
                 }
             }

diff --git a/src/ledger/LedgerManagerImpl.h b/src/ledger/LedgerManagerImpl.h
@@ -156,7 +156,6 @@ class LedgerManagerImpl : public LedgerManager
 
     // The current reusable / inter-ledger soroban module cache.
     ::rust::Box<rust_bridge::SorobanModuleCache> mModuleCache;
-    size_t mLastBytesCompiled{1};
     // Manager object that (re)builds the module cache in background threads.
     // Only non-nullptr when there's a background compilation in progress.
     std::unique_ptr<SharedModuleCacheCompiler> mCompiler;

diff --git a/src/ledger/SharedModuleCacheCompiler.cpp b/src/ledger/SharedModuleCacheCompiler.cpp
@@ -204,4 +204,18 @@ SharedModuleCacheCompiler::getBytesCompiled()
     return mBytesCompiled;
 }
 
+std::chrono::nanoseconds
+SharedModuleCacheCompiler::getCompileTime()
+{
+    std::unique_lock lock(mMutex);
+    return mTotalCompileTime;
+}
+
+size_t
+SharedModuleCacheCompiler::getContractsCompiled()
+{
+    std::unique_lock lock(mMutex);
+    return mContractsCompiled;
+}
+
 }
diff --git a/src/ledger/SharedModuleCacheCompiler.h b/src/ledger/SharedModuleCacheCompiler.h
@@ -45,7 +45,7 @@ class SharedModuleCacheCompiler : NonMovableOrCopyable
     std::condition_variable mHaveContracts;
 
     std::chrono::steady_clock::time_point mStarted;
-    std::chrono::microseconds mTotalCompileTime{0};
+    std::chrono::nanoseconds mTotalCompileTime{0};
 
     void setFinishedLoading(size_t nContracts);
     bool isFinishedCompiling(std::unique_lock<std::mutex>& lock);
@@ -62,5 +62,7 @@ class SharedModuleCacheCompiler : NonMovableOrCopyable
     void start();
     ::rust::Box<stellar::rust_bridge::SorobanModuleCache> wait();
     size_t getBytesCompiled();
+    std::chrono::nanoseconds getCompileTime();
+    size_t getContractsCompiled();
 };
 }
diff --git a/src/ledger/SorobanMetrics.cpp b/src/ledger/SorobanMetrics.cpp
@@ -20,6 +20,11 @@ SorobanMetrics::SorobanMetrics(medida::MetricsRegistry& metrics)
           metrics.NewHistogram({"soroban", "ledger", "write-entry"}))
     , mLedgerWriteLedgerByte(
           metrics.NewHistogram({"soroban", "ledger", "write-ledger-byte"}))
+    , mLedgerHostFnCpuInsnsRatio(metrics.NewHistogram(
+          {"soroban", "host-fn-op", "ledger-cpu-insns-ratio"}))
+    , mLedgerHostFnCpuInsnsRatioExclVm(metrics.NewHistogram(
+          {"soroban", "host-fn-op", "ledger-cpu-insns-ratio-excl-vm"}))
+
     /* tx-wide metrics */
     , mTxSizeByte(metrics.NewHistogram({"soroban", "tx", "size-byte"}))
     /* InvokeHostFunctionOp metrics */
@@ -62,6 +67,8 @@ SorobanMetrics::SorobanMetrics(medida::MetricsRegistry& metrics)
     , mHostFnOpInvokeTimeFsecsCpuInsnRatioExclVm(
           metrics.NewHistogram({"soroban", "host-fn-op",
                                 "invoke-time-fsecs-cpu-insn-ratio-excl-vm"}))
+    , mHostFnOpDeclaredInsnsUsageRatio(metrics.NewHistogram(
+          {"soroban", "host-fn-op", "declared-cpu-insns-usage-ratio"}))
     , mHostFnOpMaxRwKeyByte(metrics.NewMeter(
           {"soroban", "host-fn-op", "max-rw-key-byte"}, "byte"))
     , mHostFnOpMaxRwDataByte(metrics.NewMeter(
@@ -128,12 +135,17 @@ SorobanMetrics::SorobanMetrics(medida::MetricsRegistry& metrics)
           {"soroban", "config", "bucket-list-target-size-byte"}))
     , mConfigFeeWrite1KB(
           metrics.NewCounter({"soroban", "config", "fee-write-1kb"}))
-    , mLedgerHostFnCpuInsnsRatio(metrics.NewHistogram(
-          {"soroban", "host-fn-op", "ledger-cpu-insns-ratio"}))
-    , mLedgerHostFnCpuInsnsRatioExclVm(metrics.NewHistogram(
-          {"soroban", "host-fn-op", "ledger-cpu-insns-ratio-excl-vm"}))
-    , mHostFnOpDeclaredInsnsUsageRatio(metrics.NewHistogram(
-          {"soroban", "host-fn-op", "declared-cpu-insns-usage-ratio"}))
+
+    /* Module cache related metrics */
+    , mModuleCacheNumEntries(
+          metrics.NewCounter({"soroban", "module-cache", "num-entries"}))
+    , mModuleCompilationTime(
+          metrics.NewTimer({"soroban", "module-cache", "compilation-time"}))
+    , mModuleCacheRebuildTime(
+          metrics.NewTimer({"soroban", "module-cache", "rebuild-time"}))
+    , mModuleCacheRebuildBytes(
+          metrics.NewCounter({"soroban", "module-cache", "rebuild-bytes"}))
+
 {
 }
 

diff --git a/src/ledger/SorobanMetrics.h b/src/ledger/SorobanMetrics.h
@@ -111,6 +111,12 @@ class SorobanMetrics
     medida::Counter& mConfigBucketListTargetSizeByte;
     medida::Counter& mConfigFeeWrite1KB;
 
+    // Module cache related metrics
+    medida::Counter& mModuleCacheNumEntries;
+    medida::Timer& mModuleCompilationTime;
+    medida::Timer& mModuleCacheRebuildTime;
+    medida::Counter& mModuleCacheRebuildBytes;
+
     SorobanMetrics(medida::MetricsRegistry& metrics);
 
     void accumulateModelledCpuInsns(uint64_t insnsCount,

diff --git a/src/transactions/test/InvokeHostFunctionTests.cpp b/src/transactions/test/InvokeHostFunctionTests.cpp
@@ -4740,3 +4740,70 @@ TEST_CASE("contract constructor support", "[tx][soroban]")
         REQUIRE(invocation.getReturnValue().u32() == 303);
     }
 }
+
+TEST_CASE("Module cache across protocol versions", "[tx][soroban]")
+{
+
+    if (protocolVersionIsBefore(Config::CURRENT_LEDGER_PROTOCOL_VERSION,
+                                REUSABLE_SOROBAN_MODULE_CACHE_PROTOCOL_VERSION))
+    {
+        LOG_INFO(DEFAULT_LOG, "Skipping test, compiled for protocol version "
+                              "without reusable module cache");
+        return;
+    }
+
+    VirtualClock clock;
+    auto cfg = getTestConfig(0);
+    cfg.USE_CONFIG_FOR_GENESIS = false;
+
+    auto app = createTestApplication(clock, cfg);
+
+    // Start in protocol 22
+    auto upgradeTo22 = LedgerUpgrade{LEDGER_UPGRADE_VERSION};
+    upgradeTo22.newLedgerVersion() =
+        static_cast<int>(REUSABLE_SOROBAN_MODULE_CACHE_PROTOCOL_VERSION) - 1;
+    executeUpgrade(*app, upgradeTo22);
+
+    // Deploy and invoke contract in protocol 22
+    SorobanTest test(app);
+    auto const& addContract =
+        test.deployWasmContract(rust_bridge::get_test_wasm_add_i32());
+
+    auto invoke = [&](int64_t instructions) -> bool {
+        auto fnName = "add";
+        auto sc7 = makeI32(7);
+        auto sc16 = makeI32(16);
+        auto spec = SorobanInvocationSpec()
+                        .setInstructions(instructions)
+                        .setReadBytes(2'000)
+                        .setInclusionFee(12345)
+                        .setNonRefundableResourceFee(33'000)
+                        .setRefundableResourceFee(100'000);
+        auto invocation =
+            addContract.prepareInvocation(fnName, {sc7, sc16}, spec);
+        auto tx = invocation.createTx();
+        auto res = test.invokeTx(tx);
+        return isSuccessResult(res);
+    };
+
+    // In the pre-module-cache-reuse protocol, the contract needs 900k insns to
+    // run, 800k is not enough.
+    REQUIRE(!invoke(800'000));
+    REQUIRE(invoke(900'000));
+
+    // The upload should have triggered a single compilation for the p23 module
+    // cache, which _exists_ in this version of stellar-core, and needs to be
+    // populated on each upload, is just not yet active.
+    REQUIRE(app->getLedgerManager()
+                .getSorobanMetrics()
+                .mModuleCacheNumEntries.count() == 1);
+
+    // Upgrade to protocol 23 (with the reusable module cache)
+    auto upgradeTo23 = LedgerUpgrade{LEDGER_UPGRADE_VERSION};
+    upgradeTo23.newLedgerVersion() =
+        static_cast<int>(REUSABLE_SOROBAN_MODULE_CACHE_PROTOCOL_VERSION);
+    executeUpgrade(*app, upgradeTo23);
+
+    // We can now run the same contract with 700k instructions
+    REQUIRE(invoke(700'000));
+}