Bug #65585: unittest-seastore (Timeout) - crimson - Ceph

Actions

Copy link

Bug #65585

open

unittest-seastore (Timeout)

Added by Yingxin Cheng almost 2 years ago. Updated almost 2 years ago.

Status:

Need More Info

Priority:

Normal

Assignee:

Category:

Seastore

Target version:

% Done:

Source:

Backport:

Regression:

Severity:

3 - minor

Reviewed:

Affected Versions:

ceph-qa-suite:

Pull request ID:

Tags (freeform):

Merge Commit:

Fixed In:

Released In:

Upkeep Timestamp:

Description

[ RUN      ] seastore_test/seastore_test_t.object_data_omap_remove/1
INFO  2024-04-19 04:33:11,283 [shard 0:main] test - EphemeralTestState::tm_setup: begin with 1 devices ...
Reactor stalled for 70 ms on shard 0. Backtrace: 0x9442faa 0xf4e2df4 0xf4e22cc 0xf2d84f3 0xf2d2aef 0xf2d2597 0xf2d2f78 0xf2d9aba 0x4251f 0x1afbb9 0x9489923 0xa492d66 0xa49f31b 0xa49d836 0xa49d4f7 0xa49d3a6 0xa49cd90 0xa49ca63 0xa4e02a3 0xa4dfefa 0xa4df89c 0xa4df6a7 0xa4df2c0 0xf2fd49d 0xf30ae4e 0xf310f8d 0xf30eabd 0xf0a2752 0xf09fbc6 0xf0a2f36 0x99e2610 0x99e2409 0x99e231c 0x99e212c 0x99e2090 0x99e1f98 0x99e1da0 0xdc2c2 0x94b42 0x1269ff
Reactor stalled for 130 ms on shard 0. Backtrace: 0x9442faa 0xf4e2df4 0xf4e22cc 0xf2d84f3 0xf2d2aef 0xf2d2597 0xf2d2f78 0xf2d9aba 0x4251f 0x1afbb9 0x9489923 0xa492d66 0xa49f31b 0xa49d836 0xa49d4f7 0xa49d3a6 0xa49cd90 0xa49ca63 0xa4e02a3 0xa4dfefa 0xa4df89c 0xa4df6a7 0xa4df2c0 0xf2fd49d 0xf30ae4e 0xf310f8d 0xf30eabd 0xf0a2752 0xf09fbc6 0xf0a2f36 0x99e2610 0x99e2409 0x99e231c 0x99e212c 0x99e2090 0x99e1f98 0x99e1da0 0xdc2c2 0x94b42 0x1269ff
INFO  2024-04-19 04:33:11,421 [shard 0:main] seastore_cache - Cache::Cache: created, lru_size=67108864
Reactor stalled for 354 ms on shard 0. Backtrace: 0x9442faa 0xf4e2df4 0xf4e22cc 0xf2d84f3 0xf2d2aef 0xf2d2597 0xf2d2f78 0xf2d9aba 0x4251f 0x9fcb72f 0xf1901a3 0xf1938ab 0xf18671d 0xaadd117 0xaaca394 0xa8edd70 0xa7b5f7b 0x9b3caa2 0x9b3f4ff 0x9f68e0b 0x9f68935 0x9f68737 0x9f68615 0x9f68513 0xa3ce3c3 0xa3ce1c7 0xa3ce097 0xa3cdf07 0xa3cdc67 0xa3cdb41 0xa3cd8bc 0xa3cd6b6 0xa3cd11a 0xf2fd49d 0xf30ae4e 0xf310f8d 0xf30eabd 0xf0a2752 0xf09fbc6 0xf0a2f36 0x99e2610 0x99e2409 0x99e231c 0x99e212c 0x99e2090 0x99e1f98 0x99e1da0 0xdc2c2 0x94b42 0x1269ff
INFO  2024-04-19 04:33:11,765 [shard 0:main] seastore_journal - RecordSubmitter:  io_depth_limit=5, batch_capacity=16, batch_flush_size=16777216, preferred_fullness=0.95
INFO  2024-04-19 04:33:11,765 [shard 0:main] seastore_tm - TransactionManager::mkfs: enter
INFO  2024-04-19 04:33:11,768 [shard 0:main] seastore_cleaner - JournalTrimmerImpl::update_journal_tails: journal_dirty_tail JOURNAL_SEQ_NULL => jseq(sseq(0), paddr<Dev(128),8192>), JournalTrimmer(not-ready)
INFO  2024-04-19 04:33:11,769 [shard 0:main] seastore_cleaner - JournalTrimmerImpl::update_journal_tails: journal_alloc_tail JOURNAL_SEQ_NULL => jseq(sseq(0), paddr<Dev(128),8192>), JournalTrimmer(not-ready)
INFO  2024-04-19 04:33:11,769 [shard 0:main] seastore_cleaner - JournalTrimmerImpl::set_journal_head: journal_head JOURNAL_SEQ_NULL => jseq(sseq(0), paddr<Dev(128),8192>), JournalTrimmer(not-ready)
INFO  2024-04-19 04:33:11,769 [shard 0:main] seastore_epm - ExtentPlacementManager::open_for_write: started with 1 devices
INFO  2024-04-19 04:33:11,769 [shard 0:main] seastore_cache - Cache::init: init root -- CachedExtent(addr=0x61b000031e80, type=ROOT, version=0, dirty_from_or_retired_at=JOURNAL_SEQ_NULL, modify_time=tp(NULL), paddr=paddr<Dev(ROOT),0>, prior_paddr=nullopt, length=0, state=CLEAN, last_committed_crc=0, refcount=1, user_hint=Hint(NULL), fully_loaded=1, rewrite_gen=GEN_NULL, root_block(lba_root_node=0, backref_root_node=0))
INFO  2024-04-19 04:33:11,769 [shard 0:main] seastore_cache - 0x6170000d8280 trans.1 Cache::mkfs: create root
INFO  2024-04-19 04:33:11,770 [shard 0:main] seastore_lba - 0x6170000d8280 trans.1 BtreeLBAManager::mkfs: start
INFO  2024-04-19 04:33:11,770 [shard 0:main] seastore_backref - 0x6170000d8280 trans.1 BtreeBackrefManager::mkfs: start
INFO  2024-04-19 04:33:11,771 [shard 0:main] seastore_tm - 0x6170000d8280 trans.1 TransactionManager::mkfs: submitting mkfs transaction
INFO  2024-04-19 04:33:11,772 [shard 0:main] seastore_tm - TransactionManager::close: enter
INFO  2024-04-19 04:33:11,772 [shard 0:main] seastore_epm - BackgroundProcess::stop_background: done, JournalTrimmer(not-ready, journal_head=jseq(sseq(0), paddr<Dev(128),8192>), alloc_tail=jseq(sseq(0), paddr<Dev(128),8192>), dirty_tail=jseq(sseq(0), paddr<Dev(128),8192>)), 
INFO  2024-04-19 04:33:11,773 [shard 0:main] seastore_cache - Cache::close: close with 1(0B) dirty, dirty_from=jseq(sseq(0), paddr<Dev(128),8192>), alloc_from=jseq(sseq(0), paddr<Dev(128),8192>), 2(8192B) lru, totally 3(8192B) indexed extents
INFO  2024-04-19 04:33:11,773 [shard 0:main] seastore_epm - ExtentPlacementManager::close: started
INFO  2024-04-19 04:33:11,773 [shard 0:main] seastore_tm - TransactionManager::close: completed
INFO  2024-04-19 04:33:11,774 [shard 0:main] seastore_tm - TransactionManager::mkfs: completed
INFO  2024-04-19 04:33:11,877 [shard 0:main] seastore_cache - Cache::Cache: created, lru_size=67108864
INFO  2024-04-19 04:33:12,336 [shard 0:main] seastore_journal - RecordSubmitter:  io_depth_limit=5, batch_capacity=16, batch_flush_size=16777216, preferred_fullness=0.95
INFO  2024-04-19 04:33:12,336 [shard 0:main] seastore_tm - TransactionManager::mount: enter
INFO  2024-04-19 04:33:12,337 [shard 0:main] seastore_cache - Cache::init: init root -- CachedExtent(addr=0x61b000037280, type=ROOT, version=0, dirty_from_or_retired_at=JOURNAL_SEQ_NULL, modify_time=tp(NULL), paddr=paddr<Dev(ROOT),0>, prior_paddr=nullopt, length=0, state=CLEAN, last_committed_crc=0, refcount=1, user_hint=Hint(NULL), fully_loaded=1, rewrite_gen=GEN_NULL, root_block(lba_root_node=0, backref_root_node=0))
INFO  2024-04-19 04:33:12,339 [shard 0:main] seastore_journal - Journal::scan_valid_record_delta: starting at jseq(sseq(0), paddr<Dev(128),8192>) 
INFO  2024-04-19 04:33:12,340 [shard 0:main] seastore_journal - RecordScanner::consume_next_records: complete at cursor(last_valid_header_found=1, seq=jseq(sseq(0), paddr<Dev(128),12288>), last_committed=JOURNAL_SEQ_NULL, pending_record_groups=0, num_consumed_records=1), no more record group
INFO  2024-04-19 04:33:12,354 [shard 0:main] seastore_journal - RecordScanner::scan_valid_records: complete at cursor(last_valid_header_found=1, seq=jseq(sseq(1), paddr<Dev(128),8192>), last_committed=JOURNAL_SEQ_NULL, pending_record_groups=0, num_consumed_records=1), invalid record group metadata
INFO  2024-04-19 04:33:12,355 [shard 0:main] seastore_journal - Journal::scan_valid_record_delta: starting at jseq(sseq(0), paddr<Dev(128),8192>) 
INFO  2024-04-19 04:33:12,356 [shard 0:main] seastore_journal - RecordScanner::consume_next_records: complete at cursor(last_valid_header_found=1, seq=jseq(sseq(0), paddr<Dev(128),12288>), last_committed=JOURNAL_SEQ_NULL, pending_record_groups=0, num_consumed_records=1), no more record group
INFO  2024-04-19 04:33:12,356 [shard 0:main] seastore_journal - RecordScanner::scan_valid_records: complete at cursor(last_valid_header_found=1, seq=jseq(sseq(1), paddr<Dev(128),8192>), last_committed=JOURNAL_SEQ_NULL, pending_record_groups=0, num_consumed_records=1), invalid record group metadata
INFO  2024-04-19 04:33:12,357 [shard 0:main] seastore_cleaner - JournalTrimmerImpl::update_journal_tails: journal_dirty_tail JOURNAL_SEQ_NULL => jseq(sseq(0), paddr<Dev(128),8192>), JournalTrimmer(not-ready)
INFO  2024-04-19 04:33:12,357 [shard 0:main] seastore_cleaner - JournalTrimmerImpl::update_journal_tails: journal_alloc_tail JOURNAL_SEQ_NULL => jseq(sseq(0), paddr<Dev(128),8192>), JournalTrimmer(not-ready)
INFO  2024-04-19 04:33:12,358 [shard 0:main] seastore_cleaner - JournalTrimmerImpl::set_journal_head: journal_head JOURNAL_SEQ_NULL => jseq(sseq(0), paddr<Dev(128),12288>), JournalTrimmer(not-ready)
INFO  2024-04-19 04:33:12,359 [shard 0:main] seastore_cache - 0x6170000dbe00 trans.1 Cache::init_cached_extents: start with 1(0B) extents, 1 dirty, dirty_from=jseq(sseq(0), paddr<Dev(128),8192>), alloc_from=jseq(sseq(0), paddr<Dev(128),8192>)
INFO  2024-04-19 04:33:12,359 [shard 0:main] seastore_cache - 0x6170000dbe00 trans.1 Cache::init_cached_extents: finish with 1(0B) extents, 1 dirty, dirty_from=jseq(sseq(0), paddr<Dev(128),8192>), alloc_from=jseq(sseq(0), paddr<Dev(128),8192>)
INFO  2024-04-19 04:33:12,361 [shard 0:main] seastore_epm - ExtentPlacementManager::open_for_write: started with 1 devices
INFO  2024-04-19 04:33:12,361 [shard 0:main] seastore_epm - BackgroundProcess::start_background: JournalTrimmer(not-ready, journal_head=jseq(sseq(0), paddr<Dev(128),12288>), alloc_tail=jseq(sseq(0), paddr<Dev(128),8192>), dirty_tail=jseq(sseq(0), paddr<Dev(128),8192>)), 
INFO  2024-04-19 04:33:12,361 [shard 0:main] seastore_tm - TransactionManager::mount: completed
INFO  2024-04-19 04:33:12,363 [shard 0:main] seastore_onode - 0x6170000dba80 trans.2 OTree::Node::mkfs: allocated root NodeL0@0x0+4000Lv0$
INFO  2024-04-19 04:33:12,376 [shard 0:main] test - EphemeralTestState::restart_fut: begin ...
INFO  2024-04-19 04:33:12,376 [shard 0:main] seastore_tm - TransactionManager::close: enter
INFO  2024-04-19 04:33:12,377 [shard 0:main] seastore_epm - BackgroundProcess::stop_background: done, JournalTrimmer(should_block_io_on_trim=0, should_(trim_dirty=0, trim_alloc=0), journal_head=jseq(sseq(0), paddr<Dev(128),24576>), alloc_tail=jseq(sseq(0), paddr<Dev(128),8192>), dirty_tail=jseq(sseq(0), paddr<Dev(128),12288>), alloc_tail_target=JOURNAL_SEQ_MIN, dirty_tail_target=JOURNAL_SEQ_MIN, tail_limit=JOURNAL_SEQ_MIN), 
INFO  2024-04-19 04:33:12,381 [shard 0:main] seastore_cache - Cache::close: close with 2(4096B) dirty, dirty_from=jseq(sseq(0), paddr<Dev(128),12288>), alloc_from=jseq(sseq(0), paddr<Dev(128),8192>), 3(24576B) lru, totally 5(28672B) indexed extents
INFO  2024-04-19 04:33:12,382 [shard 0:main] seastore_epm - ExtentPlacementManager::close: started
INFO  2024-04-19 04:33:12,382 [shard 0:main] seastore_tm - TransactionManager::close: completed
INFO  2024-04-19 04:33:12,528 [shard 0:main] seastore_cache - Cache::Cache: created, lru_size=67108864
INFO  2024-04-19 04:33:12,827 [shard 0:main] seastore_journal - RecordSubmitter:  io_depth_limit=5, batch_capacity=16, batch_flush_size=16777216, preferred_fullness=0.95
INFO  2024-04-19 04:33:12,827 [shard 0:main] seastore_tm - TransactionManager::mount: enter
INFO  2024-04-19 04:33:12,828 [shard 0:main] seastore_cache - Cache::init: init root -- CachedExtent(addr=0x61b000026180, type=ROOT, version=0, dirty_from_or_retired_at=JOURNAL_SEQ_NULL, modify_time=tp(NULL), paddr=paddr<Dev(ROOT),0>, prior_paddr=nullopt, length=0, state=CLEAN, last_committed_crc=0, refcount=1, user_hint=Hint(NULL), fully_loaded=1, rewrite_gen=GEN_NULL, root_block(lba_root_node=0, backref_root_node=0))
INFO  2024-04-19 04:33:12,830 [shard 0:main] seastore_journal - Journal::scan_valid_record_delta: starting at jseq(sseq(0), paddr<Dev(128),8192>) 
INFO  2024-04-19 04:33:12,835 [shard 0:main] seastore_journal - RecordScanner::scan_valid_records: complete at cursor(last_valid_header_found=1, seq=jseq(sseq(0), paddr<Dev(128),28672>), last_committed=jseq(sseq(0), paddr<Dev(128),24576>), pending_record_groups=0, num_consumed_records=5), invalid record group metadata
INFO  2024-04-19 04:33:12,838 [shard 0:main] seastore_journal - RecordScanner::scan_valid_records: complete at cursor(last_valid_header_found=1, seq=jseq(sseq(1), paddr<Dev(128),8192>), last_committed=jseq(sseq(0), paddr<Dev(128),24576>), pending_record_groups=0, num_consumed_records=5), invalid record group metadata
INFO  2024-04-19 04:33:12,839 [shard 0:main] seastore_journal - Journal::scan_valid_record_delta: starting at jseq(sseq(0), paddr<Dev(128),8192>) 
INFO  2024-04-19 04:33:12,845 [shard 0:main] seastore_journal - RecordScanner::scan_valid_records: complete at cursor(last_valid_header_found=1, seq=jseq(sseq(0), paddr<Dev(128),28672>), last_committed=jseq(sseq(0), paddr<Dev(128),24576>), pending_record_groups=0, num_consumed_records=5), invalid record group metadata
INFO  2024-04-19 04:33:12,845 [shard 0:main] seastore_journal - RecordScanner::scan_valid_records: complete at cursor(last_valid_header_found=1, seq=jseq(sseq(1), paddr<Dev(128),8192>), last_committed=jseq(sseq(0), paddr<Dev(128),24576>), pending_record_groups=0, num_consumed_records=5), invalid record group metadata
INFO  2024-04-19 04:33:12,845 [shard 0:main] seastore_cleaner - JournalTrimmerImpl::update_journal_tails: journal_dirty_tail JOURNAL_SEQ_NULL => jseq(sseq(0), paddr<Dev(128),8192>), JournalTrimmer(not-ready)
INFO  2024-04-19 04:33:12,845 [shard 0:main] seastore_cleaner - JournalTrimmerImpl::update_journal_tails: journal_alloc_tail JOURNAL_SEQ_NULL => jseq(sseq(0), paddr<Dev(128),8192>), JournalTrimmer(not-ready)
INFO  2024-04-19 04:33:12,847 [shard 0:main] seastore_cleaner - JournalTrimmerImpl::set_journal_head: journal_head JOURNAL_SEQ_NULL => jseq(sseq(0), paddr<Dev(128),28672>), JournalTrimmer(not-ready)
INFO  2024-04-19 04:33:12,849 [shard 0:main] seastore_cache - 0x6170000da200 trans.1 Cache::init_cached_extents: start with 2(4096B) extents, 2 dirty, dirty_from=jseq(sseq(0), paddr<Dev(128),12288>), alloc_from=jseq(sseq(0), paddr<Dev(128),8192>)
INFO  2024-04-19 04:33:12,851 [shard 0:main] seastore_cache - 0x6170000da200 trans.1 Cache::init_cached_extents: finish with 2(4096B) extents, 2 dirty, dirty_from=jseq(sseq(0), paddr<Dev(128),12288>), alloc_from=jseq(sseq(0), paddr<Dev(128),8192>)
INFO  2024-04-19 04:33:12,852 [shard 0:main] seastore_epm - ExtentPlacementManager::open_for_write: started with 1 devices
INFO  2024-04-19 04:33:12,852 [shard 0:main] seastore_epm - BackgroundProcess::start_background: JournalTrimmer(not-ready, journal_head=jseq(sseq(0), paddr<Dev(128),28672>), alloc_tail=jseq(sseq(0), paddr<Dev(128),8192>), dirty_tail=jseq(sseq(0), paddr<Dev(128),8192>)), 
INFO  2024-04-19 04:33:12,853 [shard 0:main] seastore_tm - TransactionManager::mount: completed
INFO  2024-04-19 04:33:12,853 [shard 0:main] test - EphemeralTestState::restart_fut: finish
INFO  2024-04-19 04:33:12,853 [shard 0:main] test - EphemeralTestState::tm_setup: finish

Looks somehow blocked.

Related issues 1 (0 open — 1 closed)

Actions

Copy link

Updated by Yingxin Cheng almost 2 years ago

The pasted log is from https://github.com/ceph/ceph/pull/56998#issuecomment-2065880693

Actions

Copy link

Updated by Yingxin Cheng almost 2 years ago

https://github.com/ceph/ceph/pull/56982

[ RUN      ] seastore_test/seastore_test_t.fiemap_holes/0
...
INFO  2024-04-18 13:13:22,647 [shard 0:main] seastore_cleaner - SegmentCleaner::clean_space: reclaim Seg[Dev(0),12] seg_info_t(state=CLOSED, Seg[Dev(0),12] OOL sseq(9) MD GEN(3), modify_time=tp(NULL), num_extents=0, written_to=8388608) start, usage=0, time_bound=tp(2024-04-18 13:13:19)
INFO  2024-04-18 13:13:22,723 [shard 0:main] seastore_cleaner - SegmentCleaner::clean_space: reclaim Seg[Dev(0),12] finish, reclaimed alive/total=0
INFO  2024-04-18 13:13:22,728 [shard 0:main] seastore_cleaner - segments_info_t::mark_empty: releasing Seg[Dev(0),12], seg_info_t(state=CLOSED, Seg[Dev(0),12] OOL sseq(9) MD GEN(3), modify_time=tp(NULL), num_extents=0, written_to=8388608), num_segments(empty=117, opened=7, closed=4)
INFO  2024-04-18 13:13:22,728 [shard 0:main] seastore_cleaner - SegmentCleaner::clean_space: released Seg[Dev(0),12], SegmentCleaner(should_block_io_on_clean=0, should_clean=1, projected_avail_ratio=0.975834, reclaim_ratio=0.994002, alive_ratio=0.000144958)
INFO  2024-04-18 13:13:22,729 [shard 0:main] seastore_cleaner - SegmentCleaner::clean_space: reclaim Seg[Dev(0),13] seg_info_t(state=CLOSED, Seg[Dev(0),13] OOL sseq(10) MD GEN(4), modify_time=tp(NULL), num_extents=0, written_to=8388608) start, usage=0, time_bound=tp(2024-04-18 13:13:19)
INFO  2024-04-18 13:13:22,801 [shard 0:main] seastore_cleaner - SegmentCleaner::clean_space: reclaim Seg[Dev(0),13] finish, reclaimed alive/total=0
INFO  2024-04-18 13:13:22,808 [shard 0:main] seastore_cleaner - segments_info_t::mark_empty: releasing Seg[Dev(0),13], seg_info_t(state=CLOSED, Seg[Dev(0),13] OOL sseq(10) MD GEN(4), modify_time=tp(NULL), num_extents=0, written_to=8388608), num_segments(empty=118, opened=7, closed=3)
INFO  2024-04-18 13:13:22,808 [shard 0:main] seastore_cleaner - SegmentCleaner::clean_space: released Seg[Dev(0),13], SegmentCleaner(should_block_io_on_clean=0, should_clean=1, projected_avail_ratio=0.983582, reclaim_ratio=0.990474, alive_ratio=0.000156403)
INFO  2024-04-18 13:13:22,809 [shard 0:main] seastore_cleaner - SegmentCleaner::clean_space: reclaim Seg[Dev(0),0] seg_info_t(state=CLOSED, Seg[Dev(0),0] JOURNAL sseq(0) MD GEN_INL, modify_time=tp(2024-04-18 13:13:19), num_extents=2, written_to=8388608) start, usage=0.0009765625, time_bound=tp(2024-04-18 13:13:19)
INFO  2024-04-18 13:13:22,819 [shard 0:main] seastore_cleaner - JournalTrimmerImpl::update_journal_tails: journal_dirty_tail jseq(sseq(1), paddr<Seg[Dev(0),7],8192>) => jseq(sseq(2), paddr<Seg[Dev(0),14],8192>), JournalTrimmer(should_block_io_on_trim=0, should_(trim_dirty=0, trim_alloc=0))
INFO  2024-04-18 13:13:22,870 [shard 0:main] seastore_cleaner - SegmentCleaner::clean_space: reclaim Seg[Dev(0),0] finish, reclaimed alive/total=0.0009765625
INFO  2024-04-18 13:13:22,874 [shard 0:main] seastore_cleaner - segments_info_t::mark_empty: releasing Seg[Dev(0),0], seg_info_t(state=CLOSED, Seg[Dev(0),0] JOURNAL sseq(0) MD GEN_INL, modify_time=tp(2024-04-18 13:13:19), num_extents=2, written_to=8388608), num_segments(empty=119, opened=7, closed=2)
INFO  2024-04-18 13:13:22,874 [shard 0:main] seastore_cleaner - SegmentCleaner::clean_space: released Seg[Dev(0),0], SegmentCleaner(should_block_io_on_clean=0, should_clean=0, projected_avail_ratio=0.991356, reclaim_ratio=0.981906, alive_ratio=0.000156403)

Actions

Copy link

Updated by Yingxin Cheng almost 2 years ago · Edited

https://github.com/ceph/ceph/pull/56979

[ RUN      ] seastore_test/seastore_test_t.sparse_read/0
...
INFO  2024-04-18 10:15:31,147 [shard 0:main] seastore_cleaner - SegmentCleaner::clean_space: released Seg[Dev(0),10], SegmentCleaner(should_block_io_on_clean=0, should_clean=1, projected_avail_ratio=0.960361, reclaim_ratio=0.997113, alive_ratio=0.000114441)
INFO  2024-04-18 10:15:31,148 [shard 0:main] seastore_cleaner - SegmentCleaner::clean_space: reclaim Seg[Dev(0),11] seg_info_t(state=CLOSED, Seg[Dev(0),11] OOL sseq(8) MD GEN_OOL, modify_time=tp(NULL), num_extents=0, written_to=8388608) start, usage=0, time_bound=tp(2024-04-18 10:15:21)
INFO  2024-04-18 10:15:31,569 [shard 0:main] seastore_cleaner - SegmentCleaner::clean_space: reclaim Seg[Dev(0),11] finish, reclaimed alive/total=0
INFO  2024-04-18 10:15:31,573 [shard 0:main] seastore_cleaner - segments_info_t::mark_empty: releasing Seg[Dev(0),11], seg_info_t(state=CLOSED, Seg[Dev(0),11] OOL sseq(8) MD GEN_OOL, modify_time=tp(NULL), num_extents=0, written_to=8388608), num_segments(empty=116, opened=7, closed=5)
INFO  2024-04-18 10:15:31,573 [shard 0:main] seastore_cleaner - SegmentCleaner::clean_space: released Seg[Dev(0),11], SegmentCleaner(should_block_io_on_clean=0, should_clean=1, projected_avail_ratio=0.968109, reclaim_ratio=0.996172, alive_ratio=0.00012207)
INFO  2024-04-18 10:15:31,574 [shard 0:main] seastore_cleaner - SegmentCleaner::clean_space: reclaim Seg[Dev(0),12] seg_info_t(state=CLOSED, Seg[Dev(0),12] OOL sseq(9) MD GEN(3), modify_time=tp(NULL), num_extents=0, written_to=8388608) start, usage=0, time_bound=tp(2024-04-18 10:15:21)
INFO  2024-04-18 10:15:31,942 [shard 0:main] seastore_cleaner - SegmentCleaner::clean_space: reclaim Seg[Dev(0),12] finish, reclaimed alive/total=0
INFO  2024-04-18 10:15:31,970 [shard 0:main] seastore_cleaner - segments_info_t::mark_empty: releasing Seg[Dev(0),12], seg_info_t(state=CLOSED, Seg[Dev(0),12] OOL sseq(9) MD GEN(3), modify_time=tp(NULL), num_extents=0, written_to=8388608), num_segments(empty=117, opened=7, closed=4)
INFO  2024-04-18 10:15:31,971 [shard 0:main] seastore_cleaner - SegmentCleaner::clean_space: released Seg[Dev(0),12], SegmentCleaner(should_block_io_on_clean=0, should_clean=1, projected_avail_ratio=0.975857, reclaim_ratio=0.994469, alive_ratio=0.000133514)
INFO  2024-04-18 10:15:31,971 [shard 0:main] seastore_cleaner - SegmentCleaner::clean_space: reclaim Seg[Dev(0),13] seg_info_t(state=CLOSED, Seg[Dev(0),13] OOL sseq(10) MD GEN(4), modify_time=tp(NULL), num_extents=0, written_to=8388608) start, usage=0, time_bound=tp(2024-04-18 10:15:21)
INFO  2024-04-18 10:15:32,374 [shard 0:main] seastore_cleaner - SegmentCleaner::clean_space: reclaim Seg[Dev(0),13] finish, reclaimed alive/total=0
INFO  2024-04-18 10:15:32,379 [shard 0:main] seastore_cleaner - segments_info_t::mark_empty: releasing Seg[Dev(0),13], seg_info_t(state=CLOSED, Seg[Dev(0),13] OOL sseq(10) MD GEN(4), modify_time=tp(NULL), num_extents=0, written_to=8388608), num_segments(empty=118, opened=7, closed=3)
INFO  2024-04-18 10:15:32,380 [shard 0:main] seastore_cleaner - SegmentCleaner::clean_space: released Seg[Dev(0),13], SegmentCleaner(should_block_io_on_clean=0, should_clean=1, projected_avail_ratio=0.983616, reclaim_ratio=0.991153, alive_ratio=0.000144958)
INFO  2024-04-18 10:15:32,380 [shard 0:main] seastore_cleaner - SegmentCleaner::clean_space: reclaim Seg[Dev(0),0] seg_info_t(state=CLOSED, Seg[Dev(0),0] JOURNAL sseq(0) MD GEN_INL, modify_time=tp(2024-04-18 10:15:21), num_extents=2, written_to=8388608) start, usage=0.0009765625, time_bound=tp(2024-04-18 10:15:21)
INFO  2024-04-18 10:15:32,482 [shard 0:main] seastore_cleaner - JournalTrimmerImpl::update_journal_tails: journal_dirty_tail jseq(sseq(1), paddr<Seg[Dev(0),7],8192>) => jseq(sseq(2), paddr<Seg[Dev(0),14],8192>), JournalTrimmer(should_block_io_on_trim=0, should_(trim_dirty=0, trim_alloc=0))
INFO  2024-04-18 10:15:32,753 [shard 0:main] seastore_cleaner - SegmentCleaner::clean_space: reclaim Seg[Dev(0),0] finish, reclaimed alive/total=0.0009765625
INFO  2024-04-18 10:15:32,789 [shard 0:main] seastore_cleaner - segments_info_t::mark_empty: releasing Seg[Dev(0),0], seg_info_t(state=CLOSED, Seg[Dev(0),0] JOURNAL sseq(0) MD GEN_INL, modify_time=tp(2024-04-18 10:15:21), num_extents=2, written_to=8388608), num_segments(empty=119, opened=7, closed=2)
INFO  2024-04-18 10:15:32,789 [shard 0:main] seastore_cleaner - SegmentCleaner::clean_space: released Seg[Dev(0),0], SegmentCleaner(should_block_io_on_clean=0, should_clean=0, projected_avail_ratio=0.99139, reclaim_ratio=0.983163, alive_ratio=0.000144958)

Actions

Copy link

Updated by Matan Breizman almost 2 years ago

Category set to Seastore

Actions

Copy link

Updated by Yingxin Cheng almost 2 years ago

Related to Bug #65628: unittest-seastore (Timeout) added

Actions

Copy link

Updated by Yingxin Cheng almost 2 years ago

https://jenkins.ceph.com/job/ceph-pull-requests-arm64/55512/console

[ RUN      ] seastore_test/seastore_test_t.object_data_omap_remove/1
...
INFO  2024-04-22 16:47:30,107 [shard 0:main] test - EphemeralTestState::restart_fut: finish
INFO  2024-04-22 16:47:30,107 [shard 0:main] test - EphemeralTestState::tm_setup: finish

Seems like there are 2 distinct patterns of timeout, probably imply that there are 2 different issues.

Actions

Copy link

Updated by Rongqi Sun almost 2 years ago

If each test's execution time was correct, timeout is caused by "stuck in one of tests".

e.g. https://jenkins.ceph.com/job/ceph-pull-requests/133763/consoleFull

38 tests from 1 test suite

seastore_test/seastore_test_t.fiemap_holes/0 is the 33rd test

total time 32 tests spent is 184672ms, which much shorter than 7200s (set(CEPH_TEST_TIMEOUT 7200 CACHE STRING "Maximum time before a CTest gets killed" ))

