Details
-
Bug
-
Status: Closed
-
Major - P3
-
Resolution: Fixed
-
None
-
None
-
5
-
Storage Engines 2019-12-30
Description
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
|
############################################
|