Lost in the lab: Building an Index....tion

I am working on the lab Building an Index in the Foreground in Production

This is what I can observe and think is the relevant information in the server log file:

2020-12-19T06:12:08.896+0000 ... : createIndexes { createIndexes: "employees", indexes: [ { name: "last_name_1_first_name_1", key: { last_name: 1, first_name: 1 } } ] } numYields:0 reslen:113 locks:{...} protocol:op_query 5413ms

2020-12-19T06:12:08.893+0000 ... : find { find: "employees", filter: { _id: ObjectId('5fdd97ab11c6d11eaba6b890') } } planSummary: IDHACK keysExamined:1 docsExamined:1 cursorExhausted:1 numYields:0 nreturned:1 reslen:471 locks:{...} protocol:op_query 5229ms

To judge if this is a long running operation (or not) I look at what follows protocol:op_query.

And I also look at the time stamp at the beginning of the line (to answer the question).

Everything I can see before 2020-12-19T06:12:08.893 in the logs has a time length of a few hundred milliseconds or so; everything I can see after has a time length of a few seconds. Therefore I consider this time stamp (2020-12-19T06:12:08.893) to be the starting point of long running operations.

Comparing the two relevant time stamps I have in the logs (mentioned above):

2020-12-19T06:12:08.893
and:
2020-12-19T06:12:08.896

seeing that the difference between the two is less than a second.
The only possible answer that seems to fit my observation is:

The second one in the list.

But this answer is flagged as Incorrect!

In front of this result I must say, I am kind of lost and don’t really know where to look at.

Am I looking at the logs in a totally wrong way from start?
Or am I just missing one small detail?

Some help would be very useful and welcome.

P.S.
I could also take a different approach, since the consequence cannot come before the cause and conclude that the proper answer is the third one. But since the point of this lab is to be able to find information in the logs. I doubt this approach is the right one here.

Hi @Michel_Bouchet ,

I think the error is occuring among the following choices:

  • Less than one second before the index build began.
  • Less than one second after the index build began.
  • Less than one second before the index build ended.
  • Less than one second after the index build ended.

Try re-reviewing your log files and see if the index build began or ended.

Please feel free to reach out if you have any questions.

Kind Regards,
Sonali

Following your answer, do you mean:
“2020-12-19T06:12:08.896+0000” is the end of the createIndexes operation?
I had taken for granted that it was the start, but after all I may have been wrong.

Anyway, if this is the case, can I ask you how you can see that this is the end and not the beginning?

Second point, let us assume that this is indeed the end of the createIndexes operation that is happening at timing “2020-12-19T06:12:08.896+0000”. In this case that would mean that troubles (meaning “long running operations”) are not coming while the createIndexes operation is happening but after. In other words, it was a mistake to create an index; putting in a different way the DBA who did the createIndexes brough trouble rather than solved problems. If this is the case, just for the purpose of the exercise; then why not ? But that makes the homework even more difficult for us students.

Please clarify it all so that I understand where I am thinking right or wrong.

Michel,

I apologize for the course not being clear. Any timestamp listed in a log is the end of the operation. When an operation finishes, either successfully or not, the last thing it does is output a log line. So if a timestamp says 2020-12-19T12:00:05.000 and it took 5,000 milliseconds to complete, the operation began at 2020-12-19T12:00:00.000.

Let’s apply this thinking back to the problem at hand. You see the createIndexes log line at 2020-12-19T06:12:08.896 and it takes 5413ms to execute. Subtract the times and we can see that the createIndexes command started at 2020-12-19T06:12:03.483.

Now let’s do the same for the query you identified. 2020-12-19T06:12:08.893+0000 is the end time and 5229ms is the duration. That means the query started at 2020-12-19T06:12:03.664. Thus, the query started after the createIndexes.

Because foreground index builds block all other operations on a database, any query that attempts to run during the foreground build needs to wait for the build to finish before executing. Because of this massive performance hit, we previously recommended users use background index builds on populated collections. This lab was meant to show why using foreground instead of background was a bad idea. In MongoDB 4.2, we changed the process so that every index was built with minimal performance impact.

I haven’t given you the answer for the Lab but it should be pretty simple to figure out with the above information. Just remember, the timestamp in the logs is the end of the operation.

Many thanks for this reply. It makes things much clearer, starting with the important fact that the log-time refers to the end of the operation, not the start as I used to think. Sorry if this is one point that I missed in the lectures. I took the time to redo the calculations while following your explanations.

So we have this:

createIndexes
starts at: 2020-12-19T06:12:03.483
ends at: 2020-12-19T06:12:08.896

and:

the-long-operation
starts at: 2020-12-19T06:12:03.664
ends at: 2020-12-19T06:12:08.893

So the-long-operation starts after createIndexes starts and ends before createIndexes ends.

Now, if I consider the question in the homework:

When do the long-running operations begin to appear in the log files, based on their timestamps?

Since 12:03.664 is less than one second after 12:03.483.

I see only one possible answer:

Less than one second after the index build began

But I also already know this answer is wrong because this is one of the two I have tried (even if that was with an incorrect thinking paradygme).

So what am I still missing?

The question asks “when do the long-running operations begin to appear in the log files” NOT “when do the long-running operations begin”.

However, can you rerun the script and see what the values are then? I think there is an inconsistency in what you’re seeing in the logs and the expected answer and I’m not sure where the problem is.

I kind of thought the two were going together, but you’re right, about the question reading “long-running operations begin to appear in the log files”.

I did the experiment again so you can check what you want. And I include the output of two commands that I ran, for the second one I removed part of it to avoid overwelming you with a too long message.

Here createIndexes is the first time taking operation appearing.

vagrant@m312:~/shared$ mloginfo --queries …/data/m312RS/rs?/mongod.log
source: …/data/m312RS/rs1/mongod.log
host: m312:30000
start: 2021 Jan 12 07:15:54.191
end: 2021 Jan 12 07:20:47.750
date format: iso8601-local
length: 584
binary: mongod
version: 3.4.2
storage: wiredTiger

QUERIES

