Add some trace events to debug

fdbclient/DatabaseConfiguration.cpp

@@ -395,7 +395,10 @@ bool DatabaseConfiguration::setInternal(KeyRef key, ValueRef value) {
 	int type;
 
 	if (ck == LiteralStringRef("initialized")) initialized = true;
-	else if (ck == LiteralStringRef("proxies")) parse(&proxyCount, value);
+	else if (ck == LiteralStringRef("proxies")) {
+		parse(&proxyCount, value);
+		ASSERT(proxyCount >= 2 || proxyCount == -1);
+	}
 	else if (ck == LiteralStringRef("resolvers")) parse(&resolverCount, value);
 	else if (ck == LiteralStringRef("logs")) parse(&desiredTLogCount, value);
 	else if (ck == LiteralStringRef("log_replicas")) {
@@ -429,7 +432,10 @@ bool DatabaseConfiguration::setInternal(KeyRef key, ValueRef value) {
 	}
 	else if (ck == LiteralStringRef("log_spill")) { parse((&type), value); tLogSpillType = (TLogSpillType::SpillType)type; }
 	else if (ck == LiteralStringRef("storage_engine")) { parse((&type), value); storageServerStoreType = (KeyValueStoreType::StoreType)type; }
-	else if (ck == LiteralStringRef("auto_proxies")) parse(&autoProxyCount, value);
+	else if (ck == LiteralStringRef("auto_proxies")) {
+		parse(&autoProxyCount, value);
+		ASSERT(autoProxyCount >= 2 || autoProxyCount == -1);
+	}
 	else if (ck == LiteralStringRef("auto_resolvers")) parse(&autoResolverCount, value);
 	else if (ck == LiteralStringRef("auto_logs")) parse(&autoDesiredTLogCount, value);
 	else if (ck == LiteralStringRef("storage_replication_policy")) parseReplicationPolicy(&storagePolicy, value);

fdbclient/ManagementAPI.actor.cpp

@@ -724,7 +724,7 @@ ConfigureAutoResult parseConfig( StatusObject const& status ) {
 		resolverCount = result.old_resolvers;
 	}
 
-	result.desired_proxies = std::min( 12, processCount / 15 );
+	result.desired_proxies = std::max(std::min( 12, processCount / 15 ), 2);
 	int proxyCount;
 	if (!statusObjConfig.get("proxies", result.old_proxies)) {
 		result.old_proxies = CLIENT_KNOBS->DEFAULT_AUTO_PROXIES;

fdbserver/ClusterController.actor.cpp

@@ -730,6 +730,7 @@ public:
 
 		auto resolvers = getWorkersForRoleInDatacenter( dcId, ProcessClass::Resolver, req.configuration.getDesiredResolvers(), req.configuration, id_used, first_resolver );
 		auto proxies = getWorkersForRoleInDatacenter( dcId, ProcessClass::Proxy, req.configuration.getDesiredProxies(), req.configuration, id_used, first_two_proxies );
+		TraceEvent("GetWorkersForProxy").detail("Loc", 2).detail("Proxy", proxies.size()).detail("ConfigSize", req.configuration.getDesiredProxies());
 		ASSERT(proxies.size() >= 2 && proxies.size() <= req.configuration.getDesiredProxies());
 		int grvProxiesCount = std::max(1, (int) (CLIENT_KNOBS->GRV_PROXIES_RATIO * proxies.size()));
 		for(int i = 0; i < resolvers.size(); i++)
@@ -879,6 +880,7 @@ public:
 						  getWorkerForRoleInDatacenter( dcId, ProcessClass::Proxy, ProcessClass::ExcludeFit, req.configuration, used )};
 					auto resolvers = getWorkersForRoleInDatacenter( dcId, ProcessClass::Resolver, req.configuration.getDesiredResolvers(), req.configuration, used, first_resolver );
 					auto proxies = getWorkersForRoleInDatacenter( dcId, ProcessClass::Proxy, req.configuration.getDesiredProxies(), req.configuration, used, first_two_proxies );
+					TraceEvent("GetWorkersForProxy").detail("Loc", 1).detail("Proxy", proxies.size()).detail("ConfigSize", req.configuration.getDesiredProxies());
 					ASSERT(proxies.size() >= 2 && proxies.size() <= req.configuration.getDesiredProxies());
 
 					RoleFitnessPair fitness( RoleFitness(proxies, ProcessClass::Proxy), RoleFitness(resolvers, ProcessClass::Resolver) );
@@ -889,6 +891,7 @@ public:
 						for(int i = 0; i < resolvers.size(); i++)
 							result.resolvers.push_back(resolvers[i].interf);
 
+						TraceEvent("GetWorkersForProxy").detail("Loc", 3).detail("Proxy", proxies.size()).detail("ConfigSize", req.configuration.getDesiredProxies());
 						ASSERT(proxies.size() >= 2 && proxies.size() <= req.configuration.getDesiredProxies());
 						deterministicRandom()->randomShuffle(proxies);
 						int grvProxiesCount = std::max(1, (int) (CLIENT_KNOBS->GRV_PROXIES_RATIO * proxies.size()));
@@ -1228,6 +1231,7 @@ public:
 			  getWorkerForRoleInDatacenter( clusterControllerDcId, ProcessClass::Proxy, ProcessClass::ExcludeFit, db.config, id_used, true ) };
 		auto resolvers = getWorkersForRoleInDatacenter( clusterControllerDcId, ProcessClass::Resolver, db.config.getDesiredResolvers(), db.config, id_used, first_resolver, true );
 		auto proxies = getWorkersForRoleInDatacenter( clusterControllerDcId, ProcessClass::Proxy, db.config.getDesiredProxies(), db.config, id_used, first_two_proxies, true );
+		TraceEvent("GetWorkersForProxy").detail("Loc", 4).detail("Proxy", proxies.size()).detail("ConfigSize", db.config.getDesiredProxies());
 		ASSERT(proxies.size() >= 2 && proxies.size() <= db.config.getDesiredProxies());
 
 		RoleFitnessPair newInFit(RoleFitness(proxies, ProcessClass::Proxy), RoleFitness(resolvers, ProcessClass::Resolver));

fdbserver/GrvProxyServer.actor.cpp

@@ -472,6 +472,7 @@ ACTOR Future<Void> sendGrvReplies(Future<GetReadVersionReply> replyFuture, std::
 		}
 
 		request.reply.send(reply);
+//		TraceEvent("ReadVersion").detail("V", reply.version);
 		++stats->txnRequestOut;
 	}
 

fdbserver/MasterProxyServer.actor.cpp

@@ -1331,6 +1331,7 @@ ACTOR Future<Void> commitBatch(
 		self->metadataVersion = metadataVersionAfter;
 		self->committedVersion.set(commitVersion);
 	}
+//	TraceEvent("ProxyCommit").detail("V", commitVersion);
 
 	if (forceRecovery) {
 		TraceEvent(SevWarn, "RestartingTxnSubsystem", self->dbgid).detail("Stage", "ProxyShutdown");

fdbserver/storageserver.actor.cpp

@@ -914,6 +914,7 @@ ACTOR Future<Version> waitForVersionNoTooOld( StorageServer* data, Version versi
 }
 
 ACTOR Future<Void> getValueQ( StorageServer* data, GetValueRequest req ) {
+//	TraceEvent("GetValue").detail("Key", req.key.toString()).detail("V", req.version);
 	state int64_t resultSize = 0;
 	Span span("SS:getValue"_loc, { req.spanContext });
 

fdbserver/workloads/Storefront.actor.cpp

@@ -55,11 +55,13 @@ struct StorefrontWorkload : TestWorkload {
 
 	virtual std::string description() { return "StorefrontWorkload"; }
 
-	virtual Future<Void> setup( Database const& cx ) { 
+	virtual Future<Void> setup( Database const& cx ) {
+//		TraceEvent("StoreFrontSetup");
 		return bulkSetup( cx, this, itemCount, Promise<double>() );
 	}
 
-	virtual Future<Void> start( Database const& cx ) { 
+	virtual Future<Void> start( Database const& cx ) {
+//		TraceEvent("StoreFrontStart");
 		for(int c=0; c<actorCount; c++)
 			clients.push_back(
 				orderingClient( cx->clone(), this, actorCount / transactionsPerSecond ) );
@@ -110,6 +112,7 @@ struct StorefrontWorkload : TestWorkload {
 
 	ACTOR Future<Void> itemUpdater( Transaction* tr, StorefrontWorkload* self, int item, int quantity ) {
 		state Key iKey = self->itemKey( item );
+//		TraceEvent("ItemUpdaterGetKey").detail("Key", printable(iKey));
 		Optional<Value> val = wait( tr->get( iKey ) );
 		if (!val.present()) {
 			TraceEvent(SevError, "StorefrontItemMissing").detail("Key", printable(iKey)).detail("Item", item)
@@ -117,6 +120,8 @@ struct StorefrontWorkload : TestWorkload {
 			ASSERT( val.present() );
 		}
 		int currentCount = valueToInt( val.get() );
+//		TraceEvent("ItemUpdaterGetValue").detail("Value", val.present() ? val.get().toString() : "absent");
+//		TraceEvent("ItemUpdaterSetKeyValue").detail("Key", printable(iKey)).detail("Value", currentCount + quantity);
 		tr->set( iKey, self->itemValue( currentCount + quantity ) );
 		return Void();
 	}
@@ -134,7 +139,10 @@ struct StorefrontWorkload : TestWorkload {
 				state Transaction tr(cx);
 				loop {
 					try {
+//						TraceEvent("OrderingClientGetKey").detail("Key", printable(orderKey));
 						Optional<Value> order = wait( tr.get( orderKey ) );
+//						TraceEvent("OrderingClientGetKeyValue").detail("Key", printable(orderKey))
+//						    .detail("Value", order.present() ? printable(order.get()) : "absent");
 						if( order.present() ) {
 							++self->spuriousCommitFailures;
 							break; // the order was already committed
@@ -159,8 +167,11 @@ struct StorefrontWorkload : TestWorkload {
 
 						// set value for the order
 						BinaryWriter wr(AssumeVersion(currentProtocolVersion)); wr << itemList;
-						tr.set( orderKey, wr.toValue() );
+//						TraceEvent("OrderingClientSetKeyValue").detail("Key", printable(orderKey))
+//						    .detail("Value", wr.toValue());
+						tr.set( orderKey, printable(wr.toValue()) );
 
+//						TraceEvent("OrderClientCommit");
 						wait( tr.commit() );
 						self->orders[id] = items; // save this in a local list to test durability
 						break;
@@ -185,6 +196,7 @@ struct StorefrontWorkload : TestWorkload {
 		state KeySelectorRef begin = firstGreaterThan(keyRange.begin);
 		state KeySelectorRef end = lastLessThan(keyRange.end);
 		while( fetched == 10000 ) {
+//			TraceEvent("OrderAccumulatorGetRange").detail("Begin", begin.toString()).detail("End", end.toString());
 			Standalone<RangeResultRef> values = wait( tr.getRange( begin, end, 10000 ) );
 			int orderIdx;
 			for(orderIdx=0; orderIdx<values.size(); orderIdx++) {
@@ -209,6 +221,7 @@ struct StorefrontWorkload : TestWorkload {
 					KeyRangeRef( Key(format("/orders/%x", c)), Key(format("/orders/%x", c+1)) ) ) );
 
 		Transaction tr(cx);
+//		TraceEvent("TableBalancerGetRange");
 		state Future<Standalone<RangeResultRef>> values = tr.getRange( 
 				KeyRangeRef( self->itemKey(0), self->itemKey(self->itemCount)), self->itemCount+1 );
 
@@ -238,7 +251,9 @@ struct StorefrontWorkload : TestWorkload {
 			try {
 				for(; idx < ids.size(); idx++ ) {
 					state orderID id = ids[idx];
+//					TraceEvent("OrderCheckerGetKey").detail("Key", printable(self->orderKey(id)));
 					Optional<Value> val = wait( tr.get( self->orderKey( id ) ) );
+//					TraceEvent("OrderCheckerGetValue").detail("Key", printable(self->orderKey(id))).detail("Value", val.present() ? val.get().toString() : "absent");
 					if( !val.present() ) {
 						TraceEvent( SevError, "TestFailure").detail("Reason", "OrderNotPresent" ).detail("OrderID", id);
 						return false;