Track latencies of certain code blocks, and log if they take too long

src/ripple/app/consensus/RCLValidations.cpp

@@ -25,6 +25,7 @@
 #include <ripple/app/misc/NetworkOPs.h>
 #include <ripple/app/misc/ValidatorList.h>
 #include <ripple/basics/Log.h>
+#include <ripple/basics/PerfLog.h>
 #include <ripple/basics/StringUtilities.h>
 #include <ripple/basics/chrono.h>
 #include <ripple/consensus/LedgerTiming.h>
@@ -126,7 +127,13 @@ RCLValidationsAdaptor::now() const
 std::optional<RCLValidatedLedger>
 RCLValidationsAdaptor::acquire(LedgerHash const& hash)
 {
-    auto ledger = app_.getLedgerMaster().getLedgerByHash(hash);
+    using namespace std::chrono_literals;
+    auto ledger = perf::measureDurationAndLog(
+        [&]() { return app_.getLedgerMaster().getLedgerByHash(hash); },
+        "getLedgerByHash",
+        10ms,
+        j_);
+
     if (!ledger)
     {
         JLOG(j_.debug())

src/ripple/app/ledger/impl/InboundLedgers.cpp

@@ -23,6 +23,7 @@
 #include <ripple/app/misc/NetworkOPs.h>
 #include <ripple/basics/DecayingSample.h>
 #include <ripple/basics/Log.h>
+#include <ripple/basics/PerfLog.h>
 #include <ripple/beast/container/aged_map.h>
 #include <ripple/beast/core/LexicalCast.h>
 #include <ripple/core/JobQueue.h>
@@ -69,76 +70,83 @@ class InboundLedgersImp : public InboundLedgers
         std::uint32_t seq,
         InboundLedger::Reason reason) override
     {
-        assert(hash.isNonZero());
-        assert(
-            reason != InboundLedger::Reason::SHARD ||
-            (seq != 0 && app_.getShardStore()));
-
-        // probably not the right rule
-        if (app_.getOPs().isNeedNetworkLedger() &&
-            (reason != InboundLedger::Reason::GENERIC) &&
-            (reason != InboundLedger::Reason::CONSENSUS))
-            return {};
-
-        bool isNew = true;
-        std::shared_ptr<InboundLedger> inbound;
-        {
-            ScopedLockType sl(mLock);
-            if (stopping_)
-            {
+        auto doAcquire = [&, seq, reason]() -> std::shared_ptr<Ledger const> {
+            assert(hash.isNonZero());
+            assert(
+                reason != InboundLedger::Reason::SHARD ||
+                (seq != 0 && app_.getShardStore()));
+
+            // probably not the right rule
+            if (app_.getOPs().isNeedNetworkLedger() &&
+                (reason != InboundLedger::Reason::GENERIC) &&
+                (reason != InboundLedger::Reason::CONSENSUS))
                 return {};
-            }
 
-            auto it = mLedgers.find(hash);
-            if (it != mLedgers.end())
+            bool isNew = true;
+            std::shared_ptr<InboundLedger> inbound;
             {
-                isNew = false;
-                inbound = it->second;
-            }
-            else
-            {
-                inbound = std::make_shared<InboundLedger>(
-                    app_,
-                    hash,
-                    seq,
-                    reason,
-                    std::ref(m_clock),
-                    mPeerSetBuilder->build());
-                mLedgers.emplace(hash, inbound);
-                inbound->init(sl);
-                ++mCounter;
+                ScopedLockType sl(mLock);
+                if (stopping_)
+                {
+                    return {};
+                }
+
+                auto it = mLedgers.find(hash);
+                if (it != mLedgers.end())
+                {
+                    isNew = false;
+                    inbound = it->second;
+                }
+                else
+                {
+                    inbound = std::make_shared<InboundLedger>(
+                        app_,
+                        hash,
+                        seq,
+                        reason,
+                        std::ref(m_clock),
+                        mPeerSetBuilder->build());
+                    mLedgers.emplace(hash, inbound);
+                    inbound->init(sl);
+                    ++mCounter;
+                }
             }
-        }
 
-        if (inbound->isFailed())
-            return {};
+            if (inbound->isFailed())
+                return {};
 
-        if (!isNew)
-            inbound->update(seq);
+            if (!isNew)
+                inbound->update(seq);
 
-        if (!inbound->isComplete())
-            return {};
+            if (!inbound->isComplete())
+                return {};
 
-        if (reason == InboundLedger::Reason::HISTORY)
-        {
-            if (inbound->getLedger()->stateMap().family().isShardBacked())
-                app_.getNodeStore().storeLedger(inbound->getLedger());
-        }
-        else if (reason == InboundLedger::Reason::SHARD)
-        {
-            auto shardStore = app_.getShardStore();
-            if (!shardStore)
+            if (reason == InboundLedger::Reason::HISTORY)
             {
-                JLOG(j_.error())
-                    << "Acquiring shard with no shard store available";
-                return {};
+                if (inbound->getLedger()->stateMap().family().isShardBacked())
+                    app_.getNodeStore().storeLedger(inbound->getLedger());
             }
-            if (inbound->getLedger()->stateMap().family().isShardBacked())
-                shardStore->setStored(inbound->getLedger());
-            else
-                shardStore->storeLedger(inbound->getLedger());
-        }
-        return inbound->getLedger();
+            else if (reason == InboundLedger::Reason::SHARD)
+            {
+                auto shardStore = app_.getShardStore();
+                if (!shardStore)
+                {
+                    JLOG(j_.error())
+                        << "Acquiring shard with no shard store available";
+                    return {};
+                }
+                if (inbound->getLedger()->stateMap().family().isShardBacked())
+                    shardStore->setStored(inbound->getLedger());
+                else
+                    shardStore->storeLedger(inbound->getLedger());
+            }
+            return inbound->getLedger();
+        };
+        using namespace std::chrono_literals;
+        std::shared_ptr<Ledger const> ledger = perf::measureDurationAndLog(
+            doAcquire, "InboundLedgersImp::acquire", 500ms, j_);
+
+        return ledger;
     }
 
     std::shared_ptr<InboundLedger>

src/ripple/app/main/Application.cpp

@@ -942,7 +942,7 @@ class ApplicationImp : public Application, public BasicApp
             auto setup = setup_DatabaseCon(*config_, m_journal);
             setup.useGlobalPragma = false;
 
-            mWalletDB = makeWalletDB(setup);
+            mWalletDB = makeWalletDB(setup, m_journal);
         }
         catch (std::exception const& e)
         {

src/ripple/app/main/Main.cpp

@@ -595,7 +595,7 @@ run(int argc, char** argv)
         try
         {
             auto setup = setup_DatabaseCon(*config);
-            if (!doVacuumDB(setup))
+            if (!doVacuumDB(setup, config->journal()))
                 return -1;
         }
         catch (std::exception const& e)

src/ripple/app/rdb/Download.h

@@ -36,13 +36,15 @@ namespace ripple {
  *        download process or continues an existing one.
  * @param setup Path to the database and other opening parameters.
  * @param path Path of the new file to download.
+ * @param j Journal.
  * @return Pair containing a unique pointer to the database and the amount of
  *         bytes already downloaded if a download is being continued.
  */
 std::pair<std::unique_ptr<DatabaseCon>, std::optional<std::uint64_t>>
 openDatabaseBodyDb(
     DatabaseCon::Setup const& setup,
-    boost::filesystem::path const& path);
+    boost::filesystem::path const& path,
+    beast::Journal j);
 
 /**
  * @brief databaseBodyDoPut Saves a new fragment of a downloaded file.

src/ripple/app/rdb/ShardArchive.h

@@ -30,10 +30,14 @@ namespace ripple {
  *        descriptor.
  * @param dir Path to the database to open.
  * @param dbName Name of the database.
+ * @param j Journal.
  * @return Unique pointer to the opened database.
  */
 std::unique_ptr<DatabaseCon>
-makeArchiveDB(boost::filesystem::path const& dir, std::string const& dbName);
+makeArchiveDB(
+    boost::filesystem::path const& dir,
+    std::string const& dbName,
+    beast::Journal j);
 
 /**
  * @brief readArchiveDB Reads entries from the shard archive database and

src/ripple/app/rdb/UnitaryShard.h

@@ -39,28 +39,32 @@ struct DatabasePair
  *        and returns their descriptors.
  * @param config Config object.
  * @param setup Path to the databases and other opening parameters.
+ * @param j Journal.
  * @return Pair of unique pointers to the opened ledger and transaction
  *         databases.
  */
 DatabasePair
 makeShardCompleteLedgerDBs(
     Config const& config,
-    DatabaseCon::Setup const& setup);
+    DatabaseCon::Setup const& setup,
+    beast::Journal j);
 
 /**
  * @brief makeShardIncompleteLedgerDBs Opens shard databases for partially
  *        downloaded or unverified shards and returns their descriptors.
  * @param config Config object.
  * @param setup Path to the databases and other opening parameters.
  * @param checkpointerSetup Checkpointer parameters.
+ * @param j Journal.
  * @return Pair of unique pointers to the opened ledger and transaction
  *         databases.
  */
 DatabasePair
 makeShardIncompleteLedgerDBs(
     Config const& config,
     DatabaseCon::Setup const& setup,
-    DatabaseCon::CheckpointerSetup const& checkpointerSetup);
+    DatabaseCon::CheckpointerSetup const& checkpointerSetup,
+    beast::Journal j);
 
 /**
  * @brief updateLedgerDBs Saves the given ledger to shard databases.
@@ -86,12 +90,14 @@ updateLedgerDBs(
  *        descriptor.
  * @param setup Path to the database and other opening parameters.
  * @param checkpointerSetup Checkpointer parameters.
+ * @param j Journal.
  * @return Unique pointer to the opened database.
  */
 std::unique_ptr<DatabaseCon>
 makeAcquireDB(
     DatabaseCon::Setup const& setup,
-    DatabaseCon::CheckpointerSetup const& checkpointerSetup);
+    DatabaseCon::CheckpointerSetup const& checkpointerSetup,
+    beast::Journal j);
 
 /**
  * @brief insertAcquireDBIndex Adds a new shard index to the shard acquire

src/ripple/app/rdb/Vacuum.h

@@ -27,10 +27,11 @@ namespace ripple {
 /**
  * @brief doVacuumDB Creates, initialises, and performs cleanup on a database.
  * @param setup Path to the database and other opening parameters.
+ * @param j Journal.
  * @return True if the vacuum process completed successfully.
  */
 bool