namespace operation pattern count min (ms) max (ms) mean (ms) 95%-ile (ms) sum (ms)
()
m312.employees find {"_id": 1} 30 789 5685 3251 n/a 97540
m312.employees update {"_id": 1} 30 749 5638 3196 n/a 95908


 source: ../data/m312RS/rs2/mongod.log
   host: m312:30001
  start: 2021 Jan 12 07:15:54.361
    end: 2021 Jan 12 07:18:47.533

date format: iso8601-local
length: 128
binary: mongod
version: 3.4.2
storage: wiredTiger

QUERIES

no queries found.


 source: ../data/m312RS/rs3/mongod.log
   host: m312:30002
  start: 2021 Jan 12 07:15:54.520
    end: 2021 Jan 12 07:20:47.750

date format: iso8601-local
length: 130
binary: mongod
version: 3.4.2
storage: wiredTiger

QUERIES

no queries found.
vagrant@m312:~/shared$

vagrant@m312:~/shared$ mlogfilter …/data/m312RS/rs1/mongod.log --component COMMAND

lots of lines:
protocol:op_query 100~200 ms

2021-01-12T07:18:03.387+0000 I COMMAND [conn22] command m312.employees command: insert { insert: “employees”, documents: 1000, writeConcern: { getLastError: 1, w: “majority” }, ordered: false } ninserted:1000 keysInserted:1000 numYields:0 reslen:104 locks:{ Global: { acquireCount: { r: 32, w: 32 } }, Database: { acquireCount: { w: 32 } }, Collection: { acquireCount: { w: 16 } }, Metadata: { acquireCount: { w: 16 } }, oplog: { acquireCount: { w: 16 } } } protocol:op_query 189ms
2021-01-12T07:18:26.649+0000 I COMMAND [conn28] CMD: dropIndexes m312.employees
2021-01-12T07:18:41.379+0000 I COMMAND [conn28] command m312.$cmd command: createIndexes { createIndexes: “employees”, indexes: [ { name: “last_name_1_first_name_1”, key: { last_name: 1, first_name: 1 } } ] } numYields:0 reslen:113 locks:{ Global: { acquireCount: { r: 2, w: 2 } }, Database: { acquireCount: { w: 1, W: 1 } }, Collection: { acquireCount: { w: 1 } }, Metadata: { acquireCount: { w: 1 } }, oplog: { acquireCount: { w: 1 } } } protocol:op_query 5679ms
2021-01-12T07:18:41.380+0000 I COMMAND [conn30] command m312.$cmd command: update { update: “employees”, ordered: true, updates: [ { q: { _id: ObjectId(‘5ffd4cbf346d8b1cc01aa4cf’) }, u: { $inc: { count: 1 } }, multi: false, upsert: false } ] } numYields:0 reslen:119 locks:{ Global: { acquireCount: { r: 2, w: 2 } }, Database: { acquireCount: { w: 2 }, acquireWaitCount: { w: 1 }, timeAcquiringMicros: { w: 5595248 } }, Collection: { acquireCount: { w: 1 } }, Metadata: { acquireCount: { w: 1 } }, oplog: { acquireCount: { w: 1 } } } protocol:op_query 5638ms
2021-01-12T07:18:41.380+0000 I COMMAND [conn34] command m312.$cmd command: update { update: “employees”, ordered: true, updates: [ { q: { _id: ObjectId(‘5ffd4cbf346d8b1cc01aa4cf’) }, u: { $inc: { count: 1 } }, multi: false, upsert: false } ] } numYields:0 reslen:119 locks:{ Global: { acquireCount: { r: 2, w: 2 } }, Database: { acquireCount: { w: 2 }, acquireWaitCount: { w: 1 }, timeAcquiringMicros: { w: 5494955 } }, Collection: { acquireCount: { w: 1 } }, Metadata: { acquireCount: { w: 1 } }, oplog: { acquireCount: { w: 1 } } } protocol:op_query 5538ms
2021-01-12T07:18:41.380+0000 I COMMAND [conn40] command m312.employees command: find { find: “employees”, filter: { _id: ObjectId(‘5ffd4cbf346d8b1cc01aa4cf’) } } planSummary: IDHACK keysExamined:1 docsExamined:1 cursorExhausted:1 numYields:0 nreturned:1 reslen:482 locks:{ Global: { acquireCount: { r: 2 } }, Database: { acquireCount: { r: 1 }, acquireWaitCount: { r: 1 }, timeAcquiringMicros: { r: 5351853 } }, Collection: { acquireCount: { r: 1 } } } protocol:op_query 5395ms
2021-01-12T07:18:41.381+0000 I COMMAND [conn38] command m312.$cmd command: update { update: “employees”, ordered: true, updates: [ { q: { _id: ObjectId(‘5ffd4cbf346d8b1cc01aa4cf’) }, u: { $inc: { count: 1 } }, multi: false, upsert: false } ] } numYields:0 reslen:119 locks:{ Global: { acquireCount: { r: 2, w: 2 } }, Database: { acquireCount: { w: 2 }, acquireWaitCount: { w: 1 }, timeAcquiringMicros: { w: 5400829 } }, Collection: { acquireCount: { w: 1 } }, Metadata: { acquireCount: { w: 1 } }, oplog: { acquireCount: { w: 1 } } } protocol:op_query 5443ms
2021-01-12T07:18:41.381+0000 I COMMAND [conn36] command m312.employees command: find { find: “employees”, filter: { _id: ObjectId(‘5ffd4cbf346d8b1cc01aa4cf’) } } planSummary: IDHACK keysExamined:1 docsExamined:1 cursorExhausted:1 numYields:0 nreturned:1 reslen:482 locks:{ Global: { acquireCount: { r: 2 } }, Database: { acquireCount: { r: 1 }, acquireWaitCount: { r: 1 }, timeAcquiringMicros: { r: 5452989 } }, Collection: { acquireCount: { r: 1 } } } protocol:op_query 5496ms
2021-01-12T07:18:41.381+0000 I COMMAND [conn32] command m312.employees command: find { find: “employees”, filter: { _id: ObjectId(‘5ffd4cbf346d8b1cc01aa4cf’) } } planSummary: IDHACK keysExamined:1 docsExamined:1 cursorExhausted:1 numYields:0 nreturned:1 reslen:482 locks:{ Global: { acquireCount: { r: 2 } }, Database: { acquireCount: { r: 1 }, acquireWaitCount: { r: 1 }, timeAcquiringMicros: { r: 5557626 } }, Collection: { acquireCount: { r: 1 } } } protocol:op_query 5600ms
2021-01-12T07:18:41.382+0000 I COMMAND [conn44] command m312.employees command: find { find: “employees”, filter: { _id: ObjectId(‘5ffd4cbf346d8b1cc01aa4cf’) } } planSummary: IDHACK keysExamined:1 docsExamined:1 cursorExhausted:1 numYields:0 nreturned:1 reslen:482 locks:{ Global: { acquireCount: { r: 2 } }, Database: { acquireCount: { r: 1 }, acquireWaitCount: { r: 1 }, timeAcquiringMicros: { r: 5252833 } }, Collection: { acquireCount: { r: 1 } } } protocol:op_query 5297ms
2021-01-12T07:18:41.383+0000 I COMMAND [conn42] command m312.$cmd command: update { update: “employees”, ordered: true, updates: [ { q: { _id: ObjectId(‘5ffd4cbf346d8b1cc01aa4cf’) }, u: { $inc: { count: 1 } }, multi: false, upsert: false } ] } numYields:0 reslen:119 locks:{ Global: { acquireCount: { r: 2, w: 2 } }, Database: { acquireCount: { w: 2 }, acquireWaitCount: { w: 1 }, timeAcquiringMicros: { w: 5290180 } }, Collection: { acquireCount: { w: 1 } }, Metadata: { acquireCount: { w: 1 } }, oplog: { acquireCount: { w: 1 } } } protocol:op_query 5334ms
2021-01-12T07:18:41.389+0000 I COMMAND [conn46] command m312.$cmd command: update { update: “employees”, ordered: true, updates: [ { q: { _id: ObjectId(‘5ffd4cbf346d8b1cc01aa4cf’) }, u: { $inc: { count: 1 } }, multi: false, upsert: false } ] } numYields:0 reslen:119 locks:{ Global: { acquireCount: { r: 2, w: 2 } }, Database: { acquireCount: { w: 2 }, acquireWaitCount: { w: 1 }, timeAcquiringMicros: { w: 5175870 } }, Collection: { acquireCount: { w: 1 } }, Metadata: { acquireCount: { w: 1 } }, oplog: { acquireCount: { w: 1 } } } protocol:op_query 5226ms
2021-01-12T07:18:41.389+0000 I COMMAND [conn48] command m312.employees command: find { find: “employees”, filter: { _id: ObjectId(‘5ffd4cbf346d8b1cc01aa4cf’) } } planSummary: IDHACK keysExamined:1 docsExamined:1 cursorExhausted:1 numYields:0 nreturned:1 reslen:482 locks:{ Global: { acquireCount: { r: 2 } }, Database: { acquireCount: { r: 1 }, acquireWaitCount: { r: 1 }, timeAcquiringMicros: { r: 5145310 } }, Collection: { acquireCount: { r: 1 } } } protocol:op_query 5195ms
2021-01-12T07:18:41.389+0000 I COMMAND [conn52] command m312.employees command: find { find: “employees”, filter: { _id: ObjectId(‘5ffd4cbf346d8b1cc01aa4cf’) } } planSummary: IDHACK keysExamined:1 docsExamined:1 cursorExhausted:1 numYields:0 nreturned:1 reslen:482 locks:{ Global: { acquireCount: { r: 2 } }, Database: { acquireCount: { r: 1 }, acquireWaitCount: { r: 1 }, timeAcquiringMicros: { r: 5027888 } }, Collection: { acquireCount: { r: 1 } } } protocol:op_query 5079ms
2021-01-12T07:18:41.389+0000 I COMMAND [conn50] command m312.$cmd command: update { update: “employees”, ordered: true, updates: [ { q: { _id: ObjectId(‘5ffd4cbf346d8b1cc01aa4cf’) }, u: { $inc: { count: 1 } }, multi: false, upsert: false } ] } numYields:0 reslen:119 locks:{ Global: { acquireCount: { r: 2, w: 2 } }, Database: { acquireCount: { w: 2 }, acquireWaitCount: { w: 1 }, timeAcquiringMicros: { w: 5088703 } }, Collection: { acquireCount: { w: 1 } }, Metadata: { acquireCount: { w: 1 } }, oplog: { acquireCount: { w: 1 } } } protocol:op_query 5140ms
2021-01-12T07:18:41.391+0000 I COMMAND [conn68] command m312.employees command: find { find: “employees”, filter: { _id: ObjectId(‘5ffd4cbf346d8b1cc01aa4ce’) } } planSummary: IDHACK keysExamined:1 docsExamined:1 cursorExhausted:1 numYields:0 nreturned:1 reslen:459 locks:{ Global: { acquireCount: { r: 2 } }, Database: { acquireCount: { r: 1 }, acquireWaitCount: { r: 1 }, timeAcquiringMicros: { r: 5632417 } }, Collection: { acquireCount: { r: 1 } } } protocol:op_query 5685ms
2021-01-12T07:18:41.392+0000 I COMMAND [conn54] command m312.$cmd command: update { update: “employees”, ordered: true, updates: [ { q: { _id: ObjectId(‘5ffd4cbf346d8b1cc01aa4cf’) }, u: { $inc: { count: 1 } }, multi: false, upsert: false } ] } numYields:0 reslen:119 locks:{ Global: { acquireCount: { r: 2, w: 2 } }, Database: { acquireCount: { w: 2 }, acquireWaitCount: { w: 1 }, timeAcquiringMicros: { w: 4982229 } }, Collection: { acquireCount: { w: 1 } }, Metadata: { acquireCount: { w: 1 } }, oplog: { acquireCount: { w: 1 } } } protocol:op_query 5035ms
2021-01-12T07:18:41.394+0000 I COMMAND [conn56] command m312.employees command: find { find: “employees”, filter: { _id: ObjectId(‘5ffd4cbf346d8b1cc01aa4cf’) } } planSummary: IDHACK keysExamined:1 docsExamined:1 cursorExhausted:1 numYields:0 nreturned:1 reslen:482 locks:{ Global: { acquireCount: { r: 2 } }, Database: { acquireCount: { r: 1 }, acquireWaitCount: { r: 1 }, timeAcquiringMicros: { r: 4940457 } }, Collection: { acquireCount: { r: 1 } } } protocol:op_query 4995ms
2021-01-12T07:18:41.394+0000 I COMMAND [conn58] command m312.$cmd command: update { update: “employees”, ordered: true, updates: [ { q: { _id: ObjectId(‘5ffd4cbf346d8b1cc01aa4cf’) }, u: { $inc: { count: 1 } }, multi: false, upsert: false } ] } numYields:0 reslen:119 locks:{ Global: { acquireCount: { r: 2, w: 2 } }, Database: { acquireCount: { w: 2 }, acquireWaitCount: { w: 1 }, timeAcquiringMicros: { w: 4876575 } }, Collection: { acquireCount: { w: 1 } }, Metadata: { acquireCount: { w: 1 } }, oplog: { acquireCount: { w: 1 } } } protocol:op_query 4930ms
2021-01-12T07:18:41.395+0000 I COMMAND [conn62] command m312.$cmd command: update { update: “employees”, ordered: true, updates: [ { q: { _id: ObjectId(‘5ffd4cbf346d8b1cc01aa4cf’) }, u: { $inc: { count: 1 } }, multi: false, upsert: false } ] } numYields:0 reslen:119 locks:{ Global: { acquireCount: { r: 2, w: 2 } }, Database: { acquireCount: { w: 2 }, acquireWaitCount: { w: 1 }, timeAcquiringMicros: { w: 4779470 } }, Collection: { acquireCount: { w: 1 } }, Metadata: { acquireCount: { w: 1 } }, oplog: { acquireCount: { w: 1 } } } protocol:op_query 4833ms
2021-01-12T07:18:41.395+0000 I COMMAND [conn64] command m312.employees command: find { find: “employees”, filter: { _id: ObjectId(‘5ffd4cbf346d8b1cc01aa4cf’) } } planSummary: IDHACK keysExamined:1 docsExamined:1 cursorExhausted:1 numYields:0 nreturned:1 reslen:482 locks:{ Global: { acquireCount: { r: 2 } }, Database: { acquireCount: { r: 1 }, acquireWaitCount: { r: 1 }, timeAcquiringMicros: { r: 4728211 } }, Collection: { acquireCount: { r: 1 } } } protocol:op_query 4781ms
2021-01-12T07:18:41.395+0000 I COMMAND [conn69] command m312.employees command: find { find: “employees”, filter: { _id: ObjectId(‘5ffd4cbf346d8b1cc01aa4cf’) } } planSummary: IDHACK keysExamined:1 docsExamined:1 cursorExhausted:1 numYields:0 nreturned:1 reslen:482 locks:{ Global: { acquireCount: { r: 2 } }, Database: { acquireCount: { r: 1 }, acquireWaitCount: { r: 1 }, timeAcquiringMicros: { r: 3630726 } }, Collection: { acquireCount: { r: 1 } } } protocol:op_query 3684ms
2021-01-12T07:18:41.395+0000 I COMMAND [conn70] command m312.$cmd command: update { update: “employees”, ordered: true, updates: [ { q: { _id: ObjectId(‘5ffd4cbf346d8b1cc01aa4d0’) }, u: { $inc: { count: 1 } }, multi: false, upsert: false } ] } numYields:0 reslen:119 locks:{ Global: { acquireCount: { r: 2, w: 2 } }, Database: { acquireCount: { w: 2 }, acquireWaitCount: { w: 1 }, timeAcquiringMicros: { w: 3596076 } }, Collection: { acquireCount: { w: 1 } }, Metadata: { acquireCount: { w: 1 } }, oplog: { acquireCount: { w: 1 } } } protocol:op_query 3649ms
2021-01-12T07:18:41.395+0000 I COMMAND [conn71] command m312.employees command: find { find: “employees”, filter: { _id: ObjectId(‘5ffd4cbf346d8b1cc01aa4d0’) } } planSummary: IDHACK keysExamined:1 docsExamined:1 cursorExhausted:1 numYields:0 nreturned:1 reslen:495 locks:{ Global: { acquireCount: { r: 2 } }, Database: { acquireCount: { r: 1 }, acquireWaitCount: { r: 1 }, timeAcquiringMicros: { r: 3558438 } }, Collection: { acquireCount: { r: 1 } } } protocol:op_query 3612ms
2021-01-12T07:18:41.395+0000 I COMMAND [conn73] command m312.employees command: find { find: “employees”, filter: { _id: ObjectId(‘5ffd4cbf346d8b1cc01aa4d0’) } } planSummary: IDHACK keysExamined:1 docsExamined:1 cursorExhausted:1 numYields:0 nreturned:1 reslen:495 locks:{ Global: { acquireCount: { r: 2 } }, Database: { acquireCount: { r: 1 }, acquireWaitCount: { r: 1 }, timeAcquiringMicros: { r: 3454149 } }, Collection: { acquireCount: { r: 1 } } } protocol:op_query 3507ms
2021-01-12T07:18:41.396+0000 I COMMAND [conn74] command m312.$cmd command: update { update: “employees”, ordered: true, updates: [ { q: { _id: ObjectId(‘5ffd4cbf346d8b1cc01aa4d0’) }, u: { $inc: { count: 1 } }, multi: false, upsert: false } ] } numYields:0 reslen:119 locks:{ Global: { acquireCount: { r: 2, w: 2 } }, Database: { acquireCount: { w: 2 }, acquireWaitCount: { w: 1 }, timeAcquiringMicros: { w: 3402141 } }, Collection: { acquireCount: { w: 1 } }, Metadata: { acquireCount: { w: 1 } }, oplog: { acquireCount: { w: 1 } } } protocol:op_query 3455ms
2021-01-12T07:18:41.399+0000 I COMMAND [conn60] command m312.employees command: find { find: “employees”, filter: { _id: ObjectId(‘5ffd4cbf346d8b1cc01aa4cf’) } } planSummary: IDHACK keysExamined:1 docsExamined:1 cursorExhausted:1 numYields:0 nreturned:1 reslen:482 locks:{ Global: { acquireCount: { r: 2 } }, Database: { acquireCount: { r: 1 }, acquireWaitCount: { r: 1 }, timeAcquiringMicros: { r: 4837690 } }, Collection: { acquireCount: { r: 1 } } } protocol:op_query 4889ms
2021-01-12T07:18:41.399+0000 I COMMAND [conn66] command m312.$cmd command: update { update: “employees”, ordered: true, updates: [ { q: { _id: ObjectId(‘5ffd4cbf346d8b1cc01aa4cf’) }, u: { $inc: { count: 1 } }, multi: false, upsert: false } ] } numYields:0 reslen:119 locks:{ Global: { acquireCount: { r: 2, w: 2 } }, Database: { acquireCount: { w: 2 }, acquireWaitCount: { w: 1 }, timeAcquiringMicros: { w: 4683948 } }, Collection: { acquireCount: { w: 1 } }, Metadata: { acquireCount: { w: 1 } }, oplog: { acquireCount: { w: 1 } } } protocol:op_query 4736ms
2021-01-12T07:18:41.399+0000 I COMMAND [conn72] command m312.$cmd command: update { update: “employees”, ordered: true, updates: [ { q: { _id: ObjectId(‘5ffd4cbf346d8b1cc01aa4d0’) }, u: { $inc: { count: 1 } }, multi: false, upsert: false } ] } numYields:0 reslen:119 locks:{ Global: { acquireCount: { r: 2, w: 2 } }, Database: { acquireCount: { w: 2 }, acquireWaitCount: { w: 1 }, timeAcquiringMicros: { w: 3502119 } }, Collection: { acquireCount: { w: 1 } }, Metadata: { acquireCount: { w: 1 } }, oplog: { acquireCount: { w: 1 } } } protocol:op_query 3554ms
2021-01-12T07:18:41.399+0000 I COMMAND [conn75] command m312.employees command: find { find: “employees”, filter: { _id: ObjectId(‘5ffd4cbf346d8b1cc01aa4d0’) } } planSummary: IDHACK keysExamined:1 docsExamined:1 cursorExhausted:1 numYields:0 nreturned:1 reslen:495 locks:{ Global: { acquireCount: { r: 2 } }, Database: { acquireCount: { r: 1 }, acquireWaitCount: { r: 1 }, timeAcquiringMicros: { r: 3358555 } }, Collection: { acquireCount: { r: 1 } } } protocol:op_query 3410ms
2021-01-12T07:18:41.403+0000 I COMMAND [conn77] command m312.employees command: find { find: “employees”, filter: { _id: ObjectId(‘5ffd4cbf346d8b1cc01aa4d0’) } } planSummary: IDHACK keysExamined:1 docsExamined:1 cursorExhausted:1 numYields:0 nreturned:1 reslen:495 locks:{ Global: { acquireCount: { r: 2 } }, Database: { acquireCount: { r: 1 }, acquireWaitCount: { r: 1 }, timeAcquiringMicros: { r: 3263084 } }, Collection: { acquireCount: { r: 1 } } } protocol:op_query 3314ms
2021-01-12T07:18:41.403+0000 I COMMAND [conn78] command m312.$cmd command: update { update: “employees”, ordered: true, updates: [ { q: { _id: ObjectId(‘5ffd4cbf346d8b1cc01aa4d0’) }, u: { $inc: { count: 1 } }, multi: false, upsert: false } ] } numYields:0 reslen:119 locks:{ Global: { acquireCount: { r: 2, w: 2 } }, Database: { acquireCount: { w: 2 }, acquireWaitCount: { w: 1 }, timeAcquiringMicros: { w: 3185961 } }, Collection: { acquireCount: { w: 1 } }, Metadata: { acquireCount: { w: 1 } }, oplog: { acquireCount: { w: 1 } } } protocol:op_query 3237ms
2021-01-12T07:18:41.403+0000 I COMMAND [conn79] command m312.employees command: find { find: “employees”, filter: { _id: ObjectId(‘5ffd4cbf346d8b1cc01aa4d0’) } } planSummary: IDHACK keysExamined:1 docsExamined:1 cursorExhausted:1 numYields:0 nreturned:1 reslen:495 locks:{ Global: { acquireCount: { r: 2 } }, Database: { acquireCount: { r: 1 }, acquireWaitCount: { r: 1 }, timeAcquiringMicros: { r: 3153985 } }, Collection: { acquireCount: { r: 1 } } } protocol:op_query 3205ms
2021-01-12T07:18:41.403+0000 I COMMAND [conn80] command m312.$cmd command: update { update: “employees”, ordered: true, updates: [ { q: { _id: ObjectId(‘5ffd4cbf346d8b1cc01aa4d0’) }, u: { $inc: { count: 1 } }, multi: false, upsert: false } ] } numYields:0 reslen:119 locks:{ Global: { acquireCount: { r: 2, w: 2 } }, Database: { acquireCount: { w: 2 }, acquireWaitCount: { w: 1 }, timeAcquiringMicros: { w: 3099015 } }, Collection: { acquireCount: { w: 1 } }, Metadata: { acquireCount: { w: 1 } }, oplog: { acquireCount: { w: 1 } } } protocol:op_query 3151ms
2021-01-12T07:18:41.406+0000 I COMMAND [conn81] command m312.employees command: find { find: “employees”, filter: { _id: ObjectId(‘5ffd4cbf346d8b1cc01aa4d0’) } } planSummary: IDHACK keysExamined:1 docsExamined:1 cursorExhausted:1 numYields:0 nreturned:1 reslen:495 locks:{ Global: { acquireCount: { r: 2 } }, Database: { acquireCount: { r: 1 }, acquireWaitCount: { r: 1 }, timeAcquiringMicros: { r: 3039686 } }, Collection: { acquireCount: { r: 1 } } } protocol:op_query 3094ms
2021-01-12T07:18:41.406+0000 I COMMAND [conn83] command m312.employees command: find { find: “employees”, filter: { _id: ObjectId(‘5ffd4cbf346d8b1cc01aa4d0’) } } planSummary: IDHACK keysExamined:1 docsExamined:1 cursorExhausted:1 numYields:0 nreturned:1 reslen:495 locks:{ Global: { acquireCount: { r: 2 } }, Database: { acquireCount: { r: 1 }, acquireWaitCount: { r: 1 }, timeAcquiringMicros: { r: 2950341 } }, Collection: { acquireCount: { r: 1 } } } protocol:op_query 3005ms
2021-01-12T07:18:41.407+0000 I COMMAND [conn84] command m312.$cmd command: update { update: “employees”, ordered: true, updates: [ { q: { _id: ObjectId(‘5ffd4cbf346d8b1cc01aa4d0’) }, u: { $inc: { count: 1 } }, multi: false, upsert: false } ] } numYields:0 reslen:119 locks:{ Global: { acquireCount: { r: 2, w: 2 } }, Database: { acquireCount: { w: 2 }, acquireWaitCount: { w: 1 }, timeAcquiringMicros: { w: 2884199 } }, Collection: { acquireCount: { w: 1 } }, Metadata: { acquireCount: { w: 1 } }, oplog: { acquireCount: { w: 1 } } } protocol:op_query 2939ms
2021-01-12T07:18:41.410+0000 I COMMAND [conn82] command m312.$cmd command: update { update: “employees”, ordered: true, updates: [ { q: { _id: ObjectId(‘5ffd4cbf346d8b1cc01aa4d0’) }, u: { $inc: { count: 1 } }, multi: false, upsert: false } ] } numYields:0 reslen:119 locks:{ Global: { acquireCount: { r: 2, w: 2 } }, Database: { acquireCount: { w: 2 }, acquireWaitCount: { w: 1 }, timeAcquiringMicros: { w: 2995822 } }, Collection: { acquireCount: { w: 1 } }, Metadata: { acquireCount: { w: 1 } }, oplog: { acquireCount: { w: 1 } } } protocol:op_query 3050ms
2021-01-12T07:18:41.410+0000 I COMMAND [conn85] command m312.employees command: find { find: “employees”, filter: { _id: ObjectId(‘5ffd4cbf346d8b1cc01aa4d0’) } } planSummary: IDHACK keysExamined:1 docsExamined:1 cursorExhausted:1 numYields:0 nreturned:1 reslen:495 locks:{ Global: { acquireCount: { r: 2 } }, Database: { acquireCount: { r: 1 }, acquireWaitCount: { r: 1 }, timeAcquiringMicros: { r: 2840877 } }, Collection: { acquireCount: { r: 1 } } } protocol:op_query 2895ms
2021-01-12T07:18:41.410+0000 I COMMAND [conn76] command m312.$cmd command: update { update: “employees”, ordered: true, updates: [ { q: { _id: ObjectId(‘5ffd4cbf346d8b1cc01aa4d0’) }, u: { $inc: { count: 1 } }, multi: false, upsert: false } ] } numYields:0 reslen:119 locks:{ Global: { acquireCount: { r: 2, w: 2 } }, Database: { acquireCount: { w: 2 }, acquireWaitCount: { w: 1 }, timeAcquiringMicros: { w: 3304235 } }, Collection: { acquireCount: { w: 1 } }, Metadata: { acquireCount: { w: 1 } }, oplog: { acquireCount: { w: 1 } } } protocol:op_query 3359ms
2021-01-12T07:18:41.414+0000 I COMMAND [conn86] command m312.$cmd command: update { update: “employees”, ordered: true, updates: [ { q: { _id: ObjectId(‘5ffd4cbf346d8b1cc01aa4d0’) }, u: { $inc: { count: 1 } }, multi: false, upsert: false } ] } numYields:0 reslen:119 locks:{ Global: { acquireCount: { r: 2, w: 2 } }, Database: { acquireCount: { w: 2 }, acquireWaitCount: { w: 1 }, timeAcquiringMicros: { w: 2792543 } }, Collection: { acquireCount: { w: 1 } }, Metadata: { acquireCount: { w: 1 } }, oplog: { acquireCount: { w: 1 } } } protocol:op_query 2848ms
2021-01-12T07:18:41.414+0000 I COMMAND [conn87] command m312.employees command: find { find: “employees”, filter: { _id: ObjectId(‘5ffd4cbf346d8b1cc01aa4d0’) } } planSummary: IDHACK keysExamined:1 docsExamined:1 cursorExhausted:1 numYields:0 nreturned:1 reslen:495 locks:{ Global: { acquireCount: { r: 2 } }, Database: { acquireCount: { r: 1 }, acquireWaitCount: { r: 1 }, timeAcquiringMicros: { r: 2732546 } }, Collection: { acquireCount: { r: 1 } } } protocol:op_query 2788ms
2021-01-12T07:18:41.414+0000 I COMMAND [conn93] command m312.employees command: find { find: “employees”, filter: { _id: ObjectId(‘5ffd4cbf346d8b1cc01aa4d1’) } } planSummary: IDHACK keysExamined:1 docsExamined:1 cursorExhausted:1 numYields:0 nreturned:1 reslen:502 locks:{ Global: { acquireCount: { r: 2 } }, Database: { acquireCount: { r: 1 }, acquireWaitCount: { r: 1 }, timeAcquiringMicros: { r: 1467898 } }, Collection: { acquireCount: { r: 1 } } } protocol:op_query 1523ms
2021-01-12T07:18:41.415+0000 I COMMAND [conn95] command m312.employees command: find { find: “employees”, filter: { _id: ObjectId(‘5ffd4cbf346d8b1cc01aa4d1’) } } planSummary: IDHACK keysExamined:1 docsExamined:1 cursorExhausted:1 numYields:0 nreturned:1 reslen:502 locks:{ Global: { acquireCount: { r: 2 } }, Database: { acquireCount: { r: 1 }, acquireWaitCount: { r: 1 }, timeAcquiringMicros: { r: 1366180 } }, Collection: { acquireCount: { r: 1 } } } protocol:op_query 1422ms
2021-01-12T07:18:41.415+0000 I COMMAND [conn90] command m312.$cmd command: update { update: “employees”, ordered: true, updates: [ { q: { _id: ObjectId(‘5ffd4cbf346d8b1cc01aa4d1’) }, u: { $inc: { count: 1 } }, multi: false, upsert: false } ] } numYields:0 reslen:119 locks:{ Global: { acquireCount: { r: 3, w: 3 } }, Database: { acquireCount: { w: 3 }, acquireWaitCount: { w: 1 }, timeAcquiringMicros: { w: 1607884 } }, Collection: { acquireCount: { w: 2 } }, Metadata: { acquireCount: { w: 1 } }, oplog: { acquireCount: { w: 1 } } } protocol:op_query 1665ms
2021-01-12T07:18:41.416+0000 I COMMAND [conn89] command m312.employees command: find { find: “employees”, filter: { _id: ObjectId(‘5ffd4cbf346d8b1cc01aa4d0’) } } planSummary: IDHACK keysExamined:1 docsExamined:1 cursorExhausted:1 numYields:0 nreturned:1 reslen:495 locks:{ Global: { acquireCount: { r: 2 } }, Database: { acquireCount: { r: 1 }, acquireWaitCount: { r: 1 }, timeAcquiringMicros: { r: 1642840 } }, Collection: { acquireCount: { r: 1 } } } protocol:op_query 1699ms
2021-01-12T07:18:41.416+0000 I COMMAND [conn88] command m312.$cmd command: update { update: “employees”, ordered: true, updates: [ { q: { _id: ObjectId(‘5ffd4cbf346d8b1cc01aa4d0’) }, u: { $inc: { count: 1 } }, multi: false, upsert: false } ] } numYields:0 reslen:119 locks:{ Global: { acquireCount: { r: 2, w: 2 } }, Database: { acquireCount: { w: 2 }, acquireWaitCount: { w: 1 }, timeAcquiringMicros: { w: 2693164 } }, Collection: { acquireCount: { w: 1 } }, Metadata: { acquireCount: { w: 1 } }, oplog: { acquireCount: { w: 1 } } } protocol:op_query 2750ms
2021-01-12T07:18:41.416+0000 I COMMAND [conn94] command m312.$cmd command: update { update: “employees”, ordered: true, updates: [ { q: { _id: ObjectId(‘5ffd4cbf346d8b1cc01aa4d1’) }, u: { $inc: { count: 1 } }, multi: false, upsert: false } ] } numYields:0 reslen:119 locks:{ Global: { acquireCount: { r: 3, w: 3 } }, Database: { acquireCount: { w: 3 }, acquireWaitCount: { w: 1 }, timeAcquiringMicros: { w: 1415711 } }, Collection: { acquireCount: { w: 2 } }, Metadata: { acquireCount: { w: 1 } }, oplog: { acquireCount: { w: 1 } } } protocol:op_query 1472ms
2021-01-12T07:18:41.416+0000 I COMMAND [conn91] command m312.employees command: find { find: “employees”, filter: { _id: ObjectId(‘5ffd4cbf346d8b1cc01aa4d1’) } } planSummary: IDHACK keysExamined:1 docsExamined:1 cursorExhausted:1 numYields:1 nreturned:1 reslen:502 locks:{ Global: { acquireCount: { r: 4 } }, Database: { acquireCount: { r: 2 }, acquireWaitCount: { r: 1 }, timeAcquiringMicros: { r: 1572543 } }, Collection: { acquireCount: { r: 2 } } } protocol:op_query 1630ms
2021-01-12T07:18:41.417+0000 I COMMAND [conn96] command m312.$cmd command: update { update: “employees”, ordered: true, updates: [ { q: { _id: ObjectId(‘5ffd4cbf346d8b1cc01aa4d1’) }, u: { $inc: { count: 1 } }, multi: false, upsert: false } ] } numYields:0 reslen:119 locks:{ Global: { acquireCount: { r: 2, w: 2 } }, Database: { acquireCount: { w: 2 }, acquireWaitCount: { w: 1 }, timeAcquiringMicros: { w: 1306261 } }, Collection: { acquireCount: { w: 1 } }, Metadata: { acquireCount: { w: 1 } }, oplog: { acquireCount: { w: 1 } } } protocol:op_query 1359ms
2021-01-12T07:18:41.416+0000 I COMMAND [conn92] command m312.$cmd command: update { update: “employees”, ordered: true, updates: [ { q: { _id: ObjectId(‘5ffd4cbf346d8b1cc01aa4d1’) }, u: { $inc: { count: 1 } }, multi: false, upsert: false } ] } numYields:0 reslen:119 locks:{ Global: { acquireCount: { r: 3, w: 3 } }, Database: { acquireCount: { w: 3 }, acquireWaitCount: { w: 1 }, timeAcquiringMicros: { w: 1509704 } }, Collection: { acquireCount: { w: 2 } }, Metadata: { acquireCount: { w: 1 } }, oplog: { acquireCount: { w: 1 } } } protocol:op_query 1567ms
2021-01-12T07:18:41.417+0000 I COMMAND [conn97] command m312.employees command: find { find: “employees”, filter: { _id: ObjectId(‘5ffd4cbf346d8b1cc01aa4d1’) } } planSummary: IDHACK keysExamined:1 docsExamined:1 cursorExhausted:1 numYields:0 nreturned:1 reslen:513 locks:{ Global: { acquireCount: { r: 2 } }, Database: { acquireCount: { r: 1 }, acquireWaitCount: { r: 1 }, timeAcquiringMicros: { r: 1270583 } }, Collection: { acquireCount: { r: 1 } } } protocol:op_query 1324ms
2021-01-12T07:18:41.417+0000 I COMMAND [conn98] command m312.$cmd command: update { update: “employees”, ordered: true, updates: [ { q: { _id: ObjectId(‘5ffd4cbf346d8b1cc01aa4d1’) }, u: { $inc: { count: 1 } }, multi: false, upsert: false } ] } numYields:0 reslen:119 locks:{ Global: { acquireCount: { r: 2, w: 2 } }, Database: { acquireCount: { w: 2 }, acquireWaitCount: { w: 1 }, timeAcquiringMicros: { w: 1195547 } }, Collection: { acquireCount: { w: 1 } }, Metadata: { acquireCount: { w: 1 } }, oplog: { acquireCount: { w: 1 } } } protocol:op_query 1249ms
2021-01-12T07:18:41.417+0000 I COMMAND [conn99] command m312.employees command: find { find: “employees”, filter: { _id: ObjectId(‘5ffd4cbf346d8b1cc01aa4d1’) } } planSummary: IDHACK keysExamined:1 docsExamined:1 cursorExhausted:1 numYields:0 nreturned:1 reslen:513 locks:{ Global: { acquireCount: { r: 2 } }, Database: { acquireCount: { r: 1 }, acquireWaitCount: { r: 1 }, timeAcquiringMicros: { r: 1160892 } }, Collection: { acquireCount: { r: 1 } } } protocol:op_query 1214ms
2021-01-12T07:18:41.417+0000 I COMMAND [conn100] command m312.$cmd command: update { update: “employees”, ordered: true, updates: [ { q: { _id: ObjectId(‘5ffd4cbf346d8b1cc01aa4d1’) }, u: { $inc: { count: 1 } }, multi: false, upsert: false } ] } numYields:0 reslen:119 locks:{ Global: { acquireCount: { r: 2, w: 2 } }, Database: { acquireCount: { w: 2 }, acquireWaitCount: { w: 1 }, timeAcquiringMicros: { w: 1115374 } }, Collection: { acquireCount: { w: 1 } }, Metadata: { acquireCount: { w: 1 } }, oplog: { acquireCount: { w: 1 } } } protocol:op_query 1162ms
2021-01-12T07:18:41.418+0000 I COMMAND [conn101] command m312.employees command: find { find: “employees”, filter: { _id: ObjectId(‘5ffd4cbf346d8b1cc01aa4d1’) } } planSummary: IDHACK keysExamined:1 docsExamined:1 cursorExhausted:1 numYields:0 nreturned:1 reslen:513 locks:{ Global: { acquireCount: { r: 2 } }, Database: { acquireCount: { r: 1 }, acquireWaitCount: { r: 1 }, timeAcquiringMicros: { r: 1062252 } }, Collection: { acquireCount: { r: 1 } } } protocol:op_query 1101ms
2021-01-12T07:18:41.418+0000 I COMMAND [conn105] command m312.employees command: find { find: “employees”, filter: { _id: ObjectId(‘5ffd4cbf346d8b1cc01aa4d1’) } } planSummary: IDHACK keysExamined:1 docsExamined:1 cursorExhausted:1 numYields:0 nreturned:1 reslen:513 locks:{ Global: { acquireCount: { r: 2 } }, Database: { acquireCount: { r: 1 }, acquireWaitCount: { r: 1 }, timeAcquiringMicros: { r: 860906 } }, Collection: { acquireCount: { r: 1 } } } protocol:op_query 900ms
2021-01-12T07:18:41.419+0000 I COMMAND [conn108] command m312.$cmd command: update { update: “employees”, ordered: true, updates: [ { q: { _id: ObjectId(‘5ffd4cbf346d8b1cc01aa4d1’) }, u: { inc: { count: 1 } }, multi: false, upsert: false } ] } numYields:0 reslen:119 locks:{ Global: { acquireCount: { r: 2, w: 2 } }, Database: { acquireCount: { w: 2 }, acquireWaitCount: { w: 1 }, timeAcquiringMicros: { w: 709349 } }, Collection: { acquireCount: { w: 1 } }, Metadata: { acquireCount: { w: 1 } }, oplog: { acquireCount: { w: 1 } } } protocol:op_query 749ms vagrant@m312:~/shared

