wbtiger
/
foundationdb
mirror of https://github.com/apple/foundationdb.git
1
0
Fork 0
Code Issues Packages Projects Releases Wiki Activity

Clean up and rework the debugMutation API. 

As a relatively unknown debugging tool for simulation tests, one could
have simulation print when a particular key is handled in various stages
of the commit process.  This functionality was enabled by changing a 0
to a 1 in an #if, and changing a constant to the key in question.

As a proxy and storage server handle mutations, they call debugMutation
or debugKeyRange, which then checks against the mutation against the key
in question, and logs if they match.  A mixture of printfs and
TraceEvents would then be emitted, and for this to actually be usable,
one also needs to comment out some particularly spammy debugKeyRange()
calls.

This PR reworks the API of debugMutation/debugKeyRange, pulls it out
into its own file, and trims what is logged by default into something
useful and understandable:
* debugMutation() now returns a TraceEvent, that one can add more details to before it is logged.
* Data distribution and storage server cleanup operations are no longer logged by default
This commit is contained in:
Alex Miller 2020-03-27 01:35:26 -07:00
parent 0547cf2b4c
commit 72e5891058
12 changed files with 139 additions and 117 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

10
fdbclient/CommitTransaction.h
View File

@ -124,6 +124,13 @@ struct MutationRef {
};
};
template<>
struct Traceable<MutationRef> : std::true_type {
static std::string toString(MutationRef const& value) {
return value.toString();
}
};
// A 'single key mutation' is one which affects exactly the value of the key specified by its param1
static inline bool isSingleKeyMutation(MutationRef::Type type) {
return (MutationRef::SINGLE_KEY_MASK & (1<<type)) != 0;
@ -183,7 +190,4 @@ struct CommitTransactionRef {
}
};
bool debugMutation( const char* context, Version version, MutationRef const& m );
bool debugKeyRange( const char* context, Version version, KeyRangeRef const& keyRange );
#endif

14
fdbclient/FDBTypes.h
View File

@ -222,11 +222,25 @@ std::string describe( std::vector<T> const& items, int max_items = -1 ) {
return describeList(items, max_items);
}
template<typename T>
struct Traceable<std::vector<T>> : std::true_type {
static std::string toString(const std::vector<T>& value) {
return describe(value);
}
};
template <class T>
std::string describe( std::set<T> const& items, int max_items = -1 ) {
return describeList(items, max_items);
}
template<typename T>
struct Traceable<std::set<T>> : std::true_type {
static std::string toString(const std::set<T>& value) {
return describe(value);
}
};
std::string printable( const StringRef& val );
std::string printable( const std::string& val );
std::string printable( const KeyRangeRef& range );

10
fdbserver/MasterProxyServer.actor.cpp
View File

@ -38,6 +38,7 @@
#include "fdbserver/LogSystem.h"
#include "fdbserver/LogSystemDiskQueueAdapter.h"
#include "fdbserver/MasterInterface.h"
#include "fdbserver/MutationTracking.h"
#include "fdbserver/RecoveryState.h"
#include "fdbserver/ServerDBInfo.h"
#include "fdbserver/WaitFailure.h"
@ -938,8 +939,7 @@ ACTOR Future<Void> commitBatch(
self->singleKeyMutationEvent->log();
}
if (debugMutation("ProxyCommit", commitVersion, m))
TraceEvent("ProxyCommitTo", self->dbgid).detail("To", describe(tags)).detail("Mutation", m.toString()).detail("Version", commitVersion);
debugMutation("ProxyCommit", commitVersion, m).detail("Dbgid", self->dbgid).detail("To", tags).detail("Mutation", m);
toCommit.addTags(tags);
if(self->cacheInfo[m.param1]) {
@ -954,8 +954,7 @@ ACTOR Future<Void> commitBatch(
++firstRange;
if (firstRange == ranges.end()) {
// Fast path
if (debugMutation("ProxyCommit", commitVersion, m))
TraceEvent("ProxyCommitTo", self->dbgid).detail("To", describe(ranges.begin().value().tags)).detail("Mutation", m.toString()).detail("Version", commitVersion);
debugMutation("ProxyCommit", commitVersion, m).detail("Dbgid", self->dbgid).detail("To", ranges.begin().value().tags).detail("Mutation", m);
ranges.begin().value().populateTags();
toCommit.addTags(ranges.begin().value().tags);
@ -967,8 +966,7 @@ ACTOR Future<Void> commitBatch(
r.value().populateTags();
allSources.insert(r.value().tags.begin(), r.value().tags.end());
}
if (debugMutation("ProxyCommit", commitVersion, m))
TraceEvent("ProxyCommitTo", self->dbgid).detail("To", describe(allSources)).detail("Mutation", m.toString()).detail("Version", commitVersion);
debugMutation("ProxyCommit", commitVersion, m).detail("Dbgid", self->dbgid).detail("To", allSources).detail("Mutation", m);
toCommit.addTags(allSources);
}

61
fdbserver/MutationTracking.cpp Normal file
View File

@ -0,0 +1,61 @@
/*
* MutationTracking.cpp
*
* This source file is part of the FoundationDB open source project
*
* Copyright 2013-2020 Apple Inc. and the FoundationDB project authors
*
* Licensed under the Apache License, Version 2.0 (the "License");
* you may not use this file except in compliance with the License.
* You may obtain a copy of the License at
*
* http://www.apache.org/licenses/LICENSE-2.0
*
* Unless required by applicable law or agreed to in writing, software
* distributed under the License is distributed on an "AS IS" BASIS,
* WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
* See the License for the specific language governing permissions and
* limitations under the License.
*/
#include <vector>
#include "fdbserver/MutationTracking.h"
#include "fdbserver/LogProtocolMessage.h"
#if defined(FDB_CLEAN_BUILD) && MUTATION_TRACKING_ENABLED
#error "You cannot use mutation tracking in a clean/release build."
#endif
StringRef debugKey = LiteralStringRef( "\xff/globals/lastEpochEnd" );
StringRef debugKey2 = LiteralStringRef( "\xff\xff\xff\xff" );
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))) {
return std::move(TraceEvent("MutationTracking").detail("At", context).detail("Version", version).detail("MutationType", typeString[mutation.type]).detail("KeyBegin", mutation.param1).detail("KeyEnd", mutation.param2));
} else if (mutation.param1 == debugKey || mutation.param1 == debugKey2) {
return std::move(TraceEvent("MutationTracking").detail("At", context).detail("Version", version).detail("MutationType", typeString[mutation.type]).detail("Key", mutation.param1).detail("Value", mutation.param2));
} else {
return std::move(TraceEvent());
}
}
TraceEvent debugKeyRangeEnabled( const char* context, Version version, KeyRangeRef const& keys ) {
if (keys.contains(debugKey) || keys.contains(debugKey2)) {
return std::move(debugMutation(context, version, MutationRef(MutationRef::DebugKeyRange, keys.begin, keys.end) ));
} else {
return std::move(TraceEvent());
}
}
#if MUTATION_TRACKING_ENABLED
TraceEvent debugMutation( const char* context, Version version, MutationRef const& mutation ) {
return debugMutationEnabled( context, version, mutation );
}
TraceEvent debugKeyRange( const char* context, Version version, KeyRangeRef const& keys ) {
return debugKeyRangeEnabled( context, version, keys );
}
#else
TraceEvent debugMutation( const char* context, Version version, MutationRef const& mutation ) { return std::move(TraceEvent()); }
TraceEvent debugKeyRange( const char* context, Version version, KeyRangeRef const& keys ) { return std::move(TraceEvent()); }
#endif

33
fdbserver/MutationTracking.h Normal file
View File

@ -0,0 +1,33 @@
/*
* MutationTracking.h
*
* This source file is part of the FoundationDB open source project
*
* Copyright 2013-2020 Apple Inc. and the FoundationDB project authors
*
* Licensed under the Apache License, Version 2.0 (the "License");
* you may not use this file except in compliance with the License.
* You may obtain a copy of the License at
*
* http://www.apache.org/licenses/LICENSE-2.0
*
* Unless required by applicable law or agreed to in writing, software
* distributed under the License is distributed on an "AS IS" BASIS,
* WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
* See the License for the specific language governing permissions and
* limitations under the License.
*/
#ifndef _FDBSERVER_MUTATIONTRACKING_H_
#define _FDBSERVER_MUTATIONTRACKING_H_
#pragma once
#include "fdbclient/FDBTypes.h"
#include "fdbclient/CommitTransaction.h"
#define MUTATION_TRACKING_ENABLED 0
TraceEvent debugMutation( const char* context, Version version, MutationRef const& mutation );
TraceEvent debugKeyRange( const char* context, Version version, KeyRangeRef const& keys );
#endif

15
fdbserver/StorageCache.actor.cpp
View File

@ -26,6 +26,7 @@
#include "fdbclient/Atomic.h"
#include "fdbclient/Notified.h"
#include "fdbserver/LogSystem.h"
#include "fdbserver/MutationTracking.h"
#include "fdbserver/WaitFailure.h"
#include "fdbserver/WorkerInterface.actor.h"
#include "flow/actorcompiler.h" // This must be the last #include.
@ -710,22 +711,10 @@ void StorageCacheData::addMutation(KeyRangeRef const& cachedKeyRange, Version ve
return;
}
expanded = addMutationToMutationLog(mLog, expanded);
if (debugMutation("expandedMutation", version, expanded)) {
const char* type =
mutation.type == MutationRef::SetValue ? "SetValue" :
mutation.type == MutationRef::ClearRange ? "ClearRange" :
mutation.type == MutationRef::DebugKeyRange ? "DebugKeyRange" :
mutation.type == MutationRef::DebugKey ? "DebugKey" :
"UnknownMutation";
printf("DEBUGMUTATION:\t%.6f\t%s\t%s\t%s\t%s\t%s\n",
now(), g_network->getLocalAddress().toString().c_str(), "originalMutation",
type, printable(mutation.param1).c_str(), printable(mutation.param2).c_str());
printf(" Cached Key-range: %s - %s\n", printable(cachedKeyRange.begin).c_str(), printable(cachedKeyRange.end).c_str());
}
debugMutation("expandedMutation", version, expanded).detail("Begin", cachedKeyRange.begin).detail("End", cachedKeyRange.end);
applyMutation( this, expanded, mLog.arena(), mutableData() );
printf("\nSCUpdate: Printing versioned tree after applying mutation\n");
mutableData().printTree(version);
}
// Helper class for updating the storage cache (i.e. applying mutations)

20
fdbserver/WorkerInterface.actor.h
View File

@ -388,26 +388,6 @@ struct EventLogRequest {
}
};
struct DebugEntryRef {
double time;
NetworkAddress address;
StringRef context;
Version version;
MutationRef mutation;
DebugEntryRef() {}
DebugEntryRef( const char* c, Version v, MutationRef const& m ) : context((const uint8_t*)c,strlen(c)), version(v), mutation(m), time(now()), address( g_network->getLocalAddress() ) {}
DebugEntryRef( Arena& a, DebugEntryRef const& d ) : time(d.time), address(d.address), context(d.context), version(d.version), mutation(a, d.mutation) {}
size_t expectedSize() const {
return context.expectedSize() + mutation.expectedSize();
}
template <class Ar>
void serialize(Ar& ar) {
serializer(ar, time, address, context, version, mutation);
}
};
struct DiskStoreRequest {
constexpr static FileIdentifier file_identifier = 1986262;
bool includePartialStores;

57
fdbserver/fdbserver.actor.cpp
View File

@ -198,63 +198,6 @@ bool enableFailures = true;
#define test_assert(x) if (!(x)) { cout << "Test failed: " #x << endl; return false; }
vector< Standalone<VectorRef<DebugEntryRef>> > debugEntries;
int64_t totalDebugEntriesSize = 0;
#if CENABLED(0, NOT_IN_CLEAN)
StringRef debugKey = LiteralStringRef( "" );
StringRef debugKey2 = LiteralStringRef( "\xff\xff\xff\xff" );
bool debugMutation( const char* context, Version version, MutationRef const& mutation ) {
if ((mutation.type == mutation.SetValue || mutation.type == mutation.AddValue || mutation.type==mutation.DebugKey) && (mutation.param1 == debugKey || mutation.param1 == debugKey2))
;//TraceEvent("MutationTracking").detail("At", context).detail("Version", version).detail("MutationType", "SetValue").detail("Key", mutation.param1).detail("Value", mutation.param2);
else if ((mutation.type == mutation.ClearRange || mutation.type == mutation.DebugKeyRange) && ((mutation.param1<=debugKey && mutation.param2>debugKey) || (mutation.param1<=debugKey2 && mutation.param2>debugKey2)))
;//TraceEvent("MutationTracking").detail("At", context).detail("Version", version).detail("MutationType", "ClearRange").detail("KeyBegin", mutation.param1).detail("KeyEnd", mutation.param2);
else
return false;
const char* type =
mutation.type == MutationRef::SetValue ? "SetValue" :
mutation.type == MutationRef::ClearRange ? "ClearRange" :
mutation.type == MutationRef::AddValue ? "AddValue" :
mutation.type == MutationRef::DebugKeyRange ? "DebugKeyRange" :
mutation.type == MutationRef::DebugKey ? "DebugKey" :
"UnknownMutation";
printf("DEBUGMUTATION:\t%.6f\t%s\t%s\t%lld\t%s\t%s\t%s\n", now(), g_network->getLocalAddress().toString().c_str(), context, version, type, printable(mutation.param1).c_str(), printable(mutation.param2).c_str());
return true;
}
bool debugKeyRange( const char* context, Version version, KeyRangeRef const& keys ) {
if (keys.contains(debugKey) || keys.contains(debugKey2)) {
debugMutation(context, version, MutationRef(MutationRef::DebugKeyRange, keys.begin, keys.end) );
//TraceEvent("MutationTracking").detail("At", context).detail("Version", version).detail("KeyBegin", keys.begin).detail("KeyEnd", keys.end);
return true;
} else
return false;
}
#elif CENABLED(0, NOT_IN_CLEAN)
bool debugMutation( const char* context, Version version, MutationRef const& mutation ) {
if (!debugEntries.size() || debugEntries.back().size() >= 1000) {
if (debugEntries.size()) totalDebugEntriesSize += debugEntries.back().arena().getSize() + sizeof(debugEntries.back());
debugEntries.push_back(Standalone<VectorRef<DebugEntryRef>>());
TraceEvent("DebugMutationBuffer").detail("Bytes", totalDebugEntriesSize);
}
auto& v = debugEntries.back();
v.push_back_deep( v.arena(), DebugEntryRef(context, version, mutation) );
return false; // No auxiliary logging
}
bool debugKeyRange( const char* context, Version version, KeyRangeRef const& keys ) {
return debugMutation( context, version, MutationRef(MutationRef::DebugKeyRange, keys.begin, keys.end) );
}
#else // Default implementation.
bool debugMutation( const char* context, Version version, MutationRef const& mutation ) { return false; }
bool debugKeyRange( const char* context, Version version, KeyRangeRef const& keys ) { return false; }
#endif
#ifdef _WIN32
#include <sddl.h>

2
fdbserver/fdbserver.vcxproj
View File

@ -41,6 +41,7 @@
<ActorCompiler Include="CoordinatedState.actor.cpp" />
<ActorCompiler Include="CoroFlow.actor.cpp" />
<ActorCompiler Include="MasterProxyServer.actor.cpp" />
<ClCompile Include="MutationTracking.cpp" />
<ActorCompiler Include="KeyValueStoreSQLite.actor.cpp" />
<ActorCompiler Include="LeaderElection.actor.cpp" />
<ActorCompiler Include="Ratekeeper.actor.cpp" />
@ -202,6 +203,7 @@
<ClInclude Include="LogSystemConfig.h" />
<ClInclude Include="LogSystemDiskQueueAdapter.h" />
<ClInclude Include="MasterInterface.h" />
<ClInclude Include="MutationTracking.h" />
<ActorCompiler Include="MoveKeys.actor.h">
<EnableCompile Condition="'$(Configuration)|$(Platform)'=='Debug|X64'">false</EnableCompile>
<EnableCompile Condition="'$(Configuration)|$(Platform)'=='Release|X64'">false</EnableCompile>

31
fdbserver/storageserver.actor.cpp
View File

@ -42,6 +42,7 @@
#include "fdbserver/LogProtocolMessage.h"
#include "fdbserver/LogSystem.h"
#include "fdbserver/MoveKeys.actor.h"
#include "fdbserver/MutationTracking.h"
#include "fdbserver/RecoveryState.h"
#include "fdbserver/StorageMetrics.h"
#include "fdbserver/ServerDBInfo.h"
@ -2288,7 +2289,8 @@ void changeServerKeys( StorageServer* data, const KeyRangeRef& keys, bool nowAss
// .detail("Context", changeServerKeysContextName[(int)context]);
validate(data);
debugKeyRange( nowAssigned ? "KeysAssigned" : "KeysUnassigned", version, keys );
// TODO(alexmiller): Figure out how to selectively enable spammy data distribution events.
//debugKeyRange( nowAssigned ? "KeysAssigned" : "KeysUnassigned", version, keys );
bool isDifferent = false;
auto existingShards = data->shards.intersectingRanges(keys);
@ -2414,18 +2416,7 @@ void StorageServer::addMutation(Version version, MutationRef const& mutation, Ke
return;
}
expanded = addMutationToMutationLog(mLog, expanded);
if (debugMutation("expandedMutation", version, expanded)) {
const char* type =
mutation.type == MutationRef::SetValue ? "SetValue" :
mutation.type == MutationRef::ClearRange ? "ClearRange" :
mutation.type == MutationRef::DebugKeyRange ? "DebugKeyRange" :
mutation.type == MutationRef::DebugKey ? "DebugKey" :
"UnknownMutation";
printf("DEBUGMUTATION:\t%.6f\t%s\t%s\t%" PRId64 "\t%s\t%s\t%s\n", now(), g_network->getLocalAddress().toString().c_str(), "originalMutation", version, type, printable(mutation.param1).c_str(), printable(mutation.param2).c_str());
printf(" shard: %s - %s\n", printable(shard.begin).c_str(), printable(shard.end).c_str());
if (mutation.type == MutationRef::ClearRange && mutation.param2 != shard.end)
printf(" eager: %s\n", printable( eagerReads->getKeyEnd( mutation.param2 ) ).c_str() );
}
debugMutation("applyMutation", version, expanded).detail("UID", thisServerID).detail("ShardBegin", shard.begin).detail("ShardEnd", shard.end);
applyMutation( this, expanded, mLog.arena(), mutableData() );
//printf("\nSSUpdate: Printing versioned tree after applying mutation\n");
//mutableData().printTree(version);
@ -2766,7 +2757,8 @@ ACTOR Future<Void> update( StorageServer* data, bool* pReceivedUpdate )
rd >> msg;
if (ver != invalidVersion) { // This change belongs to a version < minVersion
if (debugMutation("SSPeek", ver, msg) || ver == 1) {
debugMutation("SSPeek", ver, msg).detail("ServerID", data->thisServerID);
if (ver == 1) {
TraceEvent("SSPeekMutation", data->thisServerID);
// The following trace event may produce a value with special characters
//TraceEvent("SSPeekMutation", data->thisServerID).detail("Mutation", msg.toString()).detail("Version", cloneCursor2->version().toString());
@ -2819,7 +2811,8 @@ ACTOR Future<Void> update( StorageServer* data, bool* pReceivedUpdate )
}
if(ver != invalidVersion && ver > data->version.get()) {
debugKeyRange("SSUpdate", ver, allKeys);
// TODO(alexmiller): Update to version tracking.
debugKeyRange("SSUpdate", ver, KeyRangeRef());
data->mutableData().createNewVersion(ver);
if (data->otherError.getFuture().isReady()) data->otherError.getFuture().get();
@ -3033,7 +3026,7 @@ void StorageServerDisk::writeMutation( MutationRef mutation ) {
void StorageServerDisk::writeMutations( MutationListRef mutations, Version debugVersion, const char* debugContext ) {
for(auto m = mutations.begin(); m; ++m) {
debugMutation(debugContext, debugVersion, *m);
debugMutation(debugContext, debugVersion, *m).detail("UID", data->thisServerID);
if (m->type == MutationRef::SetValue) {
storage->set( KeyValueRef(m->param1, m->param2) );
} else if (m->type == MutationRef::ClearRange) {
@ -3050,7 +3043,8 @@ bool StorageServerDisk::makeVersionMutationsDurable( Version& prevStorageVersion
if (u != data->getMutationLog().end() && u->first <= newStorageVersion) {
VersionUpdateRef const& v = u->second;
ASSERT( v.version > prevStorageVersion && v.version <= newStorageVersion );
debugKeyRange("makeVersionMutationsDurable", v.version, allKeys);
// TODO(alexmiller): Update to version tracking.
debugKeyRange("makeVersionMutationsDurable", v.version, KeyRangeRef());
writeMutations(v.mutations, v.version, "makeVersionDurable");
for(auto m=v.mutations.begin(); m; ++m)
bytesLeft -= mvccStorageBytes(*m);
@ -3236,7 +3230,8 @@ ACTOR Future<bool> restoreDurableState( StorageServer* data, IKeyValueStore* sto
for(auto it = data->newestAvailableVersion.ranges().begin(); it != data->newestAvailableVersion.ranges().end(); ++it) {
if (it->value() == invalidVersion) {
KeyRangeRef clearRange(it->begin(), it->end());
debugKeyRange("clearInvalidVersion", invalidVersion, clearRange);
// TODO(alexmiller): Figure out how to selectively enable spammy data distribution events.
//debugKeyRange("clearInvalidVersion", invalidVersion, clearRange);
storage->clear( clearRange );
data->byteSampleApplyClear( clearRange, invalidVersion );
}

1
fdbserver/workloads/ApiCorrectness.actor.cpp
View File

@ -20,6 +20,7 @@
#include "fdbserver/QuietDatabase.h"
#include "fdbserver/MutationTracking.h"
#include "fdbserver/workloads/workloads.actor.h"
#include "fdbserver/workloads/ApiWorkload.h"
#include "fdbserver/workloads/MemoryKeyValueStore.h"

2
flow/Trace.cpp
View File

@ -765,6 +765,7 @@ TraceEvent::TraceEvent(TraceEvent &&ev) {
tmpEventMetric = ev.tmpEventMetric;
trackingKey = ev.trackingKey;
type = ev.type;
timeIndex = ev.timeIndex;
ev.initialized = true;
ev.enabled = false;
@ -785,6 +786,7 @@ TraceEvent& TraceEvent::operator=(TraceEvent &&ev) {
tmpEventMetric = ev.tmpEventMetric;
trackingKey = ev.trackingKey;
type = ev.type;
timeIndex = ev.timeIndex;
ev.initialized = true;
ev.enabled = false;