[SERVER-48227] review log messages for index build Created: 14/May/20  Updated: 29/Oct/23  Resolved: 09/Jun/20

Status: Closed
Project: Core Server
Component/s: Storage
Affects Version/s: None
Fix Version/s: 4.4.0-rc10, 4.7.0

Type: Improvement Priority: Major - P3
Reporter: Benety Goh Assignee: Samyukta Lanka
Resolution: Fixed Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Issue Links:
Backports
Problem/Incident
causes SERVER-48692 Fix 'commit_quorum.js' to check for n... Closed
Related
related to SERVER-47604 Don't log "Index build failed" if it ... Closed
related to SERVER-51048 review log messages for resumable ind... Closed
Backwards Compatibility: Fully Compatible
Backport Requested:
v4.4
Sprint: Execution Team 2020-06-15
Participants:
Linked BF Score: 43

 Description   

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


 Comments   
Comment by Githook User [ 12/Jun/20 ]

Author:

{'name': 'Samy Lanka', 'email': 'samy.lanka@mongodb.com', 'username': 'lankas'}

Message: SERVER-48227 Clean up log messages for index builds

(cherry picked from commit e6178cc59ed10e987d92b414f09f617082ea9da5)
Branch: v4.4
https://github.com/mongodb/mongo/commit/cc80078a7c3c2469ee6de39791cf0288e6771ef1

Comment by Githook User [ 09/Jun/20 ]

Author:

{'name': 'Samy Lanka', 'email': 'samy.lanka@mongodb.com', 'username': 'lankas'}

Message: SERVER-48227 Clean up log messages for index builds
Branch: master
https://github.com/mongodb/mongo/commit/e6178cc59ed10e987d92b414f09f617082ea9da5

Comment by Bruce Lucas (Inactive) [ 15/May/20 ]

Might also be good to make the msg prefix consistent - currently "Index build", "Index build:", nothing.

Generated at Thu Feb 08 05:16:30 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.