Ok that log matches what I expected to see. You should be able to answer the lab correctly based on those logs!

I will think based on this part of the logs:

2021-01-12T07:18:41.379+0000 I COMMAND [conn28] command m312.$cmd command: createIndexes { createIndexes: “employees”, indexes: [ { name: “last_name_1_first_name_1”, key: { last_name: 1, first_name: 1 } } ] } numYields:0 reslen:113 locks:{ Global: { acquireCount: { r: 2, w: 2 } }, Database: { acquireCount: { w: 1, W: 1 } }, Collection: { acquireCount: { w: 1 } }, Metadata: { acquireCount: { w: 1 } }, oplog: { acquireCount: { w: 1 } } } protocol:op_query 5679ms
2021-01-12T07:18:41.380+0000 I COMMAND [conn30] command m312.$cmd command: update { update: “employees”, ordered: true, updates: [ { q: { _id: ObjectId(‘5ffd4cbf346d8b1cc01aa4cf’) }, u: { $inc: { count: 1 } }, multi: false, upsert: false } ] } numYields:0 reslen:119 locks:{ Global: { acquireCount: { r: 2, w: 2 } }, Database: { acquireCount: { w: 2 }, acquireWaitCount: { w: 1 }, timeAcquiringMicros: { w: 5595248 } }, Collection: { acquireCount: { w: 1 } }, Metadata: { acquireCount: { w: 1 } }, oplog: { acquireCount: { w: 1 } } } protocol:op_query 5638ms

OK, so let us see the two first relevant events, the “createIndexes” and the following one (“update”):

This is what I see in the logs (stripping the parts not needed):

07:18:41.379 (5679ms) [createIndexes]
07:18:41.380 (5638ms) [update]

Using the technic you gave me in one of your previous messages, I can deduce the following:

Start: 07:18:35.700 End: 07:18:41.379 [createIndexes]
Start: 07:18:35.742 End: 07:18:41.380 [update]

The data I observe here don’t look to me that much different from what I previously saw. But taking into account your remark about the question in your previous message, I will try to make sense of all that and make a guess for the answer. … Hoping I am lucky!