From 3df6a86d220b17f9dbbca5e4b05b678f737d5fc3 Mon Sep 17 00:00:00 2001 From: Steve Atherton Date: Wed, 14 Sep 2022 01:26:31 -0700 Subject: [PATCH] Add new latency samples for GetValue, GetRange, QueueWait which is the time between request receipt and when it starts to be processed, and VersionWait which is the time after QueueWait spent waiting for the necessary data version to arrive. --- fdbserver/storageserver.actor.cpp | 44 +++++++++++++++++++++++++++++++ 1 file changed, 44 insertions(+) diff --git a/fdbserver/storageserver.actor.cpp b/fdbserver/storageserver.actor.cpp index eb542b4980..2c510d7634 100644 --- a/fdbserver/storageserver.actor.cpp +++ b/fdbserver/storageserver.actor.cpp @@ -1122,6 +1122,11 @@ public: Counter changeFeedDiskReads; LatencySample readLatencySample; + LatencySample readValueLatencySample; + LatencySample readRangeLatencySample; + LatencySample readVersionWaitSample; + LatencySample readQueueWaitSample; + LatencyBands readLatencyBands; LatencySample mappedRangeSample; // Samples getMappedRange latency LatencySample mappedRangeRemoteSample; // Samples getMappedRange remote subquery latency @@ -1159,6 +1164,22 @@ public: self->thisServerID, SERVER_KNOBS->LATENCY_METRICS_LOGGING_INTERVAL, SERVER_KNOBS->LATENCY_SAMPLE_SIZE), + readValueLatencySample("ReadValueLatencyMetrics", + self->thisServerID, + SERVER_KNOBS->LATENCY_METRICS_LOGGING_INTERVAL, + SERVER_KNOBS->LATENCY_SAMPLE_SIZE), + readRangeLatencySample("ReadRangeLatencyMetrics", + self->thisServerID, + SERVER_KNOBS->LATENCY_METRICS_LOGGING_INTERVAL, + SERVER_KNOBS->LATENCY_SAMPLE_SIZE), + readVersionWaitSample("ReadVersionWaitMetrics", + self->thisServerID, + SERVER_KNOBS->LATENCY_METRICS_LOGGING_INTERVAL, + SERVER_KNOBS->LATENCY_SAMPLE_SIZE), + readQueueWaitSample("ReadQueueWaitMetrics", + self->thisServerID, + SERVER_KNOBS->LATENCY_METRICS_LOGGING_INTERVAL, + SERVER_KNOBS->LATENCY_SAMPLE_SIZE), readLatencyBands("ReadLatencyBands", self->thisServerID, SERVER_KNOBS->STORAGE_LOGGING_DELAY), mappedRangeSample("GetMappedRangeMetrics", self->thisServerID, @@ -1837,6 +1858,10 @@ ACTOR Future getValueQ(StorageServer* data, GetValueRequest req) { // so we need to downgrade here wait(data->getQueryDelay()); + // Track time from requestTime through now as read queueing wait time + state double queueWaitEnd = g_network->timer(); + data->counters.readQueueWaitSample.addMeasurement(queueWaitEnd - req.requestTime()); + if (req.options.present() && req.options.get().debugID.present()) g_traceBatch.addEvent("GetValueDebug", req.options.get().debugID.get().first(), @@ -1845,6 +1870,8 @@ ACTOR Future getValueQ(StorageServer* data, GetValueRequest req) { state Optional v; Version commitVersion = getLatestCommitVersion(req.ssLatestCommitVersions, data->tag); state Version version = wait(waitForVersion(data, commitVersion, req.version, req.spanContext)); + data->counters.readVersionWaitSample.addMeasurement(g_network->timer() - queueWaitEnd); + if (req.options.present() && req.options.get().debugID.present()) g_traceBatch.addEvent("GetValueDebug", req.options.get().debugID.get().first(), @@ -1940,6 +1967,7 @@ ACTOR Future getValueQ(StorageServer* data, GetValueRequest req) { double duration = g_network->timer() - req.requestTime(); data->counters.readLatencySample.addMeasurement(duration); + data->counters.readValueLatencySample.addMeasurement(duration); if (data->latencyBandConfig.present()) { int maxReadBytes = data->latencyBandConfig.get().readConfig.maxReadBytes.orDefault(std::numeric_limits::max()); @@ -3732,6 +3760,10 @@ ACTOR Future getKeyValuesQ(StorageServer* data, GetKeyValuesRequest req) wait(data->getQueryDelay()); } + // Track time from requestTime through now as read queueing wait time + state double queueWaitEnd = g_network->timer(); + data->counters.readQueueWaitSample.addMeasurement(queueWaitEnd - req.requestTime()); + try { if (req.options.present() && req.options.get().debugID.present()) g_traceBatch.addEvent( @@ -3739,6 +3771,7 @@ ACTOR Future getKeyValuesQ(StorageServer* data, GetKeyValuesRequest req) Version commitVersion = getLatestCommitVersion(req.ssLatestCommitVersions, data->tag); state Version version = wait(waitForVersion(data, commitVersion, req.version, span.context)); + data->counters.readVersionWaitSample.addMeasurement(g_network->timer() - queueWaitEnd); state Optional tenantEntry = data->getTenantEntry(version, req.tenantInfo); state Optional tenantPrefix = tenantEntry.map([](TenantMapEntry e) { return e.prefix; }); @@ -3882,6 +3915,7 @@ ACTOR Future getKeyValuesQ(StorageServer* data, GetKeyValuesRequest req) double duration = g_network->timer() - req.requestTime(); data->counters.readLatencySample.addMeasurement(duration); + data->counters.readRangeLatencySample.addMeasurement(duration); if (data->latencyBandConfig.present()) { int maxReadBytes = data->latencyBandConfig.get().readConfig.maxReadBytes.orDefault(std::numeric_limits::max()); @@ -4479,6 +4513,10 @@ ACTOR Future getMappedKeyValuesQ(StorageServer* data, GetMappedKeyValuesRe wait(data->getQueryDelay()); } + // Track time from requestTime through now as read queueing wait time + state double queueWaitEnd = g_network->timer(); + data->counters.readQueueWaitSample.addMeasurement(queueWaitEnd - req.requestTime()); + try { if (req.options.present() && req.options.get().debugID.present()) g_traceBatch.addEvent( @@ -4486,6 +4524,7 @@ ACTOR Future getMappedKeyValuesQ(StorageServer* data, GetMappedKeyValuesRe // VERSION_VECTOR change Version commitVersion = getLatestCommitVersion(req.ssLatestCommitVersions, data->tag); state Version version = wait(waitForVersion(data, commitVersion, req.version, span.context)); + data->counters.readVersionWaitSample.addMeasurement(g_network->timer() - queueWaitEnd); state Optional tenantEntry = data->getTenantEntry(req.version, req.tenantInfo); state Optional tenantPrefix = tenantEntry.map([](TenantMapEntry e) { return e.prefix; }); @@ -4899,9 +4938,14 @@ ACTOR Future getKeyQ(StorageServer* data, GetKeyRequest req) { // so we need to downgrade here wait(data->getQueryDelay()); + // Track time from requestTime through now as read queueing wait time + state double queueWaitEnd = g_network->timer(); + data->counters.readQueueWaitSample.addMeasurement(queueWaitEnd - req.requestTime()); + try { Version commitVersion = getLatestCommitVersion(req.ssLatestCommitVersions, data->tag); state Version version = wait(waitForVersion(data, commitVersion, req.version, req.spanContext)); + data->counters.readVersionWaitSample.addMeasurement(g_network->timer() - queueWaitEnd); state Optional tenantEntry = data->getTenantEntry(version, req.tenantInfo); if (tenantEntry.present()) {