-
Type:
Improvement
-
Resolution: Fixed
-
Priority:
Major - P3
-
Affects Version/s: None
-
Component/s: Storage
-
Labels:None
-
Fully Compatible
-
v4.4
-
Execution Team 2020-06-15
-
43
As of this commit, running a basic two phase index build produces the following messages in the server logs:
{"t":{"$date":"2020-05-14T14:25:11.667-04:00"},"s":"I", "c":"INDEX", "id":20438, "ctx":"conn1","msg":"Registering index build","attr":{"buildUUID":{"uuid":{"$uuid":"c940280f-5df3-45aa-89b3-eb5838b67f34"}},"ns":"test.t","collectionUUID":{"uuid":{"$uuid":"9ff380dd-607a-4d61-85ca-42d1c7ec7f6b"}},"indexes":1,"firstIndex":{"name":"a_1"}}}
{"t":{"$date":"2020-05-14T14:25:11.701-04:00"},"s":"I", "c":"INDEX", "id":20384, "ctx":"IndexBuildsCoordinatorMongod-0","msg":"index build: starting","attr":{"namespace":"test.t","properties":{"v":2,"key":{"a":1.0},"name":"a_1"},"method":"Hybrid"}}
{"t":{"$date":"2020-05-14T14:25:11.701-04:00"},"s":"I", "c":"INDEX", "id":20385, "ctx":"IndexBuildsCoordinatorMongod-0","msg":"build may temporarily use RAM up to","attr":{"maxMemoryUsageMB":200}}
{"t":{"$date":"2020-05-14T14:25:11.702-04:00"},"s":"I", "c":"STORAGE", "id":20346, "ctx":"IndexBuildsCoordinatorMongod-0","msg":"Index build initialized","attr":{"indexBuildUUID":{"uuid":{"$uuid":"c940280f-5df3-45aa-89b3-eb5838b67f34"}},"namespace":"test.t","collectionUuid":{"uuid":{"$uuid":"9ff380dd-607a-4d61-85ca-42d1c7ec7f6b"}},"numIndexes":1}}
{"t":{"$date":"2020-05-14T14:25:11.702-04:00"},"s":"I", "c":"INDEX", "id":20440, "ctx":"conn1","msg":"Waiting for index build to complete","attr":{"buildUUID":{"uuid":{"$uuid":"c940280f-5df3-45aa-89b3-eb5838b67f34"}},"deadline":{"$date":{"$numberLong":"9223372036854775807"}}}}
{"t":{"$date":"2020-05-14T14:25:11.703-04:00"},"s":"I", "c":"INDEX", "id":20391, "ctx":"IndexBuildsCoordinatorMongod-0","msg":"Index build: collection scan done","attr":{"totalRecords":1,"durationMillis":0}}
{"t":{"$date":"2020-05-14T14:25:11.704-04:00"},"s":"I", "c":"INDEX", "id":20685, "ctx":"IndexBuildsCoordinatorMongod-0","msg":"index build: inserted {bulk_getKeysInserted} keys from external sorter into index in {timer_seconds} seconds","attr":{"bulk_getKeysInserted":1,"timer_seconds":0}}
{"t":{"$date":"2020-05-14T14:25:11.716-04:00"},"s":"I", "c":"STORAGE", "id":3856201, "ctx":"IndexBuildsCoordinatorMongod-0","msg":"Index build commit quorum satisfied:","attr":{"indexBuildEntry":{"_id":{"$uuid":"c940280f-5df3-45aa-89b3-eb5838b67f34"},"collectionUUID":{"$uuid":"9ff380dd-607a-4d61-85ca-42d1c7ec7f6b"},"commitQuorum":"votingMembers","indexNames":["a_1"],"commitReadyMembers":["benetymbp3.fios-router.home:30001"]}}}
{"t":{"$date":"2020-05-14T14:25:11.724-04:00"},"s":"I", "c":"STORAGE", "id":3856203, "ctx":"IndexBuildsCoordinatorMongod-0","msg":"Index build waiting for next action before completing final phase","attr":{"buildUUID":{"uuid":{"$uuid":"c940280f-5df3-45aa-89b3-eb5838b67f34"}}}}
{"t":{"$date":"2020-05-14T14:25:11.724-04:00"},"s":"I", "c":"STORAGE", "id":3856204, "ctx":"IndexBuildsCoordinatorMongod-0","msg":"Index build received signal","attr":{"buildUUID":{"uuid":{"$uuid":"c940280f-5df3-45aa-89b3-eb5838b67f34"}},"action":"Commit quorum Satisfied"}}
{"t":{"$date":"2020-05-14T14:25:11.725-04:00"},"s":"I", "c":"INDEX", "id":20345, "ctx":"IndexBuildsCoordinatorMongod-0","msg":"index build: done building","attr":{"namespace":"test.t","index":"a_1"}}
{"t":{"$date":"2020-05-14T14:25:11.734-04:00"},"s":"I", "c":"STORAGE", "id":20663, "ctx":"IndexBuildsCoordinatorMongod-0","msg":"Index build completed successfully","attr":{"buildUUID":{"uuid":{"$uuid":"c940280f-5df3-45aa-89b3-eb5838b67f34"}},"collection":"test.t","collectionUUID":{"uuid":{"$uuid":"9ff380dd-607a-4d61-85ca-42d1c7ec7f6b"}},"indexesBuilt":1,"numIndexesBefore":1,"numIndexesAfter":2}}
{"t":{"$date":"2020-05-14T14:25:11.735-04:00"},"s":"I", "c":"STORAGE", "id":4656004, "ctx":"IndexBuildsCoordinatorMongod-0","msg":"Unregistering index build","attr":{"buildUUID":{"uuid":{"$uuid":"c940280f-5df3-45aa-89b3-eb5838b67f34"}}}}
{"t":{"$date":"2020-05-14T14:25:11.735-04:00"},"s":"I", "c":"INDEX", "id":20447, "ctx":"conn1","msg":"Index build completed","attr":{"buildUUID":{"uuid":{"$uuid":"c940280f-5df3-45aa-89b3-eb5838b67f34"}}}}
With the new index build process in 4.4, this would be a good opportunity to review the log messages in the code. A few considerations to keep in mind:
- eliminate redundant messages.
- consistent identifying information across different stages of the index build
- index build UUID
- collection UUID
- index names (since index builds typically build a single index - perhaps just logging the first index name would be sufficient for most use cases)
- single/two phase build method (this is more relevant if we back port these improvements to 4.4)
- what stage of the index build are we in?
- including timestamp information into the log messages relating to catalog writes
- this may involve moving log messages into the RecoveryUnit commit handlers for adding/updating the index catalog.
- Updating capitalization of log messages per logging guidelines established in 4.4
- causes
-
SERVER-48692 Fix 'commit_quorum.js' to check for new log message
-
- Closed
-
- related to
-
-
- Closed
-
-
-
- Closed
-