debug time bounds using sim_validation

fdbclient/NativeAPI.actor.cpp

@@ -58,6 +58,7 @@
 #include "fdbrpc/LoadBalance.h"
 #include "fdbrpc/Net2FileSystem.h"
 #include "fdbrpc/simulator.h"
+#include "fdbrpc/sim_validation.h"
 #include "fdbserver/Knobs.h"
 #include "flow/Arena.h"
 #include "flow/ActorCollection.h"
@@ -195,9 +196,14 @@ void DatabaseContext::removeTssMapping(StorageServerInterface const& ssi) {
 }
 
 void DatabaseContext::updateCachedRV(double t, Version v) {
-	if (t >= lastTimedGrv.get()) {
-		lastTimedGrv = t;
+	if (t > lastTimedGrv.get()) {
+		// TraceEvent("CheckpointCacheUpdate")
+		// 	.detail("Version", v)
+		// 	.detail("CurTime", t)
+		// 	.detail("LastVersion", cachedRv)
+		// 	.detail("LastTime", lastTimedGrv.get());
 		cachedRv = v;
+		lastTimedGrv = t;
 	}
 }
 
@@ -5758,18 +5764,20 @@ ACTOR Future<Version> extractReadVersion(Location location,
 	return rep.version;
 }
 
-ACTOR Future<Version> getDBCachedReadVersion(DatabaseContext* cx) {
-	double t = cx->lastTimedGrv.get();
-	if (now() - t > CLIENT_KNOBS->MAX_VERSION_CACHE_LAG) {
-		wait(cx->lastTimedGrv.whenAtLeast(now() - CLIENT_KNOBS->MAX_VERSION_CACHE_LAG));
+ACTOR Future<Version> getDBCachedReadVersion(DatabaseContext* cx, double requestTime) {
+	if (requestTime - cx->lastTimedGrv.get() > CLIENT_KNOBS->MAX_VERSION_CACHE_LAG) {
+		wait(cx->lastTimedGrv.whenAtLeast(requestTime - CLIENT_KNOBS->MAX_VERSION_CACHE_LAG));
 	}
+	// Want to check that the cached version is at most
+	// MAX_VERSION_CACHE_LAG (100ms) old compared to requestTime.
+	ASSERT(!debug_checkVersionTime(cx->cachedRv, requestTime, "CheckStaleness"));
 	return cx->cachedRv;
 }
 
 Future<Version> Transaction::getReadVersion(uint32_t flags) {
 	if (!readVersion.isValid()) {
 		if (options.useGrvCache && cx->cachedRv > Version(0)) {
-			readVersion = getDBCachedReadVersion(getDatabase().getPtr());
+			readVersion = getDBCachedReadVersion(getDatabase().getPtr(), now());
 			return readVersion;
 		}
 		++cx->transactionReadVersions;

fdbrpc/sim_validation.cpp

@@ -25,6 +25,7 @@
 
 // used for simulation validations
 static std::map<std::string, int64_t> validationData;
+static std::map<std::string, double> validationData2;
 static std::set<UID> disabledMachines;
 
 void debug_setVersionCheckEnabled(UID uid, bool enabled) {
@@ -127,3 +128,71 @@ bool debug_isCheckRelocationDuration() {
 void debug_setCheckRelocationDuration(bool check) {
 	checkRelocationDuration = check;
 }
+void debug_advanceVersionTimestamp(int64_t version, double minTime, double maxTime) {
+	debug_advanceVersionMinTimestamp(version, minTime);
+	debug_advanceVersionMaxTimestamp(version, maxTime);
+}
+
+void debug_advanceTime(int64_t version, double t, const char* suffix) {
+	auto& entry = validationData2[std::to_string(version) + suffix];
+	if (t > entry) {
+		entry = t;
+	}
+}
+
+void debug_advanceVersionMinTimestamp(int64_t version, double t) {
+	if (!g_network->isSimulated() || g_simulator.extraDB)
+		return;
+	debug_advanceTime(version, t, "min");
+}
+
+void debug_advanceVersionMaxTimestamp(int64_t version, double t) {
+	if (!g_network->isSimulated() || g_simulator.extraDB)
+		return;
+	debug_advanceTime(version, t, "max");
+}
+
+bool debug_checkPartVersionTime(int64_t version,
+                                double t,
+                                std::string context,
+                                std::string minormax,
+                                Severity sev = SevError) {
+	if (!g_network->isSimulated() || g_simulator.extraDB)
+		return false;
+	if (!validationData2.count(std::to_string(version) + minormax)) {
+		TraceEvent(SevWarn, (context + "UnknownTime").c_str())
+		    .detail("VersionChecking", version)
+		    .detail("TimeChecking", t);
+		return false;
+	}
+	int sign = minormax == "min" ? 1 : -1;
+	if (t * sign < validationData2[std::to_string(version) + minormax] * sign) {
+		TraceEvent(sev, (context + "DurabilityError").c_str())
+		    .detail("VersionChecking", version)
+		    .detail("TimeChecking", t)
+		    .detail("MinMaxChecking", minormax)
+		    .detail("MinTime", validationData2[std::to_string(version) + "min"])
+		    .detail("MaxTime", validationData2[std::to_string(version) + "max"]);
+		return true;
+	}
+	return false;
+}
+
+bool debug_checkVersionTime(int64_t version, double t, std::string context, Severity sev) {
+	if (!g_network->isSimulated() || g_simulator.extraDB)
+		return false;
+	return debug_checkPartVersionTime(version, t, context, "min", sev) ||
+	       debug_checkPartVersionTime(version, t, context, "max", sev);
+}
+
+bool debug_checkVersionMinTime(int64_t version, double t, std::string context, Severity sev) {
+	if (!g_network->isSimulated() || g_simulator.extraDB)
+		return false;
+	return debug_checkPartVersionTime(version, t, context, "min", sev);
+}
+
+bool debug_checkVersionMaxTime(int64_t version, double t, std::string context, Severity sev) {
+	if (!g_network->isSimulated() || g_simulator.extraDB)
+		return false;
+	return debug_checkPartVersionTime(version, t, context, "max", sev);
+}

fdbrpc/sim_validation.h

@@ -48,4 +48,12 @@ bool debug_checkMaxRestoredVersion(UID id, int64_t version, std::string context,
 bool debug_isCheckRelocationDuration();
 void debug_setCheckRelocationDuration(bool check);
 
+void debug_advanceVersionTimestamp(int64_t version, double minTime, double maxTime);
+void debug_advanceVersionMinTimestamp(int64_t version, double t);
+void debug_advanceVersionMaxTimestamp(int64_t version, double t);
+
+bool debug_checkVersionTime(int64_t version, double t, std::string context, Severity sev = SevError);
+bool debug_checkVersionMinTime(int64_t version, double t, std::string context, Severity sev = SevError);
+bool debug_checkVersionMaxTime(int64_t version, double t, std::string context, Severity sev = SevError);
+
 #endif

fdbserver/CommitProxyServer.actor.cpp

@@ -1187,6 +1187,8 @@ ACTOR Future<Void> postResolution(CommitBatchContext* self) {
 
 	self->commitStartTime = now();
 	pProxyCommitData->lastStartCommit = self->commitStartTime;
+	auto curTime = now();
+	debug_advanceVersionTimestamp(self->commitVersion, curTime, curTime + CLIENT_KNOBS->MAX_VERSION_CACHE_LAG);
 	self->loggingComplete = pProxyCommitData->logSystem->push(self->prevVersion,
 	                                                          self->commitVersion,
 	                                                          pProxyCommitData->committedVersion.get(),

fdbserver/GrvProxyServer.actor.cpp

@@ -26,6 +26,7 @@
 #include "fdbclient/GrvProxyInterface.h"
 #include "fdbserver/WaitFailure.h"
 #include "fdbserver/WorkerInterface.actor.h"
+#include "fdbrpc/sim_validation.h"
 #include "flow/flow.h"
 #include "flow/actorcompiler.h" // This must be the last #include.
 

fdbserver/workloads/Cycle.actor.cpp

@@ -132,6 +132,7 @@ struct CycleWorkload : TestWorkload {
 						// TraceEvent("CyclicTest").detail("Key", self->key(r2).toString()).detail("Value", self->value(r4).toString());
 						// TraceEvent("CyclicTest").detail("Key", self->key(r3).toString()).detail("Value", self->value(r2).toString());
 
+						tr.setOption(FDBTransactionOptions::USE_GRV_CACHE);
 						wait(tr.commit());
 						// TraceEvent("CycleCommit");
 						break;