Uploaded image for project: 'Core Server'
  1. Core Server
  2. SERVER-48227

review log messages for index build

XMLWordPrintableJSON

    • Type: Icon: Improvement Improvement
    • Resolution: Fixed
    • Priority: Icon: Major - P3 Major - P3
    • 4.4.0-rc10, 4.7.0
    • Affects Version/s: None
    • Component/s: Storage
    • 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

            Assignee:
            samy.lanka@mongodb.com Samyukta Lanka
            Reporter:
            benety.goh@mongodb.com Benety Goh
            Votes:
            0 Vote for this issue
            Watchers:
            3 Start watching this issue

              Created:
              Updated:
              Resolved: