Uploaded image for project: 'WiredTiger'
  1. WiredTiger
  2. WT-6729

Quiesce eviction prior running rollback to stable's active transaction check

XMLWordPrintableJSON

    • Type: Icon: Bug Bug
    • Resolution: Fixed
    • Priority: Icon: Major - P3 Major - P3
    • WT10.0.1, 4.4.8, 5.0.2, 5.1.0-rc0
    • Affects Version/s: None
    • Component/s: None
    • None
    • 3
    • Storage - Ra 2020-11-02, Storage - Ra 2020-11-16, Storage - Ra 2020-11-30, Storage - Ra 2020-12-14, Storage - Ra 2020-12-28, Storage - Ra 2021-05-17, Storage - Ra 2021-05-31, Storage - Ra 2021-06-14, Storage - Ra 2021-06-28, Storage - Ra 2021-07-12, Storage - Ra 2021-07-26
    • v5.0, v4.4

      In a recent build failure, MongoDB hit an error when trying to perform a rollback to stable due to active transactions running in the system.

      Some debugging information was posted on the original build failure which showed that the transaction was doing a search_near at "read uncommitted" which corresponds to a history store operation. My hunch is that this is a transaction that is created by an eviction thread doing some history store work and it happens to be running concurrently to a rollback_to_stable thread from a MongoDB application thread.

      MongoDB log:

      [js_test:rollback_recovery_commit_transaction_before_stable_timestamp] 2020-07-15T01:10:34.935+0000 d22030| 2020-07-15T01:10:34.929+00:00 I  ROLLBACK 23991   [BackgroundSync] "Rolling back to the stable timestamp","attr":{"stableTimestamp":{"$timestamp":{"t":1594775434,"i":5}},"initialDataTimestamp":{"$timestamp":{"t":1594775432,"i":1}}}
[js_test:rollback_recovery_commit_transaction_before_stable_timestamp] 2020-07-15T01:10:34.935+0000 d22030| 2020-07-15T01:10:34.929+00:00 E  STORAGE  22435   [BackgroundSync] "WiredTiger error","attr":{"error":22,"message":"[1594775434:929642][92130:0x7f949a9a1700], txn rollback_to_stable: __rollback_to_stable_check, 972: rollback_to_stable illegal with active transactions: Invalid argument"}
[js_test:rollback_recovery_commit_transaction_before_stable_timestamp] 2020-07-15T01:10:34.935+0000 d22030| 2020-07-15T01:10:34.929+00:00 F  -        23093   [BackgroundSync] "Fatal assertion","attr":{"msgid":31049,"error":"UnrecoverableRollbackError: Error rolling back to stable. Err: Invalid argument","file":"src/mongo/db/repl/storage_interface_impl.cpp","line":1258}
[js_test:rollback_recovery_commit_transaction_before_stable_timestamp] 2020-07-15T01:10:34.935+0000 d22030| 2020-07-15T01:10:34.929+00:00 F  -        23094   [BackgroundSync] "\n\n***aborting after fassert() failure\n\n"
[js_test:rollback_recovery_commit_transaction_before_stable_timestamp] 2020-07-15T01:10:34.935+0000 d22030| 2020-07-15T01:10:34.929+00:00 F  CONTROL  4757800 [BackgroundSync] "Writing fatal message","attr":{"message":"Got signal: 6 (Aborted).\n"}
[js_test:rollback_recovery_commit_transaction_before_stable_timestamp] 2020-07-15T01:10:34.939+0000 d22032| 2020-07-15T01:10:34.938+00:00 I  REPL     21079   [BackgroundSync] "bgsync - stopReplProducer fail point enabled. Blocking until fail point is disabled."

      Debugging information:

      [js_test:upgrade_downgrade_cluster] 2020-07-01T08:26:23.541+0000 c20278| 2020-07-01T08:26:23.541+00:00 I  STORAGE  22430   [BackgroundSync] "WiredTiger message","attr":{"message":"Transaction state of active sessions:"}
[js_test:upgrade_downgrade_cluster] 2020-07-01T08:26:23.541+0000 c20278| 2020-07-01T08:26:23.541+00:00 I  STORAGE  22430   [BackgroundSync] "WiredTiger message","attr":{"message":"ID: 0, pinned ID: 4554, metadata pinned ID: 4551, name: EMPTY"}
[js_test:upgrade_downgrade_cluster] 2020-07-01T08:26:23.541+0000 c20278| 2020-07-01T08:26:23.541+00:00 I  STORAGE  22430   [BackgroundSync] "WiredTiger message","attr":{"message":"transaction id: 0, mod count: 0, snap min: 4551, snap max: 4554, snapshot count: 1, commit_timestamp: (1593591983, 1), durable_timestamp: (1593591983, 1), first_commit_timestamp: (1593591983, 1), prepare_timestamp: (0, 0), pinned_durable_timestamp: (1593591983, 1), read_timestamp: (0, 0), checkpoint LSN: [0][0], full checkpoint: false, rollback reason: , flags: 0x00000408, isolation: WT_ISO_SNAPSHOT"}

       

        1. Screen Shot 2020-12-23 at 8.35.54 am.png
          Screen Shot 2020-12-23 at 8.35.54 am.png
          66 kB
        2. Screen Shot 2020-12-23 at 8.40.07 am.png
          Screen Shot 2020-12-23 at 8.40.07 am.png
          130 kB
        3. Screen Shot 2021-07-06 at 4.29.51 pm.png
          Screen Shot 2021-07-06 at 4.29.51 pm.png
          258 kB
        4. WiredTigerStat.22.00
          3.44 MB

            Assignee:
            alex.cameron@mongodb.com Alex Cameron (Inactive)
            Reporter:
            alex.cameron@mongodb.com Alex Cameron (Inactive)
            Votes:
            0 Vote for this issue
            Watchers:
            19 Start watching this issue

              Created:
              Updated:
              Resolved: