add debug traces

fdbserver/LogRouter.actor.cpp

@@ -35,7 +35,7 @@
 #include "flow/Histogram.h"
 #include "flow/TDMetric.actor.h"
 #include "flow/network.h"
-
+#include "flow/DebugTrace.h"
 #include "flow/actorcompiler.h" // This must be the last #include.
 
 struct LogRouterData {
@@ -499,9 +499,13 @@ Future<Void> logRouterPeekMessages(PromiseType replyPromise,
 		}
 	}
 
-	//TraceEvent("LogRouterPeek1", self->dbgid).detail("From", replyPromise.getEndpoint().getPrimaryAddress()).detail("Ver", self->version.get()).detail("Begin", reqBegin);
+	DebugLogTraceEvent("LogRouterPeek0", self->dbgid)
+	    .detail("ReturnIfBlocked", reqReturnIfBlocked)
+	    .detail("Tag", reqTag.toString())
+	    .detail("Ver", self->version.get())
+	    .detail("Begin", reqBegin);
+
 	if (reqReturnIfBlocked && self->version.get() < reqBegin) {
-		//TraceEvent("LogRouterPeek2", self->dbgid);
 		replyPromise.sendError(end_of_stream());
 		if (reqSequence.present()) {
 			auto& trackerData = self->peekTracker[peekId];
@@ -603,7 +607,7 @@ Future<Void> logRouterPeekMessages(PromiseType replyPromise,
 	}
 
 	replyPromise.send(reply);
-	DisabledTraceEvent("LogRouterPeek4", self->dbgid)
+	DebugLogTraceEvent("LogRouterPeek4", self->dbgid)
 	    .detail("Tag", reqTag.toString())
 	    .detail("ReqBegin", reqBegin)
 	    .detail("End", reply.end)
@@ -638,8 +642,9 @@ ACTOR Future<Void> logRouterPeekStream(LogRouterData* self, TLogPeekStreamReques
 			}
 		} catch (Error& e) {
 			self->activePeekStreams--;
-			TraceEvent(SevDebug, "TLogPeekStreamEnd", self->dbgid)
+			TraceEvent(SevDebug, "LogRouterPeekStreamEnd", self->dbgid)
 			    .errorUnsuppressed(e)
+			    .detail("Tag", req.tag)
 			    .detail("PeerAddr", req.reply.getEndpoint().getPrimaryAddress());
 
 			if (e.code() == error_code_end_of_stream || e.code() == error_code_operation_obsolete) {

fdbserver/LogSystemPeekCursor.actor.cpp

@@ -23,6 +23,7 @@
 #include "fdbserver/Knobs.h"
 #include "fdbserver/MutationTracking.h"
 #include "fdbrpc/ReplicationUtils.h"
+#include "flow/DebugTrace.h"
 #include "flow/actorcompiler.h" // has to be last include
 
 // create a peek stream for cursor when it's possible
@@ -35,9 +36,12 @@ ACTOR Future<Void> tryEstablishPeekStream(ILogSystem::ServerPeekCursor* self) {
 	}
 	wait(IFailureMonitor::failureMonitor().onStateEqual(self->interf->get().interf().peekStreamMessages.getEndpoint(),
 	                                                    FailureStatus(false)));
-	self->peekReplyStream = self->interf->get().interf().peekStreamMessages.getReplyStream(TLogPeekStreamRequest(
-	    self->messageVersion.version, self->tag, self->returnIfBlocked, std::numeric_limits<int>::max()));
-	TraceEvent(SevDebug, "SPC_StreamCreated", self->randomID)
+
+	auto req = TLogPeekStreamRequest(
+	    self->messageVersion.version, self->tag, self->returnIfBlocked, std::numeric_limits<int>::max());
+	self->peekReplyStream = self->interf->get().interf().peekStreamMessages.getReplyStream(req);
+	DebugLogTraceEvent(SevDebug, "SPC_StreamCreated", self->randomID)
+	    .detail("Tag", self->tag)
 	    .detail("PeerAddr", self->interf->get().interf().peekStreamMessages.getEndpoint().getPrimaryAddress())
 	    .detail("PeerToken", self->interf->get().interf().peekStreamMessages.getEndpoint().token);
 	return Void();
@@ -56,7 +60,7 @@ ILogSystem::ServerPeekCursor::ServerPeekCursor(Reference<AsyncVar<OptionalInterf
     fastReplies(0), unknownReplies(0) {
 	this->results.maxKnownVersion = 0;
 	this->results.minKnownCommittedVersion = 0;
-	DisabledTraceEvent(SevDebug, "SPC_Starting", randomID)
+	DebugLogTraceEvent(SevDebug, "SPC_Starting", randomID)
 	    .detail("Tag", tag.toString())
 	    .detail("UsePeekStream", usePeekStream)
 	    .detail("Begin", begin)
@@ -356,7 +360,8 @@ ACTOR Future<Void> serverPeekStreamGetMore(ILogSystem::ServerPeekCursor* self, T
 					}
 					updateCursorWithReply(self, res);
 					expectedBegin = res.end;
-					DisabledTraceEvent(SevDebug, "SPC_GetMoreB", self->randomID)
+					DebugLogTraceEvent(SevDebug, "SPC_GetMoreB", self->randomID)
+					    .detail("Tag", self->tag)
 					    .detail("Has", self->hasMessage())
 					    .detail("End", res.end)
 					    .detail("Popped", res.popped.present() ? res.popped.get() : 0);
@@ -368,7 +373,9 @@ ACTOR Future<Void> serverPeekStreamGetMore(ILogSystem::ServerPeekCursor* self, T
 				}
 			}
 		} catch (Error& e) {
-			DisabledTraceEvent(SevDebug, "SPC_GetMoreB_Error", self->randomID).errorUnsuppressed(e);
+			DebugLogTraceEvent(SevDebug, "SPC_GetMoreB_Error", self->randomID)
+			    .errorUnsuppressed(e)
+			    .detail("Tag", self->tag);
 			if (e.code() == error_code_connection_failed || e.code() == error_code_operation_obsolete) {
 				// NOTE: delay in order to avoid the endless retry loop block other tasks
 				self->peekReplyStream.reset();

fdbserver/TLogServer.actor.cpp

@@ -46,6 +46,7 @@
 #include "fdbserver/RecoveryState.h"
 #include "fdbserver/FDBExecHelper.actor.h"
 #include "flow/Histogram.h"
+#include "flow/DebugTrace.h"
 #include "flow/actorcompiler.h" // This must be the last #include.
 
 struct TLogQueueEntryRef {
@@ -1675,6 +1676,7 @@ Future<Void> tLogPeekMessages(PromiseType replyPromise,
 	state int sequence = -1;
 	state UID peekId;
 	state double queueStart = now();
+	state Future<Void> recoveryTxnReceived = logData->recoveryTxnReceived.getFuture();
 
 	if (reqTag.locality == tagLocalityTxs && reqTag.id >= logData->txsTags && logData->txsTags > 0) {
 		reqTag.id = reqTag.id % logData->txsTags;
@@ -1746,7 +1748,7 @@ Future<Void> tLogPeekMessages(PromiseType replyPromise,
 		return Void();
 	}
 
-	DisabledTraceEvent("TLogPeekMessages0", self->dbgid)
+	DebugLogTraceEvent("TLogPeekMessages0", self->dbgid)
 	    .detail("LogId", logData->logId)
 	    .detail("Tag", reqTag.toString())
 	    .detail("ReqBegin", reqBegin)
@@ -1758,11 +1760,17 @@ Future<Void> tLogPeekMessages(PromiseType replyPromise,
 		wait(delay(SERVER_KNOBS->TLOG_PEEK_DELAY, g_network->getCurrentTask()));
 	}
 	if (!logData->stopped && reqTag.locality != tagLocalityTxs && reqTag != txsTag) {
+		DebugLogTraceEvent("TLogPeekMessages1", self->dbgid)
+		    .detail("LogId", logData->logId)
+		    .detail("Tag", reqTag.toString())
+		    .detail("ReqBegin", reqBegin)
+		    .detail("Version", logData->version.get())
+		    .detail("RecoveredAt", logData->recoveredAt);
 		// Make sure the peek reply has the recovery txn for the current TLog.
 		// Older generation TLog has been stopped and doesn't wait here.
 		// Similarly during recovery, reading transaction state store
 		// doesn't wait here.
-		wait(logData->recoveryTxnReceived.getFuture());
+		wait(recoveryTxnReceived);
 	}
 
 	if (logData->locality != tagLocalitySatellite && reqTag.locality == tagLocalityLogRouter) {
@@ -1803,7 +1811,7 @@ Future<Void> tLogPeekMessages(PromiseType replyPromise,
 		poppedVer = poppedVersion(logData, reqTag);
 	}
 
-	DisabledTraceEvent("TLogPeekMessages1", self->dbgid)
+	DebugLogTraceEvent("TLogPeekMessages2", self->dbgid)
 	    .detail("LogId", logData->logId)
 	    .detail("Tag", reqTag.toString())
 	    .detail("ReqBegin", reqBegin)
@@ -1852,7 +1860,7 @@ Future<Void> tLogPeekMessages(PromiseType replyPromise,
 		onlySpilled = false;
 
 		// grab messages from disk
-		DisabledTraceEvent("TLogPeekMessages2", self->dbgid)
+		DebugLogTraceEvent("TLogPeekMessages3", self->dbgid)
 		    .detail("ReqBegin", reqBegin)
 		    .detail("Tag", reqTag.toString());
 		if (reqBegin <= logData->persistentDataDurableVersion) {
@@ -2015,7 +2023,7 @@ Future<Void> tLogPeekMessages(PromiseType replyPromise,
 	reply.end = endVersion;
 	reply.onlySpilled = onlySpilled;
 
-	DisabledTraceEvent("TLogPeekMessages4", self->dbgid)
+	DebugLogTraceEvent("TLogPeekMessages4", self->dbgid)
 	    .detail("LogId", logData->logId)
 	    .detail("Tag", reqTag.toString())
 	    .detail("ReqBegin", reqBegin)
@@ -2101,6 +2109,7 @@ ACTOR Future<Void> tLogPeekStream(TLogData* self, TLogPeekStreamRequest req, Ref
 			self->activePeekStreams--;
 			TraceEvent(SevDebug, "TLogPeekStreamEnd", logData->logId)
 			    .errorUnsuppressed(e)
+			    .detail("Tag", req.tag)
 			    .detail("PeerAddr", req.reply.getEndpoint().getPrimaryAddress());
 
 			if (e.code() == error_code_end_of_stream || e.code() == error_code_operation_obsolete) {

flow/DebugTrace.h

@@ -0,0 +1,13 @@
+//
+// Created by Xiaoxi Wang on 5/18/22.
+//
+
+#ifndef FOUNDATIONDB_DEBUGTRACE_H
+#define FOUNDATIONDB_DEBUGTRACE_H
+
+#define DebugTraceEvent(enable, ...) enable&& TraceEvent(__VA_ARGS__)
+
+constexpr bool debugLogTraces = true;
+#define DebugLogTraceEvent(...) DebugTraceEvent(debugLogTraces, __VA_ARGS__)
+
+#endif // FOUNDATIONDB_DEBUGTRACE_H