From 9ba243b3ee3ba46bf41f2d5d16581925ef691d42 Mon Sep 17 00:00:00 2001 From: Vitaliy Filippov Date: Wed, 27 Nov 2019 18:07:08 +0300 Subject: [PATCH] Add debug prints --- blockstore.h | 2 ++ blockstore_flush.cpp | 20 ++++++++++++++++++++ blockstore_stable.cpp | 3 +++ blockstore_sync.cpp | 9 +++++++++ blockstore_write.cpp | 9 +++++++++ fio_engine.cpp | 22 ++++++++++++---------- 6 files changed, 55 insertions(+), 10 deletions(-) diff --git a/blockstore.h b/blockstore.h index 9cf707c00..770773efd 100644 --- a/blockstore.h +++ b/blockstore.h @@ -25,6 +25,8 @@ #include "allocator.h" #include "ringloop.h" +//#define BLOCKSTORE_DEBUG + // States are not stored on disk. Instead, they're deduced from the journal #define ST_IN_FLIGHT 1 diff --git a/blockstore_flush.cpp b/blockstore_flush.cpp index 318bcd018..1c5bb5f2e 100644 --- a/blockstore_flush.cpp +++ b/blockstore_flush.cpp @@ -141,6 +141,9 @@ resume_0: repeat_it = flusher->sync_to_repeat.find(cur.oid); if (repeat_it != flusher->sync_to_repeat.end()) { +#ifdef BLOCKSTORE_DEBUG + printf("Postpone %lu:%lu v%lu\n", cur.oid.inode, cur.oid.stripe, cur.version); +#endif // We don't flush different parts of history of the same object in parallel // So we check if someone is already flushing this object // In that case we set sync_to_repeat and pick another object @@ -152,6 +155,9 @@ resume_0: } else flusher->sync_to_repeat[cur.oid] = 0; +#ifdef BLOCKSTORE_DEBUG + printf("Flushing %lu:%lu v%lu\n", cur.oid.inode, cur.oid.stripe, cur.version); +#endif dirty_it = dirty_end; flusher->active_flushers++; flusher->active_until_sync++; @@ -406,6 +412,9 @@ resume_0: { bs->data_alloc->set(dirty_it->second.location >> bs->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 = --bs->journal.used_sectors[dirty_it->second.journal_sector]; if (used == 0) { @@ -430,6 +439,11 @@ resume_0: { flusher->journal_trim_counter = 0; journal_used_it = bs->journal.used_sectors.lower_bound(bs->journal.used_start); +#ifdef BLOCKSTORE_DEBUG + printf("Trimming journal (used_start=%lu, next_free=%lu, first_used=%lu, usage_count=%lu)\n", bs->journal.used_start, bs->journal.next_free, + journal_used_it == bs->journal.used_sectors.end() ? 0 : journal_used_it->first, + journal_used_it == bs->journal.used_sectors.end() ? 0 : journal_used_it->second); +#endif if (journal_used_it == bs->journal.used_sectors.end()) { // Journal is cleared to its end, restart from the beginning @@ -455,6 +469,9 @@ resume_0: // Can't trim journal goto do_not_trim; } +#ifdef BLOCKSTORE_DEBUG + printf("Journal trimmed to %lu (next_free=%lu)\n", bs->journal.used_start, bs->journal.next_free); +#endif // Update journal "superblock" await_sqe(12); data->callback = simple_callback; @@ -479,6 +496,9 @@ resume_0: } do_not_trim: // All done +#ifdef BLOCKSTORE_DEBUG + printf("Flushed %lu:%lu v%lu\n", cur.oid.inode, cur.oid.stripe, cur.version); +#endif wait_state = 0; flusher->active_flushers--; repeat_it = flusher->sync_to_repeat.find(cur.oid); diff --git a/blockstore_stable.cpp b/blockstore_stable.cpp index e6be1f70d..deb765e5d 100644 --- a/blockstore_stable.cpp +++ b/blockstore_stable.cpp @@ -168,6 +168,9 @@ void blockstore::handle_stable_event(ring_data_t *data, blockstore_operation *op break; } } +#ifdef BLOCKSTORE_DEBUG + printf("enqueue_flush %lu:%lu v%lu\n", v->oid.inode, v->oid.stripe, v->version); +#endif flusher->queue_flush(*v); } } diff --git a/blockstore_sync.cpp b/blockstore_sync.cpp index 44edff5f3..4dd99d970 100644 --- a/blockstore_sync.cpp +++ b/blockstore_sync.cpp @@ -84,6 +84,9 @@ int blockstore::continue_sync(blockstore_operation *op) prefill_single_journal_entry(journal, JE_BIG_WRITE, sizeof(journal_entry_big_write)); dirty_db[*it].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_db[*it].journal_sector, it->oid.inode, it->oid.stripe, it->version); +#endif je->oid = it->oid; je->version = it->version; je->location = dirty_db[*it].location; @@ -189,12 +192,18 @@ void blockstore::ack_one_sync(blockstore_operation *op) // Handle states for (auto it = op->sync_big_writes.begin(); it != op->sync_big_writes.end(); it++) { +#ifdef BLOCKSTORE_DEBUG + printf("Ack sync big %lu:%lu v%lu\n", it->oid.inode, it->oid.stripe, it->version); +#endif auto & unstab = unstable_writes[it->oid]; unstab = unstab < it->version ? it->version : unstab; dirty_db[*it].state = ST_D_META_SYNCED; } for (auto it = op->sync_small_writes.begin(); it != op->sync_small_writes.end(); it++) { +#ifdef BLOCKSTORE_DEBUG + printf("Ack sync small %lu:%lu v%lu\n", it->oid.inode, it->oid.stripe, it->version); +#endif auto & unstab = unstable_writes[it->oid]; unstab = unstab < it->version ? it->version : unstab; dirty_db[*it].state = ST_J_SYNCED; diff --git a/blockstore_write.cpp b/blockstore_write.cpp index 2e6ef284c..1467492bb 100644 --- a/blockstore_write.cpp +++ b/blockstore_write.cpp @@ -30,6 +30,9 @@ void blockstore::enqueue_write(blockstore_operation *op) } } // Immediately add the operation into dirty_db, so subsequent reads could see it +#ifdef BLOCKSTORE_DEBUG + printf("Write %lu:%lu v%lu\n", op->oid.inode, op->oid.stripe, op->version); +#endif dirty_db.emplace((obj_ver_id){ .oid = op->oid, .version = op->version, @@ -119,6 +122,9 @@ int blockstore::dequeue_write(blockstore_operation *op) prefill_single_journal_entry(journal, JE_SMALL_WRITE, sizeof(struct journal_entry_small_write)); 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); +#endif // Figure out where data will be journal.next_free = (journal.next_free + op->len) < journal.len ? journal.next_free : 512; je->oid = op->oid; @@ -181,6 +187,9 @@ void blockstore::handle_write_event(ring_data_t *data, blockstore_operation *op) .oid = op->oid, .version = op->version, }]; +#ifdef BLOCKSTORE_DEBUG + printf("Ack write %lu:%lu v%lu = %d\n", op->oid.inode, op->oid.stripe, op->version, dirty_entry.state); +#endif if (dirty_entry.state == ST_J_SUBMITTED) { dirty_entry.state = ST_J_WRITTEN; diff --git a/fio_engine.cpp b/fio_engine.cpp index f7cd70951..5cd5a23dc 100644 --- a/fio_engine.cpp +++ b/fio_engine.cpp @@ -8,8 +8,6 @@ extern "C" { #include "fio/optgroup.h" } -static const int DEBUG = 0; - struct bs_data { blockstore *bs; @@ -154,8 +152,9 @@ static enum fio_q_status bs_queue(struct thread_data *td, struct io_u *io) bs_data *bsd = (bs_data*)io->engine_data; bsd->inflight--; bsd->completed.push_back(io); - if (DEBUG) - printf("--- OP_WRITE %llx n=%d retval=%d\n", io, n, op->retval); +#ifdef BLOCKSTORE_DEBUG + printf("--- OP_WRITE %llx n=%d retval=%d\n", io, n, op->retval); +#endif delete op; }; break; @@ -187,8 +186,9 @@ static enum fio_q_status bs_queue(struct thread_data *td, struct io_u *io) bsd->inflight--; obj_ver_id *vers = (obj_ver_id*)op->buf; delete[] vers; - if (DEBUG) - printf("--- OP_SYNC %llx n=%d retval=%d\n", io, n, op->retval); +#ifdef BLOCKSTORE_DEBUG + printf("--- OP_SYNC %llx n=%d retval=%d\n", io, n, op->retval); +#endif delete op; }; bsd->bs->enqueue_op(op); @@ -198,8 +198,9 @@ static enum fio_q_status bs_queue(struct thread_data *td, struct io_u *io) io->error = op->retval < 0 ? -op->retval : 0; bsd->completed.push_back(io); bsd->inflight--; - if (DEBUG) - printf("--- OP_SYNC %llx n=%d retval=%d\n", io, n, op->retval); +#ifdef BLOCKSTORE_DEBUG + printf("--- OP_SYNC %llx n=%d retval=%d\n", io, n, op->retval); +#endif delete op; } }; @@ -209,8 +210,9 @@ static enum fio_q_status bs_queue(struct thread_data *td, struct io_u *io) return FIO_Q_COMPLETED; } - if (DEBUG) - printf("+++ %s %llx\n", op->flags == OP_WRITE ? "OP_WRITE" : "OP_SYNC", io); +#ifdef BLOCKSTORE_DEBUG + printf("+++ %s %llx\n", op->flags == OP_WRITE ? "OP_WRITE" : "OP_SYNC", io); +#endif io->error = 0; bsd->inflight++; bsd->bs->enqueue_op(op);