-doVacuumDB(DatabaseCon::Setup const& setup);
+doVacuumDB(DatabaseCon::Setup const& setup, beast::Journal j);
 
 }  // namespace ripple
 

src/ripple/app/rdb/Wallet.h

@@ -32,19 +32,24 @@ namespace ripple {
 /**
  * @brief makeWalletDB Opens the wallet database and returns it.
  * @param setup Path to the database and other opening parameters.
+ * @param j Journal.
  * @return Unique pointer to the database descriptor.
  */
 std::unique_ptr<DatabaseCon>
-makeWalletDB(DatabaseCon::Setup const& setup);
+makeWalletDB(DatabaseCon::Setup const& setup, beast::Journal j);
 
 /**
  * @brief makeTestWalletDB Opens a test wallet database with an arbitrary name.
  * @param setup Path to the database and other opening parameters.
  * @param dbname Name of the database.
+ * @param j Journal.
  * @return Unique pointer to the database descriptor.
  */
 std::unique_ptr<DatabaseCon>
-makeTestWalletDB(DatabaseCon::Setup const& setup, std::string const& dbname);
+makeTestWalletDB(
+    DatabaseCon::Setup const& setup,
+    std::string const& dbname,
+    beast::Journal j);
 
 /**
  * @brief getManifests Loads a manifest from the wallet database and stores it

src/ripple/app/rdb/backend/detail/Node.h

@@ -47,14 +47,16 @@ struct DatabasePairValid
  * @param config Config object.
  * @param setup Path to database and opening parameters.
  * @param checkpointerSetup Database checkpointer setup.
+ * @param j Journal.
  * @return Struct DatabasePairValid which contain unique pointers to ledger
  *         and transaction databases and flag if opening was successfull.
  */
 DatabasePairValid
 makeLedgerDBs(
     Config const& config,
     DatabaseCon::Setup const& setup,
-    DatabaseCon::CheckpointerSetup const& checkpointerSetup);
+    DatabaseCon::CheckpointerSetup const& checkpointerSetup,
+    beast::Journal j);
 
 /**
  * @brief getMinLedgerSeq Returns minimum ledger sequence in given table.

src/ripple/app/rdb/backend/detail/Shard.h

@@ -37,14 +37,16 @@ namespace detail {
  * @param config Config object.
  * @param setup Path to database and opening parameters.
  * @param checkpointerSetup Database checkpointer setup.
+ * @param j Journal.
  * @return Struct DatabasePair which contains unique pointers to the ledger
  *         and transaction databases.
  */
 DatabasePair
 makeMetaDBs(
     Config const& config,
     DatabaseCon::Setup const& setup,
-    DatabaseCon::CheckpointerSetup const& checkpointerSetup);
+    DatabaseCon::CheckpointerSetup const& checkpointerSetup,
+    beast::Journal j);
 
 /**
  * @brief saveLedgerMeta Stores (transaction ID -> shard index) and

src/ripple/app/rdb/backend/detail/impl/Node.cpp

@@ -67,11 +67,12 @@ DatabasePairValid
 makeLedgerDBs(
     Config const& config,
     DatabaseCon::Setup const& setup,
-    DatabaseCon::CheckpointerSetup const& checkpointerSetup)
+    DatabaseCon::CheckpointerSetup const& checkpointerSetup,
+    beast::Journal j)
 {
     // ledger database
     auto lgr{std::make_unique<DatabaseCon>(
-        setup, LgrDBName, LgrDBPragma, LgrDBInit, checkpointerSetup)};
+        setup, LgrDBName, LgrDBPragma, LgrDBInit, checkpointerSetup, j)};
     lgr->getSession() << boost::str(
         boost::format("PRAGMA cache_size=-%d;") %
         kilobytes(config.getValueFor(SizedItem::lgrDBCache)));
@@ -80,7 +81,7 @@ makeLedgerDBs(
     {
         // transaction database
         auto tx{std::make_unique<DatabaseCon>(
-            setup, TxDBName, TxDBPragma, TxDBInit, checkpointerSetup)};
+            setup, TxDBName, TxDBPragma, TxDBInit, checkpointerSetup, j)};
         tx->getSession() << boost::str(
             boost::format("PRAGMA cache_size=-%d;") %
             kilobytes(config.getValueFor(SizedItem::txnDBCache)));