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

Retry the alter command after a system wide checkpoint

XMLWordPrintableJSON

    • Type: Icon: Bug Bug
    • Resolution: Fixed
    • Priority: Icon: Major - P3 Major - P3
    • WT10.0.1, 5.0.4, 4.4.10, 5.1.0-rc0
    • Affects Version/s: None
    • Component/s: None
    • Labels:
      None
    • 8
    • Storage - Ra 2021-08-09, Storage - Ra 2021-08-23, Storage - Ra 2021-09-06

      Looks like there is a catalog entry for a file, collection-54-5382503626820225150, setting logging on this file after recovery fails with EBUSY. Since this file was pending delete at some point I confirmed it actually exists in the dbPath this mongod started from. This looks like WT-7528, so I am creating this ticket to have a relook at it.

      [js_test:incremental_backup_e2e] d20277| 2021-07-26T00:52:28.831+00:00 D2 RECOVERY 4615634 [initandlisten] "Catalog entry","attr":{"catalogId":"27","value":{"md":{"ns":"test2_fsmdb0.tmp.agg_out.d549d27c-b582-4456-b808-2c8075d3a8fb","options":{"uuid":{"$uuid":"51307719-9e17-43e9-bc35-30bfb11a9cc3"},"temp":true},"indexes":[{"spec":{"v":2,"key":{"_id":1},"name":"_id_"},"ready":true,"multikey":false,"multikeyPaths":{"_id":{"$binary":{"base64":"AA==","subType":"0"}}},"head":0,"backgroundSecondary":false}]},"idxIdent":{"_id_":"index-55-5382503626820225150"},"ns":"test2_fsmdb0.tmp.agg_out.d549d27c-b582-4456-b808-2c8075d3a8fb","ident":"collection-54-5382503626820225150"}}
