MutationTracking now uses a vector of keys to track. Removed "Mutation" detail from DEBUG_MUTATION() events because they are duplicates of the fields already logged in the returned MutationTracking event, which are now renamed and combined into "Mutation". Removed more toString() calls in TraceEvent detail values.

This commit is contained in:
Steve Atherton 2021-08-09 23:29:09 -07:00
parent 2626fdc992
commit faa4154a56
8 changed files with 37 additions and 53 deletions

View File

@ -744,7 +744,6 @@ ACTOR Future<Void> saveMutationsToFile(BackupData* self, Version popVersion, int
DEBUG_MUTATION("addMutation", message.version.version, m)
.detail("Version", message.version.toString())
.detail("Mutation", m)
.detail("KCV", self->minKnownCommittedVersion)
.detail("SavedVersion", self->savedVersion);

View File

@ -941,8 +941,7 @@ ACTOR Future<Void> assignMutationsToStorageServers(CommitBatchContext* self) {
DEBUG_MUTATION("ProxyCommit", self->commitVersion, m)
.detail("Dbgid", pProxyCommitData->dbgid)
.detail("To", tags)
.detail("Mutation", m);
.detail("To", tags);
self->toCommit.addTags(tags);
if (pProxyCommitData->cacheInfo[m.param1]) {
self->toCommit.addTag(cacheTag);
@ -957,8 +956,7 @@ ACTOR Future<Void> assignMutationsToStorageServers(CommitBatchContext* self) {
// Fast path
DEBUG_MUTATION("ProxyCommit", self->commitVersion, m)
.detail("Dbgid", pProxyCommitData->dbgid)
.detail("To", ranges.begin().value().tags)
.detail("Mutation", m);
.detail("To", ranges.begin().value().tags);
ranges.begin().value().populateTags();
self->toCommit.addTags(ranges.begin().value().tags);
@ -995,8 +993,7 @@ ACTOR Future<Void> assignMutationsToStorageServers(CommitBatchContext* self) {
}
DEBUG_MUTATION("ProxyCommit", self->commitVersion, m)
.detail("Dbgid", pProxyCommitData->dbgid)
.detail("To", allSources)
.detail("Mutation", m);
.detail("To", allSources);
self->toCommit.addTags(allSources);
}

View File

@ -18,6 +18,7 @@
* limitations under the License.
*/
#include <algorithm>
#include <vector>
#include "fdbserver/MutationTracking.h"
#include "fdbserver/LogProtocolMessage.h"
@ -27,40 +28,32 @@
#error "You cannot use mutation tracking in a clean/release build."
#endif
// Track up to 2 keys in simulation via enabling MUTATION_TRACKING_ENABLED and setting the keys here.
StringRef debugKey = LiteralStringRef("");
StringRef debugKey2 = LiteralStringRef("\xff\xff\xff\xff");
// Track any of these keys in simulation via enabling MUTATION_TRACKING_ENABLED and setting the keys here.
std::vector<KeyRef> debugKeys = { ""_sr, "\xff\xff"_sr };
TraceEvent debugMutationEnabled(const char* context, Version version, MutationRef const& mutation) {
if ((mutation.type == mutation.ClearRange || mutation.type == mutation.DebugKeyRange) &&
((mutation.param1 <= debugKey && mutation.param2 > debugKey) ||
(mutation.param1 <= debugKey2 && mutation.param2 > debugKey2))) {
if (std::any_of(debugKeys.begin(), debugKeys.end(), [&mutation](const KeyRef& debugKey) {
return ((mutation.type == mutation.ClearRange || mutation.type == mutation.DebugKeyRange) &&
mutation.param1 <= debugKey && mutation.param2 > debugKey) ||
mutation.param1 == debugKey;
})) {
TraceEvent event("MutationTracking");
event.detail("At", context)
.detail("Version", version)
.detail("MutationType", typeString[mutation.type])
.detail("KeyBegin", mutation.param1)
.detail("KeyEnd", mutation.param2);
event.detail("At", context).detail("Version", version).detail("Mutation", mutation);
return event;
} else if (mutation.param1 == debugKey || mutation.param1 == debugKey2) {
TraceEvent event("MutationTracking");
event.detail("At", context)
.detail("Version", version)
.detail("MutationType", typeString[mutation.type])
.detail("Key", mutation.param1)
.detail("Value", mutation.param2);
return event;
} else {
return TraceEvent();
}
return TraceEvent();
}
TraceEvent debugKeyRangeEnabled(const char* context, Version version, KeyRangeRef const& keys) {
if (keys.contains(debugKey) || keys.contains(debugKey2)) {
return debugMutation(context, version, MutationRef(MutationRef::DebugKeyRange, keys.begin, keys.end));
} else {
return TraceEvent();
if (std::any_of(
debugKeys.begin(), debugKeys.end(), [&keys](const KeyRef& debugKey) { return keys.contains(debugKey); })) {
TraceEvent event("MutationTracking");
event.detail("At", context).detail("Version", version).detail("Mutation", MutationRef(MutationRef::DebugKeyRange, keys.begin, keys.end));
return event;
}
return TraceEvent();
}
TraceEvent debugTagsAndMessageEnabled(const char* context, Version version, StringRef commitBlob) {

View File

@ -63,8 +63,7 @@ struct StagingKey {
ASSERT(m.type != MutationRef::SetVersionstampedKey && m.type != MutationRef::SetVersionstampedValue);
DEBUG_MUTATION("StagingKeyAdd", newVersion.version, m)
.detail("Version", version.toString())
.detail("NewVersion", newVersion.toString())
.detail("Mutation", m);
.detail("NewVersion", newVersion.toString());
if (version == newVersion) {
// This could happen because the same mutation can be present in
// overlapping mutation logs, because new TLogs can copy mutations

View File

@ -892,8 +892,7 @@ ACTOR Future<Void> sendMutationsToApplier(
MutationRef mutation = mvector[splitMutationIndex];
UID applierID = nodeIDs[splitMutationIndex];
DEBUG_MUTATION("RestoreLoaderSplittedMutation", commitVersion.version, mutation)
.detail("Version", commitVersion.toString())
.detail("Mutation", mutation);
.detail("Version", commitVersion.toString());
// CAREFUL: The splitted mutations' lifetime is shorter than the for-loop
// Must use deep copy for splitted mutations
applierVersionedMutationsBuffer[applierID].push_back_deep(
@ -996,7 +995,7 @@ void splitMutation(const KeyRangeMap<UID>& krMap,
VectorRef<MutationRef>& mvector,
Arena& nodeIDs_arena,
VectorRef<UID>& nodeIDs) {
TraceEvent(SevDebug, "FastRestoreSplitMutation").detail("Mutation", m.toString());
TraceEvent(SevDebug, "FastRestoreSplitMutation").detail("Mutation", m);
ASSERT(mvector.empty());
ASSERT(nodeIDs.empty());
auto r = krMap.intersectingRanges(KeyRangeRef(m.param1, m.param2));
@ -1527,15 +1526,15 @@ TEST_CASE("/FastRestore/RestoreLoader/splitMutation") {
KeyRange krange(KeyRangeRef(result.param1, result.param2));
KeyRange krange2(KeyRangeRef(result2.param1, result2.param2));
TraceEvent("Result")
.detail("KeyRange1", krange.toString())
.detail("KeyRange2", krange2.toString())
.detail("KeyRange1", krange)
.detail("KeyRange2", krange2)
.detail("ApplierID1", applierID)
.detail("ApplierID2", applierID2);
if (krange != krange2 || applierID != applierID2) {
TraceEvent(SevError, "IncorrectResult")
.detail("Mutation", mutation.toString())
.detail("KeyRange1", krange.toString())
.detail("KeyRange2", krange2.toString())
.detail("Mutation", mutation)
.detail("KeyRange1", krange)
.detail("KeyRange2", krange2)
.detail("ApplierID1", applierID)
.detail("ApplierID2", applierID2);
}

View File

@ -1582,7 +1582,7 @@ void CacheRangeInfo::addMutation(Version version, MutationRef const& mutation) {
// even allow them on un-assigned range?)
TraceEvent(SevError, "DeliveredToNotAssigned")
.detail("Version", version)
.detail("Mutation", mutation.toString());
.detail("Mutation", mutation);
ASSERT(false); // Mutation delivered to notAssigned cacheRange!
}
}
@ -1719,7 +1719,7 @@ public:
DEBUG_MUTATION("SCUpdateMutation", ver, m);
if (m.param1.startsWith(systemKeys.end)) {
//TraceEvent("SCPrivateData", data->thisServerID).detail("Mutation", m.toString()).detail("Version", ver);
//TraceEvent("SCPrivateData", data->thisServerID).detail("Mutation", m).detail("Version", ver);
applyPrivateCacheData(data, m);
} else {
splitMutation(data, data->cachedRangeMap, m, ver);
@ -2011,7 +2011,7 @@ ACTOR Future<Void> pullAsyncData(StorageCacheData* data) {
}
} else {
TraceEvent(SevError, "DiscardingPeekedData", data->thisServerID)
.detail("Mutation", msg.toString())
.detail("Mutation", msg)
.detail("CursorVersion", cloneCursor2->version().version)
.detail("DataVersion", data->version.get());
}

View File

@ -3198,9 +3198,7 @@ void ShardInfo::addMutation(Version version, MutationRef const& mutation) {
else if (readWrite)
readWrite->addMutation(version, mutation, this->keys, readWrite->updateEagerReads);
else if (mutation.type != MutationRef::ClearRange) {
TraceEvent(SevError, "DeliveredToNotAssigned")
.detail("Version", version)
.detail("Mutation", mutation);
TraceEvent(SevError, "DeliveredToNotAssigned").detail("Version", version).detail("Mutation", mutation);
ASSERT(false); // Mutation delivered to notAssigned shard!
}
}
@ -3828,7 +3826,7 @@ ACTOR Future<Void> update(StorageServer* data, bool* pReceivedUpdate) {
(msg.param1.size() < 2 || msg.param1[0] != 0xff || msg.param1[1] != 0xff) &&
deterministicRandom()->random01() < 0.05) {
TraceEvent(SevWarnAlways, "TSSInjectDropMutation", data->thisServerID)
.detail("Mutation", msg.toString())
.detail("Mutation", msg)
.detail("Version", cloneCursor2->version().toString());
} else if (data->isTSSInQuarantine() &&
(msg.param1.size() < 2 || msg.param1[0] != 0xff || msg.param1[1] != 0xff)) {
@ -4148,7 +4146,6 @@ void StorageServerDisk::writeKeyValue(KeyValueRef kv) {
}
void StorageServerDisk::writeMutation(MutationRef mutation) {
// FIXME: DEBUG_MUTATION(debugContext, debugVersion, *m);
if (mutation.type == MutationRef::SetValue) {
storage->set(KeyValueRef(mutation.param1, mutation.param2));
} else if (mutation.type == MutationRef::ClearRange) {

View File

@ -258,13 +258,13 @@ struct SerializabilityWorkload : TestWorkload {
} else if (ops[opNum].mutationOp.present()) {
auto& op = ops[opNum].mutationOp.get();
if (op.type == MutationRef::SetValue) {
//TraceEvent("SRL_Set").detail("Mutation", op.toString());
//TraceEvent("SRL_Set").detail("Mutation", op);
tr->set(op.param1, op.param2);
} else if (op.type == MutationRef::ClearRange) {
//TraceEvent("SRL_Clear").detail("Mutation", op.toString());
//TraceEvent("SRL_Clear").detail("Mutation", op);
tr->clear(KeyRangeRef(op.param1, op.param2));
} else {
//TraceEvent("SRL_AtomicOp").detail("Mutation", op.toString());
//TraceEvent("SRL_AtomicOp").detail("Mutation", op);
tr->atomicOp(op.param1, op.param2, op.type);
}
} else if (ops[opNum].readConflictOp.present()) {