Actions

Copy link

Updated by Yingxin Cheng almost 2 years ago

Seem to me the blocking issue of test-seastore reveals a deadlock from background cleaning -- the IO transaction didn't proceed after a conflict. But I'm not able to root cause it yet, because adding more logs seem to make it unreproducible.

From https://github.com/ceph/ceph/pull/57128

Actions

Copy link

Updated by Xuehan Xu almost 2 years ago

Yingxin Cheng wrote in #note-8:

Seem to me the blocking issue of test-seastore reveals a deadlock from background cleaning -- the IO transaction didn't proceed after a conflict. But I'm not able to root cause it yet, because adding more logs seem to make it unreproducible.

From https://github.com/ceph/ceph/pull/57128

I also met this issue and the last commit in https://github.com/ceph/ceph/pull/57069 should be able to fix it. I'll split it into a dedicated PR.

Actions

Copy link

#10

Updated by Xuehan Xu almost 2 years ago

Xuehan Xu wrote in #note-9:

Yingxin Cheng wrote in #note-8:

Seem to me the blocking issue of test-seastore reveals a deadlock from background cleaning -- the IO transaction didn't proceed after a conflict. But I'm not able to root cause it yet, because adding more logs seem to make it unreproducible.

From https://github.com/ceph/ceph/pull/57128

I also met this issue and the last commit in https://github.com/ceph/ceph/pull/57069 should be able to fix it. I'll split it into a dedicated PR.

https://github.com/ceph/ceph/pull/57129

Actions

Copy link

#11

Updated by Yingxin Cheng almost 2 years ago

Status changed from New to Resolved

Actions

Copy link

#12

Updated by Casey Bodley almost 2 years ago

i spotted unittest-seastore (Timeout) again during [ RUN ] seastore_test/seastore_test_t.sparse_read/0 in https://jenkins.ceph.com/job/ceph-pull-requests/134781/

would you like me to create a separate tracker issue, or should we reopen this one?

Actions

Copy link

#13

Updated by Yingxin Cheng almost 2 years ago

Status changed from Resolved to Need More Info

Hi Casey! Can you paste the log snippet like above, the link can become invalid soon.

Seems to me the issue doesn't appear in the make check after the fix (or not as frequent as before, at least).

Actions

Copy link

Also available in: Atom PDF

Project

General

Profile

Ceph » crimson

Tags

Custom queries

Bug #65585

unittest-seastore (Timeout)

Updated by Yingxin Cheng almost 2 years ago

Updated by Yingxin Cheng almost 2 years ago

Updated by Yingxin Cheng almost 2 years ago · Edited

Updated by Matan Breizman almost 2 years ago

Updated by Yingxin Cheng almost 2 years ago

Updated by Yingxin Cheng almost 2 years ago

Updated by Rongqi Sun almost 2 years ago

Updated by Yingxin Cheng almost 2 years ago

Updated by Xuehan Xu almost 2 years ago

Updated by Xuehan Xu almost 2 years ago

Updated by Yingxin Cheng almost 2 years ago

Updated by Casey Bodley almost 2 years ago

Updated by Yingxin Cheng almost 2 years ago