[js_test:incremental_backup_e2e] d20277| 2021-07-26T00:52:28.831+00:00 D2 RECOVERY 4615634 [initandlisten] "Catalog entry","attr":{"catalogId":"28","value":{"md":{"ns":"test2_fsmdb0.tmp.agg_out.6f07ff1d-31ea-4930-b6aa-b5953e2f5e16","options":{"uuid":{"$uuid":"10dd4243-5124-4043-b12d-c9248e34c400"},"temp":true},"indexes":[{"spec":{"v":2,"key":{"_id":1},"name":"_id_"},"ready":true,"multikey":false,"multikeyPaths":{"_id":{"$binary":{"base64":"AA==","subType":"0"}}},"head":0,"backgroundSecondary":false}]},"idxIdent":{"_id_":"index-57-5382503626820225150"},"ns":"test2_fsmdb0.tmp.agg_out.6f07ff1d-31ea-4930-b6aa-b5953e2f5e16","ident":"collection-56-5382503626820225150"}}
[js_test:incremental_backup_e2e] d20277| 2021-07-26T00:52:28.832+00:00 D2 RECOVERY 5380110 [initandlisten] "Catalog entries at the oldest timestamp","attr":{"oldestTimestamp":{"$timestamp":{"t":1627260731,"i":1}}}
[js_test:incremental_backup_e2e] d20277| 2021-07-26T00:52:28.832+00:00 D2 RECOVERY 5380109 [initandlisten] "Historical entry","attr":{"catalogId":"2","ident":"collection-0-5382503626820225150","namespace":"local.startup_log"}
[js_test:incremental_backup_e2e] d20277| 2021-07-26T00:52:28.832+00:00 D2 RECOVERY 5380109 [initandlisten] "Historical entry","attr":{"catalogId":"3","ident":"collection-2-5382503626820225150","namespace":"local.replset.oplogTruncateAfterPoint"}
[js_test:incremental_backup_e2e] d20277| 2021-07-26T00:52:28.832+00:00 D2 RECOVERY 5380109 [initandlisten] "Historical entry","attr":{"catalogId":"4","ident":"collection-4-5382503626820225150","namespace":"local.replset.minvalid"}
[js_test:incremental_backup_e2e] d20277| 2021-07-26T00:52:28.832+00:00 D2 RECOVERY 5380109 [initandlisten] "Historical entry","attr":{"catalogId":"5","ident":"collection-6-5382503626820225150","namespace":"local.replset.election"}
[js_test:incremental_backup_e2e] d20277| 2021-07-26T00:52:28.832+00:00 D2 RECOVERY 5380109 [initandlisten] "Historical entry","attr":{"catalogId":"6","ident":"collection-8-5382503626820225150","namespace":"local.system.rollback.id"}
[js_test:incremental_backup_e2e] d20277| 2021-07-26T00:52:28.832+00:00 D2 RECOVERY 5380109 [initandlisten] "Historical entry","attr":{"catalogId":"7","ident":"collection-10-5382503626820225150","namespace":"local.system.views"}
[js_test:incremental_backup_e2e] d20277| 2021-07-26T00:52:28.832+00:00 D2 RECOVERY 5380109 [initandlisten] "Historical entry","attr":{"catalogId":"8","ident":"collection-12-5382503626820225150","namespace":"admin.system.version"}
[js_test:incremental_backup_e2e] d20277| 2021-07-26T00:52:28.832+00:00 D2 RECOVERY 5380109 [initandlisten] "Historical entry","attr":{"catalogId":"9","ident":"collection-14-5382503626820225150","namespace":"local.oplog.rs"}
[js_test:incremental_backup_e2e] d20277| 2021-07-26T00:52:28.832+00:00 D2 RECOVERY 5380109 [initandlisten] "Historical entry","attr":{"catalogId":"10","ident":"collection-15-5382503626820225150","namespace":"local.system.replset"}
[js_test:incremental_backup_e2e] d20277| 2021-07-26T00:52:28.832+00:00 D2 RECOVERY 5380109 [initandlisten] "Historical entry","attr":{"catalogId":"11","ident":"collection-17-5382503626820225150","namespace":"local.replset.initialSyncId"}
[js_test:incremental_backup_e2e] d20277| 2021-07-26T00:52:28.843+00:00 I  STORAGE  22383   [initandlisten] "The size storer reports that the oplog contains","attr":{"numRecords":28980,"dataSize":33904887}
[js_test:incremental_backup_e2e] d20277| 2021-07-26T00:52:28.843+00:00 I  STORAGE  22386   [initandlisten] "Sampling the oplog to determine where to place markers for truncation"
[js_test:incremental_backup_e2e] d20277| 2021-07-26T00:52:28.843+00:00 I  STORAGE  22389   [initandlisten] "Sampling from the oplog to determine where to place markers for truncation","attr":{"from":{"$timestamp":{"t":1627260731,"i":1}},"to":{"$timestamp":{"t":1627260746,"i":27076}}}
[js_test:incremental_backup_e2e] d20277| 2021-07-26T00:52:28.843+00:00 I  STORAGE  22390   [initandlisten] "Taking samples and assuming each oplog section contains","attr":{"numSamples":80,"containsNumRecords":3586,"containsNumBytes":4195408}
[js_test:incremental_backup_e2e] d20277| 2021-07-26T00:52:28.848+00:00 I  STORAGE  22393   [initandlisten] "Oplog sampling complete"
[js_test:incremental_backup_e2e] d20277| 2021-07-26T00:52:28.848+00:00 I  STORAGE  22382   [initandlisten] "WiredTiger record store oplog processing finished","attr":{"durationMillis":5}
[js_test:incremental_backup_e2e] d20277| 2021-07-26T00:52:28.873+00:00 F  STORAGE  50756   [initandlisten] "Failed to update log setting","attr":{"uri":"table:collection-54-5382503626820225150","loggingEnabled":true,"error":16,"metadata":"access_pattern_hint=none,allocation_size=4KB,app_metadata=(formatVersion=1),assert=(commit_timestamp=none,durable_timestamp=none,read_timestamp=none,write_timestamp=off),block_allocation=best,block_compressor=snappy,cache_resident=false,checksum=on,colgroups=,collator=,columns=,dictionary=0,encryption=(keyid=,name=),exclusive=false,extractor=,format=btree,huffman_key=,huffman_value=,ignore_in_memory_cache_size=false,immutable=false,import=(enabled=false,file_metadata=,repair=false),internal_item_max=0,internal_key_max=0,internal_key_truncate=true,internal_page_max=4KB,key_format=q,key_gap=10,leaf_item_max=0,leaf_key_max=0,leaf_page_max=32KB,leaf_value_max=64MB,log=(enabled=false),lsm=(auto_throttle=true,bloom=true,bloom_bit_count=16,bloom_config=,bloom_hash_count=8,bloom_oldest=false,chunk_count_limit=0,chunk_max=5GB,chunk_size=10MB,merge_custom=(prefix=,start_generation=0,suffix=),merge_max=15,merge_min=0),memory_page_image_max=0,memory_page_max=10m,os_cache_dirty_max=0,os_cache_max=0,prefix_compression=false,prefix_compression_min=4,readonly=false,source=\"file:collection-54-5382503626820225150.wt\",split_deepen_min_child=0,split_deepen_per_child=0,split_pct=90,tiered_object=false,tiered_storage=(auth_token=,bucket=,bucket_prefix=,local_retention=300,name=,object_target_size=10M),type=file,value_format=u,verbose=[],write_timestamp_usage=none","message":"Device or resource busy"}

      We need to root cause why alter() fails with EBUSY. Note there have been several attempts at fixing same/similar issue in the past, notably - WT-6816 , WT-6521, WT-7528

            Assignee:
            haribabu.kommi@mongodb.com Haribabu Kommi
            Reporter:
            sulabh.mahajan@mongodb.com Sulabh Mahajan
            Votes:
            0 Vote for this issue
            Watchers:
            14 Start watching this issue

              Created:
              Updated:
              Resolved: