SERVER-51456 Database Profiler outputs incorrect value of property "keysDeleted" for a remove operation when a write conflict occurs

15 files changed, 268 insertions, 0 deletions

diff --git a/buildscripts/resmokeconfig/suites/cst_jscore_passthrough.yml b/buildscripts/resmokeconfig/suites/cst_jscore_passthrough.yml
index 6f13f2f3b26..47561591768 100755
--- a/buildscripts/resmokeconfig/suites/cst_jscore_passthrough.yml
+++ b/buildscripts/resmokeconfig/suites/cst_jscore_passthrough.yml
@@ -346,6 +346,7 @@ selector:
   - jstests/core/profile_mapreduce.js
   - jstests/core/profile_sampling.js
   - jstests/core/profile_update.js
+  - jstests/core/profile_write_conflict.js
   - jstests/core/proj_key1.js
   - jstests/core/projection_meta_index_key.js
   - jstests/core/pull2.js
diff --git a/buildscripts/resmokeconfig/suites/replica_sets_fcbis_jscore_passthrough.yml b/buildscripts/resmokeconfig/suites/replica_sets_fcbis_jscore_passthrough.yml
index 86d4531c9ca..7d52cb61b82 100644
--- a/buildscripts/resmokeconfig/suites/replica_sets_fcbis_jscore_passthrough.yml
+++ b/buildscripts/resmokeconfig/suites/replica_sets_fcbis_jscore_passthrough.yml
@@ -28,6 +28,7 @@ selector:
   - jstests/core/profile_mapreduce.js
   - jstests/core/profile_sampling.js
   - jstests/core/profile_update.js
+  - jstests/core/profile_write_conflict.js
   - jstests/core/txns/transactions_profiling.js
   # The downstream syncing node affects the top output.
   - jstests/core/top.js
diff --git a/buildscripts/resmokeconfig/suites/replica_sets_initsync_jscore_passthrough.yml b/buildscripts/resmokeconfig/suites/replica_sets_initsync_jscore_passthrough.yml
index ad359bc6607..1e7dfcc243f 100644
--- a/buildscripts/resmokeconfig/suites/replica_sets_initsync_jscore_passthrough.yml
+++ b/buildscripts/resmokeconfig/suites/replica_sets_initsync_jscore_passthrough.yml
@@ -28,6 +28,7 @@ selector:
   - jstests/core/profile_mapreduce.js
   - jstests/core/profile_sampling.js
   - jstests/core/profile_update.js
+  - jstests/core/profile_write_conflict.js
   - jstests/core/txns/transactions_profiling.js
   # The downstream syncing node affects the top output.
   - jstests/core/top.js
diff --git a/buildscripts/resmokeconfig/suites/replica_sets_reconfig_jscore_stepdown_passthrough.yml b/buildscripts/resmokeconfig/suites/replica_sets_reconfig_jscore_stepdown_passthrough.yml
index f0187167f88..ffb5bd02d1c 100644
--- a/buildscripts/resmokeconfig/suites/replica_sets_reconfig_jscore_stepdown_passthrough.yml
+++ b/buildscripts/resmokeconfig/suites/replica_sets_reconfig_jscore_stepdown_passthrough.yml
@@ -21,6 +21,7 @@ selector:
   - jstests/core/profile2.js
   - jstests/core/profile3.js
   - jstests/core/profile_findandmodify.js
+  - jstests/core/profile_write_conflict.js
   - jstests/core/top.js
   - jstests/core/views/views_stats.js
 
diff --git a/buildscripts/resmokeconfig/suites/replica_sets_terminate_primary_jscore_passthrough.yml b/buildscripts/resmokeconfig/suites/replica_sets_terminate_primary_jscore_passthrough.yml
index 57472342f04..be7f0fd585e 100644
--- a/buildscripts/resmokeconfig/suites/replica_sets_terminate_primary_jscore_passthrough.yml
+++ b/buildscripts/resmokeconfig/suites/replica_sets_terminate_primary_jscore_passthrough.yml
@@ -13,6 +13,7 @@ selector:
   - jstests/core/profile2.js
   - jstests/core/profile3.js
   - jstests/core/profile_findandmodify.js
+  - jstests/core/profile_write_conflict.js
   - jstests/core/top.js
   - jstests/core/views/views_stats.js
 
diff --git a/buildscripts/resmokeconfig/suites/retryable_writes_downgrade.yml b/buildscripts/resmokeconfig/suites/retryable_writes_downgrade.yml
index 2ccddb9eaa8..08ff2a71112 100644
--- a/buildscripts/resmokeconfig/suites/retryable_writes_downgrade.yml
+++ b/buildscripts/resmokeconfig/suites/retryable_writes_downgrade.yml
@@ -13,6 +13,7 @@ selector:
   - jstests/core/profile2.js
   - jstests/core/profile3.js
   - jstests/core/profile_findandmodify.js
+  - jstests/core/profile_write_conflict.js
   - jstests/core/top.js
   - jstests/core/views/views_stats.js
 
diff --git a/buildscripts/resmokeconfig/suites/retryable_writes_jscore_passthrough.yml b/buildscripts/resmokeconfig/suites/retryable_writes_jscore_passthrough.yml
index 6a16af8357c..b0006809d7e 100644
--- a/buildscripts/resmokeconfig/suites/retryable_writes_jscore_passthrough.yml
+++ b/buildscripts/resmokeconfig/suites/retryable_writes_jscore_passthrough.yml
@@ -13,6 +13,7 @@ selector:
   - jstests/core/profile2.js
   - jstests/core/profile3.js
   - jstests/core/profile_findandmodify.js
+  - jstests/core/profile_write_conflict.js
   - jstests/core/top.js
   - jstests/core/views/views_stats.js
 
diff --git a/buildscripts/resmokeconfig/suites/retryable_writes_jscore_stepdown_passthrough.yml b/buildscripts/resmokeconfig/suites/retryable_writes_jscore_stepdown_passthrough.yml
index fd1a3c2963a..ee838cad66f 100644
--- a/buildscripts/resmokeconfig/suites/retryable_writes_jscore_stepdown_passthrough.yml
+++ b/buildscripts/resmokeconfig/suites/retryable_writes_jscore_stepdown_passthrough.yml
@@ -13,6 +13,7 @@ selector:
   - jstests/core/profile2.js
   - jstests/core/profile3.js
   - jstests/core/profile_findandmodify.js
+  - jstests/core/profile_write_conflict.js
   - jstests/core/top.js
   - jstests/core/views/views_stats.js
 
diff --git a/buildscripts/resmokeconfig/suites/sharded_retryable_writes_downgrade.yml b/buildscripts/resmokeconfig/suites/sharded_retryable_writes_downgrade.yml
index c577c6f464b..71d63097bac 100644
--- a/buildscripts/resmokeconfig/suites/sharded_retryable_writes_downgrade.yml
+++ b/buildscripts/resmokeconfig/suites/sharded_retryable_writes_downgrade.yml
@@ -13,6 +13,7 @@ selector:
   - jstests/core/profile2.js
   - jstests/core/profile3.js
   - jstests/core/profile_findandmodify.js
+  - jstests/core/profile_write_conflict.js
   - jstests/core/top.js
   - jstests/core/views/views_stats.js
 
diff --git a/buildscripts/resmokeconfig/suites/tenant_migration_kill_primary_jscore_passthrough.yml b/buildscripts/resmokeconfig/suites/tenant_migration_kill_primary_jscore_passthrough.yml
index 3e45bda292f..320569ab721 100644
--- a/buildscripts/resmokeconfig/suites/tenant_migration_kill_primary_jscore_passthrough.yml
+++ b/buildscripts/resmokeconfig/suites/tenant_migration_kill_primary_jscore_passthrough.yml
@@ -111,6 +111,7 @@ selector:
   - jstests/core/profile2.js
   - jstests/core/profile3.js
   - jstests/core/profile_findandmodify.js
+  - jstests/core/profile_write_conflict.js
   - jstests/core/top.js
   - jstests/core/views/views_stats.js
 
diff --git a/buildscripts/resmokeconfig/suites/tenant_migration_stepdown_jscore_passthrough.yml b/buildscripts/resmokeconfig/suites/tenant_migration_stepdown_jscore_passthrough.yml
index 37a9e5a07b0..f3fa2320e9e 100644
--- a/buildscripts/resmokeconfig/suites/tenant_migration_stepdown_jscore_passthrough.yml
+++ b/buildscripts/resmokeconfig/suites/tenant_migration_stepdown_jscore_passthrough.yml
@@ -109,6 +109,7 @@ selector:
   - jstests/core/profile2.js
   - jstests/core/profile3.js
   - jstests/core/profile_findandmodify.js
+  - jstests/core/profile_write_conflict.js
   - jstests/core/top.js
   - jstests/core/views/views_stats.js
 
diff --git a/buildscripts/resmokeconfig/suites/tenant_migration_terminate_primary_jscore_passthrough.yml b/buildscripts/resmokeconfig/suites/tenant_migration_terminate_primary_jscore_passthrough.yml
index 3c81d1c1605..0638eb49e73 100644
--- a/buildscripts/resmokeconfig/suites/tenant_migration_terminate_primary_jscore_passthrough.yml
+++ b/buildscripts/resmokeconfig/suites/tenant_migration_terminate_primary_jscore_passthrough.yml
@@ -109,6 +109,7 @@ selector:
   - jstests/core/profile2.js
   - jstests/core/profile3.js
   - jstests/core/profile_findandmodify.js
+  - jstests/core/profile_write_conflict.js
   - jstests/core/top.js
   - jstests/core/views/views_stats.js
 
diff --git a/jstests/core/profile_write_conflict.js b/jstests/core/profile_write_conflict.js
new file mode 100644
index 00000000000..15201e22392
--- /dev/null
+++ b/jstests/core/profile_write_conflict.js
@@ -0,0 +1,232 @@
+// Test profiling of insert, update, delete with write conflicts (SERVER-51456).
+//
+// @tags: [
+//   assumes_write_concern_unchanged,
+//   does_not_support_stepdowns,
+//   requires_profiling,
+// ]
+
+(function() {
+"use strict";
+
+load("jstests/libs/fail_point_util.js");  // for 'configureFailPoint()'
+load("jstests/libs/profiler.js");         // for 'getLatestProfilerEntry()'
+
+if (jsTestOptions().storageEngine !== "ephemeralForTest") {
+    jsTestLog("This test requires ephemeralForTest - exiting");
+    return 0;
+}
+
+const testDB = db.getSiblingDB(jsTestName());
+assert.commandWorked(testDB.dropDatabase());
+const coll = testDB.getCollection("test");
+const doc = {
+    a: 1,
+    b: 1
+};
+const writeConflicts = 100;
+
+assert.commandWorked(testDB.setProfilingLevel(2));
+
+{
+    // Test insert.
+    assert.commandWorked(testDB.createCollection(coll.getName()));
+    const fp = configureFailPoint(db, "EFTThrowWCEOnMerge", {}, {times: writeConflicts});
+    assert.commandWorked(testDB.runCommand(
+        {insert: coll.getName(), documents: [doc], comment: jsTestName() + "-insert"}));
+    fp.off();
+
+    const profileObj =
+        getLatestProfilerEntry(testDB, {"command.comment": jsTestName() + "-insert"});
+
+    assert.eq(profileObj.ninserted, 1, profileObj);
+    assert.eq(profileObj.keysInserted, 1, profileObj);
+    assert.gt(profileObj.writeConflicts, 0, profileObj);
+}
+
+{
+    // Test delete.
+    coll.drop();
+    assert.commandWorked(coll.insert(doc));
+    const fp = configureFailPoint(db, "EFTThrowWCEOnMerge", {}, {times: writeConflicts});
+    assert.commandWorked(testDB.runCommand({
+        delete: coll.getName(),
+        deletes: [{q: doc, limit: 0}],
+        comment: jsTestName() + "-delete"
+    }));
+    fp.off();
+
+    const profileObj =
+        getLatestProfilerEntry(testDB, {"command.comment": jsTestName() + "-delete"});
+
+    assert.eq(profileObj.ndeleted, 1, profileObj);
+    assert.eq(profileObj.keysDeleted, 1, profileObj);
+    assert.gt(profileObj.writeConflicts, 0, profileObj);
+}
+
+{
+    // Test update.
+    coll.drop();
+    assert.commandWorked(coll.insert(doc));
+    assert.commandWorked(coll.createIndex({a: 1}));
+    const fp = configureFailPoint(db, "EFTThrowWCEOnMerge", {}, {times: writeConflicts});
+    assert.commandWorked(testDB.runCommand({
+        update: coll.getName(),
+        updates: [{q: {a: 1}, u: {$set: {c: 1}, $inc: {a: -10}}}],
+        comment: jsTestName() + "-update"
+    }));
+    fp.off();
+
+    const profileObj =
+        getLatestProfilerEntry(testDB, {"command.comment": jsTestName() + "-update"});
+
+    assert.eq(profileObj.keysInserted, 1, profileObj);
+    assert.eq(profileObj.keysDeleted, 1, profileObj);
+    assert.eq(profileObj.nMatched, 1, profileObj);
+    assert.eq(profileObj.nModified, 1, profileObj);
+    assert.gt(profileObj.writeConflicts, 0, profileObj);
+}
+
+{
+    // Test upsert - update.
+    coll.drop();
+    assert.commandWorked(coll.insert(doc));
+    assert.commandWorked(coll.createIndex({a: 1}));
+    const fp = configureFailPoint(db, "EFTThrowWCEOnMerge", {}, {times: writeConflicts});
+    assert.commandWorked(testDB.runCommand({
+        update: coll.getName(),
+        updates: [{q: {a: 1}, u: {$set: {c: 1}, $inc: {a: -10}}, upsert: true}],
+        comment: jsTestName() + "-upsertu"
+    }));
+    fp.off();
+
+    const profileObj =
+        getLatestProfilerEntry(testDB, {"command.comment": jsTestName() + "-upsertu"});
+
+    assert.eq(profileObj.keysInserted, 1, profileObj);
+    assert.eq(profileObj.keysDeleted, 1, profileObj);
+    assert.eq(profileObj.nMatched, 1, profileObj);
+    assert.eq(profileObj.nModified, 1, profileObj);
+    assert.eq(profileObj.nUpserted, 0, profileObj);
+    assert.gt(profileObj.writeConflicts, 0, profileObj);
+}
+
+{
+    // Test upsert - insert.
+    coll.drop();
+    assert.commandWorked(coll.insert(doc));
+    assert.commandWorked(coll.createIndex({a: 1}));
+    const fp = configureFailPoint(db, "EFTThrowWCEOnMerge", {}, {times: writeConflicts});
+    assert.commandWorked(testDB.runCommand({
+        update: coll.getName(),
+        updates: [{q: {a: 2}, u: {$set: {c: 1}, $inc: {a: -10}}, upsert: true}],
+        comment: jsTestName() + "-upserti"
+    }));
+    fp.off();
+
+    const profileObj =
+        getLatestProfilerEntry(testDB, {"command.comment": jsTestName() + "-upserti"});
+
+    assert.eq(profileObj.keysInserted, 2, profileObj);
+    assert.eq(profileObj.nMatched, 0, profileObj);
+    assert.eq(profileObj.nModified, 0, profileObj);
+    assert.eq(profileObj.nUpserted, 1, profileObj);
+    assert.gt(profileObj.writeConflicts, 0, profileObj);
+}
+
+{
+    // Test findAndModify - delete.
+    coll.drop();
+    assert.commandWorked(coll.insert(doc));
+    const fp = configureFailPoint(db, "EFTThrowWCEOnMerge", {}, {times: writeConflicts});
+    assert.commandWorked(testDB.runCommand({
+        findAndModify: coll.getName(),
+        query: doc,
+        remove: true,
+        comment: jsTestName() + "-fnmdel"
+    }));
+    fp.off();
+
+    const profileObj =
+        getLatestProfilerEntry(testDB, {"command.comment": jsTestName() + "-fnmdel"});
+
+    assert.eq(profileObj.ndeleted, 1, profileObj);
+    assert.eq(profileObj.keysDeleted, 1, profileObj);
+    assert.gt(profileObj.writeConflicts, 0, profileObj);
+}
+
+{
+    // Test findAndModify - update.
+    coll.drop();
+    assert.commandWorked(coll.insert(doc));
+    assert.commandWorked(coll.createIndex({a: 1}));
+    const fp = configureFailPoint(db, "EFTThrowWCEOnMerge", {}, {times: writeConflicts});
+    assert.commandWorked(testDB.runCommand({
+        findAndModify: coll.getName(),
+        query: doc,
+        update: {$set: {c: 1}, $inc: {a: -10}},
+        comment: jsTestName() + "-fnmupd"
+    }));
+    fp.off();
+
+    const profileObj =
+        getLatestProfilerEntry(testDB, {"command.comment": jsTestName() + "-fnmupd"});
+
+    assert.eq(profileObj.keysInserted, 1, profileObj);
+    assert.eq(profileObj.keysDeleted, 1, profileObj);
+    assert.eq(profileObj.nMatched, 1, profileObj);
+    assert.eq(profileObj.nModified, 1, profileObj);
+    assert.gt(profileObj.writeConflicts, 0, profileObj);
+}
+
+{
+    // Test findAndModify - upsert - update.
+    coll.drop();
+    assert.commandWorked(coll.insert(doc));
+    assert.commandWorked(coll.createIndex({a: 1}));
+    const fp = configureFailPoint(db, "EFTThrowWCEOnMerge", {}, {times: writeConflicts});
+    assert.commandWorked(testDB.runCommand({
+        findAndModify: coll.getName(),
+        query: doc,
+        update: {$set: {c: 1}, $inc: {a: -10}},
+        upsert: true,
+        comment: jsTestName() + "-fnmupsu"
+    }));
+    fp.off();
+
+    const profileObj =
+        getLatestProfilerEntry(testDB, {"command.comment": jsTestName() + "-fnmupsu"});
+
+    assert.eq(profileObj.keysInserted, 1, profileObj);
+    assert.eq(profileObj.keysDeleted, 1, profileObj);
+    assert.eq(profileObj.nMatched, 1, profileObj);
+    assert.eq(profileObj.nModified, 1, profileObj);
+    assert.eq(profileObj.nUpserted, 0, profileObj);
+    assert.gt(profileObj.writeConflicts, 0, profileObj);
+}
+
+{
+    // Test findAndModify - upsert - insert.
+    coll.drop();
+    assert.commandWorked(coll.insert(doc));
+    assert.commandWorked(coll.createIndex({a: 1}));
+    const fp = configureFailPoint(db, "EFTThrowWCEOnMerge", {}, {times: writeConflicts});
+    assert.commandWorked(testDB.runCommand({
+        findAndModify: coll.getName(),
+        query: {a: 2},
+        update: {$set: {c: 1}, $inc: {a: -10}},
+        upsert: true,
+        comment: jsTestName() + "-fnmupsi"
+    }));
+    fp.off();
+
+    const profileObj =
+        getLatestProfilerEntry(testDB, {"command.comment": jsTestName() + "-fnmupsi"});
+
+    assert.eq(profileObj.keysInserted, 2, profileObj);
+    assert.eq(profileObj.nMatched, 0, profileObj);
+    assert.eq(profileObj.nModified, 0, profileObj);
+    assert.eq(profileObj.nUpserted, 1, profileObj);
+    assert.gt(profileObj.writeConflicts, 0, profileObj);
+}
+})();
diff --git a/src/mongo/db/catalog/collection_impl.cpp b/src/mongo/db/catalog/collection_impl.cpp
index 97a437950cc..e58330d61c4 100644
--- a/src/mongo/db/catalog/collection_impl.cpp
+++ b/src/mongo/db/catalog/collection_impl.cpp
@@ -954,6 +954,12 @@ Status CollectionImpl::_insertDocuments(OperationContext* opCtx,
 
     if (opDebug) {
         opDebug->additiveMetrics.incrementKeysInserted(keysInserted);
+        // 'opDebug' may be deleted at rollback time in case of multi-document transaction.
+        if (!opCtx->inMultiDocumentTransaction()) {
+            opCtx->recoveryUnit()->onRollback([opDebug, keysInserted]() {
+                opDebug->additiveMetrics.incrementKeysInserted(-keysInserted);
+            });
+        }
     }
 
     opCtx->getServiceContext()->getOpObserver()->onInserts(
@@ -1236,6 +1242,12 @@ void CollectionImpl::deleteDocument(OperationContext* opCtx,
 
     if (opDebug) {
         opDebug->additiveMetrics.incrementKeysDeleted(keysDeleted);
+        // 'opDebug' may be deleted at rollback time in case of multi-document transaction.
+        if (!opCtx->inMultiDocumentTransaction()) {
+            opCtx->recoveryUnit()->onRollback([opDebug, keysDeleted]() {
+                opDebug->additiveMetrics.incrementKeysDeleted(-keysDeleted);
+            });
+        }
     }
 }
 
@@ -1358,6 +1370,13 @@ RecordId CollectionImpl::updateDocument(OperationContext* opCtx,
         if (opDebug) {
             opDebug->additiveMetrics.incrementKeysInserted(keysInserted);
             opDebug->additiveMetrics.incrementKeysDeleted(keysDeleted);
+            // 'opDebug' may be deleted at rollback time in case of multi-document transaction.
+            if (!opCtx->inMultiDocumentTransaction()) {
+                opCtx->recoveryUnit()->onRollback([opDebug, keysInserted, keysDeleted]() {
+                    opDebug->additiveMetrics.incrementKeysInserted(-keysInserted);
+                    opDebug->additiveMetrics.incrementKeysDeleted(-keysDeleted);
+                });
+            }
         }
     }
 
diff --git a/src/mongo/db/storage/ephemeral_for_test/ephemeral_for_test_recovery_unit.cpp b/src/mongo/db/storage/ephemeral_for_test/ephemeral_for_test_recovery_unit.cpp
index 307c6e79078..252b3a0616e 100644
--- a/src/mongo/db/storage/ephemeral_for_test/ephemeral_for_test_recovery_unit.cpp
+++ b/src/mongo/db/storage/ephemeral_for_test/ephemeral_for_test_recovery_unit.cpp
@@ -42,6 +42,7 @@ namespace mongo {
 namespace ephemeral_for_test {
 namespace {
 MONGO_FAIL_POINT_DEFINE(EFTAlwaysThrowWCEOnWrite);
+MONGO_FAIL_POINT_DEFINE(EFTThrowWCEOnMerge);
 }  // namespace
 
 RecoveryUnit::RecoveryUnit(KVEngine* parentKVEngine, std::function<void()> cb)
@@ -62,6 +63,10 @@ void RecoveryUnit::doCommitUnitOfWork() {
 
     if (_dirty) {
         invariant(_forked);
+        if (MONGO_unlikely(EFTThrowWCEOnMerge.shouldFail())) {
+            throw WriteConflictException();
+        }
+
         while (true) {
             auto masterInfo = _KVEngine->getMasterInfo(_readAtTimestamp);
             try {