[WT-5312] Add thread doing random cursor operations to format's cache size calculation - MongoDB Jira

XML

Word

Printable

JSON

Details

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

Story Points:
5
Sprint:
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

############################################

Attachments

Activity

People

Assignee:: Keith Bostic (Inactive)

Reporter:: Luke Chen

Votes:: 0 Vote for this issue

Watchers:: 3 Start watching this issue

Dates

Created:: Dec 08 2019 10:21:18 PM UTC

Updated:: Jan 06 2020 04:39:27 PM UTC

Resolved:: Dec 27 2019 02:41:01 AM UTC