From c22e096943415c39851aa6b622832bf83c24677b Mon Sep 17 00:00:00 2001 From: Vitaliy Filippov Date: Mon, 1 Jun 2020 01:55:54 +0300 Subject: [PATCH] Output journal offsets in debug trace in hex, add detailed "still waiting" messages --- blockstore_flush.cpp | 5 ++++- blockstore_impl.cpp | 18 ++++++++++++------ blockstore_init.cpp | 9 ++++++--- blockstore_journal.cpp | 4 ++-- blockstore_rollback.cpp | 10 ++++++---- blockstore_sync.cpp | 6 +++++- blockstore_write.cpp | 18 +++++++++++++++--- 7 files changed, 50 insertions(+), 20 deletions(-) diff --git a/blockstore_flush.cpp b/blockstore_flush.cpp index bbf77396..ea8ec885 100644 --- a/blockstore_flush.cpp +++ b/blockstore_flush.cpp @@ -182,6 +182,9 @@ resume_0: dirty_end->second.journal_sector < bs->journal.used_start)) { // We can't flush journal sectors that are still written to +#ifdef BLOCKSTORE_DEBUG + printf("Flusher overran writers - stopping\n"); +#endif flusher->enqueue_flush(cur); flusher->dequeuing = false; wait_state = 0; @@ -436,7 +439,7 @@ resume_1: } // All done #ifdef BLOCKSTORE_DEBUG - printf("Flushed %lu:%lu v%lu\n", cur.oid.inode, cur.oid.stripe, cur.version); + printf("Flushed %lu:%lu v%lu (%ld left)\n", cur.oid.inode, cur.oid.stripe, cur.version, flusher->flush_queue.size()); #endif flusher->active_flushers--; repeat_it = flusher->sync_to_repeat.find(cur.oid); diff --git a/blockstore_impl.cpp b/blockstore_impl.cpp index ba632595..bff05d94 100644 --- a/blockstore_impl.cpp +++ b/blockstore_impl.cpp @@ -124,12 +124,6 @@ void blockstore_impl_t::loop() if (PRIV(op)->wait_for) { check_wait(op); -#ifdef BLOCKSTORE_DEBUG - if (PRIV(op)->wait_for) - { - printf("still waiting for %d\n", PRIV(op)->wait_for); - } -#endif if (PRIV(op)->wait_for == WAIT_SQE) { break; @@ -271,6 +265,9 @@ void blockstore_impl_t::check_wait(blockstore_op_t *op) if (ringloop->space_left() < PRIV(op)->wait_detail) { // stop submission if there's still no free space +#ifdef BLOCKSTORE_DEBUG + printf("Still waiting for %lu SQE(s)\n", PRIV(op)->wait_detail); +#endif return; } PRIV(op)->wait_for = 0; @@ -280,6 +277,9 @@ void blockstore_impl_t::check_wait(blockstore_op_t *op) if (journal.used_start == PRIV(op)->wait_detail) { // do not submit +#ifdef BLOCKSTORE_DEBUG + printf("Still waiting to flush journal offset %08lx\n", PRIV(op)->wait_detail); +#endif return; } PRIV(op)->wait_for = 0; @@ -291,6 +291,9 @@ void blockstore_impl_t::check_wait(blockstore_op_t *op) journal.sector_info[next].dirty) { // do not submit +#ifdef BLOCKSTORE_DEBUG + printf("Still waiting for a journal buffer\n"); +#endif return; } PRIV(op)->wait_for = 0; @@ -299,6 +302,9 @@ void blockstore_impl_t::check_wait(blockstore_op_t *op) { if (!data_alloc->get_free_count() && !flusher->is_active()) { +#ifdef BLOCKSTORE_DEBUG + printf("Still waiting for free space on the data device\n"); +#endif return; } PRIV(op)->wait_for = 0; diff --git a/blockstore_init.cpp b/blockstore_init.cpp index 6425674e..50afd339 100644 --- a/blockstore_init.cpp +++ b/blockstore_init.cpp @@ -404,7 +404,7 @@ resume_1: bs->journal.trim(); bs->journal.dirty_start = bs->journal.next_free; printf( - "Journal entries loaded: %lu, free journal space: %lu bytes (%lu..%lu is used), free blocks: %lu / %lu\n", + "Journal entries loaded: %lu, free journal space: %lu bytes (%08lx..%08lx is used), free blocks: %lu / %lu\n", entries_loaded, (bs->journal.next_free >= bs->journal.used_start ? bs->journal.len-bs->journal.block_size - (bs->journal.next_free-bs->journal.used_start) @@ -475,7 +475,7 @@ int blockstore_init_journal::handle_journal_part(void *buf, uint64_t done_pos, u if (location != je->small_write.data_offset) { char err[1024]; - snprintf(err, 1024, "BUG: calculated journal data offset (%lu) != stored journal data offset (%lu)", location, je->small_write.data_offset); + snprintf(err, 1024, "BUG: calculated journal data offset (%08lx) != stored journal data offset (%08lx)", location, je->small_write.data_offset); throw std::runtime_error(err); } uint32_t data_crc32 = 0; @@ -537,7 +537,10 @@ int blockstore_init_journal::handle_journal_part(void *buf, uint64_t done_pos, u }); bs->journal.used_sectors[proc_pos]++; #ifdef BLOCKSTORE_DEBUG - printf("journal offset %lu is used by %lu:%lu v%lu\n", proc_pos, ov.oid.inode, ov.oid.stripe, ov.version); + printf( + "journal offset %08lx is used by %lu:%lu v%lu (%lu refs)\n", + proc_pos, ov.oid.inode, ov.oid.stripe, ov.version, bs->journal.used_sectors[proc_pos] + ); #endif auto & unstab = bs->unstable_writes[ov.oid]; unstab = unstab < ov.version ? ov.version : unstab; diff --git a/blockstore_journal.cpp b/blockstore_journal.cpp index 21e70f50..feab013c 100644 --- a/blockstore_journal.cpp +++ b/blockstore_journal.cpp @@ -180,8 +180,8 @@ bool journal_t::trim() auto journal_used_it = used_sectors.lower_bound(used_start); #ifdef BLOCKSTORE_DEBUG printf( - "Trimming journal (used_start=%08lx, next_free=%08lx, first_used=%08lx, usage_count=%08lx)\n", - used_start, next_free, + "Trimming journal (used_start=%08lx, next_free=%08lx, dirty_start=%08lx, new_start=%08lx, new_refcount=%ld)\n", + used_start, next_free, dirty_start, journal_used_it == used_sectors.end() ? 0 : journal_used_it->first, journal_used_it == used_sectors.end() ? 0 : journal_used_it->second ); diff --git a/blockstore_rollback.cpp b/blockstore_rollback.cpp index 1b502b10..3da1fa61 100644 --- a/blockstore_rollback.cpp +++ b/blockstore_rollback.cpp @@ -225,11 +225,13 @@ void blockstore_impl_t::erase_dirty(blockstore_dirty_db_t::iterator dirty_start, #endif data_alloc->set(dirty_it->second.location >> block_order, false); } -#ifdef BLOCKSTORE_DEBUG - printf("remove usage of journal offset %lu by %lu:%lu v%lu\n", dirty_it->second.journal_sector, - dirty_it->first.oid.inode, dirty_it->first.oid.stripe, dirty_it->first.version); -#endif int used = --journal.used_sectors[dirty_it->second.journal_sector]; +#ifdef BLOCKSTORE_DEBUG + printf( + "remove usage of journal offset %08lx by %lu:%lu v%lu (%d refs)\n", dirty_it->second.journal_sector, + dirty_it->first.oid.inode, dirty_it->first.oid.stripe, dirty_it->first.version, used + ); +#endif if (used == 0) { journal.used_sectors.erase(dirty_it->second.journal_sector); diff --git a/blockstore_sync.cpp b/blockstore_sync.cpp index 905c6304..3f3899de 100644 --- a/blockstore_sync.cpp +++ b/blockstore_sync.cpp @@ -133,7 +133,11 @@ int blockstore_impl_t::continue_sync(blockstore_op_t *op) journal.sector_info[journal.cur_sector].dirty = false; journal.used_sectors[journal.sector_info[journal.cur_sector].offset]++; #ifdef BLOCKSTORE_DEBUG - printf("journal offset %lu is used by %lu:%lu v%lu\n", dirty_db[*it].journal_sector, it->oid.inode, it->oid.stripe, it->version); + printf( + "journal offset %08lx is used by %lu:%lu v%lu (%lu refs)\n", + dirty_db[*it].journal_sector, it->oid.inode, it->oid.stripe, it->version, + journal.used_sectors[journal.sector_info[journal.cur_sector].offset] + ); #endif je->oid = it->oid; je->version = it->version; diff --git a/blockstore_write.cpp b/blockstore_write.cpp index 932bed4a..0b085184 100644 --- a/blockstore_write.cpp +++ b/blockstore_write.cpp @@ -213,7 +213,11 @@ int blockstore_impl_t::dequeue_write(blockstore_op_t *op) dirty_it->second.journal_sector = journal.sector_info[journal.cur_sector].offset; journal.used_sectors[journal.sector_info[journal.cur_sector].offset]++; #ifdef BLOCKSTORE_DEBUG - printf("journal offset %lu is used by %lu:%lu v%lu\n", dirty_it->second.journal_sector, dirty_it->first.oid.inode, dirty_it->first.oid.stripe, dirty_it->first.version); + printf( + "journal offset %08lx is used by %lu:%lu v%lu (%lu refs)\n", + dirty_it->second.journal_sector, dirty_it->first.oid.inode, dirty_it->first.oid.stripe, dirty_it->first.version, + journal.used_sectors[journal.sector_info[journal.cur_sector].offset] + ); #endif // Figure out where data will be journal.next_free = (journal.next_free + op->len) <= journal.len ? journal.next_free : journal_block_size; @@ -306,7 +310,11 @@ resume_2: journal.sector_info[journal.cur_sector].dirty = false; journal.used_sectors[journal.sector_info[journal.cur_sector].offset]++; #ifdef BLOCKSTORE_DEBUG - printf("journal offset %lu is used by %lu:%lu v%lu\n", journal.sector_info[journal.cur_sector].offset, op->oid.inode, op->oid.stripe, op->version); + printf( + "journal offset %08lx is used by %lu:%lu v%lu (%lu refs)\n", + journal.sector_info[journal.cur_sector].offset, op->oid.inode, op->oid.stripe, op->version, + journal.used_sectors[journal.sector_info[journal.cur_sector].offset] + ); #endif je->oid = op->oid; je->version = op->version; @@ -457,7 +465,11 @@ int blockstore_impl_t::dequeue_del(blockstore_op_t *op) dirty_it->second.journal_sector = journal.sector_info[journal.cur_sector].offset; journal.used_sectors[journal.sector_info[journal.cur_sector].offset]++; #ifdef BLOCKSTORE_DEBUG - printf("journal offset %lu is used by %lu:%lu v%lu\n", dirty_it->second.journal_sector, dirty_it->first.oid.inode, dirty_it->first.oid.stripe, dirty_it->first.version); + printf( + "journal offset %08lx is used by %lu:%lu v%lu (%lu refs)\n", + dirty_it->second.journal_sector, dirty_it->first.oid.inode, dirty_it->first.oid.stripe, dirty_it->first.version, + journal.used_sectors[journal.sector_info[journal.cur_sector].offset] + ); #endif je->oid = op->oid; je->version = op->version;