SERVER-50286 Indicate in logs whether an operation involves a view

4 files changed, 192 insertions, 0 deletions

diff --git a/jstests/noPassthrough/views_log_depchain.js b/jstests/noPassthrough/views_log_depchain.js
new file mode 100644
index 00000000000..500af32a7c5
--- /dev/null
+++ b/jstests/noPassthrough/views_log_depchain.js
@@ -0,0 +1,102 @@
+// Tests that a view dependency chain is correctly logged in the global log for a find command
+// against the view.
+// @tags: [requires_profiling]
+
+// The entry in the log should contain a field that looks like this:
+// "resolvedViews":
+// [
+//   {
+//     "viewNamespace":"<full name of the view>",
+//     "dependencyChain":[<names of views/collection in the dep chain, db name omitted>],
+//     "resolvedPipeline":[<the resolved pipeline of the view>]
+//   },
+//   {
+//     <repeat for all other views that had to be resolved for the query>
+//   }
+// ],
+(function() {
+'use strict';
+
+load("jstests/libs/logv2_helpers.js");
+
+function resetProfiler(db) {
+    assert.commandWorked(db.setProfilingLevel(0, {slowms: 0}));
+    db.system.profile.drop();
+    assert.commandWorked(db.setProfilingLevel(1, {slowms: 0}));
+}
+
+function assertResolvedView(resolvedView, nss, dependencyDepth, pipelineSize) {
+    assert.eq(nss, resolvedView["viewNamespace"], resolvedView);
+    assert.eq(dependencyDepth, resolvedView["dependencyChain"].length, resolvedView);
+    assert.eq(pipelineSize, resolvedView["resolvedPipeline"].length, resolvedView);
+}
+
+// Check that the profiler has the expected record.
+function checkProfilerLog(db) {
+    const result = db.system.profile.find({ns: "views_log_depchain_db.c_view"}).toArray();
+    assert.eq(1, result.length, result);
+    const record = result[0];
+    assert(record.hasOwnProperty("resolvedViews"), record);
+    const resolvedViews = record["resolvedViews"];
+    assert.eq(2, resolvedViews.length, resolvedViews);
+
+    // The views are logged sorted by their original namespace, not in the order of resolution.
+    assertResolvedView(resolvedViews[0], `${db.getName()}.b_view`, 2, 1);
+    assertResolvedView(resolvedViews[1], `${db.getName()}.c_view`, 3, 3);
+}
+
+const mongodOptions = {};
+const conn = MongoRunner.runMongod(mongodOptions);
+assert.neq(null, conn, `mongod failed to start with options ${tojson(mongodOptions)}`);
+
+// Setup the tree of views.
+const db = conn.getDB(`${jsTest.name()}_db`);
+assert.commandWorked(db.dropDatabase());
+assert.commandWorked(db.createCollection("base"));
+assert.commandWorked(db.createView("a_view", "base", [{$project: {"aa": 0}}, {$sort: {"a": 1}}]));
+assert.commandWorked(db.createView("b_view", "base", [{$project: {"bb": 0}}]));
+assert.commandWorked(db.createView("c_view", "a_view", [
+    {$lookup: {from: "b_view", localField: "x", foreignField: "x", as: "y"}}
+]));
+
+// Run a simple query against the top view.
+assert.commandWorked(db.setProfilingLevel(1, {slowms: 0}));
+assert.commandWorked(db.runCommand({find: "c_view", filter: {}}));
+checkProfilerLog(db);
+
+// Sanity-check the "slow query" log (we do it only once, because the data between the profiler
+// and "slow query" log are identical).
+checkLog.containsWithCount(conn,
+                           `"resolvedViews":[{"viewNamespace":"${db.getName()}.b_view",` +
+                               `"dependencyChain":["b_view","base"],"resolvedPipeline":[{"$project`,
+                           1);
+
+// Run an aggregate query against the top view which uses one of the views from its dependency
+// chain, so the logged data is the same as above.
+resetProfiler(db);
+const lookup = {
+    $lookup: {from: "b_view", localField: "x", foreignField: "x", as: "y"}
+};
+assert.commandWorked(db.runCommand({aggregate: "c_view", pipeline: [lookup], cursor: {}}));
+checkProfilerLog(db);
+
+// If a view is modified, the logs should reflect that.
+assert.commandWorked(db.runCommand({drop: "c_view"}));
+assert.commandWorked(db.createView("c_view", "b_view", [
+    {$lookup: {from: "a_view", localField: "x", foreignField: "x", as: "y"}}
+]));
+resetProfiler(db);
+assert.commandWorked(db.runCommand({find: "c_view", filter: {}}));
+
+const result = db.system.profile.find({ns: "views_log_depchain_db.c_view"}).toArray();
+assert.eq(1, result.length, result);
+const record = result[0];
+assert(record.hasOwnProperty("resolvedViews"), record);
+const resolvedViews = record["resolvedViews"];
+assert.eq(2, resolvedViews.length, resolvedViews);
+assertResolvedView(resolvedViews[0], `${db.getName()}.a_view`, 2, 2);
+assertResolvedView(resolvedViews[1], `${db.getName()}.c_view`, 3, 2);
+
+assert.commandWorked(db.dropDatabase());
+MongoRunner.stopMongod(conn);
+})();
diff --git a/src/mongo/db/curop.cpp b/src/mongo/db/curop.cpp
index 32dd1a531d4..20bc4610e65 100644
--- a/src/mongo/db/curop.cpp
+++ b/src/mongo/db/curop.cpp
@@ -882,6 +882,10 @@ string OpDebug::report(OperationContext* opCtx, const SingleThreadedLockStats* l
         s << " dataThroughputAverage: " << *dataThroughputAverage << " MB/sec";
     }
 
+    if (!resolvedViews.empty()) {
+        s << " resolvedViews: " << getResolvedViewsInfo();
+    }
+
     OPDEBUG_TOSTRING_HELP(nShards);
     OPDEBUG_TOSTRING_HELP(cursorid);
     if (mongotCursorId) {
@@ -1061,6 +1065,10 @@ void OpDebug::report(OperationContext* opCtx,
         pAttrs->add("dataThroughputAverageMBPerSec", *dataThroughputAverage);
     }
 
+    if (!resolvedViews.empty()) {
+        pAttrs->add("resolvedViews", getResolvedViewsInfo());
+    }
+
     OPDEBUG_TOATTR_HELP(nShards);
     OPDEBUG_TOATTR_HELP(cursorid);
     if (mongotCursorId) {
@@ -1205,6 +1213,10 @@ void OpDebug::append(OperationContext* opCtx,
         appendAsObjOrString("originatingCommand", originatingCommand, appendMaxElementSize, &b);
     }
 
+    if (!resolvedViews.empty()) {
+        appendResolvedViewsInfo(b);
+    }
+
     OPDEBUG_APPEND_NUMBER(b, nShards);
     OPDEBUG_APPEND_NUMBER(b, cursorid);
     if (mongotCursorId) {
@@ -1667,6 +1679,55 @@ BSONObj OpDebug::makeMongotDebugStatsObject() const {
     return cursorBuilder.obj();
 }
 
+void OpDebug::addResolvedViews(const std::vector<NamespaceString>& namespaces,
+                               const std::vector<BSONObj>& pipeline) {
+    if (namespaces.empty())
+        return;
+
+    if (resolvedViews.find(namespaces.front()) == resolvedViews.end()) {
+        resolvedViews[namespaces.front()] = std::make_pair(namespaces, pipeline);
+    }
+}
+
+static void appendResolvedViewsInfoImpl(
+    BSONArrayBuilder& resolvedViewsArr,
+    const std::map<NamespaceString, std::pair<std::vector<NamespaceString>, std::vector<BSONObj>>>&
+        resolvedViews) {
+    for (const auto& kv : resolvedViews) {
+        const NamespaceString& viewNss = kv.first;
+        const std::vector<NamespaceString>& dependencies = kv.second.first;
+        const std::vector<BSONObj>& pipeline = kv.second.second;
+
+        BSONObjBuilder aView;
+        aView.append("viewNamespace", viewNss.ns());
+
+        BSONArrayBuilder dependenciesArr(aView.subarrayStart("dependencyChain"));
+        for (const auto& nss : dependencies) {
+            dependenciesArr.append(nss.coll().toString());
+        }
+        dependenciesArr.doneFast();
+
+        BSONArrayBuilder pipelineArr(aView.subarrayStart("resolvedPipeline"));
+        for (const auto& stage : pipeline) {
+            pipelineArr.append(stage);
+        }
+        pipelineArr.doneFast();
+
+        resolvedViewsArr.append(redact(aView.done()));
+    }
+}
+
+BSONArray OpDebug::getResolvedViewsInfo() const {
+    BSONArrayBuilder resolvedViewsArr;
+    appendResolvedViewsInfoImpl(resolvedViewsArr, this->resolvedViews);
+    return resolvedViewsArr.arr();
+}
+
+void OpDebug::appendResolvedViewsInfo(BSONObjBuilder& builder) const {
+    BSONArrayBuilder resolvedViewsArr(builder.subarrayStart("resolvedViews"));
+    appendResolvedViewsInfoImpl(resolvedViewsArr, this->resolvedViews);
+    resolvedViewsArr.doneFast();
+}
 
 namespace {
 
diff --git a/src/mongo/db/curop.h b/src/mongo/db/curop.h
index 44530fcfbfd..aab0d9fad30 100644
--- a/src/mongo/db/curop.h
+++ b/src/mongo/db/curop.h
@@ -201,6 +201,18 @@ public:
      */
     BSONObj makeMongotDebugStatsObject() const;
 
+    /**
+     * Accumulate resolved views.
+     */
+    void addResolvedViews(const std::vector<NamespaceString>& namespaces,
+                          const std::vector<BSONObj>& pipeline);
+
+    /**
+     * Get or append the array with resolved views' info.
+     */
+    BSONArray getResolvedViewsInfo() const;
+    void appendResolvedViewsInfo(BSONObjBuilder& builder) const;
+
     // -------------------
 
     // basic options
@@ -279,6 +291,12 @@ public:
 
     // Whether this is an oplog getMore operation for replication oplog fetching.
     bool isReplOplogGetMore{false};
+
+    // Maps namespace of a resolved view to its dependency chain and the fully unrolled pipeline. To
+    // make log line deterministic and easier to test, use ordered map. As we don't expect many
+    // resolved views per query, a hash map would unlikely provide any benefits.
+    std::map<NamespaceString, std::pair<std::vector<NamespaceString>, std::vector<BSONObj>>>
+        resolvedViews;
 };
 
 /**
diff --git a/src/mongo/db/views/view_catalog.cpp b/src/mongo/db/views/view_catalog.cpp
index de708b34df2..d74e9148350 100644
--- a/src/mongo/db/views/view_catalog.cpp
+++ b/src/mongo/db/views/view_catalog.cpp
@@ -43,6 +43,7 @@
 #include "mongo/db/audit.h"
 #include "mongo/db/catalog/collection_catalog.h"
 #include "mongo/db/catalog/database.h"
+#include "mongo/db/curop.h"
 #include "mongo/db/namespace_string.h"
 #include "mongo/db/operation_context.h"
 #include "mongo/db/pipeline/aggregate_command_gen.h"
@@ -695,6 +696,8 @@ StatusWith<ResolvedView> ViewCatalog::resolveView(OperationContext* opCtx,
         // 'resolvedNss'.
         std::shared_ptr<ViewDefinition> lastViewDefinition;
 
+        std::vector<NamespaceString> dependencyChain{nss};
+
         int depth = 0;
         for (; depth < ViewGraph::kMaxViewDepth; depth++) {
             auto view =
@@ -710,6 +713,10 @@ StatusWith<ResolvedView> ViewCatalog::resolveView(OperationContext* opCtx,
                             str::stream() << "View pipeline exceeds maximum size; maximum size is "
                                           << ViewGraph::kMaxViewPipelineSizeBytes};
                 }
+
+                auto curOp = CurOp::get(opCtx);
+                curOp->debug().addResolvedViews(dependencyChain, resolvedPipeline);
+
                 return StatusWith<ResolvedView>(
                     {*resolvedNss,
                      std::move(resolvedPipeline),
@@ -717,6 +724,7 @@ StatusWith<ResolvedView> ViewCatalog::resolveView(OperationContext* opCtx,
             }
 
             resolvedNss = &view->viewOn();
+            dependencyChain.push_back(*resolvedNss);
             if (!collation) {
                 collation = view->defaultCollator() ? view->defaultCollator()->getSpec().toBSON()
                                                     : CollationSpec::kSimpleSpec;
@@ -728,6 +736,9 @@ StatusWith<ResolvedView> ViewCatalog::resolveView(OperationContext* opCtx,
 
             // If the first stage is a $collStats, then we return early with the viewOn namespace.
             if (toPrepend.size() > 0 && !toPrepend[0]["$collStats"].eoo()) {
+                auto curOp = CurOp::get(opCtx);
+                curOp->debug().addResolvedViews(dependencyChain, resolvedPipeline);
+
                 return StatusWith<ResolvedView>(
                     {*resolvedNss, std::move(resolvedPipeline), std::move(collation.get())});
             }