SERVER-34726 Lock acquisitions for profiling in transaction have 0 second timeout

7 files changed, 149 insertions, 29 deletions

diff --git a/jstests/core/txns/transactions_profiling_with_drops.js b/jstests/core/txns/transactions_profiling_with_drops.js
new file mode 100644
index 00000000000..3ab6e45e990
--- /dev/null
+++ b/jstests/core/txns/transactions_profiling_with_drops.js
@@ -0,0 +1,110 @@
+// Tests that locks acquisitions for profiling in a transaction have a 0-second timeout.
+// @tags: [uses_transactions]
+(function() {
+    "use strict";
+
+    load("jstests/libs/profiler.js");  // For getLatestProfilerEntry.
+
+    const dbName = "test";
+    const collName = "transactions_profiling_with_drops";
+    const otherCollName = "other";
+    const adminDB = db.getSiblingDB("admin");
+    const testDB = db.getSiblingDB(dbName);
+    const otherColl = testDB[otherCollName];
+    const session = db.getMongo().startSession({causalConsistency: false});
+    const sessionDb = session.getDatabase(dbName);
+    const sessionColl = sessionDb[collName];
+
+    sessionDb.runCommand({dropDatabase: 1, writeConcern: {w: "majority"}});
+    assert.commandWorked(sessionColl.insert({_id: "doc"}, {w: "majority"}));
+    assert.commandWorked(otherColl.insert({_id: "doc"}, {w: "majority"}));
+    assert.commandWorked(sessionDb.runCommand({profile: 1, slowms: 1}));
+
+    jsTest.log("Test read profiling with drops.");
+
+    jsTest.log("Start transaction.");
+    session.startTransaction();
+
+    jsTest.log("Run a slow read. Profiling in the transaction should succeed.");
+    assert.docEq(
+        [{_id: "doc"}],
+        sessionColl.find({$where: "sleep(1000); return true;"}).comment("read success").toArray());
+    profilerHasSingleMatchingEntryOrThrow(
+        {profileDB: testDB, filter: {"command.comment": "read success"}});
+
+    jsTest.log("Start a drop, which will hang.");
+    let awaitDrop = startParallelShell(function() {
+        db.getSiblingDB("test").runCommand({drop: "other", writeConcern: {w: "majority"}});
+    });
+
+    // Wait for the drop to have a pending MODE_X lock on the database.
+    assert.soon(
+        function() {
+            return adminDB
+                       .aggregate([
+                           {$currentOp: {}},
+                           {$match: {"command.drop": otherCollName, waitingForLock: true}}
+                       ])
+                       .itcount() === 1;
+        },
+        function() {
+            return "Failed to find drop in currentOp output: " +
+                tojson(adminDB.aggregate([{$currentOp: {}}]));
+        });
+
+    jsTest.log("Run a slow read. Profiling in the transaction should fail.");
+    assert.docEq(
+        [{_id: "doc"}],
+        sessionColl.find({$where: "sleep(1000); return true;"}).comment("read failure").toArray());
+    session.commitTransaction();
+    awaitDrop();
+    profilerHasZeroMatchingEntriesOrThrow(
+        {profileDB: testDB, filter: {"command.comment": "read failure"}});
+
+    jsTest.log("Test write profiling with drops.");
+
+    // Recreate the "other" collection so it can be dropped again.
+    assert.commandWorked(otherColl.insert({_id: "doc"}, {w: "majority"}));
+
+    jsTest.log("Start transaction.");
+    session.startTransaction();
+
+    jsTest.log("Run a slow write. Profiling in the transaction should succeed.");
+    assert.commandWorked(sessionColl.update(
+        {$where: "sleep(1000); return true;"}, {$inc: {good: 1}}, {collation: {locale: "en"}}));
+    profilerHasSingleMatchingEntryOrThrow(
+        {profileDB: testDB, filter: {"command.collation": {locale: "en"}}});
+
+    jsTest.log("Start a drop, which will hang.");
+    awaitDrop = startParallelShell(function() {
+        db.getSiblingDB("test").runCommand({drop: "other", writeConcern: {w: "majority"}});
+    });
+
+    // Wait for the drop to have a pending MODE_X lock on the database.
+    assert.soon(
+        function() {
+            return adminDB
+                       .aggregate([
+                           {$currentOp: {}},
+                           {$match: {"command.drop": otherCollName, waitingForLock: true}}
+                       ])
+                       .itcount() === 1;
+        },
+        function() {
+            return "Failed to find drop in currentOp output: " +
+                tojson(adminDB.aggregate([{$currentOp: {}}]));
+        });
+
+    jsTest.log("Run a slow write. Profiling in the transaction should fail.");
+    assert.commandWorked(sessionColl.update(
+        {$where: "sleep(1000); return true;"}, {$inc: {bad: 1}}, {collation: {locale: "fr"}}));
+    session.commitTransaction();
+    awaitDrop();
+    profilerHasZeroMatchingEntriesOrThrow(
+        {profileDB: testDB, filter: {"command.collation": {locale: "fr"}}});
+
+    jsTest.log("Both writes should succeed, even if profiling failed.");
+    assert.docEq({_id: "doc", good: 1, bad: 1}, sessionColl.findOne());
+
+    session.endSession();
+}());
diff --git a/jstests/noPassthrough/read_concern_snapshot_yielding.js b/jstests/noPassthrough/read_concern_snapshot_yielding.js
index bcefdc5b3c8..a357f2f199d 100644
--- a/jstests/noPassthrough/read_concern_snapshot_yielding.js
+++ b/jstests/noPassthrough/read_concern_snapshot_yielding.js
@@ -13,8 +13,6 @@
         return;
     }
 
-    load("jstests/libs/profiler.js");  // For getLatestProfilerEntry.
-
     const dbName = "test";
     const collName = "coll";
 
@@ -44,7 +42,6 @@
     // Set 'internalQueryExecYieldIterations' to 2 to ensure that commands yield on the second try
     // (i.e. after they have established a snapshot but before they have returned any documents).
     assert.commandWorked(db.adminCommand({setParameter: 1, internalQueryExecYieldIterations: 2}));
-    db.setProfilingLevel(2);
 
     function waitForOpId(curOpFilter) {
         let opId;
@@ -96,7 +93,7 @@
         }));
     }
 
-    function testCommand(awaitCommandFn, curOpFilter, profilerFilter, testWriteConflict) {
+    function testCommand(awaitCommandFn, curOpFilter, testWriteConflict) {
         //
         // Test that the command can be killed.
         //
@@ -147,13 +144,6 @@
         // Now the drop can complete.
         awaitDrop();
 
-        // Confirm that the command did not yield.
-        if (profilerFilter) {
-            let profilerEntry = getLatestProfilerEntry(db, profilerFilter);
-            assert(profilerEntry.hasOwnProperty("numYield"), tojson(profilerEntry));
-            assert.eq(0, profilerEntry.numYield, tojson(profilerEntry));
-        }
-
         //
         // Test that the command does not read data that is inserted during its execution.
         // 'awaitCommandFn' should fail if it reads the following document:
@@ -223,7 +213,7 @@
             txnNumber: NumberLong(TestData.txnNumber)
         }));
         assert.eq(res.cursor.firstBatch.length, TestData.numDocs, tojson(res));
-    }, {"command.filter": {x: 1}}, {op: "query"});
+    }, {"command.filter": {x: 1}});
 
     // Test getMore on a find established cursor.
     testCommand(function() {
@@ -251,7 +241,7 @@
         }));
         assert.eq(
             res.cursor.nextBatch.length, TestData.numDocs - initialFindBatchSize, tojson(res));
-    }, {"originatingCommand.filter": {x: 1}}, {op: "getmore"});
+    }, {"originatingCommand.filter": {x: 1}});
 
     // Test aggregate.
     testCommand(function() {
@@ -264,7 +254,7 @@
             txnNumber: NumberLong(TestData.txnNumber)
         }));
         assert.eq(res.cursor.firstBatch.length, TestData.numDocs, tojson(res));
-    }, {"command.pipeline": [{$match: {x: 1}}]}, {"command.pipeline": [{$match: {x: 1}}]});
+    }, {"command.pipeline": [{$match: {x: 1}}]});
 
     // TODO: SERVER-34113 Remove this test when we completely remove snapshot
     // reads since this command is not supported with transaction api.
@@ -279,7 +269,7 @@
         }));
         assert(res.hasOwnProperty("results"));
         assert.eq(res.results.length, TestData.numDocs, tojson(res));
-    }, {"command.geoNear": "coll"}, {"command.geoNear": "coll"});
+    }, {"command.geoNear": "coll"});
 
     // Test getMore with an initial find batchSize of 0. Interrupt behavior of a getMore is not
     // expected to change with a change of batchSize in the originating command.
@@ -307,7 +297,7 @@
         }));
         assert.eq(
             res.cursor.nextBatch.length, TestData.numDocs - initialFindBatchSize, tojson(res));
-    }, {"originatingCommand.filter": {x: 1}}, {op: "getmore"});
+    }, {"originatingCommand.filter": {x: 1}});
 
     // Test count.
     testCommand(function() {
@@ -319,7 +309,7 @@
             txnNumber: NumberLong(TestData.txnNumber)
         }));
         assert.eq(res.n, 3, tojson(res));
-    }, {"command.count": "coll"}, {"command.count": "coll"});
+    }, {"command.count": "coll"});
 
     // Test distinct.
     testCommand(function() {
@@ -332,7 +322,7 @@
         }));
         assert(res.hasOwnProperty("values"));
         assert.eq(res.values.length, 4, tojson(res));
-    }, {"command.distinct": "coll"}, {"command.distinct": "coll"});
+    }, {"command.distinct": "coll"});
 
     // Test group.
     testCommand(function() {
@@ -344,11 +334,9 @@
         }));
         assert(res.hasOwnProperty("count"), tojson(res));
         assert.eq(res.count, 4);
-    }, {"command.group.ns": "coll"}, {"command.group.ns": "coll"});
+    }, {"command.group.ns": "coll"});
 
     // Test update.
-    // TODO SERVER-33548: We cannot provide a 'profilerFilter' because profiling is turned off for
-    // batch write commands in transactions.
     testCommand(function() {
         const res = assert.commandWorked(db.runCommand({
             update: "coll",
@@ -371,11 +359,9 @@
         // Only update one existing doc committed before the transaction.
         assert.eq(res.n, 1, tojson(res));
         assert.eq(res.nModified, 1, tojson(res));
-    }, {op: "update"}, null, true);
+    }, {op: "update"}, true);
 
     // Test delete.
-    // We cannot provide a 'profilerFilter' because profiling is turned off for write commands in
-    // transactions.
     testCommand(function() {
         const res = assert.commandWorked(db.runCommand({
             delete: "coll",
@@ -396,7 +382,7 @@
         }));
         // Only remove one existing doc committed before the transaction.
         assert.eq(res.n, 1, tojson(res));
-    }, {op: "remove"}, null, true);
+    }, {op: "remove"}, true);
 
     // Test findAndModify.
     testCommand(function() {
@@ -421,7 +407,7 @@
         assert(res.hasOwnProperty("lastErrorObject"));
         assert.eq(res.lastErrorObject.n, 0, tojson(res));
         assert.eq(res.lastErrorObject.updatedExisting, false, tojson(res));
-    }, {"command.findAndModify": "coll"}, {"command.findAndModify": "coll"}, true);
+    }, {"command.findAndModify": "coll"}, true);
 
     testCommand(function() {
         const res = assert.commandWorked(db.runCommand({
@@ -445,7 +431,7 @@
         assert(res.hasOwnProperty("lastErrorObject"));
         assert.eq(res.lastErrorObject.n, 0, tojson(res));
         assert.eq(res.lastErrorObject.updatedExisting, false, tojson(res));
-    }, {"command.findAndModify": "coll"}, {"command.findAndModify": "coll"}, true);
+    }, {"command.findAndModify": "coll"}, true);
 
     rst.stopSet();
 }());
diff --git a/src/mongo/db/concurrency/lock_state.h b/src/mongo/db/concurrency/lock_state.h
index 7a5d68e6ebf..0cf5081fb6b 100644
--- a/src/mongo/db/concurrency/lock_state.h
+++ b/src/mongo/db/concurrency/lock_state.h
@@ -122,6 +122,10 @@ public:
         _maxLockTimeout = maxTimeout;
     }
 
+    bool hasMaxLockTimeout() override {
+        return static_cast<bool>(_maxLockTimeout);
+    }
+
     void unsetMaxLockTimeout() override {
         _maxLockTimeout = boost::none;
     }
diff --git a/src/mongo/db/concurrency/locker.h b/src/mongo/db/concurrency/locker.h
index ad39397979b..8310fc866e4 100644
--- a/src/mongo/db/concurrency/locker.h
+++ b/src/mongo/db/concurrency/locker.h
@@ -124,6 +124,11 @@ public:
     virtual void setMaxLockTimeout(Milliseconds maxTimeout) = 0;
 
     /**
+     * Returns whether this Locker has a maximum lock timeout set.
+     */
+    virtual bool hasMaxLockTimeout() = 0;
+
+    /**
      * Clears the max lock timeout override set by setMaxLockTimeout() above.
      */
     virtual void unsetMaxLockTimeout() = 0;
diff --git a/src/mongo/db/concurrency/locker_noop.h b/src/mongo/db/concurrency/locker_noop.h
index 530a9cd6263..590489f255f 100644
--- a/src/mongo/db/concurrency/locker_noop.h
+++ b/src/mongo/db/concurrency/locker_noop.h
@@ -73,6 +73,10 @@ public:
         MONGO_UNREACHABLE;
     }
 
+    bool hasMaxLockTimeout() override {
+        MONGO_UNREACHABLE;
+    }
+
     void unsetMaxLockTimeout() override {
         MONGO_UNREACHABLE;
     }
diff --git a/src/mongo/db/introspect.cpp b/src/mongo/db/introspect.cpp
index c48ab2089eb..493f80ccc4f 100644
--- a/src/mongo/db/introspect.cpp
+++ b/src/mongo/db/introspect.cpp
@@ -118,8 +118,12 @@ void profile(OperationContext* opCtx, NetworkOp op) {
     try {
         // Even if the operation we are profiling was interrupted, we still want to output the
         // profiler entry.  This lock guard will prevent lock acquisitions from throwing exceptions
-        // before we finish writing the entry.
-        UninterruptibleLockGuard noInterrupt(opCtx->lockState());
+        // before we finish writing the entry. However, our maximum lock timeout overrides
+        // uninterruptibility.
+        boost::optional<UninterruptibleLockGuard> noInterrupt;
+        if (!opCtx->lockState()->hasMaxLockTimeout()) {
+            noInterrupt.emplace(opCtx->lockState());
+        }
 
         bool acquireDbXLock = false;
         while (true) {
diff --git a/src/mongo/db/session.cpp b/src/mongo/db/session.cpp
index 22683a3ab59..b1dff7aa220 100644
--- a/src/mongo/db/session.cpp
+++ b/src/mongo/db/session.cpp
@@ -662,6 +662,13 @@ Session::TxnResources::TxnResources(OperationContext* opCtx) {
     _locker->releaseTicket();
     _locker->unsetThreadId();
 
+    // This thread must still respect the transaction lock timeout, since it can prevent the
+    // transaction from making progress.
+    auto maxTransactionLockMillis = maxTransactionLockRequestTimeoutMillis.load();
+    if (maxTransactionLockMillis >= 0) {
+        opCtx->lockState()->setMaxLockTimeout(Milliseconds(maxTransactionLockMillis));
+    }
+
     _recoveryUnit = std::unique_ptr<RecoveryUnit>(opCtx->releaseRecoveryUnit());
     opCtx->setRecoveryUnit(opCtx->getServiceContext()->getStorageEngine()->newRecoveryUnit(),
                            WriteUnitOfWork::RecoveryUnitState::kNotInUnitOfWork);