wbtiger
/
foundationdb
mirror of https://github.com/apple/foundationdb.git
0
0
Fork 0
Code Issues Packages Projects Releases Wiki Activity

Merge pull request #5260 from FuhengZhao/RedwoodHistogram 

Redwood local histograms
This commit is contained in:
Steve Atherton 2021-08-26 12:05:44 -07:00 committed by GitHub
parent 1a50dea6c8 67600d436e
commit be440ab954
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
5 changed files with 139 additions and 77 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

3
fdbclient/ServerKnobs.cpp
View File

@ -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 );

3
fdbclient/ServerKnobs.h
View File

@ -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;

146
fdbserver/VersionedBTree.actor.cpp
View File

@ -1526,36 +1526,9 @@ struct RedwoodMetrics {
Reference<Histogram> buildItemCountSketch;
Reference<Histogram> 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<Histogram>(
new Histogram(Reference<HistogramRegistry>(), "kvSize", "Written", Histogram::Unit::bytes));
kvSizeReadByGet = Reference<Histogram>(
new Histogram(Reference<HistogramRegistry>(), "kvSize", "ReadByGet", Histogram::Unit::bytes));
kvSizeReadByGetRange = Reference<Histogram>(
new Histogram(Reference<HistogramRegistry>(), "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<Histogram>(new Histogram(
Reference<HistogramRegistry>(), "buildFillPct", levelString, Histogram::Unit::percentage));
level.modifyFillPctSketch = Reference<Histogram>(new Histogram(
Reference<HistogramRegistry>(), "modifyFillPct", levelString, Histogram::Unit::percentage));
level.buildStoredPctSketch = Reference<Histogram>(new Histogram(
Reference<HistogramRegistry>(), "buildStoredPct", levelString, Histogram::Unit::percentage));
level.modifyStoredPctSketch = Reference<Histogram>(new Histogram(
Reference<HistogramRegistry>(), "modifyStoredPct", levelString, Histogram::Unit::percentage));
level.buildItemCountSketch = Reference<Histogram>(new Histogram(Reference<HistogramRegistry>(),
"buildItemCount",
levelString,
Histogram::Unit::count,
0,
maxRecordCount));
level.modifyItemCountSketch = Reference<Histogram>(new Histogram(Reference<HistogramRegistry>(),
"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<Histogram> kvSizeWritten;
Reference<Histogram> kvSizeReadByGet;
Reference<Histogram> 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<Void> g_redwoodMetricsActor;
ACTOR Future<Void> redwoodHistogramsLogger(double interval) {
state double currTime;
loop {
currTime = now();
wait(delay(interval));
double elapsed = now() - currTime;
g_redwoodMetrics.logHistograms(elapsed);
}
}
ACTOR Future<Void> redwoodMetricsLogger() {
g_redwoodMetrics.clear();
state Future<Void> 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<Reference<ArenaPage>> 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<Reference<Histogram>> 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<double, std::milli>(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();

25
flow/Histogram.cpp
View File

@ -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);
}

39
flow/Histogram.h
View File

@ -23,12 +23,10 @@
#pragma once
#include <flow/Arena.h>
#include <string>
#include <map>
#include <unordered_map>
#include <iomanip>
#ifdef _WIN32
#include <intrin.h>
#pragma intrinsic(_BitScanReverse)
@ -36,12 +34,13 @@
class Histogram;
class HistogramRegistry {
class HistogramRegistry : public ReferenceCounted<HistogramRegistry> {
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<HistogramRegistry> 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<Histogram> 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<HistogramRegistry>::addRef(&registry), group_str, op_str, unit, lower, upper);
registry.registerHistogram(h);
return Reference<Histogram>(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<HistogramRegistry> registry;
uint32_t buckets[32];
uint32_t lowerBound;
uint32_t upperBound;