diff --git a/fdbclient/ServerKnobs.cpp b/fdbclient/ServerKnobs.cpp index f7039af120..19681e1f03 100644 --- a/fdbclient/ServerKnobs.cpp +++ b/fdbclient/ServerKnobs.cpp @@ -748,7 +748,8 @@ void ServerKnobs::initialize(Randomize randomize, ClientKnobs* clientKnobs, IsSi init( REDWOOD_LAZY_CLEAR_MAX_PAGES, 1e6 ); init( REDWOOD_REMAP_CLEANUP_WINDOW, 50 ); init( REDWOOD_REMAP_CLEANUP_LAG, 0.1 ); - init( REDWOOD_LOGGING_INTERVAL, 5.0 ); + init( REDWOOD_METRICS_INTERVAL, 5.0 ); + init( REDWOOD_HISTOGRAM_INTERVAL, 30.0 ); // Server request latency measurement init( LATENCY_SAMPLE_SIZE, 100000 ); diff --git a/fdbclient/ServerKnobs.h b/fdbclient/ServerKnobs.h index e463997c82..cb37713da0 100644 --- a/fdbclient/ServerKnobs.h +++ b/fdbclient/ServerKnobs.h @@ -695,7 +695,8 @@ public: int64_t REDWOOD_REMAP_CLEANUP_WINDOW; // Remap remover lag interval in which to coalesce page writes double REDWOOD_REMAP_CLEANUP_LAG; // Maximum allowed remap remover lag behind the cleanup window as a multiple of // the window size - double REDWOOD_LOGGING_INTERVAL; + double REDWOOD_METRICS_INTERVAL; + double REDWOOD_HISTOGRAM_INTERVAL; // Server request latency measurement int LATENCY_SAMPLE_SIZE; diff --git a/fdbserver/VersionedBTree.actor.cpp b/fdbserver/VersionedBTree.actor.cpp index 5d01169ee8..fe096ba0e3 100644 --- a/fdbserver/VersionedBTree.actor.cpp +++ b/fdbserver/VersionedBTree.actor.cpp @@ -1526,36 +1526,9 @@ struct RedwoodMetrics { Reference buildItemCountSketch; Reference modifyItemCountSketch; - Level() { clear(); } + Level() { metrics = {}; } - void clear(int level = 0) { - metrics = {}; - - 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(); - } - } + void clear() { metrics = {}; } }; struct metrics { @@ -1583,33 +1556,57 @@ struct RedwoodMetrics { }; RedwoodMetrics() { - kvSizeWritten = - Histogram::getHistogram(LiteralStringRef("kvSize"), LiteralStringRef("Written"), Histogram::Unit::bytes); - kvSizeReadByGet = - Histogram::getHistogram(LiteralStringRef("kvSize"), LiteralStringRef("ReadByGet"), Histogram::Unit::bytes); - kvSizeReadByGetRange = Histogram::getHistogram( - LiteralStringRef("kvSize"), LiteralStringRef("ReadByGetRange"), Histogram::Unit::bytes); + // All histograms have reset their buckets to 0 in the constructor. + kvSizeWritten = Reference( + new Histogram(Reference(), "kvSize", "Written", Histogram::Unit::bytes)); + kvSizeReadByGet = Reference( + new Histogram(Reference(), "kvSize", "ReadByGet", Histogram::Unit::bytes)); + kvSizeReadByGetRange = Reference( + new Histogram(Reference(), "kvSize", "ReadByGetRange", Histogram::Unit::bytes)); + + // These histograms are used for Btree events, hence level > 0 + unsigned int levelCounter = 0; + for (RedwoodMetrics::Level& level : levels) { + if (levelCounter > 0) { + std::string levelString = "L" + std::to_string(levelCounter); + level.buildFillPctSketch = Reference(new Histogram( + Reference(), "buildFillPct", levelString, Histogram::Unit::percentage)); + level.modifyFillPctSketch = Reference(new Histogram( + Reference(), "modifyFillPct", levelString, Histogram::Unit::percentage)); + level.buildStoredPctSketch = Reference(new Histogram( + Reference(), "buildStoredPct", levelString, Histogram::Unit::percentage)); + level.modifyStoredPctSketch = Reference(new Histogram( + Reference(), "modifyStoredPct", levelString, Histogram::Unit::percentage)); + level.buildItemCountSketch = Reference(new Histogram(Reference(), + "buildItemCount", + levelString, + Histogram::Unit::count, + 0, + maxRecordCount)); + level.modifyItemCountSketch = Reference(new Histogram(Reference(), + "modifyItemCount", + levelString, + Histogram::Unit::count, + 0, + maxRecordCount)); + } + ++levelCounter; + } clear(); } void clear() { - unsigned int levelCounter = 0; for (RedwoodMetrics::Level& level : levels) { - level.clear(levelCounter); - ++levelCounter; + level.clear(); } - level(100).clear(); metric = {}; - - kvSizeWritten->clear(); - kvSizeReadByGet->clear(); - kvSizeReadByGetRange->clear(); - startTime = g_network ? now() : 0; } + // btree levels and one extra level for non btree level. Level levels[btreeLevels + 1]; metrics metric; + Reference kvSizeWritten; Reference kvSizeReadByGet; Reference kvSizeReadByGetRange; @@ -1640,6 +1637,25 @@ struct RedwoodMetrics { } } + void logHistograms(double elapsed) { + // All histograms have reset their buckets to 0 after writeToLog. + kvSizeWritten->writeToLog(elapsed); + kvSizeReadByGet->writeToLog(elapsed); + kvSizeReadByGetRange->writeToLog(elapsed); + unsigned int levelCounter = 0; + for (RedwoodMetrics::Level& level : levels) { + if (levelCounter > 0) { + level.buildFillPctSketch->writeToLog(elapsed); + level.modifyFillPctSketch->writeToLog(elapsed); + level.buildStoredPctSketch->writeToLog(elapsed); + level.modifyStoredPctSketch->writeToLog(elapsed); + level.buildItemCountSketch->writeToLog(elapsed); + level.modifyItemCountSketch->writeToLog(elapsed); + } + ++levelCounter; + } + } + // This will populate a trace event and/or a string with Redwood metrics. // The string is a reasonably well formatted page of information void getFields(TraceEvent* e, std::string* s = nullptr, bool skipZeroes = false) { @@ -1766,11 +1782,21 @@ int RedwoodMetrics::maxRecordCount = 315; RedwoodMetrics g_redwoodMetrics = {}; Future g_redwoodMetricsActor; +ACTOR Future redwoodHistogramsLogger(double interval) { + state double currTime; + loop { + currTime = now(); + wait(delay(interval)); + double elapsed = now() - currTime; + g_redwoodMetrics.logHistograms(elapsed); + } +} + ACTOR Future redwoodMetricsLogger() { g_redwoodMetrics.clear(); - + state Future loggingFuture = redwoodHistogramsLogger(SERVER_KNOBS->REDWOOD_HISTOGRAM_INTERVAL); loop { - wait(delay(SERVER_KNOBS->REDWOOD_LOGGING_INTERVAL)); + wait(delay(SERVER_KNOBS->REDWOOD_METRICS_INTERVAL)); TraceEvent e("RedwoodMetrics"); double elapsed = now() - g_redwoodMetrics.startTime; @@ -2919,7 +2945,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.events; + auto& eventReasons = g_redwoodMetrics.level(nonBtreeLevel).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()); @@ -5236,7 +5262,6 @@ private: .detail("BytesWritten", written); ASSERT(false); } - auto& metrics = g_redwoodMetrics.level(height); metrics.metrics.pageBuild += 1; metrics.metrics.pageBuildExt += p.blockCount - 1; @@ -5569,6 +5594,7 @@ private: // Page was updated in-place through edits and written to maybeNewID void updatedInPlace(BTreePageIDRef maybeNewID, BTreePage* btPage, int capacity) { inPlaceUpdate = true; + auto& metrics = g_redwoodMetrics.level(btPage->height); metrics.metrics.pageModify += 1; metrics.metrics.pageModifyExt += (maybeNewID.size() - 1); @@ -10085,6 +10111,30 @@ TEST_CASE(":/redwood/performance/histogramThroughput") { uniform.push_back(distribution(generator)); } std::cout << "size of input: " << uniform.size() << std::endl; + { + // Time needed to log 33 histograms. + std::vector> histograms; + for(int i = 0; i<33; i++){ + std::string levelString = "L" + std::to_string(i); + histograms.push_back( + Histogram::getHistogram( + LiteralStringRef("histogramTest"), LiteralStringRef("levelString"), Histogram::Unit::bytes) + ); + } + for(int i = 0; i<33; i++){ + for(int j = 0; j<32; j++){ + histograms[i]->sample(std::pow(2, j)); + } + } + auto t_start = std::chrono::high_resolution_clock::now(); + for(int i = 0; i<33; i++){ + histograms[i]->writeToLog(30.0); + } + auto t_end = std::chrono::high_resolution_clock::now(); + double elapsed_time_ms = std::chrono::duration(t_end - t_start).count(); + std::cout << "Time needed to log 33 histograms (millisecond): " << elapsed_time_ms << std::endl; + + } { std::cout << "Histogram Unit bytes" << std::endl; auto t_start = std::chrono::high_resolution_clock::now(); diff --git a/flow/Histogram.cpp b/flow/Histogram.cpp index 8063b4d409..fa49b9a1e3 100644 --- a/flow/Histogram.cpp +++ b/flow/Histogram.cpp @@ -85,9 +85,15 @@ Histogram* HistogramRegistry::lookupHistogram(std::string const& name) { return h->second; } -void HistogramRegistry::logReport() { +void HistogramRegistry::logReport(double elapsed) { + for (auto& i : histograms) { + i.second->writeToLog(elapsed); + i.second->clear(); + } +} + +void HistogramRegistry::clear() { for (auto& i : histograms) { - i.second->writeToLog(); i.second->clear(); } } @@ -96,13 +102,10 @@ void HistogramRegistry::logReport() { #pragma region Histogram -const char* const Histogram::UnitToStringMapper[] = { "microseconds", - "bytes", - "bytes_per_second", - "percentage", - "count" }; +const char* const Histogram::UnitToStringMapper[] = { "microseconds", "bytes", "bytes_per_second", + "percentage", "count", "none" }; -void Histogram::writeToLog() { +void Histogram::writeToLog(double elapsed) { bool active = false; for (uint32_t i = 0; i < 32; i++) { if (buckets[i]) { @@ -116,7 +119,8 @@ void Histogram::writeToLog() { TraceEvent e(SevInfo, "Histogram"); e.detail("Group", group).detail("Op", op).detail("Unit", UnitToStringMapper[(size_t)unit]); - + if (elapsed > 0) + e.detail("Elapsed", elapsed); int totalCount = 0; for (uint32_t i = 0; i < 32; i++) { uint64_t value = uint64_t(1) << (i + 1); @@ -137,6 +141,9 @@ void Histogram::writeToLog() { case Unit::count: e.detail(format("LessThan%f", (i + 1) * ((upperBound - lowerBound) / 31.0)), buckets[i]); break; + case Unit::MAXHISTOGRAMUNIT: + e.detail(format("Default%u", i), buckets[i]); + break; default: ASSERT(false); } diff --git a/flow/Histogram.h b/flow/Histogram.h index 5fa32dbb69..5135dccc18 100644 --- a/flow/Histogram.h +++ b/flow/Histogram.h @@ -23,12 +23,10 @@ #pragma once #include - #include #include #include #include - #ifdef _WIN32 #include #pragma intrinsic(_BitScanReverse) @@ -36,12 +34,13 @@ class Histogram; -class HistogramRegistry { +class HistogramRegistry : public ReferenceCounted { public: void registerHistogram(Histogram* h); void unregisterHistogram(Histogram* h); Histogram* lookupHistogram(std::string const& name); - void logReport(); + void logReport(double elapsed = -1.0); + void clear(); private: // This map is ordered by key so that ops within the same group end up @@ -62,25 +61,29 @@ public: enum class Unit { microseconds = 0, bytes, bytes_per_second, percentage, count, MAXHISTOGRAMUNIT }; static const char* const UnitToStringMapper[]; -private: - Histogram(std::string const& group, - std::string const& op, - Unit unit, - HistogramRegistry& registry, - uint32_t lower, - uint32_t upper) - : group(group), op(op), unit(unit), registry(registry), lowerBound(lower), upperBound(upper) { + Histogram(Reference regis, + std::string const& group = "", + std::string const& op = "", + Unit unit = Unit::MAXHISTOGRAMUNIT, + uint32_t lower = 0, + uint32_t upper = UINT32_MAX) + : group(group), op(op), unit(unit), registry(regis), lowerBound(lower), upperBound(upper) { - ASSERT(unit < Unit::MAXHISTOGRAMUNIT); + ASSERT(unit <= Unit::MAXHISTOGRAMUNIT); ASSERT(upperBound >= lowerBound); - clear(); } +private: static std::string generateName(std::string const& group, std::string const& op) { return group + ":" + op; } public: - ~Histogram() { registry.unregisterHistogram(this); } + ~Histogram() { + if (registry.isValid() && unit != Unit::MAXHISTOGRAMUNIT) { + registry->unregisterHistogram(this); + } + registry.clear(); + } static Reference getHistogram(StringRef group, StringRef op, @@ -93,7 +96,7 @@ public: HistogramRegistry& registry = GetHistogramRegistry(); Histogram* h = registry.lookupHistogram(name); if (!h) { - h = new Histogram(group_str, op_str, unit, registry, lower, upper); + h = new Histogram(Reference::addRef(®istry), group_str, op_str, unit, lower, upper); registry.registerHistogram(h); return Reference(h); } else { @@ -159,7 +162,7 @@ public: i = 0; } } - void writeToLog(); + void writeToLog(double elapsed = -1.0); std::string name() const { return generateName(this->group, this->op); } @@ -168,7 +171,7 @@ public: std::string const group; std::string const op; Unit const unit; - HistogramRegistry& registry; + Reference registry; uint32_t buckets[32]; uint32_t lowerBound; uint32_t upperBound;