Loading...

Type: Bug
Resolution: Duplicate
Priority: Major - P3
Fix Version/s: None
Affects Version/s: None
Component/s: None
Labels:
- format-cache-stuck

Story Points:
5
Sprint:
Storage Engines 2020-01-13

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
############################################

duplicates

WT-5366 read-committed and read-uncommitted transactions can stall eviction

Closed

Details

Description

Attachments

Issue Links

Activity

People

Dates