Add debug prints

blocking-uring-test
Vitaliy Filippov 2019-11-27 18:07:08 +03:00
parent e2b91968c5
commit 9ba243b3ee
6 changed files with 55 additions and 10 deletions

View File

@ -25,6 +25,8 @@
#include "allocator.h" #include "allocator.h"
#include "ringloop.h" #include "ringloop.h"
//#define BLOCKSTORE_DEBUG
// States are not stored on disk. Instead, they're deduced from the journal // States are not stored on disk. Instead, they're deduced from the journal
#define ST_IN_FLIGHT 1 #define ST_IN_FLIGHT 1

View File

@ -141,6 +141,9 @@ resume_0:
repeat_it = flusher->sync_to_repeat.find(cur.oid); repeat_it = flusher->sync_to_repeat.find(cur.oid);
if (repeat_it != flusher->sync_to_repeat.end()) 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 // We don't flush different parts of history of the same object in parallel
// So we check if someone is already flushing this object // So we check if someone is already flushing this object
// In that case we set sync_to_repeat and pick another object // In that case we set sync_to_repeat and pick another object
@ -152,6 +155,9 @@ resume_0:
} }
else else
flusher->sync_to_repeat[cur.oid] = 0; 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; dirty_it = dirty_end;
flusher->active_flushers++; flusher->active_flushers++;
flusher->active_until_sync++; flusher->active_until_sync++;
@ -406,6 +412,9 @@ resume_0:
{ {
bs->data_alloc->set(dirty_it->second.location >> bs->block_order, false); 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]; int used = --bs->journal.used_sectors[dirty_it->second.journal_sector];
if (used == 0) if (used == 0)
{ {
@ -430,6 +439,11 @@ resume_0:
{ {
flusher->journal_trim_counter = 0; flusher->journal_trim_counter = 0;
journal_used_it = bs->journal.used_sectors.lower_bound(bs->journal.used_start); 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()) if (journal_used_it == bs->journal.used_sectors.end())
{ {
// Journal is cleared to its end, restart from the beginning // Journal is cleared to its end, restart from the beginning
@ -455,6 +469,9 @@ resume_0:
// Can't trim journal // Can't trim journal
goto do_not_trim; 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" // Update journal "superblock"
await_sqe(12); await_sqe(12);
data->callback = simple_callback; data->callback = simple_callback;
@ -479,6 +496,9 @@ resume_0:
} }
do_not_trim: do_not_trim:
// All done // All done
#ifdef BLOCKSTORE_DEBUG
printf("Flushed %lu:%lu v%lu\n", cur.oid.inode, cur.oid.stripe, cur.version);
#endif
wait_state = 0; wait_state = 0;
flusher->active_flushers--; flusher->active_flushers--;
repeat_it = flusher->sync_to_repeat.find(cur.oid); repeat_it = flusher->sync_to_repeat.find(cur.oid);

View File

@ -168,6 +168,9 @@ void blockstore::handle_stable_event(ring_data_t *data, blockstore_operation *op
break; 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); flusher->queue_flush(*v);
} }
} }

View File

@ -84,6 +84,9 @@ int blockstore::continue_sync(blockstore_operation *op)
prefill_single_journal_entry(journal, JE_BIG_WRITE, sizeof(journal_entry_big_write)); 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; dirty_db[*it].journal_sector = journal.sector_info[journal.cur_sector].offset;
journal.used_sectors[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->oid = it->oid;
je->version = it->version; je->version = it->version;
je->location = dirty_db[*it].location; je->location = dirty_db[*it].location;
@ -189,12 +192,18 @@ void blockstore::ack_one_sync(blockstore_operation *op)
// Handle states // Handle states
for (auto it = op->sync_big_writes.begin(); it != op->sync_big_writes.end(); it++) 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]; auto & unstab = unstable_writes[it->oid];
unstab = unstab < it->version ? it->version : unstab; unstab = unstab < it->version ? it->version : unstab;
dirty_db[*it].state = ST_D_META_SYNCED; dirty_db[*it].state = ST_D_META_SYNCED;
} }
for (auto it = op->sync_small_writes.begin(); it != op->sync_small_writes.end(); it++) 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]; auto & unstab = unstable_writes[it->oid];
unstab = unstab < it->version ? it->version : unstab; unstab = unstab < it->version ? it->version : unstab;
dirty_db[*it].state = ST_J_SYNCED; dirty_db[*it].state = ST_J_SYNCED;

