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

Cache stuck with clean pages caused by read committed isolation

    XMLWordPrintable

    Details

    • Type: Bug
    • Status: Closed
    • Priority: Major - P3
    • Resolution: Duplicate
    • Affects Version/s: None
    • Fix Version/s: None
    • Component/s: None
    • Story Points:
      5
    • Sprint:
      Storage Engines 2020-01-13

      Description

      EDIT (KB):

      Failure 25671 is a duplicate of WT-5366.

      Luke Chen, the signature on that problem is an active session "name: WT_SESSION.truncate", with "isolation: WT_ISO_READ_COMMITTED".

       

      =======================

      This is another cache stuck clean case after the recent merge of WT-5312, on kodkod-aws. In this specific case, timestamp was disabled, and the cache was not full but with both a high number of internal and leaf pages.

      http://build.wiredtiger.com:8080/job/wiredtiger-test-format-stress-sanitizer/25671/

      ++ nice ./t -1 -c ../../../test/format/CONFIG.stress file_type=row leaf_page_max=9 internal_page_max=9 key_min=256 value_min=256
      t: process 16513 running
      0x7f8c1ce65070:Application thread returned a rollback error because it was forced to evict and eviction is stuck
      [1577562556:642048][16513:0x7f8c16cf7700], t, eviction-server: __evict_server, 440: Cache stuck for too long, giving up: Connection timed out
      0x7f8c1ce5d820:=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=
      0x7f8c1ce5d820:transaction state dump
      0x7f8c1ce5d820:current ID: 133975
      0x7f8c1ce5d820:last running ID: 122501
      0x7f8c1ce5d820:metadata_pinned ID: 117449
      0x7f8c1ce5d820:oldest ID: 122417
      0x7f8c1ce5d820:durable timestamp: (0, 0)
      0x7f8c1ce5d820:oldest timestamp: (0, 0)
      0x7f8c1ce5d820:pinned timestamp: (0, 0)
      0x7f8c1ce5d820:stable timestamp: (0, 0)
      0x7f8c1ce5d820:has_durable_timestamp: no
      0x7f8c1ce5d820:has_oldest_timestamp: no
      0x7f8c1ce5d820:has_pinned_timestamp: no
      0x7f8c1ce5d820:has_stable_timestamp: no
      0x7f8c1ce5d820:oldest_is_pinned: no
      0x7f8c1ce5d820:stable_is_pinned: no
      0x7f8c1ce5d820:checkpoint running: no
      0x7f8c1ce5d820:checkpoint generation: 30
      0x7f8c1ce5d820:checkpoint pinned ID: 0
      0x7f8c1ce5d820:checkpoint txn ID: 0
      0x7f8c1ce5d820:oldest named snapshot ID: 0
      0x7f8c1ce5d820:session count: 44
      0x7f8c1ce5d820:Transaction state of active sessions:
      0x7f8c1ce5d820:ID: 133899, pinned ID: 122501, metadata pinned ID: 133648, name: WT_CURSOR.search
      0x7f8c1ce5d820:transaction id: 133899, mod count: 2, snap min: 122501, snap max: 133899, snapshot count: 19, commit_timestamp: (0, 0), durable_timestamp: (0, 0), first_commit_timestamp: (0, 0), prepare_timestamp: (0, 0), read_timestamp: (0, 0), checkpoint LSN: [0][0], full checkpoint: false, rollback reason: , flags: 0x0000200c, isolation: WT_ISO_SNAPSHOT
      0x7f8c1ce5d820:ID: 0, pinned ID: 122501, metadata pinned ID: 133648, name: WT_CURSOR.prev
      0x7f8c1ce5d820:transaction id: 0, mod count: 0, snap min: 122501, snap max: 133943, snapshot count: 20, commit_timestamp: (0, 0), durable_timestamp: (0, 0), first_commit_timestamp: (0, 0), prepare_timestamp: (0, 0), read_timestamp: (0, 0), checkpoint LSN: [0][0], full checkpoint: false, rollback reason: , flags: 0x00000008, isolation: WT_ISO_READ_COMMITTED
      0x7f8c1ce5d820:ID: 0, pinned ID: 122501, metadata pinned ID: 133648, name: WT_CURSOR.prev
      0x7f8c1ce5d820:transaction id: 0, mod count: 0, snap min: 122501, snap max: 133939, snapshot count: 20, commit_timestamp: (0, 0), durable_timestamp: (0, 0), first_commit_timestamp: (0, 0), prepare_timestamp: (0, 0), read_timestamp: (0, 0), checkpoint LSN: [0][0], full checkpoint: false, rollback reason: , flags: 0x00000008, isolation: WT_ISO_READ_COMMITTED
      0x7f8c1ce5d820:ID: 133918, pinned ID: 122501, metadata pinned ID: 133648, name: WT_CURSOR.prev
      0x7f8c1ce5d820:transaction id: 133918, mod count: 1, snap min: 122501, snap max: 133916, snapshot count: 17, commit_timestamp: (0, 0), durable_timestamp: (0, 0), first_commit_timestamp: (0, 0), prepare_timestamp: (0, 0), read_timestamp: (0, 0), checkpoint LSN: [0][0], full checkpoint: false, rollback reason: , flags: 0x0000200c, isolation: WT_ISO_SNAPSHOT
      0x7f8c1ce5d820:ID: 0, pinned ID: 122501, metadata pinned ID: 133955, name: WT_CURSOR.prev
      0x7f8c1ce5d820:transaction id: 0, mod count: 0, snap min: 122501, snap max: 133957, snapshot count: 17, commit_timestamp: (0, 0), durable_timestamp: (0, 0), first_commit_timestamp: (0, 0), prepare_timestamp: (0, 0), read_timestamp: (0, 0), checkpoint LSN: [0][0], full checkpoint: false, rollback reason: , flags: 0x00000008, isolation: WT_ISO_READ_COMMITTED
      0x7f8c1ce5d820:ID: 133940, pinned ID: 122501, metadata pinned ID: 133648, name: WT_CURSOR.prev
      0x7f8c1ce5d820:transaction id: 133940, mod count: 1, snap min: 122501, snap max: 133938, snapshot count: 20, commit_timestamp: (0, 0), durable_timestamp: (0, 0), first_commit_timestamp: (0, 0), prepare_timestamp: (0, 0), read_timestamp: (0, 0), checkpoint LSN: [0][0], full checkpoint: false, rollback reason: , flags: 0x0000200c, isolation: WT_ISO_SNAPSHOT
      0x7f8c1ce5d820:ID: 133931, pinned ID: 122501, metadata pinned ID: 133648, name: WT_CURSOR.prev
      0x7f8c1ce5d820:transaction id: 133931, mod count: 2, snap min: 122501, snap max: 133931, snapshot count: 20, commit_timestamp: (0, 0), durable_timestamp: (0, 0), first_commit_timestamp: (0, 0), prepare_timestamp: (0, 0), read_timestamp: (0, 0), checkpoint LSN: [0][0], full checkpoint: false, rollback reason: , flags: 0x0000200c, isolation: WT_ISO_SNAPSHOT
      0x7f8c1ce5d820:ID: 0, pinned ID: 122501, metadata pinned ID: 133648, name: WT_CURSOR.next
      0x7f8c1ce5d820:transaction id: 0, mod count: 0, snap min: 122501, snap max: 133946, snapshot count: 17, commit_timestamp: (0, 0), durable_timestamp: (0, 0), first_commit_timestamp: (0, 0), prepare_timestamp: (0, 0), read_timestamp: (0, 0), checkpoint LSN: [0][0], full checkpoint: false, rollback reason: , flags: 0x00000008, isolation: WT_ISO_READ_COMMITTED
      0x7f8c1ce5d820:ID: 122501, pinned ID: 122417, metadata pinned ID: 117449, name: WT_SESSION.truncate
      0x7f8c1ce5d820:transaction id: 122501, mod count: 33816, snap min: 117449, snap max: 122492, snapshot count: 12, commit_timestamp: (0, 0), durable_timestamp: (0, 0), first_commit_timestamp: (0, 0), prepare_timestamp: (0, 0), read_timestamp: (0, 0), checkpoint LSN: [0][0], full checkpoint: false, rollback reason: , flags: 0x0100200c, isolation: WT_ISO_READ_COMMITTED
      0x7f8c1ce5d820:ID: 133921, pinned ID: 122501, metadata pinned ID: 133648, name: WT_CURSOR.prev
      0x7f8c1ce5d820:transaction id: 133921, mod count: 2, snap min: 122501, snap max: 133919, snapshot count: 18, commit_timestamp: (0, 0), durable_timestamp: (0, 0), first_commit_timestamp: (0, 0), prepare_timestamp: (0, 0), read_timestamp: (0, 0), checkpoint LSN: [0][0], full checkpoint: false, rollback reason: , flags: 0x0000200c, isolation: WT_ISO_SNAPSHOT
      0x7f8c1ce5d820:ID: 0, pinned ID: 122501, metadata pinned ID: 133648, name: WT_CURSOR.prev
      0x7f8c1ce5d820:transaction id: 0, mod count: 0, snap min: 122501, snap max: 133942, snapshot count: 20, commit_timestamp: (0, 0), durable_timestamp: (0, 0), first_commit_timestamp: (0, 0), prepare_timestamp: (0, 0), read_timestamp: (0, 0), checkpoint LSN: [0][0], full checkpoint: false, rollback reason: , flags: 0x00000008, isolation: WT_ISO_READ_COMMITTED
      0x7f8c1ce5d820:ID: 133920, pinned ID: 122501, metadata pinned ID: 133648, name: WT_CURSOR.prev
      0x7f8c1ce5d820:transaction id: 133920, mod count: 3, snap min: 122501, snap max: 133918, snapshot count: 17, commit_timestamp: (0, 0), durable_timestamp: (0, 0), first_commit_timestamp: (0, 0), prepare_timestamp: (0, 0), read_timestamp: (0, 0), checkpoint LSN: [0][0], full checkpoint: false, rollback reason: , flags: 0x0000200c, isolation: WT_ISO_SNAPSHOT
      0x7f8c1ce5d820:ID: 0, pinned ID: 122501, metadata pinned ID: 133648, name: WT_CURSOR.next
      0x7f8c1ce5d820:transaction id: 0, mod count: 0, snap min: 122501, snap max: 133944, snapshot count: 19, commit_timestamp: (0, 0), durable_timestamp: (0, 0), first_commit_timestamp: (0, 0), prepare_timestamp: (0, 0), read_timestamp: (0, 0), checkpoint LSN: [0][0], full checkpoint: false, rollback reason: , flags: 0x00000008, isolation: WT_ISO_READ_COMMITTED
      0x7f8c1ce5d820:ID: 133877, pinned ID: 122501, metadata pinned ID: 133648, name: WT_CURSOR.next
      0x7f8c1ce5d820:transaction id: 133877, mod count: 3, snap min: 122501, snap max: 133874, snapshot count: 19, commit_timestamp: (0, 0), durable_timestamp: (0, 0), first_commit_timestamp: (0, 0), prepare_timestamp: (0, 0), read_timestamp: (0, 0), checkpoint LSN: [0][0], full checkpoint: false, rollback reason: , flags: 0x0000200c, isolation: WT_ISO_SNAPSHOT
      0x7f8c1ce5d820:ID: 0, pinned ID: 122501, metadata pinned ID: 133648, name: WT_CURSOR.next
      0x7f8c1ce5d820:transaction id: 0, mod count: 0, snap min: 122501, snap max: 133927, snapshot count: 20, commit_timestamp: (0, 0), durable_timestamp: (0, 0), first_commit_timestamp: (0, 0), prepare_timestamp: (0, 0), read_timestamp: (0, 0), checkpoint LSN: [0][0], full checkpoint: false, rollback reason: , flags: 0x00000008, isolation: WT_ISO_READ_COMMITTED
      0x7f8c1ce5d820:ID: 133937, pinned ID: 122501, metadata pinned ID: 133648, name: WT_CURSOR.prev
      0x7f8c1ce5d820:transaction id: 133937, mod count: 1, snap min: 122501, snap max: 133933, snapshot count: 21, commit_timestamp: (0, 0), durable_timestamp: (0, 0), first_commit_timestamp: (0, 0), prepare_timestamp: (0, 0), read_timestamp: (0, 0), checkpoint LSN: [0][0], full checkpoint: false, rollback reason: , flags: 0x0000200c, isolation: WT_ISO_SNAPSHOT
      0x7f8c1ce5d820:ID: 0, pinned ID: 122501, metadata pinned ID: 133648, name: WT_CURSOR.next
      0x7f8c1ce5d820:transaction id: 0, mod count: 0, snap min: 122501, snap max: 133935, snapshot count: 20, commit_timestamp: (0, 0), durable_timestamp: (0, 0), first_commit_timestamp: (0, 0), prepare_timestamp: (0, 0), read_timestamp: (0, 0), checkpoint LSN: [0][0], full checkpoint: false, rollback reason: , flags: 0x00000008, isolation: WT_ISO_READ_COMMITTED
      0x7f8c1ce5d820:ID: 133928, pinned ID: 122501, metadata pinned ID: 133648, name: WT_CURSOR.next
      0x7f8c1ce5d820:transaction id: 133928, mod count: 2, snap min: 122501, snap max: 133928, snapshot count: 20, commit_timestamp: (0, 0), durable_timestamp: (0, 0), first_commit_timestamp: (0, 0), prepare_timestamp: (0, 0), read_timestamp: (0, 0), checkpoint LSN: [0][0], full checkpoint: false, rollback reason: , flags: 0x0000200c, isolation: WT_ISO_SNAPSHOT
      0x7f8c1ce5d820:ID: 0, pinned ID: 122501, metadata pinned ID: 133648, name: WT_CURSOR.prev
      0x7f8c1ce5d820:transaction id: 0, mod count: 0, snap min: 122501, snap max: 133925, snapshot count: 20, commit_timestamp: (0, 0), durable_timestamp: (0, 0), first_commit_timestamp: (0, 0), prepare_timestamp: (0, 0), read_timestamp: (0, 0), checkpoint LSN: [0][0], full checkpoint: false, rollback reason: , flags: 0x00000008, isolation: WT_ISO_READ_COMMITTED
      0x7f8c1ce5d820:ID: 133904, pinned ID: 122501, metadata pinned ID: 133648, name: WT_CURSOR.next
      0x7f8c1ce5d820:transaction id: 133904, mod count: 2, snap min: 122501, snap max: 133903, snapshot count: 17, commit_timestamp: (0, 0), durable_timestamp: (0, 0), first_commit_timestamp: (0, 0), prepare_timestamp: (0, 0), read_timestamp: (0, 0), checkpoint LSN: [0][0], full checkpoint: false, rollback reason: , flags: 0x0000200c, isolation: WT_ISO_SNAPSHOT
      0x7f8c1ce5d820:=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=
      0x7f8c1ce5d820:cache dump
      0x7f8c1ce5d820:cache full: no
      0x7f8c1ce5d820:cache clean check: yes (95.073%)
      0x7f8c1ce5d820:cache dirty check: no (18.614%)
      0x7f8c1ce5d820:file:wt.wt(checkpoint=WiredTigerCheckpoint.11):
      0x7f8c1ce5d820:internal: 5 pages, 0MB, 5/0 clean/dirty pages, 0/0 clean/dirty MB, 0MB max page, 0MB max dirty page
      0x7f8c1ce5d820:leaf: 5 pages, 0MB, 5/0 clean/dirty pages, 0/0 clean/dirty MB, 0MB max page, 0MB max dirty page
      0x7f8c1ce5d820:file:wt.wt(<live>):
      0x7f8c1ce5d820:internal: 17935 pages, 216MB, 16736/1199 clean/dirty pages, 202/14 clean/dirty MB, 0MB max page, 0MB max dirty page
      0x7f8c1ce5d820:leaf: 48188 pages, 55MB, 2171/46017 clean/dirty pages, 2/53 clean/dirty MB, 0MB max page, 0MB max dirty page
      0x7f8c1ce5d820:file:WiredTigerLAS.wt(<live>):
      0x7f8c1ce5d820:internal: 1 pages, 0MB, 0/1 clean/dirty pages, 0/0 clean/dirty MB, 0MB max page, 0MB max dirty page
      0x7f8c1ce5d820:leaf: 0 pages
      0x7f8c1ce5d820:file:WiredTiger.wt(<live>):
      0x7f8c1ce5d820:internal: 1 pages, 0MB, 1/0 clean/dirty pages, 0/0 clean/dirty MB, 0MB max page, 0MB max dirty page
      0x7f8c1ce5d820:leaf: 1 pages, 0MB, 0/1 clean/dirty pages, 0/0 clean/dirty MB, 0MB max page, 0MB max dirty page
      0x7f8c1ce5d820:cache dump: total found: 294MB vs tracked inuse 294MB
      0x7f8c1ce5d820:total dirty bytes: 68MB
      [1577562556:731962][16513:0x7f8c16cf7700], t, eviction-server: __wt_evict_thread_run, 315: cache eviction thread error: Connection timed out
      [1577562556:731978][16513:0x7f8c16cf7700], t, eviction-server: __wt_panic, 490: the process must exit and restart: WT_PANIC: WiredTiger library panic
      [1577562556:731984][16513:0x7f8c16cf7700], t, eviction-server: __wt_abort, 28: aborting WiredTiger library
      /tmp/jenkins6489608779926522933.sh: line 30: 16513 Aborted                 (core dumped) nice ./t -1 -c ../../../test/format/CONFIG.stress file_type=row leaf_page_max=9 internal_page_max=9 key_min=256 value_min=256 

      The configuration:

      ############################################
      #  RUN PARAMETERS
      ############################################
      abort=0
      alter=0
      assert_commit_timestamp=0
      assert_read_timestamp=0
      auto_throttle=1
      backups=0
      bitcnt=3
      bloom=1
      bloom_bit_count=50
      bloom_hash_count=20
      bloom_oldest=0
      cache=310
      cache_minimum=20
      checkpoints=on
      checkpoint_log_size=157
      checkpoint_wait=99
      checksum=off
      chunk_size=7
      compaction=0
      compression=zlib
      data_extend=0
      data_source=table
      delete_pct=9
      dictionary=0
      direct_io=0
      encryption=none
      evict_max=3
      file_type=row-store
      firstfit=0
      huffman_key=0
      huffman_value=0
      independent_thread_rng=1
      in_memory=0
      insert_pct=1
      internal_key_truncation=1
      internal_page_max=9
      isolation=snapshot
      key_gap=12
      key_max=256
      key_min=256
      leaf_page_max=9
      leak_memory=0
      logging=0
      logging_archive=1
      logging_compression=none
      logging_file_max=166177
      logging_prealloc=0
      lsm_worker_threads=4
      memory_page_max=5
      merge_max=19
      mmap=1
      modify_pct=32
      ops=0
      prefix_compression=1
      prefix_compression_min=2
      prepare=0
      quiet=1
      random_cursor=0
      read_pct=1
      rebalance=1
      repeat_data_pct=19
      reverse=0
      rows=1000000
      runs=1
      salvage=1
      split_pct=92
      statistics=0
      statistics_server=0
      threads=31
      timer=4
      timing_stress_aggressive_sweep=0
      timing_stress_checkpoint=0
      timing_stress_lookaside_sweep=0
      timing_stress_split_1=0
      timing_stress_split_2=0
      timing_stress_split_3=0
      timing_stress_split_4=0
      timing_stress_split_5=0
      timing_stress_split_6=0
      timing_stress_split_7=0
      timing_stress_split_8=0
      transaction_timestamps=0
      transaction-frequency=45
      truncate=1
      value_max=2753
      value_min=256
      verify=1
      wiredtiger_config=
      write_pct=57
      ############################################ 

        Attachments

          Issue Links

            Activity

              People

              Assignee:
              keith.bostic Keith Bostic
              Reporter:
              luke.chen Luke Chen
              Votes:
              0 Vote for this issue
              Watchers:
              4 Start watching this issue

                Dates

                Created:
                Updated:
                Resolved: