From 6657b996a7368bbd0c6e45728f3450be3921c782 Mon Sep 17 00:00:00 2001 From: Anthony Astolfi Date: Mon, 29 Jul 2024 15:10:37 -0400 Subject: [PATCH] Add more metrics to IoRingLogDevice2 and verify them in the sim test. --- src/llfs/ioring_log_device2.ipp | 4 ++ src/llfs/ioring_log_device2.test.cpp | 81 +++++++++++++++++++++++-- src/llfs/ioring_log_device2_metrics.cpp | 40 ++++++++---- src/llfs/ioring_log_device2_metrics.hpp | 15 +++++ 4 files changed, 123 insertions(+), 17 deletions(-) diff --git a/src/llfs/ioring_log_device2.ipp b/src/llfs/ioring_log_device2.ipp index 0a2ea46..39a0ede 100644 --- a/src/llfs/ioring_log_device2.ipp +++ b/src/llfs/ioring_log_device2.ipp @@ -380,6 +380,7 @@ inline void IoRingLogDriver2::start_flush(const CommitPos observed_com << BATT_INSPECT(physical_lower_bound) << BATT_INSPECT(physical_upper_bound); slot_range.upper_bound = new_upper_bound; + this->metrics_.flush_write_split_wrap_count.add(1); } } @@ -411,6 +412,8 @@ inline void IoRingLogDriver2::start_flush(const CommitPos observed_com if (this->flush_tail_ && slot_less_than(aligned_range.lower_bound, this->flush_tail_->upper_bound)) { aligned_range.lower_bound = this->flush_tail_->upper_bound; + this->metrics_.flush_write_tail_collision_count.add(1); + if (aligned_range.empty()) { flush_upper_bound = this->flush_tail_->upper_bound; continue; @@ -584,6 +587,7 @@ inline void IoRingLogDriver2::handle_flush_write(const SlotRange& slot }; if (!unflushed_remainder.empty()) { + this->metrics_.flush_tail_rewrite_count.add(1); this->start_flush_write(unflushed_remainder, this->get_aligned_range(unflushed_remainder)); } } diff --git a/src/llfs/ioring_log_device2.test.cpp b/src/llfs/ioring_log_device2.test.cpp index d85f340..533bad0 100644 --- a/src/llfs/ioring_log_device2.test.cpp +++ b/src/llfs/ioring_log_device2.test.cpp @@ -52,6 +52,17 @@ class IoringLogDevice2SimTest : public ::testing::Test //+++++++++++-+-+--+----- --- -- - - - - + /** \brief Conditions we hope to achieve in at least one test Scenario. + */ + struct GlobalTestGoals { + std::atomic concurrent_writes{false}; + std::atomic burst_mode_checked{false}; + std::atomic burst_mode_applied{false}; + std::atomic split_write{false}; + std::atomic tail_collision{false}; + std::atomic tail_rewrite{false}; + }; + /** \brief A single simulation run. * * It is safe to run multiple Scenarios concurrently on separate threads. @@ -66,6 +77,10 @@ class IoringLogDevice2SimTest : public ::testing::Test .data_alignment_log2 = batt::log2_ceil(kDataAlignment), }; + /** \brief Reference to single shared goals struct; used to report achievement of various goals. + */ + GlobalTestGoals& goals; + /** \brief The RNG seed for this scenario. */ usize seed; @@ -87,6 +102,10 @@ class IoringLogDevice2SimTest : public ::testing::Test */ llfs::LogDevice::Writer* log_writer = nullptr; + /** \brief The metrics object associated with the log device under test. + */ + const llfs::IoRingLogDevice2Metrics* log_device_metrics = nullptr; + /** \brief The slot offset ranges of all appended slots that haven't been trimmed yet; these are * not necessarily flushed yet. */ @@ -130,8 +149,9 @@ class IoringLogDevice2SimTest : public ::testing::Test /** \brief Constructs a new Scenario with the given RNG seed. */ - explicit Scenario(usize seed) noexcept - : seed{seed} + explicit Scenario(usize seed, GlobalTestGoals& goals) noexcept + : goals{goals} + , seed{seed} , rng{this->seed} , sim{batt::StateMachineEntropySource{ /*entropy_fn=*/[this](usize min_value, usize max_value) -> usize { @@ -170,13 +190,20 @@ class IoringLogDevice2SimTest : public ::testing::Test ASSERT_TRUE(storage.is_initialized()); + auto runtime_options = llfs::LogDeviceRuntimeOptions{ + .name = "test_log", + .flush_delay_threshold = kTestMaxSlotSize * 3, + .max_concurrent_writes = 16, + .optimize_burst_mode = true, + }; + auto p_device = std::make_unique>( - this->log_config, llfs::LogDeviceRuntimeOptions::with_default_values(), - std::move(storage)); + this->log_config, runtime_options, std::move(storage)); BATT_CHECK_OK(p_device->open()); + this->log_device_metrics = std::addressof(p_device->metrics()); this->log_device = std::move(p_device); this->log_writer = std::addressof(this->log_device->writer()); } @@ -186,10 +213,38 @@ class IoringLogDevice2SimTest : public ::testing::Test void shutdown_log_device() noexcept { if (this->log_device) { + BATT_CHECK_NOT_NULLPTR(this->log_device_metrics); + + // Check to see whether this scenario accomplished any global test goals. + // + if (this->log_device_metrics->max_concurrent_writes > 1) { + this->goals.concurrent_writes = true; + } + if (this->log_device_metrics->burst_mode_checked > 0) { + this->goals.burst_mode_checked = true; + } + if (this->log_device_metrics->burst_mode_applied > 0) { + BATT_CHECK_GE(this->log_device_metrics->burst_mode_checked, + this->log_device_metrics->burst_mode_applied); + this->goals.burst_mode_applied = true; + } + if (this->log_device_metrics->flush_write_split_wrap_count > 0) { + this->goals.split_write = true; + } + if (this->log_device_metrics->flush_write_tail_collision_count > 0) { + this->goals.tail_collision = true; + } + if (this->log_device_metrics->flush_tail_rewrite_count > 0) { + this->goals.tail_rewrite = true; + } + + // Shut down the device. + // this->log_device->halt(); this->log_device->join(); this->log_device.reset(); this->log_writer = nullptr; + this->log_device_metrics = nullptr; } } @@ -460,6 +515,15 @@ TEST_F(IoringLogDevice2SimTest, Simulation) LLFS_LOG_INFO() << BATT_INSPECT(kNumSeeds); + GlobalTestGoals goals; + + EXPECT_FALSE(goals.concurrent_writes); + EXPECT_FALSE(goals.burst_mode_checked); + EXPECT_FALSE(goals.burst_mode_applied); + EXPECT_FALSE(goals.split_write); + EXPECT_FALSE(goals.tail_collision); + EXPECT_FALSE(goals.tail_rewrite); + std::vector threads; usize start_seed = test_config.get_random_seed(); usize seeds_remaining = kNumSeeds; @@ -471,7 +535,7 @@ TEST_F(IoringLogDevice2SimTest, Simulation) LLFS_LOG_INFO_EVERY_N(kUpdateInterval) << "progress=" << (seed - start_seed) * 100 / (end_seed - start_seed) << "%"; - Scenario scenario{seed}; + Scenario scenario{seed, goals}; ASSERT_NO_FATAL_FAILURE(scenario.run()); } }); @@ -482,6 +546,13 @@ TEST_F(IoringLogDevice2SimTest, Simulation) for (std::thread& t : threads) { t.join(); } + + EXPECT_TRUE(goals.concurrent_writes); + EXPECT_TRUE(goals.burst_mode_checked); + EXPECT_TRUE(goals.burst_mode_applied); + EXPECT_TRUE(goals.split_write); + EXPECT_TRUE(goals.tail_collision); + EXPECT_TRUE(goals.tail_rewrite); } //==#==========+==+=+=++=+++++++++++-+-+--+----- --- -- - - - - diff --git a/src/llfs/ioring_log_device2_metrics.cpp b/src/llfs/ioring_log_device2_metrics.cpp index e413834..e498391 100644 --- a/src/llfs/ioring_log_device2_metrics.cpp +++ b/src/llfs/ioring_log_device2_metrics.cpp @@ -19,9 +19,18 @@ namespace llfs { BATT_OBJECT_PRINT_IMPL((), IoRingLogDevice2Metrics, - (bytes_written, bytes_flushed, max_concurrent_writes, burst_mode_checked, - burst_mode_applied, total_write_count, flush_write_count, - control_block_write_count)) + (bytes_written, // + bytes_flushed, // + max_concurrent_writes, // + burst_mode_checked, // + burst_mode_applied, // + total_write_count, // + flush_write_count, // + control_block_write_count, // + flush_write_split_wrap_count, // + flush_write_tail_collision_count, // + flush_tail_rewrite_count // + )) //==#==========+==+=+=++=+++++++++++-+-+--+----- --- -- - - - - // @@ -39,21 +48,28 @@ void IoRingLogDevice2Metrics::export_to(MetricRegistry& registry, LLFS_EXPORT_METRIC_(total_write_count); LLFS_EXPORT_METRIC_(flush_write_count); LLFS_EXPORT_METRIC_(control_block_write_count); + LLFS_EXPORT_METRIC_(flush_write_split_wrap_count); + LLFS_EXPORT_METRIC_(flush_write_tail_collision_count); + LLFS_EXPORT_METRIC_(flush_tail_rewrite_count); } //==#==========+==+=+=++=+++++++++++-+-+--+----- --- -- - - - - // void IoRingLogDevice2Metrics::unexport_from(MetricRegistry& registry) noexcept { - registry // - .remove(this->bytes_written) - .remove(this->bytes_flushed) - .remove(this->max_concurrent_writes) - .remove(this->burst_mode_checked) - .remove(this->burst_mode_applied) - .remove(this->total_write_count) - .remove(this->flush_write_count) - .remove(this->control_block_write_count); + registry // + .remove(this->bytes_written) // + .remove(this->bytes_flushed) // + .remove(this->max_concurrent_writes) // + .remove(this->burst_mode_checked) // + .remove(this->burst_mode_applied) // + .remove(this->total_write_count) // + .remove(this->flush_write_count) // + .remove(this->control_block_write_count) // + .remove(this->flush_write_split_wrap_count) // + .remove(this->flush_write_tail_collision_count) // + .remove(this->flush_tail_rewrite_count) // + ; } } //namespace llfs diff --git a/src/llfs/ioring_log_device2_metrics.hpp b/src/llfs/ioring_log_device2_metrics.hpp index 0288970..f7bfe19 100644 --- a/src/llfs/ioring_log_device2_metrics.hpp +++ b/src/llfs/ioring_log_device2_metrics.hpp @@ -55,6 +55,21 @@ struct IoRingLogDevice2Metrics { */ CountMetric control_block_write_count{0}; + /** \brief The number of times the slot_range interval to write has required splitting due to + * wrap-around. + */ + CountMetric flush_write_split_wrap_count{0}; + + /** \brief The number of times a flush write lower bound has been adjusted upwards to avoid + * overlapping a concurrent write. + */ + CountMetric flush_write_tail_collision_count{0}; + + /** \brief The number of times the flush tail needs to be rewritten because a subsequent + * concurrent write was initiated. + */ + CountMetric flush_tail_rewrite_count{0}; + //+++++++++++-+-+--+----- --- -- - - - - /** \brief Exports all collectors in this object to the passed registry, adding the passed labels.