From 5e1b2d3eeab81033c3d687f03c5baab92c4769e5 Mon Sep 17 00:00:00 2001 From: Mark Shabanov Date: Wed, 1 Jul 2026 16:34:40 +0300 Subject: [PATCH 1/2] Added new commit statistics metrics --- fdbclient/Schemas.cpp | 96 +++++++++++++++++++++ fdbserver/clustercontroller/Status.cpp | 47 +++++++++- fdbserver/commitproxy/CommitProxyServer.cpp | 25 +++++- fdbserver/commitproxy/ProxyCommitData.h | 45 ++++++++++ 4 files changed, 208 insertions(+), 5 deletions(-) diff --git a/fdbclient/Schemas.cpp b/fdbclient/Schemas.cpp index 7de6e08fc44..d368de688a0 100644 --- a/fdbclient/Schemas.cpp +++ b/fdbclient/Schemas.cpp @@ -289,6 +289,102 @@ const KeyRef JSONSchemas::statusSchema = R"statusSchema( "p99":0.0, "p99.9":0.0 }, + "commit_batch_transactions":{ + "count":0, + "min":0.0, + "max":0.0, + "median":0.0, + "mean":0.0, + "p25":0.0, + "p90":0.0, + "p95":0.0, + "p99":0.0, + "p99.9":0.0 + }, + "commit_batch_bytes":{ + "count":0, + "min":0.0, + "max":0.0, + "median":0.0, + "mean":0.0, + "p25":0.0, + "p90":0.0, + "p95":0.0, + "p99":0.0, + "p99.9":0.0 + }, + "commit_batching_waiting":{ + "count":0, + "min":0.0, + "max":0.0, + "median":0.0, + "mean":0.0, + "p25":0.0, + "p90":0.0, + "p95":0.0, + "p99":0.0, + "p99.9":0.0 + }, + "commit_preresolution_latency":{ + "count":0, + "min":0.0, + "max":0.0, + "median":0.0, + "mean":0.0, + "p25":0.0, + "p90":0.0, + "p95":0.0, + "p99":0.0, + "p99.9":0.0 + }, + "commit_resolution_latency":{ + "count":0, + "min":0.0, + "max":0.0, + "median":0.0, + "mean":0.0, + "p25":0.0, + "p90":0.0, + "p95":0.0, + "p99":0.0, + "p99.9":0.0 + }, + "commit_postresolution_latency":{ + "count":0, + "min":0.0, + "max":0.0, + "median":0.0, + "mean":0.0, + "p25":0.0, + "p90":0.0, + "p95":0.0, + "p99":0.0, + "p99.9":0.0 + }, + "commit_tlog_logging_latency":{ + "count":0, + "min":0.0, + "max":0.0, + "median":0.0, + "mean":0.0, + "p25":0.0, + "p90":0.0, + "p95":0.0, + "p99":0.0, + "p99.9":0.0 + }, + "commit_reply_latency":{ + "count":0, + "min":0.0, + "max":0.0, + "median":0.0, + "mean":0.0, + "p25":0.0, + "p90":0.0, + "p95":0.0, + "p99":0.0, + "p99.9":0.0 + }, "grv_latency_bands":{ "$map": 1 }, diff --git a/fdbserver/clustercontroller/Status.cpp b/fdbserver/clustercontroller/Status.cpp index 74c809d4f9c..570482d6c87 100644 --- a/fdbserver/clustercontroller/Status.cpp +++ b/fdbserver/clustercontroller/Status.cpp @@ -670,6 +670,46 @@ struct RolesInfo { if (commitBatchingWindowSize.size()) { obj["commit_batching_window_size"] = addLatencyStatistics(commitBatchingWindowSize); } + + TraceEventFields const& commitBatchTransactions = metrics.at("CommitBatchTransactions"); + if (commitBatchTransactions.size()) { + obj["commit_batch_transactions"] = addLatencyStatistics(commitBatchTransactions); + } + + TraceEventFields const& commitBatchBytes = metrics.at("CommitBatchBytes"); + if (commitBatchBytes.size()) { + obj["commit_batch_bytes"] = addLatencyStatistics(commitBatchBytes); + } + + TraceEventFields const& commitBatchingWaiting = metrics.at("CommitBatchingWaiting"); + if (commitBatchingWaiting.size()) { + obj["commit_batching_waiting"] = addLatencyStatistics(commitBatchingWaiting); + } + + TraceEventFields const& commitPreresolutionLatency = metrics.at("CommitPreresolutionLatency"); + if (commitPreresolutionLatency.size()) { + obj["commit_preresolution_latency"] = addLatencyStatistics(commitPreresolutionLatency); + } + + TraceEventFields const& commitResolutionLatency = metrics.at("CommitResolutionLatency"); + if (commitResolutionLatency.size()) { + obj["commit_resolution_latency"] = addLatencyStatistics(commitResolutionLatency); + } + + TraceEventFields const& commitPostresolutionLatency = metrics.at("CommitPostresolutionLatency"); + if (commitPostresolutionLatency.size()) { + obj["commit_postresolution_latency"] = addLatencyStatistics(commitPostresolutionLatency); + } + + TraceEventFields const& commitTLogLoggingLatency = metrics.at("CommitTLogLoggingLatency"); + if (commitTLogLoggingLatency.size()) { + obj["commit_tlog_logging_latency"] = addLatencyStatistics(commitTLogLoggingLatency); + } + + TraceEventFields const& commitReplyLatency = metrics.at("CommitReplyLatency"); + if (commitReplyLatency.size()) { + obj["commit_reply_latency"] = addLatencyStatistics(commitReplyLatency); + } } catch (Error& e) { if (e.code() != error_code_attribute_not_found) { throw e; @@ -2028,7 +2068,12 @@ static Future>> getTLogsAndMetric static Future>> getCommitProxiesAndMetrics( Reference> db, std::unordered_map address_workers) { - std::vector eventNames{ "CommitLatencyMetrics", "CommitLatencyBands", "CommitBatchingWindowSize" }; + std::vector eventNames{ + "CommitLatencyMetrics", "CommitLatencyBands", "CommitBatchingWindowSize", + "CommitBatchTransactions", "CommitBatchBytes", "CommitBatchingWaiting", + "CommitPreresolutionLatency", "CommitResolutionLatency", "CommitPostresolutionLatency", + "CommitTLogLoggingLatency", "CommitReplyLatency" + }; std::vector> results = co_await getServerMetrics(db->get().client.commitProxies, address_workers, std::move(eventNames)); diff --git a/fdbserver/commitproxy/CommitProxyServer.cpp b/fdbserver/commitproxy/CommitProxyServer.cpp index 0a05a5461c9..fa629f67b64 100644 --- a/fdbserver/commitproxy/CommitProxyServer.cpp +++ b/fdbserver/commitproxy/CommitProxyServer.cpp @@ -884,6 +884,7 @@ Future preresolutionProcessing(CommitBatchContext* self) { r->value().emplace_back(versionReply.resolverChangesVersion, it.dest); } + pProxyCommitData->stats.commitPreresolutionLatency.addMeasurement(now() - startTime); //TraceEvent("ProxyGotVer", pProxyContext->dbgid).detail("Commit", commitVersion).detail("Prev", prevVersion); if (debugID.present()) { @@ -973,7 +974,10 @@ Future getResolution(CommitBatchContext* self) { self->resolution = std::move(resolutionResp); } - self->pProxyCommitData->stats.resolutionDist->sampleSeconds(g_network->timer_monotonic() - resolutionStart); + double resolutionDuration = g_network->timer_monotonic() - resolutionStart; + + self->pProxyCommitData->stats.commitResolutionLatency.addMeasurement(resolutionDuration); + self->pProxyCommitData->stats.resolutionDist->sampleSeconds(resolutionDuration); if (self->debugID.present()) { g_traceBatch.addEvent( "CommitDebug", self->debugID.get().first(), "CommitProxyServer.commitBatch.AfterResolution"); @@ -1804,7 +1808,10 @@ Future postResolution(CommitBatchContext* self) { } } - pProxyCommitData->stats.processingMutationDist->sampleSeconds(g_network->timer_monotonic() - postResolutionQueuing); + double postResolutionEnd = g_network->timer_monotonic(); + + pProxyCommitData->stats.commitPostresolutionLatency.addMeasurement(postResolutionEnd - postResolutionStart); + pProxyCommitData->stats.processingMutationDist->sampleSeconds(postResolutionEnd - postResolutionQueuing); } Future transactionLogging(CommitBatchContext* self) { @@ -1844,7 +1851,11 @@ Future transactionLogging(CommitBatchContext* self) { pProxyCommitData->txsPopVersions.emplace_back(self->commitVersion, self->msg.popTo); } pProxyCommitData->logSystemConsumer->popTxs(self->msg.popTo); - pProxyCommitData->stats.tlogLoggingDist->sampleSeconds(g_network->timer_monotonic() - tLoggingStart); + + double tLoggingDuration = g_network->timer_monotonic() - tLoggingStart; + + pProxyCommitData->stats.commitTLogLoggingLatency.addMeasurement(tLoggingDuration); + pProxyCommitData->stats.tlogLoggingDist->sampleSeconds(tLoggingDuration); } Future reply(CommitBatchContext* self) { @@ -1986,6 +1997,7 @@ Future reply(CommitBatchContext* self) { // TODO: filter if pipelined with large commit const double duration = endTime - tr.requestTime(); pProxyCommitData->stats.commitLatencySample.addMeasurement(duration); + pProxyCommitData->stats.commitBatchingWaiting.addMeasurement(self->startTime - tr.requestTime()); if (pProxyCommitData->latencyBandConfig.present()) { bool filter = self->maxTransactionBytes > pProxyCommitData->latencyBandConfig.get().commitConfig.maxCommitBytes.orDefault( @@ -2046,7 +2058,10 @@ Future reply(CommitBatchContext* self) { pProxyCommitData->commitBatchesMemBytesCount -= self->currentBatchMemBytesCount; ASSERT_ABORT(pProxyCommitData->commitBatchesMemBytesCount >= 0); co_await self->releaseFuture; - pProxyCommitData->stats.replyCommitDist->sampleSeconds(g_network->timer_monotonic() - replyStart); + double replyDuration = g_network->timer_monotonic() - replyStart; + + pProxyCommitData->stats.commitReplyLatency.addMeasurement(replyDuration); + pProxyCommitData->stats.replyCommitDist->sampleSeconds(replyDuration); } // Commit one batch of transactions trs @@ -2064,6 +2079,8 @@ Future commitBatchImpl(CommitBatchContext* pContext) { pContext->pProxyCommitData->lastVersionTime = pContext->startTime; ++pContext->pProxyCommitData->stats.commitBatchIn; pContext->setupTraceBatch(); + pContext->pProxyCommitData->stats.commitBatchBytes.addMeasurement(pContext->currentBatchMemBytesCount); + pContext->pProxyCommitData->stats.commitBatchTransactions.addMeasurement(pContext->trs.size()); /////// Phase 1: Pre-resolution processing (CPU bound except waiting for a version # which is separately pipelined /// and *should* be available by now (unless empty commit); ordered; currently atomic but could yield) diff --git a/fdbserver/commitproxy/ProxyCommitData.h b/fdbserver/commitproxy/ProxyCommitData.h index a5684948ddd..4aebc1f725c 100644 --- a/fdbserver/commitproxy/ProxyCommitData.h +++ b/fdbserver/commitproxy/ProxyCommitData.h @@ -79,6 +79,19 @@ struct ProxyStats { LatencySample commitBatchingWindowSize; + // Number of transactions in the batch + LatencySample commitBatchTransactions; + // Summary length of transactions in the batch + LatencySample commitBatchBytes; + // what time transactions were waiting in the batch before they + // started processing with commitBatch() + LatencySample commitBatchingWaiting; + LatencySample commitPreresolutionLatency; + LatencySample commitResolutionLatency; + LatencySample commitPostresolutionLatency; + LatencySample commitTLogLoggingLatency; + LatencySample commitReplyLatency; + LatencySample computeLatency; Future logger; @@ -148,6 +161,38 @@ struct ProxyStats { id, SERVER_KNOBS->LATENCY_METRICS_LOGGING_INTERVAL, SERVER_KNOBS->LATENCY_SKETCH_ACCURACY), + commitBatchTransactions("CommitBatchTransactions", + id, + SERVER_KNOBS->LATENCY_METRICS_LOGGING_INTERVAL, + SERVER_KNOBS->LATENCY_SKETCH_ACCURACY), + commitBatchBytes("CommitBatchBytes", + id, + SERVER_KNOBS->LATENCY_METRICS_LOGGING_INTERVAL, + SERVER_KNOBS->LATENCY_SKETCH_ACCURACY), + commitBatchingWaiting("CommitBatchingWaiting", + id, + SERVER_KNOBS->LATENCY_METRICS_LOGGING_INTERVAL, + SERVER_KNOBS->LATENCY_SKETCH_ACCURACY), + commitPreresolutionLatency("CommitPreresolutionLatency", + id, + SERVER_KNOBS->LATENCY_METRICS_LOGGING_INTERVAL, + SERVER_KNOBS->LATENCY_SKETCH_ACCURACY), + commitResolutionLatency("CommitResolutionLatency", + id, + SERVER_KNOBS->LATENCY_METRICS_LOGGING_INTERVAL, + SERVER_KNOBS->LATENCY_SKETCH_ACCURACY), + commitPostresolutionLatency("CommitPostresolutionLatency", + id, + SERVER_KNOBS->LATENCY_METRICS_LOGGING_INTERVAL, + SERVER_KNOBS->LATENCY_SKETCH_ACCURACY), + commitTLogLoggingLatency("CommitTLogLoggingLatency", + id, + SERVER_KNOBS->LATENCY_METRICS_LOGGING_INTERVAL, + SERVER_KNOBS->LATENCY_SKETCH_ACCURACY), + commitReplyLatency("CommitReplyLatency", + id, + SERVER_KNOBS->LATENCY_METRICS_LOGGING_INTERVAL, + SERVER_KNOBS->LATENCY_SKETCH_ACCURACY), computeLatency("ComputeLatency", id, SERVER_KNOBS->LATENCY_METRICS_LOGGING_INTERVAL, From 4b3af741ed3de77d9d104c77ed0a1e66811cf8a2 Mon Sep 17 00:00:00 2001 From: Mark Shabanov Date: Wed, 1 Jul 2026 17:25:08 +0300 Subject: [PATCH 2/2] added new metrics into mr-status-json-schemas.rst.inc --- .../source/mr-status-json-schemas.rst.inc | 96 +++++++++++++++++++ 1 file changed, 96 insertions(+) diff --git a/documentation/sphinx/source/mr-status-json-schemas.rst.inc b/documentation/sphinx/source/mr-status-json-schemas.rst.inc index 57ffd519b1d..8529b0834ce 100644 --- a/documentation/sphinx/source/mr-status-json-schemas.rst.inc +++ b/documentation/sphinx/source/mr-status-json-schemas.rst.inc @@ -304,6 +304,102 @@ "p99":0.0, "p99.9":0.0 }, + "commit_batch_transactions":{ // Number of transactions in the commit batch + "count":0, + "min":0.0, + "max":0.0, + "median":0.0, + "mean":0.0, + "p25":0.0, + "p90":0.0, + "p95":0.0, + "p99":0.0, + "p99.9":0.0 + }, + "commit_batch_bytes":{ // Total size of transactions in the commit batch (bytes) + "count":0, + "min":0.0, + "max":0.0, + "median":0.0, + "mean":0.0, + "p25":0.0, + "p90":0.0, + "p95":0.0, + "p99":0.0, + "p99.9":0.0 + }, + "commit_batching_waiting":{ // Time transactions spent waiting in queue before commit batch processing (seconds) + "count":0, + "min":0.0, + "max":0.0, + "median":0.0, + "mean":0.0, + "p25":0.0, + "p90":0.0, + "p95":0.0, + "p99":0.0, + "p99.9":0.0 + }, + "commit_preresolution_latency":{ // Latency of the pre-resolution phase (seconds) + "count":0, + "min":0.0, + "max":0.0, + "median":0.0, + "mean":0.0, + "p25":0.0, + "p90":0.0, + "p95":0.0, + "p99":0.0, + "p99.9":0.0 + }, + "commit_resolution_latency":{ // Latency of the resolution phase (seconds) + "count":0, + "min":0.0, + "max":0.0, + "median":0.0, + "mean":0.0, + "p25":0.0, + "p90":0.0, + "p95":0.0, + "p99":0.0, + "p99.9":0.0 + }, + "commit_postresolution_latency":{ // Latency of the post-resolution phase (seconds) + "count":0, + "min":0.0, + "max":0.0, + "median":0.0, + "mean":0.0, + "p25":0.0, + "p90":0.0, + "p95":0.0, + "p99":0.0, + "p99.9":0.0 + }, + "commit_tlog_logging_latency":{ // Latency of the TLog logging phase (seconds) + "count":0, + "min":0.0, + "max":0.0, + "median":0.0, + "mean":0.0, + "p25":0.0, + "p90":0.0, + "p95":0.0, + "p99":0.0, + "p99.9":0.0 + }, + "commit_reply_latency":{ // Latency of the reply phase (seconds) + "count":0, + "min":0.0, + "max":0.0, + "median":0.0, + "mean":0.0, + "p25":0.0, + "p90":0.0, + "p95":0.0, + "p99":0.0, + "p99.9":0.0 + }, "grv_latency_bands":{ // How many GRV requests belong to the latency (in seconds) band (e.g., How many requests belong to [0.01,0.1] latency band). The key is the upper bound of the band and the lower bound is the next smallest band (or 0, if none). Example: {0.01: 27, 0.1: 18, 1: 1, inf: 98,filtered: 10}, we have 18 requests in [0.01, 0.1) band. "$map_key=upperBoundOfBand": 1 },