Adding log messages on metadata opreations

Author: apkar

src/ExtCmd.actor.cpp

@@ -50,6 +50,7 @@ ACTOR static Future<std::pair<int, int>> dropIndexMatching(Reference<DocTransact
 	state std::vector<bson::BSONObj> indexes = wait(getIndexesTransactionally(indexesPlan, tr));
 	state int count = 0;
 	state bool any = false;
+	state bson::BSONObj matchingIndexObj;
 	state Reference<QueryContext> matchingIndex;
 	state std::string matchingName;
 
@@ -63,13 +64,15 @@ ACTOR static Future<std::pair<int, int>> dropIndexMatching(Reference<DocTransact
 		if (value.getBSONType() == bson::BSONType::String) {
 			if (value.getString() == indexObj.getStringField(field.c_str())) {
 				any = true;
+				matchingIndexObj = indexObj;
 				matchingIndex = indexesCollection->bindCollectionContext(tr)->cx->getSubContext(
 				    DataValue(indexObj.getField(DocLayerConstants::ID_FIELD)).encode_key_part());
 				matchingName = std::string(indexObj.getStringField(DocLayerConstants::NAME_FIELD));
 			}
 		} else if (value.getBSONType() == bson::BSONType::Object) {
 			if (value.getPackedObject().woCompare(indexObj.getObjectField(field.c_str())) == 0) {
 				any = true;
+				matchingIndexObj = indexObj;
 				matchingIndex = indexesCollection->bindCollectionContext(tr)->cx->getSubContext(
 				    DataValue(indexObj.getField(DocLayerConstants::ID_FIELD)).encode_key_part());
 				matchingName = std::string(indexObj.getStringField(DocLayerConstants::NAME_FIELD));
@@ -82,6 +85,11 @@ ACTOR static Future<std::pair<int, int>> dropIndexMatching(Reference<DocTransact
 	matchingIndex->clearDescendants();
 	matchingIndex->clearRoot();
 
+	TraceEvent(SevInfo, "BumpMetadataVersion")
+	    .detail("reason", "dropIndex")
+	    .detail("ns", fullCollNameToString(ns))
+	    .detail("index", matchingIndexObj.toString());
+
 	Void _ = wait(matchingIndex->commitChanges());
 
 	Key indexKey = targetedCollection->getIndexesSubspace().withSuffix(StringRef(encodeMaybeDotted(matchingName)));
@@ -356,6 +364,9 @@ ACTOR static Future<int> internal_doDropIndexesActor(Reference<DocTransaction> t
 	Key indexes = unbound->getIndexesSubspace();
 	tr->tr->clear(FDB::KeyRangeRef(indexes, strinc(indexes)));
 	unbound->bindCollectionContext(tr)->bumpMetadataVersion();
+	TraceEvent(SevInfo, "BumpMetadataVersion")
+	    .detail("reason", "dropAllIndexes")
+	    .detail("ns", fullCollNameToString(ns));
 
 	return count;
 }

src/ExtMsg.actor.cpp

@@ -63,10 +63,6 @@ Namespace getDBCollectionPair(const char* ns, std::pair<std::string, std::string
 	return std::make_pair(std::string(ns, dotPtr - ns), std::string(dotPtr + 1));
 }
 
-std::string fullCollNameToString(Namespace const& ns) {
-	return ns.first + "." + (ns.second.empty() ? "$cmd" : ns.second);
-}
-
 /**
  * query := { $bool_op : [ query* ],   *          (a predicate)
  * 			  path : literal_match,    *

src/MetadataManager.actor.cpp

@@ -25,6 +25,10 @@
 
 using namespace FDB;
 
+std::string fullCollNameToString(Namespace const& ns) {
+	return ns.first + "." + (ns.second.empty() ? "$cmd" : ns.second);
+}
+
 Future<uint64_t> getMetadataVersion(Reference<DocTransaction> tr, Reference<DirectorySubspace> metadataDirectory) {
 	std::string versionKey = metadataDirectory->key().toString() +
 	                         DataValue(DocLayerConstants::VERSION_KEY, DVTypeCode::STRING).encode_key_part();
@@ -157,6 +161,9 @@ ACTOR static Future<std::pair<Reference<UnboundCollectionContext>, uint64_t>> co
 		// collectionName.c_str(), printable(tcollectionDirectory->key()).c_str(),
 		// printable(tmetadataDirectory->key()).c_str(), "");
 		tcx->bindCollectionContext(tr)->bumpMetadataVersion(); // We start at version 1.
+		TraceEvent(SevInfo, "BumpMetadataVersion")
+		    .detail("reason", "createCollection")
+		    .detail("ns", fullCollNameToString(ns));
 
 		return std::make_pair(tcx, -1); // So we don't pollute the cache in case this transaction never commits
 	}
@@ -179,6 +186,9 @@ ACTOR static Future<Reference<UnboundCollectionContext>> assembleCollectionConte
 		// Here and below don't pollute the cache if we just created the directory, since this transaction might
 		// not commit.
 		if (unboundPair.second != -1) {
+			TraceEvent(SevInfo, "MetadataCacheAdd")
+			    .detail("ns", fullCollNameToString(ns))
+			    .detail("version", unboundPair.second);
 			auto insert_result = self->contexts.insert(std::make_pair(ns, unboundPair));
 			// Somebody else may have done the lookup and finished ahead of us. Either way, replace it with ours (can no
 			// longer optimize this by only replacing if ours is newer, because the directory may have moved or
@@ -199,14 +209,16 @@ ACTOR static Future<Reference<UnboundCollectionContext>> assembleCollectionConte
 				// Create the iterator again instead of making the previous value state, because the map could have
 				// changed during the previous wait. Either way, replace it with ours (can no longer optimize this by
 				// only replacing if ours is newer, because the directory may have moved or vanished.
-				// std::map<std::pair<std::string, std::string>, std::pair<Reference<UnboundCollectionContext>,
-				// uint64_t>>::iterator match = self->contexts.find(ns);
 				auto match = self->contexts.find(ns);
-
 				if (match != self->contexts.end())
 					match->second = unboundPair;
 				else
 					self->contexts.insert(std::make_pair(ns, unboundPair));
+
+				TraceEvent(SevInfo, "MetadataCacheUpdate")
+				    .detail("ns", fullCollNameToString(ns))
+				    .detail("oldVersion", oldVersion)
+				    .detail("newVersion", unboundPair.second);
 			}
 			return unboundPair.first;
 		} else {

src/MetadataManager.h

@@ -31,6 +31,8 @@
 
 using Namespace = std::pair<std::string, std::string>;
 
+std::string fullCollNameToString(Namespace const& ns);
+
 struct MetadataManager : ReferenceCounted<MetadataManager>, NonCopyable {
 	explicit MetadataManager(struct DocumentLayer* docLayer) : docLayer(docLayer) {}
 	~MetadataManager() = default;

src/QLPlan.actor.cpp

@@ -1418,6 +1418,10 @@ ACTOR static Future<Void> doIndexInsert(PlanCheckpoint* checkpoint,
 
 		Reference<IReadWriteContext> doc = wait(indexInsert->insert(unbound->bindCollectionContext(tr)));
 		mcx->bindCollectionContext(tr)->bumpMetadataVersion();
+		TraceEvent(SevInfo, "BumpMetadataVersion")
+		    .detail("reason", "createIndex")
+		    .detail("ns", fullCollNameToString(ns))
+		    .detail("index", indexObj.toString());
 		output.send(ref(new ScanReturnedContext(doc, -1, Key())));
 		throw end_of_stream();
 	} catch (Error& e) {
@@ -1590,6 +1594,11 @@ ACTOR static Future<Void> updateIndexStatus(PlanCheckpoint* checkpoint,
 			    DataValue(DocLayerConstants::CURRENTLY_PROCESSING_DOC_FIELD, DVTypeCode::STRING).encode_key_part());
 			indexDoc->clear(DataValue(DocLayerConstants::BUILD_ID_FIELD, DVTypeCode::STRING).encode_key_part());
 			mcx->bumpMetadataVersion();
+			TraceEvent(SevInfo, "BumpMetadataVersion")
+			    .detail("reason", "updateIndexStatus")
+			    .detail("ns", fullCollNameToString(ns))
+			    .detail("indexID", printable(encodedIndexId))
+			    .detail("status", newStatus);
 			output.send(ref(new ScanReturnedContext(indexDoc, -1, Key())));
 			throw end_of_stream();
 		} else {