View File

@ -30,6 +30,9 @@ void blockstore::enqueue_write(blockstore_operation *op)
} }
} }
// Immediately add the operation into dirty_db, so subsequent reads could see it // 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){ dirty_db.emplace((obj_ver_id){
.oid = op->oid, .oid = op->oid,
.version = op->version, .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)); 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; dirty_it->second.journal_sector = journal.sector_info[journal.cur_sector].offset;
journal.used_sectors[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 // Figure out where data will be
journal.next_free = (journal.next_free + op->len) < journal.len ? journal.next_free : 512; journal.next_free = (journal.next_free + op->len) < journal.len ? journal.next_free : 512;
je->oid = op->oid; je->oid = op->oid;
@ -181,6 +187,9 @@ void blockstore::handle_write_event(ring_data_t *data, blockstore_operation *op)
.oid = op->oid, .oid = op->oid,
.version = op->version, .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) if (dirty_entry.state == ST_J_SUBMITTED)
{ {
dirty_entry.state = ST_J_WRITTEN; dirty_entry.state = ST_J_WRITTEN;

View File

@ -8,8 +8,6 @@ extern "C" {
#include "fio/optgroup.h" #include "fio/optgroup.h"
} }
static const int DEBUG = 0;
struct bs_data struct bs_data
{ {
blockstore *bs; 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; bs_data *bsd = (bs_data*)io->engine_data;
bsd->inflight--; bsd->inflight--;
bsd->completed.push_back(io); bsd->completed.push_back(io);
if (DEBUG) #ifdef BLOCKSTORE_DEBUG
printf("--- OP_WRITE %llx n=%d retval=%d\n", io, n, op->retval); printf("--- OP_WRITE %llx n=%d retval=%d\n", io, n, op->retval);
#endif
delete op; delete op;
}; };
break; break;
@ -187,8 +186,9 @@ static enum fio_q_status bs_queue(struct thread_data *td, struct io_u *io)
bsd->inflight--; bsd->inflight--;
obj_ver_id *vers = (obj_ver_id*)op->buf; obj_ver_id *vers = (obj_ver_id*)op->buf;
delete[] vers; delete[] vers;
if (DEBUG) #ifdef BLOCKSTORE_DEBUG
printf("--- OP_SYNC %llx n=%d retval=%d\n", io, n, op->retval); printf("--- OP_SYNC %llx n=%d retval=%d\n", io, n, op->retval);
#endif
delete op; delete op;
}; };
bsd->bs->enqueue_op(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; io->error = op->retval < 0 ? -op->retval : 0;
bsd->completed.push_back(io); bsd->completed.push_back(io);
bsd->inflight--; bsd->inflight--;
if (DEBUG) #ifdef BLOCKSTORE_DEBUG
printf("--- OP_SYNC %llx n=%d retval=%d\n", io, n, op->retval); printf("--- OP_SYNC %llx n=%d retval=%d\n", io, n, op->retval);
#endif
delete op; 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; return FIO_Q_COMPLETED;
} }
if (DEBUG) #ifdef BLOCKSTORE_DEBUG
printf("+++ %s %llx\n", op->flags == OP_WRITE ? "OP_WRITE" : "OP_SYNC", io); printf("+++ %s %llx\n", op->flags == OP_WRITE ? "OP_WRITE" : "OP_SYNC", io);
#endif
io->error = 0; io->error = 0;
bsd->inflight++; bsd->inflight++;
bsd->bs->enqueue_op(op); bsd->bs->enqueue_op(op);