Loading...

Type: Bug
Resolution: Fixed
Priority: Major - P3
Fix Version/s: WT10.0.0, 4.3.3, 4.2.3
Affects Version/s: None
Component/s: None
Labels:
- format-cache-stuck

Story Points:
5
Sprint:
Storage Engines 2019-12-30

Summary:
Fix a test program bug that can lead to eviction failures in testing.

=========================
This is another cache stuck clean case after the recent merge of ~~WT-5276~~, on kodkod-aws. In this specific case, the cache was full of internal pages with timestamp enabled.

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

++ nice ./t -1 -c ../../../test/format/CONFIG.stress
t: process 27495 running
[1575673649:765464][27495:0x7f2764608700], t, eviction-server: __evict_server, 440: Cache stuck for too long, giving up: Connection timed out
0x7f276e698690:=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=
0x7f276e698690:transaction state dump
0x7f276e698690:current ID: 2119
0x7f276e698690:last running ID: 1975
0x7f276e698690:metadata_pinned ID: 1949
0x7f276e698690:oldest ID: 1952
0x7f276e698690:durable timestamp: (0, 1997)
0x7f276e698690:oldest timestamp: (0, 1997)
0x7f276e698690:pinned timestamp: (0, 1880)
0x7f276e698690:stable timestamp: (0, 0)
0x7f276e698690:has_durable_timestamp: yes
0x7f276e698690:has_oldest_timestamp: yes
0x7f276e698690:has_pinned_timestamp: yes
0x7f276e698690:has_stable_timestamp: no
0x7f276e698690:oldest_is_pinned: no
0x7f276e698690:stable_is_pinned: no
0x7f276e698690:checkpoint running: no
0x7f276e698690:checkpoint generation: 31
0x7f276e698690:checkpoint pinned ID: 0
0x7f276e698690:checkpoint txn ID: 0
0x7f276e698690:oldest named snapshot ID: 0
0x7f276e698690:session count: 32
0x7f276e698690:Transaction state of active sessions:
0x7f276e698690:ID: 0, pinned ID: 1975, metadata pinned ID: 0, name: WT_CURSOR.search
0x7f276e698690:transaction id: 0, mod count: 0, snap min: 1975, snap max: 2092, snapshot count: 6, commit_timestamp: (0, 1991), durable_timestamp: (0, 1991), first_commit_timestamp: (0, 1991), prepare_timestamp: (0, 0), read_timestamp: (0, 1996), checkpoint LSN: [0][0], full checkpoint: false, rollback reason: , flags: 0x00002888, isolation: WT_ISO_SNAPSHOT
0x7f276e698690:ID: 0, pinned ID: 1975, metadata pinned ID: 1949, name: WT_CURSOR.search_near
0x7f276e698690:transaction id: 0, mod count: 0, snap min: 1949, snap max: 1978, snapshot count: 4, commit_timestamp: (0, 1983), durable_timestamp: (0, 1983), first_commit_timestamp: (0, 1983), prepare_timestamp: (0, 0), read_timestamp: (0, 1880), checkpoint LSN: [0][0], full checkpoint: false, rollback reason: , flags: 0x00002888, isolation: WT_ISO_SNAPSHOT
0x7f276e698690:ID: 1975, pinned ID: 1952, metadata pinned ID: 1949, name: WT_CURSOR.search
0x7f276e698690:transaction id: 1975, mod count: 3, snap min: 1949, snap max: 1974, snapshot count: 5, commit_timestamp: (0, 1975), durable_timestamp: (0, 1975), first_commit_timestamp: (0, 1975), prepare_timestamp: (0, 0), read_timestamp: (0, 1880), checkpoint LSN: [0][0], full checkpoint: false, rollback reason: , flags: 0x0000288c, isolation: WT_ISO_SNAPSHOT
0x7f276e698690:ID: 0, pinned ID: 1952, metadata pinned ID: 1949, name: WT_CURSOR.search
0x7f276e698690:transaction id: 0, mod count: 0, snap min: 1949, snap max: 1977, snapshot count: 5, commit_timestamp: (0, 1957), durable_timestamp: (0, 1957), first_commit_timestamp: (0, 1957), prepare_timestamp: (0, 0), read_timestamp: (0, 1979), checkpoint LSN: [0][0], full checkpoint: false, rollback reason: , flags: 0x00002888, isolation: WT_ISO_SNAPSHOT
0x7f276e698690:ID: 1980, pinned ID: 1952, metadata pinned ID: 1949, name: WT_CURSOR.search
0x7f276e698690:transaction id: 1980, mod count: 1, snap min: 1949, snap max: 1977, snapshot count: 5, commit_timestamp: (0, 1959), durable_timestamp: (0, 1959), first_commit_timestamp: (0, 1959), prepare_timestamp: (0, 0), read_timestamp: (0, 1981), checkpoint LSN: [0][0], full checkpoint: false, rollback reason: , flags: 0x0000288c, isolation: WT_ISO_SNAPSHOT
0x7f276e698690:ID: 0, pinned ID: 1975, metadata pinned ID: 0, name: WT_CURSOR.search
0x7f276e698690:transaction id: 0, mod count: 0, snap min: 1975, snap max: 2092, snapshot count: 6, commit_timestamp: (0, 1993), durable_timestamp: (0, 1993), first_commit_timestamp: (0, 1993), prepare_timestamp: (0, 0), read_timestamp: (0, 1994), checkpoint LSN: [0][0], full checkpoint: false, rollback reason: , flags: 0x00002888, isolation: WT_ISO_SNAPSHOT
0x7f276e698690:ID: 2090, pinned ID: 1975, metadata pinned ID: 1949, name: WT_CURSOR.search
0x7f276e698690:transaction id: 2090, mod count: 1, snap min: 1949, snap max: 1978, snapshot count: 4, commit_timestamp: (0, 1980), durable_timestamp: (0, 1980), first_commit_timestamp: (0, 1980), prepare_timestamp: (0, 0), read_timestamp: (0, 1982), checkpoint LSN: [0][0], full checkpoint: false, rollback reason: , flags: 0x0000288c, isolation: WT_ISO_SNAPSHOT
0x7f276e698690:ID: 0, pinned ID: 1975, metadata pinned ID: 0, name: WT_CURSOR.insert
0x7f276e698690:transaction id: 0, mod count: 0, snap min: 1975, snap max: 2092, snapshot count: 7, commit_timestamp: (0, 1978), durable_timestamp: (0, 1978), first_commit_timestamp: (0, 1978), prepare_timestamp: (0, 0), read_timestamp: (0, 1992), checkpoint LSN: [0][0], full checkpoint: false, rollback reason: , flags: 0x01002888, isolation: WT_ISO_SNAPSHOT
0x7f276e698690:ID: 1977, pinned ID: 1952, metadata pinned ID: 1949, name: WT_CURSOR.search
0x7f276e698690:transaction id: 1977, mod count: 8, snap min: 1949, snap max: 1974, snapshot count: 6, commit_timestamp: (0, 1971), durable_timestamp: (0, 1971), first_commit_timestamp: (0, 1971), prepare_timestamp: (0, 0), read_timestamp: (0, 1880), checkpoint LSN: [0][0], full checkpoint: false, rollback reason: , flags: 0x0000288c, isolation: WT_ISO_SNAPSHOT
0x7f276e698690:ID: 0, pinned ID: 1975, metadata pinned ID: 0, name: WT_CURSOR.search
0x7f276e698690:transaction id: 0, mod count: 0, snap min: 1975, snap max: 2092, snapshot count: 6, commit_timestamp: (0, 1943), durable_timestamp: (0, 1943), first_commit_timestamp: (0, 1943), prepare_timestamp: (0, 0), read_timestamp: (0, 1995), checkpoint LSN: [0][0], full checkpoint: false, rollback reason: , flags: 0x00002888, isolation: WT_ISO_SNAPSHOT
0x7f276e698690:ID: 2091, pinned ID: 1975, metadata pinned ID: 1949, name: WT_CURSOR.search_near
0x7f276e698690:transaction id: 2091, mod count: 1, snap min: 1949, snap max: 1979, snapshot count: 4, commit_timestamp: (0, 1984), durable_timestamp: (0, 1984), first_commit_timestamp: (0, 1984), prepare_timestamp: (0, 0), read_timestamp: (0, 1990), checkpoint LSN: [0][0], full checkpoint: false, rollback reason: , flags: 0x0000288c, isolation: WT_ISO_SNAPSHOT
0x7f276e698690:ID: 0, pinned ID: 1975, metadata pinned ID: 1949, name: WT_CURSOR.update
0x7f276e698690:transaction id: 0, mod count: 0, snap min: 1949, snap max: 1979, snapshot count: 5, commit_timestamp: (0, 1976), durable_timestamp: (0, 1976), first_commit_timestamp: (0, 1976), prepare_timestamp: (0, 0), read_timestamp: (0, 1985), checkpoint LSN: [0][0], full checkpoint: false, rollback reason: , flags: 0x01002888, isolation: WT_ISO_SNAPSHOT
0x7f276e698690:=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=
0x7f276e698690:cache dump
0x7f276e698690:cache full: yes
0x7f276e698690:cache clean check: yes (101.336%)
0x7f276e698690:cache dirty check: no (0.362%)
0x7f276e698690:file:wt.wt(checkpoint=WiredTigerCheckpoint.1):
0x7f276e698690:internal: 9 pages, 1MB, 9/0 clean/dirty pages, 1/0 clean/dirty MB, 0MB max page, 0MB max dirty page
0x7f276e698690:leaf: 0 pages
0x7f276e698690:file:wt.wt(<live>):
0x7f276e698690:internal: 215 pages, 22MB, 196/19 clean/dirty pages, 22/0 clean/dirty MB, 0MB max page, 0MB max dirty page
0x7f276e698690:leaf: 20 pages, 0MB, 0/20 clean/dirty pages, 0/0 clean/dirty MB, 0MB max page, 0MB max dirty page
0x7f276e698690:file:WiredTigerLAS.wt(<live>):
0x7f276e698690:internal: 1 pages, 0MB, 0/1 clean/dirty pages, 0/0 clean/dirty MB, 0MB max page, 0MB max dirty page
0x7f276e698690:leaf: 0 pages
0x7f276e698690:file:WiredTiger.wt(<live>):
0x7f276e698690:internal: 1 pages, 0MB, 0/1 clean/dirty pages, 0/0 clean/dirty MB, 0MB max page, 0MB max dirty page
0x7f276e698690:leaf: 1 pages, 0MB, 0/1 clean/dirty pages, 0/0 clean/dirty MB, 0MB max page, 0MB max dirty page
0x7f276e698690:cache dump: total found: 26MB vs tracked inuse 26MB
0x7f276e698690:total dirty bytes: 0MB
[1575673649:766424][27495:0x7f2764608700], t, eviction-server: __wt_evict_thread_run, 315: cache eviction thread error: Connection timed out
[1575673649:766439][27495:0x7f2764608700], t, eviction-server: __wt_panic, 490: the process must exit and restart: WT_PANIC: WiredTiger library panic
[1575673649:766447][27495:0x7f2764608700], t, eviction-server: __wt_abort, 28: aborting WiredTiger library
/tmp/jenkins14287420166777197545.sh: line 24: 27495 Aborted                 (core dumped) nice ./t -1 -c ../../../test/format/CONFIG.stress

The configuration:

############################################
#  RUN PARAMETERS
############################################
abort=0
alter=1
assert_commit_timestamp=0
assert_read_timestamp=0
auto_throttle=1
backups=0
bitcnt=5
bloom=1
bloom_bit_count=24
bloom_hash_count=20
bloom_oldest=0
cache=26
cache_minimum=20
checkpoints=on
checkpoint_log_size=77
checkpoint_wait=55
checksum=uncompressed
chunk_size=3
compaction=1
compression=none
data_extend=0
data_source=table
delete_pct=8
dictionary=0
direct_io=0
encryption=rotn-7
evict_max=4
file_type=row-store
firstfit=0
huffman_key=0
huffman_value=0
independent_thread_rng=1
in_memory=0
insert_pct=45
internal_key_truncation=1
internal_page_max=12
isolation=snapshot
key_gap=6
key_max=91
key_min=15
leaf_page_max=12
leak_memory=0
logging=1
logging_archive=0
logging_compression=lz4
logging_file_max=31532
logging_prealloc=1
long_running_txn=0
lsm_worker_threads=4
memory_page_max=1
merge_max=4
mmap=1
modify_pct=6
ops=0
prefix_compression=0
prefix_compression_min=2
prepare=0
quiet=1
random_cursor=0
read_pct=18
rebalance=1
repeat_data_pct=51
reverse=1
rows=1000000
runs=1
salvage=1
split_pct=54
statistics=0
statistics_server=1
threads=13
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=1
transaction-frequency=100
truncate=1
value_max=663
value_min=12
verify=1
wiredtiger_config=
write_pct=23
############################################

Details

Description

Attachments

Activity

People

Dates