SERVER-34118 Log number of upserts performed

7 files changed, 101 insertions, 26 deletions

diff --git a/jstests/concurrency/fsm_workloads/explain_update.js b/jstests/concurrency/fsm_workloads/explain_update.js
index 694eea39628..5176f8d6c62 100644
--- a/jstests/concurrency/fsm_workloads/explain_update.js
+++ b/jstests/concurrency/fsm_workloads/explain_update.js
@@ -37,7 +37,7 @@ var $config = extendWorkload($config, function($config, $super) {
                 stage = stage.shards[0].executionStages;
             }
             assertAlways.eq(stage.stage, 'UPDATE');
-            assertWhenOwnColl(stage.wouldInsert);
+            assertWhenOwnColl(stage.nWouldUpsert == 1);
 
             // make sure that the insert didn't actually happen.
             assertWhenOwnColl.eq(this.nInserted, db[collName].find().itcount());
@@ -57,7 +57,7 @@ var $config = extendWorkload($config, function($config, $super) {
                 stage = stage.shards[0].executionStages;
             }
             assertAlways.eq(stage.stage, 'UPDATE');
-            assertWhenOwnColl(!stage.wouldInsert);
+            assertWhenOwnColl(stage.nWouldUpsert == 0);
             assertWhenOwnColl.eq(3, stage.nMatched);
             assertWhenOwnColl.eq(3, stage.nWouldModify);
         }
diff --git a/jstests/core/explain_find_and_modify.js b/jstests/core/explain_find_and_modify.js
index 2bea591def8..5e385ff3743 100644
--- a/jstests/core/explain_find_and_modify.js
+++ b/jstests/core/explain_find_and_modify.js
@@ -1,6 +1,6 @@
 // Cannot implicitly shard accessed collections because of collection existing when none
 // expected.
-// @tags: [assumes_no_implicit_collection_creation_after_drop]
+// @tags: [assumes_no_implicit_collection_creation_after_drop,requires_fcv_47]
 
 /**
  * Test correctness of explaining findAndModify. Asserts the following:
@@ -121,7 +121,7 @@ var testCases = [
             executionStats: {
                 nReturned: 0,
                 executionSuccess: true,
-                executionStages: {stage: "UPDATE", nWouldModify: 0, wouldInsert: false}
+                executionStages: {stage: "UPDATE", nWouldModify: 0, nWouldUpsert: 0}
             }
         }
     },
@@ -132,7 +132,7 @@ var testCases = [
             executionStats: {
                 nReturned: 0,
                 executionSuccess: true,
-                executionStages: {stage: "UPDATE", nWouldModify: 0, wouldInsert: false}
+                executionStages: {stage: "UPDATE", nWouldModify: 0, nWouldUpsert: 0}
             }
         }
     },
@@ -143,7 +143,7 @@ var testCases = [
             executionStats: {
                 nReturned: 1,
                 executionSuccess: true,
-                executionStages: {stage: "UPDATE", nWouldModify: 1, wouldInsert: false}
+                executionStages: {stage: "UPDATE", nWouldModify: 1, nWouldUpsert: 0}
             }
         }
     },
@@ -154,7 +154,7 @@ var testCases = [
             executionStats: {
                 nReturned: 1,
                 executionSuccess: true,
-                executionStages: {stage: "UPDATE", nWouldModify: 1, wouldInsert: false}
+                executionStages: {stage: "UPDATE", nWouldModify: 1, nWouldUpsert: 0}
             }
         }
     },
@@ -166,7 +166,7 @@ var testCases = [
             executionStats: {
                 nReturned: 0,
                 executionSuccess: true,
-                executionStages: {stage: "UPDATE", nWouldModify: 0, wouldInsert: true}
+                executionStages: {stage: "UPDATE", nWouldModify: 0, nWouldUpsert: 1}
             }
         }
     },
@@ -177,7 +177,7 @@ var testCases = [
             executionStats: {
                 nReturned: 1,
                 executionSuccess: true,
-                executionStages: {stage: "UPDATE", nWouldModify: 0, wouldInsert: true}
+                executionStages: {stage: "UPDATE", nWouldModify: 0, nWouldUpsert: 1}
             }
         }
     },
@@ -188,7 +188,7 @@ var testCases = [
             executionStats: {
                 nReturned: 1,
                 executionSuccess: true,
-                executionStages: {stage: "UPDATE", nWouldModify: 1, wouldInsert: false}
+                executionStages: {stage: "UPDATE", nWouldModify: 1, nWouldUpsert: 0}
             }
         }
     }
diff --git a/jstests/core/explain_shell_helpers.js b/jstests/core/explain_shell_helpers.js
index 5ebbab7d311..1a66a032143 100644
--- a/jstests/core/explain_shell_helpers.js
+++ b/jstests/core/explain_shell_helpers.js
@@ -7,6 +7,7 @@
  *   does_not_support_stepdowns,
  *   requires_fastcount,
  *   sbe_incompatible,
+ *   requires_fcv_47,
  * ]
  */
 
@@ -342,7 +343,7 @@ if ("SHARD_WRITE" === stage.stage) {
     stage = stage.shards[0].executionStages;
 }
 assert.eq(stage.stage, "UPDATE");
-assert(stage.wouldInsert);
+assert(stage.nWouldUpsert == 1);
 
 // Make sure that the insert didn't actually happen.
 assert.eq(10, t.count());
@@ -355,7 +356,7 @@ if ("SHARD_WRITE" === stage.stage) {
     stage = stage.shards[0].executionStages;
 }
 assert.eq(stage.stage, "UPDATE");
-assert(stage.wouldInsert);
+assert(stage.nWouldUpsert == 1);
 assert.eq(0, stage.nMatched);
 
 // Make sure that the insert didn't actually happen.
@@ -369,7 +370,7 @@ if ("SHARD_WRITE" === stage.stage) {
     stage = stage.shards[0].executionStages;
 }
 assert.eq(stage.stage, "UPDATE");
-assert(!stage.wouldInsert);
+assert(stage.nWouldUpsert == 0);
 assert.eq(3, stage.nMatched);
 assert.eq(3, stage.nWouldModify);
 
@@ -381,7 +382,7 @@ if ("SHARD_WRITE" === stage.stage) {
     stage = stage.shards[0].executionStages;
 }
 assert.eq(stage.stage, "UPDATE");
-assert(!stage.wouldInsert);
+assert(stage.nWouldUpsert == 0);
 assert.eq(3, stage.nMatched);
 assert.eq(3, stage.nWouldModify);
 
@@ -414,7 +415,7 @@ if ("SINGLE_SHARD" === stage.stage) {
     stage = stage.shards[0].executionStages;
 }
 assert.eq(stage.stage, "UPDATE");
-assert(stage.wouldInsert);
+assert(stage.nWouldUpsert == 1);
 
 // Make sure that the insert didn't actually happen.
 assert.eq(10, t.count());
diff --git a/jstests/core/profile_findandmodify.js b/jstests/core/profile_findandmodify.js
index b74eb1cd284..122024b514c 100644
--- a/jstests/core/profile_findandmodify.js
+++ b/jstests/core/profile_findandmodify.js
@@ -2,6 +2,7 @@
 // @tags: [
 //   requires_profiling,
 //   sbe_incompatible,
+//   requires_fcv_47,
 // ]
 
 (function() {
@@ -94,7 +95,7 @@ assert.eq(profileObj.keysExamined, 0, tojson(profileObj));
 assert.eq(profileObj.docsExamined, 0, tojson(profileObj));
 assert.eq(profileObj.nMatched, 0, tojson(profileObj));
 assert.eq(profileObj.nModified, 0, tojson(profileObj));
-assert.eq(profileObj.upsert, true, tojson(profileObj));
+assert.eq(profileObj.nUpserted, 1, tojson(profileObj));
 assert.eq(profileObj.keysInserted, 1, tojson(profileObj));
 assert.eq(profileObj.appName, "MongoDB Shell", tojson(profileObj));
 
diff --git a/jstests/core/profile_update.js b/jstests/core/profile_update.js
index 1fc207f80de..3e5ff97a68f 100644
--- a/jstests/core/profile_update.js
+++ b/jstests/core/profile_update.js
@@ -3,6 +3,7 @@
 //   requires_non_retryable_writes,
 //   requires_profiling,
 //   sbe_incompatible,
+//   requires_fcv_47,
 // ]
 
 // Confirms that profiled update execution contains all expected metrics with proper values.
@@ -108,12 +109,55 @@ assert.eq(profileObj.docsExamined, 0, tojson(profileObj));
 assert.eq(profileObj.keysInserted, 2, tojson(profileObj));
 assert.eq(profileObj.nMatched, 0, tojson(profileObj));
 assert.eq(profileObj.nModified, 0, tojson(profileObj));
-assert.eq(profileObj.upsert, true, tojson(profileObj));
+assert.eq(profileObj.nUpserted, 1, tojson(profileObj));
 assert.eq(profileObj.planSummary, "IXSCAN { _id: 1 }", tojson(profileObj));
 assert(profileObj.execStats.hasOwnProperty("stage"), tojson(profileObj));
 assert.eq(profileObj.appName, "MongoDB Shell", tojson(profileObj));
 
 //
+// Confirm metrics for batch insert on update with "upsert: true".
+//
+coll.drop();
+for (i = 0; i < 10; ++i) {
+    assert.commandWorked(coll.insert({a: i}));
+}
+assert.commandWorked(coll.createIndex({a: 1}));
+
+assert.commandWorked(testDB.runCommand({
+    update: coll.getName(),
+    updates: [
+        {q: {_id: "new value 4", a: 4}, u: {$inc: {b: 1}}, upsert: true},
+        {q: {_id: "new value 5", a: 5}, u: {$inc: {b: 1}}, upsert: true},
+        {q: {_id: "new value 6", a: 6}, u: {$inc: {b: 1}}, upsert: true}
+    ],
+    ordered: true
+}));
+
+// We need to check profiles for each individual update because they are logged separately.
+const profiles = getNLatestProfilerEntries(testDB, 3);
+assert.eq(profiles.length, 3, tojson(profiles));
+
+const indices = [6, 5, 4];
+for (var i = 0; i < indices.length; i++) {
+    const profileObj = profiles[i];
+    const index = indices[i];
+
+    assert.eq(
+        profileObj.command,
+        {q: {_id: `new value ${index}`, a: index}, u: {$inc: {b: 1}}, multi: false, upsert: true},
+        tojson(profileObj));
+    assert.eq(profileObj.keysExamined, 0, tojson(profileObj));
+    assert.eq(profileObj.docsExamined, 0, tojson(profileObj));
+    assert.eq(profileObj.keysInserted, 2, tojson(profileObj));
+    assert.eq(profileObj.nMatched, 0, tojson(profileObj));
+    assert.eq(profileObj.nModified, 0, tojson(profileObj));
+    assert.eq(profileObj.nUpserted, 1, tojson(profileObj));
+    assert.eq(profileObj.planSummary, "IXSCAN { _id: 1 }", tojson(profileObj));
+    assert(profileObj.execStats.hasOwnProperty("stage"), tojson(profileObj));
+    assert.eq(profileObj.appName, "MongoDB Shell", tojson(profileObj));
+}
+
+//
 // Confirm "fromMultiPlanner" metric.
 //
 coll.drop();
diff --git a/jstests/libs/profiler.js b/jstests/libs/profiler.js
index 45b64d33d30..ff066013f83 100644
--- a/jstests/libs/profiler.js
+++ b/jstests/libs/profiler.js
@@ -35,16 +35,21 @@ function buildCommandProfile(command, sharded) {
     return commandProfile;
 }
 
-// Retrieve latest system.profile entry.
-function getLatestProfilerEntry(profileDB, filter) {
+// Retrieve N latest system.profile entries.
+function getNLatestProfilerEntries(profileDB, count, filter) {
     if (filter === null) {
         filter = {};
     }
-    var cursor = profileDB.system.profile.find(filter).sort({$natural: -1});
+    var cursor = profileDB.system.profile.find(filter).sort({$natural: -1}).limit(count);
     assert(
         cursor.hasNext(),
         "could not find any entries in the profile collection matching filter: " + tojson(filter));
-    return cursor.next();
+    return cursor.toArray();
+}
+
+// Retrieve latest system.profile entry.
+function getLatestProfilerEntry(profileDB, filter) {
+    return getNLatestProfilerEntries(profileDB, 1, filter)[0];
 }
 
 // Returns a string representing the wire protocol used for commands run on the given connection.
diff --git a/jstests/noPassthrough/log_format_slowms_samplerate_loglevel.js b/jstests/noPassthrough/log_format_slowms_samplerate_loglevel.js
index 64164be4a0b..0e8741318ce 100644
--- a/jstests/noPassthrough/log_format_slowms_samplerate_loglevel.js
+++ b/jstests/noPassthrough/log_format_slowms_samplerate_loglevel.js
@@ -276,7 +276,7 @@ function runLoggingTests({db, readWriteMode, slowMs, logLevel, sampleRate}) {
                 ordered: true,
                 nMatched: 0,
                 nModified: 0,
-                upsert: 1,
+                nUpserted: 1,
                 nShards: 1
             }
                                  : {
@@ -288,7 +288,7 @@ function runLoggingTests({db, readWriteMode, slowMs, logLevel, sampleRate}) {
                                        docsExamined: 0,
                                        nMatched: 0,
                                        nModified: 0,
-                                       upsert: 1
+                                       nUpserted: 1
                                    })
         },
         {
@@ -342,6 +342,29 @@ function runLoggingTests({db, readWriteMode, slowMs, logLevel, sampleRate}) {
             },
             logFields:
                 {command: "aggregate", aggregate: coll.getName(), hasSortStage: 1, usedDisk: 1}
+        },
+        {
+            test: function(db) {
+                assert.commandWorked(db.runCommand({
+                    update: "test",
+                    updates: [
+                        {q: {_id: 200}, u: {$inc: {c: 1}}, upsert: true},
+                        {q: {_id: 201}, u: {$inc: {c: 1}}, upsert: true},
+                        {q: {_id: 202}, u: {$inc: {c: 1}}, upsert: true}
+                    ],
+                    ordered: true
+                }));
+            },
+            logFields: (isMongos ? {
+                command: "update",
+                update: coll.getName(),
+                ordered: true,
+                nMatched: 0,
+                nModified: 0,
+                nUpserted: 3,
+                nShards: 1
+            }
+                                 : {command: "update", ns: `${db.getName()}.$cmd`})
         }
     ];
 
@@ -379,19 +402,20 @@ function runLoggingTests({db, readWriteMode, slowMs, logLevel, sampleRate}) {
     for (let cmdName in originatingCommands) {
         const cmdObj = originatingCommands[cmdName];
         const cmdRes = assert.commandWorked(db.runCommand(cmdObj));
+        const expectedCountOfDocuments = 14;
 
         testList.push({
             test: function(db) {
                 const cursor = new DBCommandCursor(db, cmdRes);
-                assert.eq(cursor.itcount(), 11);
+                assert.eq(cursor.itcount(), expectedCountOfDocuments);
             },
             logFields: Object.assign({getMore: cmdRes.cursor.id}, cmdObj, {
                 cursorid: cmdRes.cursor.id,
                 planSummary: "COLLSCAN",
                 cursorExhausted: 1,
-                docsExamined: 11,
+                docsExamined: expectedCountOfDocuments,
                 keysExamined: 0,
-                nreturned: 11,
+                nreturned: expectedCountOfDocuments,
                 nShards: stParams.shards
             })
         });