From 01af7062281fd847b5275b9b973807af5838ca19 Mon Sep 17 00:00:00 2001 From: Steve Atherton Date: Tue, 20 Jul 2021 21:23:50 -0700 Subject: [PATCH 1/4] Refactor metric logging to be shorter and changed text format to be more condensed. --- fdbserver/IPager.h | 20 ++--- fdbserver/VersionedBTree.actor.cpp | 117 +++++++++++++---------------- 2 files changed, 61 insertions(+), 76 deletions(-) diff --git a/fdbserver/IPager.h b/fdbserver/IPager.h index 22ee4b94ca..922df85ce3 100644 --- a/fdbserver/IPager.h +++ b/fdbserver/IPager.h @@ -42,31 +42,31 @@ typedef uint32_t QueueID; // Pager Events enum class PagerEvents { CacheLookup = 0, CacheHit, CacheMiss, PageWrite, MAXEVENTS }; -static const std::string PagerEventsStrings[] = { "Lookup", "Hit", "Miss", "Write", "Unknown" }; +static const char* const PagerEventsStrings[] = { "Lookup", "Hit", "Miss", "Write", "Unknown" }; // Reasons for page level events. enum class PagerEventReasons { PointRead = 0, RangeRead, RangePrefetch, Commit, LazyClear, MetaData, MAXEVENTREASONS }; -static const std::string PagerEventReasonsStrings[] = { "Get", "GetR", "GetRPF", "Commit", "LazyClr", "Meta", "Unknown" }; +static const char* const PagerEventReasonsStrings[] = { + "Get", "GetR", "GetRPF", "Commit", "LazyClr", "Meta", "Unknown" +}; static const int nonBtreeLevel = 0; -static const std::pair possibleEventReasonPairs[] = { +static const std::vector> possibleEventReasonPairs = { + { PagerEvents::CacheLookup, PagerEventReasons::Commit }, { PagerEvents::CacheLookup, PagerEventReasons::PointRead }, { PagerEvents::CacheLookup, PagerEventReasons::RangeRead }, { PagerEvents::CacheLookup, PagerEventReasons::LazyClear }, - { PagerEvents::CacheLookup, PagerEventReasons::MetaData }, + { PagerEvents::CacheHit, PagerEventReasons::Commit }, { PagerEvents::CacheHit, PagerEventReasons::PointRead }, { PagerEvents::CacheHit, PagerEventReasons::RangeRead }, { PagerEvents::CacheHit, PagerEventReasons::LazyClear }, - { PagerEvents::CacheHit, PagerEventReasons::MetaData }, - { PagerEvents::CacheHit, PagerEventReasons::Commit }, + { PagerEvents::CacheMiss, PagerEventReasons::Commit }, { PagerEvents::CacheMiss, PagerEventReasons::PointRead }, { PagerEvents::CacheMiss, PagerEventReasons::RangeRead }, { PagerEvents::CacheMiss, PagerEventReasons::LazyClear }, - { PagerEvents::CacheMiss, PagerEventReasons::MetaData }, - { PagerEvents::CacheMiss, PagerEventReasons::Commit }, - { PagerEvents::PageWrite, PagerEventReasons::MetaData }, + { PagerEvents::PageWrite, PagerEventReasons::Commit }, { PagerEvents::PageWrite, PagerEventReasons::LazyClear }, }; -static const std::pair L0PossibleEventReasonPairs[] = { +static const std::vector> L0PossibleEventReasonPairs = { { PagerEvents::CacheLookup, PagerEventReasons::RangePrefetch }, { PagerEvents::CacheLookup, PagerEventReasons::MetaData }, { PagerEvents::CacheHit, PagerEventReasons::RangePrefetch }, diff --git a/fdbserver/VersionedBTree.actor.cpp b/fdbserver/VersionedBTree.actor.cpp index d0fdd4e283..2882a47198 100644 --- a/fdbserver/VersionedBTree.actor.cpp +++ b/fdbserver/VersionedBTree.actor.cpp @@ -1461,71 +1461,51 @@ struct RedwoodMetrics { } } } + void addEventReason(PagerEvents event, PagerEventReasons reason) { eventReasons[(size_t)event][(size_t)reason] += 1; } - const unsigned int& getEventReason(PagerEvents event, PagerEventReasons reason) { + + unsigned int getEventReason(PagerEvents event, PagerEventReasons reason) const { return eventReasons[(size_t)event][(size_t)reason]; } - std::string ouputSummary(int currLevel) { - std::string result = ""; - PagerEvents prevEvent = PagerEvents::MAXEVENTS; - if (currLevel == 0) { - for (const auto& ER : L0PossibleEventReasonPairs) { - if (prevEvent != ER.first) { - result += "\n"; - result += PagerEventsStrings[(size_t)ER.first]; - result += "\n\t"; - prevEvent = ER.first; - } - std::string num = std::to_string(eventReasons[(size_t)ER.first][(size_t)ER.second]); - result += PagerEventReasonsStrings[(size_t)ER.second]; - result.append(16 - PagerEventReasonsStrings[(size_t)ER.second].length(), ' '); - result.append(8 - num.length(), ' '); - result += num; - result.append(13, ' '); - } - } else { - for (const auto& ER : possibleEventReasonPairs) { - if (prevEvent != ER.first) { - result += "\n"; - result += PagerEventsStrings[(size_t)ER.first]; - result += "\n\t"; - prevEvent = ER.first; - } - std::string num = std::to_string(eventReasons[(size_t)ER.first][(size_t)ER.second]); - result += PagerEventReasonsStrings[(size_t)ER.second]; - result.append(16 - PagerEventReasonsStrings[(size_t)ER.second].length(), ' '); - result.append(8 - num.length(), ' '); - result += num; - result.append(13, ' '); + std::string toString(int level, double elapsed) const { + std::string result; + + const auto& pairs = (level == 0 ? L0PossibleEventReasonPairs : possibleEventReasonPairs); + PagerEvents prevEvent = pairs.front().first; + std::string lineStart = (level == 0) ? "" : "\t"; + + for (const auto& p : pairs) { + if (p.first != prevEvent) { + result += "\n"; + result += lineStart; } + + std::string name = + format("%s%s", PagerEventsStrings[(int)p.first], PagerEventReasonsStrings[(int)p.second]); + int count = getEventReason(p.first, p.second); + result += format("%-15s %8u %8u/s ", name.c_str(), count, int(count / elapsed)); + + prevEvent = p.first; } + return result; } - void reportTrace(TraceEvent* t, int h) { - if (h == 0) { - for (const auto& ER : L0PossibleEventReasonPairs) { - t->detail( - format("L%d%s", - h, - (PagerEventsStrings[(size_t)ER.first] + PagerEventReasonsStrings[(size_t)ER.second]) - .c_str()), - eventReasons[(size_t)ER.first][(size_t)ER.second]); - } - } else { - for (const auto& ER : possibleEventReasonPairs) { - t->detail( - format("L%d%s", - h, - (PagerEventsStrings[(size_t)ER.first] + PagerEventReasonsStrings[(size_t)ER.second]) - .c_str()), - eventReasons[(size_t)ER.first][(size_t)ER.second]); - } + + void toTraceEvent(TraceEvent* t, int level) const { + const auto& pairs = (level == 0 ? L0PossibleEventReasonPairs : possibleEventReasonPairs); + for (const auto& p : pairs) { + std::string name = + format(level == 0 ? "" : "L%d", level) + + format("%s%s", PagerEventsStrings[(int)p.first], PagerEventReasonsStrings[(int)p.second]); + int count = getEventReason(p.first, p.second); + t->detail(std::move(name), count); } } }; + // Metrics by level struct Level { struct Counters { @@ -1542,7 +1522,7 @@ struct RedwoodMetrics { unsigned int lazyClearFreeExt; unsigned int forceUpdate; unsigned int detachChild; - EventReasonsArray eventReasons; + EventReasonsArray events; }; Counters metrics; Reference buildFillPctSketch; @@ -1581,7 +1561,7 @@ struct RedwoodMetrics { 0, maxRecordCount); } - metrics.eventReasons.clear(); + metrics.events.clear(); buildFillPctSketch->clear(); modifyFillPctSketch->clear(); buildStoredPctSketch->clear(); @@ -1655,8 +1635,12 @@ struct RedwoodMetrics { } Level& level(unsigned int level) { + // Storage for metrics for out of bound levels, such as if the BTree grows beyond 5 levels, + // which can happen in simulation with tiny page sizes. static Level outOfBound; // Valid levels are from 0 - btreeLevels + // Levels 1 through btreeLevels correspond to BTree node heights + // Level 0 is for operations that are not BTree level specific if (level < 0 || level > btreeLevels) { return outOfBound; } @@ -1702,7 +1686,8 @@ struct RedwoodMetrics { { "", 0 }, { "PagerRemapFree", metric.pagerRemapFree }, { "PagerRemapCopy", metric.pagerRemapCopy }, - { "PagerRemapSkip", metric.pagerRemapSkip } }; + { "PagerRemapSkip", metric.pagerRemapSkip }, + { "", 0 } }; GetHistogramRegistry().logReport(); double elapsed = now() - startTime; @@ -1714,6 +1699,7 @@ struct RedwoodMetrics { e->detail(m.first, m.second); } } + levels[0].metrics.events.toTraceEvent(e, 0); } if (s != nullptr) { @@ -1724,10 +1710,10 @@ struct RedwoodMetrics { *s += format("%-15s %-8u %8" PRId64 "/s ", m.first, m.second, int64_t(m.second / elapsed)); } } - *s += "\n"; + *s += levels[0].metrics.events.toString(0, elapsed); } - for (int i = 0; i < btreeLevels + 1; ++i) { + for (int i = 1; i < btreeLevels + 1; ++i) { auto& metric = levels[i].metrics; std::pair metrics[] = { @@ -1757,7 +1743,7 @@ struct RedwoodMetrics { e->detail(format("L%d%s", i + 1, m.first + (c == '-' ? 1 : 0)), m.second); } } - metric.eventReasons.reportTrace(e, i); + metric.events.toTraceEvent(e, i); } if (s != nullptr) { @@ -1777,8 +1763,7 @@ struct RedwoodMetrics { *s += format("%-15s %8u %8u/s ", name, m.second, rate ? int(m.second / elapsed) : 0); } } - *s += '\n'; - *s += metric.eventReasons.ouputSummary(i); + *s += metric.events.toString(i, elapsed); } } } @@ -2519,7 +2504,7 @@ public: state PriorityMultiLock::Lock lock = wait(self->ioLock.lock(header ? ioMaxPriority : ioMinPriority)); ++g_redwoodMetrics.metric.pagerDiskWrite; - g_redwoodMetrics.level(level).metrics.eventReasons.addEventReason(PagerEvents::PageWrite, reason); + g_redwoodMetrics.level(level).metrics.events.addEventReason(PagerEvents::PageWrite, reason); if (self->memoryOnly) { return Void(); @@ -2795,7 +2780,7 @@ public: bool noHit) override { // Use cached page if present, without triggering a cache hit. // Otherwise, read the page and return it but don't add it to the cache - auto& eventReasons = g_redwoodMetrics.level(level).metrics.eventReasons; + auto& eventReasons = g_redwoodMetrics.level(level).metrics.events; eventReasons.addEventReason(PagerEvents::CacheLookup, reason); if (!cacheable) { debug_printf("DWALPager(%s) op=readUncached %s\n", filename.c_str(), toString(pageID).c_str()); @@ -2953,7 +2938,7 @@ public: Future> readExtent(LogicalPageID pageID) override { debug_printf("DWALPager(%s) op=readExtent %s\n", filename.c_str(), toString(pageID).c_str()); PageCacheEntry* pCacheEntry = extentCache.getIfExists(pageID); - auto& eventReasons = g_redwoodMetrics.level(0).metrics.eventReasons; + auto& eventReasons = g_redwoodMetrics.level(0).metrics.events; if (pCacheEntry != nullptr) { eventReasons.addEventReason(PagerEvents::CacheLookup, PagerEventReasons::MetaData); debug_printf("DWALPager(%s) Cache Entry exists for %s\n", filename.c_str(), toString(pageID).c_str()); @@ -5415,8 +5400,8 @@ private: } debug_printf("readPage() op=readComplete %s @%" PRId64 " \n", toString(id).c_str(), snapshot->getVersion()); - const BTreePage* pTreePage = (const BTreePage*)page->begin(); - auto& metrics = g_redwoodMetrics.level(pTreePage->height).metrics; + const BTreePage* btPage = (const BTreePage*)page->begin(); + auto& metrics = g_redwoodMetrics.level(btPage->height).metrics; metrics.pageRead += 1; metrics.pageReadExt += (id.size() - 1); @@ -6677,7 +6662,7 @@ public: std::string toString() const { std::string r = format("{ptr=%p reason=%s %s ", this, - PagerEventsStrings[(int)reason].c_str(), + PagerEventsStrings[(int)reason], ::toString(pager->getVersion()).c_str()); for (int i = 0; i < path.size(); ++i) { std::string id = ""; From 5ff58ec8244e0cfd5c2e4c31863465203f0e2556 Mon Sep 17 00:00:00 2001 From: Steve Atherton Date: Tue, 20 Jul 2021 22:46:56 -0700 Subject: [PATCH 2/4] Fixed valgrind errors caused by memory lifetime bugs in Histogram usage. Removed usage of unneeded level 0. --- fdbserver/VersionedBTree.actor.cpp | 68 ++++++++++++------------------ 1 file changed, 27 insertions(+), 41 deletions(-) diff --git a/fdbserver/VersionedBTree.actor.cpp b/fdbserver/VersionedBTree.actor.cpp index 2882a47198..5d3cf25928 100644 --- a/fdbserver/VersionedBTree.actor.cpp +++ b/fdbserver/VersionedBTree.actor.cpp @@ -1454,13 +1454,7 @@ struct RedwoodMetrics { unsigned int eventReasons[(size_t)PagerEvents::MAXEVENTS][(size_t)PagerEventReasons::MAXEVENTREASONS]; EventReasonsArray() { clear(); } - void clear() { - for (size_t i = 0; i < (size_t)PagerEvents::MAXEVENTS; i++) { - for (size_t j = 0; j < (size_t)PagerEventReasons::MAXEVENTREASONS; j++) { - eventReasons[i][j] = 0; - } - } - } + void clear() { memset(eventReasons, 0, sizeof(eventReasons)); } void addEventReason(PagerEvents event, PagerEventReasons reason) { eventReasons[(size_t)event][(size_t)reason] += 1; @@ -1534,40 +1528,33 @@ struct RedwoodMetrics { Level() { clear(); } - void clear(int levelCounter = -1) { + void clear(int level = 0) { metrics = {}; - if (!buildFillPctSketch.isValid() || - buildFillPctSketch->name() != ("buildFillPct:" + std::to_string(levelCounter))) { - buildFillPctSketch = Histogram::getHistogram(LiteralStringRef("buildFillPct"), - LiteralStringRef(std::to_string(levelCounter).c_str()), - Histogram::Unit::percentage); - modifyFillPctSketch = Histogram::getHistogram(LiteralStringRef("modifyFillPct"), - LiteralStringRef(std::to_string(levelCounter).c_str()), - Histogram::Unit::percentage); - buildStoredPctSketch = Histogram::getHistogram(LiteralStringRef("buildStoredPct"), - LiteralStringRef(std::to_string(levelCounter).c_str()), - Histogram::Unit::percentage); - modifyStoredPctSketch = Histogram::getHistogram(LiteralStringRef("modifyStoredPct"), - LiteralStringRef(std::to_string(levelCounter).c_str()), - Histogram::Unit::percentage); - buildItemCountSketch = Histogram::getHistogram(LiteralStringRef("buildItemCount"), - LiteralStringRef(std::to_string(levelCounter).c_str()), - Histogram::Unit::count, - 0, - maxRecordCount); - modifyItemCountSketch = Histogram::getHistogram(LiteralStringRef("modifyItemCount"), - LiteralStringRef(std::to_string(levelCounter).c_str()), - Histogram::Unit::count, - 0, - maxRecordCount); + + if (level > 0) { + if (!buildFillPctSketch) { + std::string levelString = format("L%d", level); + buildFillPctSketch = Histogram::getHistogram( + LiteralStringRef("buildFillPct"), levelString, Histogram::Unit::percentage); + modifyFillPctSketch = Histogram::getHistogram( + LiteralStringRef("modifyFillPct"), levelString, Histogram::Unit::percentage); + buildStoredPctSketch = Histogram::getHistogram( + LiteralStringRef("buildStoredPct"), levelString, Histogram::Unit::percentage); + modifyStoredPctSketch = Histogram::getHistogram( + LiteralStringRef("modifyStoredPct"), levelString, Histogram::Unit::percentage); + buildItemCountSketch = Histogram::getHistogram( + LiteralStringRef("buildItemCount"), levelString, Histogram::Unit::count, 0, maxRecordCount); + modifyItemCountSketch = Histogram::getHistogram( + LiteralStringRef("modifyItemCount"), levelString, Histogram::Unit::count, 0, maxRecordCount); + } + + buildFillPctSketch->clear(); + modifyFillPctSketch->clear(); + buildStoredPctSketch->clear(); + modifyStoredPctSketch->clear(); + buildItemCountSketch->clear(); + modifyItemCountSketch->clear(); } - metrics.events.clear(); - buildFillPctSketch->clear(); - modifyFillPctSketch->clear(); - buildStoredPctSketch->clear(); - modifyStoredPctSketch->clear(); - buildItemCountSketch->clear(); - modifyItemCountSketch->clear(); } }; @@ -1650,7 +1637,7 @@ struct RedwoodMetrics { void updateMaxRecordCount(int maxRecords) { if (maxRecordCount != maxRecords) { maxRecordCount = maxRecords; - for (int i = 0; i < btreeLevels + 1; ++i) { + for (int i = 1; i <= btreeLevels; ++i) { auto& level = levels[i]; level.buildItemCountSketch->updateUpperBound(maxRecordCount); level.modifyItemCountSketch->updateUpperBound(maxRecordCount); @@ -1688,7 +1675,6 @@ struct RedwoodMetrics { { "PagerRemapCopy", metric.pagerRemapCopy }, { "PagerRemapSkip", metric.pagerRemapSkip }, { "", 0 } }; - GetHistogramRegistry().logReport(); double elapsed = now() - startTime; From 2f21e0a6bb4000b8d9d164f8f821b7c6e86fd368 Mon Sep 17 00:00:00 2001 From: Steve Atherton Date: Tue, 20 Jul 2021 23:40:35 -0700 Subject: [PATCH 3/4] BTree levels above the configured count for metrics are now included into the highest level, which fixes some valgrind errors and a crash. --- fdbserver/VersionedBTree.actor.cpp | 17 ++++++----------- 1 file changed, 6 insertions(+), 11 deletions(-) diff --git a/fdbserver/VersionedBTree.actor.cpp b/fdbserver/VersionedBTree.actor.cpp index 5d3cf25928..fdddc5c01c 100644 --- a/fdbserver/VersionedBTree.actor.cpp +++ b/fdbserver/VersionedBTree.actor.cpp @@ -1447,7 +1447,7 @@ int nextPowerOf2(uint32_t x) { } struct RedwoodMetrics { - static constexpr int btreeLevels = 5; + static constexpr unsigned int btreeLevels = 5; static int maxRecordCount; struct EventReasonsArray { @@ -1622,16 +1622,11 @@ struct RedwoodMetrics { } Level& level(unsigned int level) { - // Storage for metrics for out of bound levels, such as if the BTree grows beyond 5 levels, - // which can happen in simulation with tiny page sizes. - static Level outOfBound; // Valid levels are from 0 - btreeLevels - // Levels 1 through btreeLevels correspond to BTree node heights - // Level 0 is for operations that are not BTree level specific - if (level < 0 || level > btreeLevels) { - return outOfBound; - } - return levels[level]; + // Level 0 is for operations that are not BTree level specific, as many of the metrics are the same + // Level 0 - btreeLevels correspond to BTree node height, however heights above btreeLevels are combined + // into the level at btreeLevels + return levels[std::min(level, btreeLevels)]; } void updateMaxRecordCount(int maxRecords) { @@ -9030,7 +9025,7 @@ TEST_CASE("/redwood/correctness/btree") { mutationBytesThisCommit >= mutationBytesTargetThisCommit) { // Wait for previous commit to finish wait(commit); - printf("Last commit complete. Next commit %d bytes, %" PRId64 " bytes committed so far.", + printf("Commit complete. Next commit %d bytes, %" PRId64 " bytes committed so far.", mutationBytesThisCommit, mutationBytes.get() - mutationBytesThisCommit); printf(" Stats: Insert %.2f MB/s ClearedKeys %.2f MB/s Total %.2f\n", From c16b73bb2fbf30173d026fb52caeada1e7d38f9a Mon Sep 17 00:00:00 2001 From: Steve Atherton Date: Wed, 21 Jul 2021 01:28:25 -0700 Subject: [PATCH 4/4] Bug fix, BTreeCursor pager event reason was not being initialized. Changed metric column order. --- fdbserver/IPager.h | 6 +++--- fdbserver/VersionedBTree.actor.cpp | 4 ++-- 2 files changed, 5 insertions(+), 5 deletions(-) diff --git a/fdbserver/IPager.h b/fdbserver/IPager.h index 922df85ce3..c5558613bc 100644 --- a/fdbserver/IPager.h +++ b/fdbserver/IPager.h @@ -52,17 +52,17 @@ static const char* const PagerEventReasonsStrings[] = { static const int nonBtreeLevel = 0; static const std::vector> possibleEventReasonPairs = { { PagerEvents::CacheLookup, PagerEventReasons::Commit }, + { PagerEvents::CacheLookup, PagerEventReasons::LazyClear }, { PagerEvents::CacheLookup, PagerEventReasons::PointRead }, { PagerEvents::CacheLookup, PagerEventReasons::RangeRead }, - { PagerEvents::CacheLookup, PagerEventReasons::LazyClear }, { PagerEvents::CacheHit, PagerEventReasons::Commit }, + { PagerEvents::CacheHit, PagerEventReasons::LazyClear }, { PagerEvents::CacheHit, PagerEventReasons::PointRead }, { PagerEvents::CacheHit, PagerEventReasons::RangeRead }, - { PagerEvents::CacheHit, PagerEventReasons::LazyClear }, { PagerEvents::CacheMiss, PagerEventReasons::Commit }, + { PagerEvents::CacheMiss, PagerEventReasons::LazyClear }, { PagerEvents::CacheMiss, PagerEventReasons::PointRead }, { PagerEvents::CacheMiss, PagerEventReasons::RangeRead }, - { PagerEvents::CacheMiss, PagerEventReasons::LazyClear }, { PagerEvents::PageWrite, PagerEventReasons::Commit }, { PagerEvents::PageWrite, PagerEventReasons::LazyClear }, }; diff --git a/fdbserver/VersionedBTree.actor.cpp b/fdbserver/VersionedBTree.actor.cpp index fdddc5c01c..ecd6540ffb 100644 --- a/fdbserver/VersionedBTree.actor.cpp +++ b/fdbserver/VersionedBTree.actor.cpp @@ -6707,11 +6707,11 @@ public: // Initialize or reinitialize cursor Future init(VersionedBTree* btree_in, - PagerEventReasons reason, + PagerEventReasons reason_in, Reference pager_in, BTreePageIDRef root) { btree = btree_in; - reason = reason; + reason = reason_in; pager = pager_in; path.clear(); path.reserve(6);