diff --git a/src/llfs/basic_log_storage_driver.hpp b/src/llfs/basic_log_storage_driver.hpp index b2980be..68a5ecc 100644 --- a/src/llfs/basic_log_storage_driver.hpp +++ b/src/llfs/basic_log_storage_driver.hpp @@ -112,7 +112,12 @@ class BasicLogStorageDriver // //==#==========+==+=+=++=+++++++++++-+-+--+----- --- -- - - - - - Impl& impl() + Impl& impl() noexcept + { + return this->impl_; + } + + const Impl& impl() const noexcept { return this->impl_; } diff --git a/src/llfs/basic_ring_buffer_log_device.hpp b/src/llfs/basic_ring_buffer_log_device.hpp index 3399d0e..7afaea9 100644 --- a/src/llfs/basic_ring_buffer_log_device.hpp +++ b/src/llfs/basic_ring_buffer_log_device.hpp @@ -75,7 +75,12 @@ class BasicRingBufferLogDevice Status sync(LogReadMode mode, SlotUpperBoundAt event) override; - driver_type& driver() + driver_type& driver() noexcept + { + return this->driver_; + } + + const driver_type& driver() const noexcept { return this->driver_; } diff --git a/src/llfs/ioring_log_device.test.hpp b/src/llfs/ioring_log_device.test.hpp index dcffb72..3d9785e 100644 --- a/src/llfs/ioring_log_device.test.hpp +++ b/src/llfs/ioring_log_device.test.hpp @@ -103,9 +103,9 @@ inline void run_log_device_benchmark( const auto flushed_range = log_device.slot_range(LogReadMode::kDurable); const auto committed_range = log_device.slot_range(LogReadMode::kSpeculative); - LLFS_LOG_INFO() << BATT_INSPECT(flushed_range) << BATT_INSPECT(flushed_range.size()) - << BATT_INSPECT(committed_range) << BATT_INSPECT(committed_range.size()) - << BATT_INSPECT(last_iteration); + LLFS_VLOG(1) << BATT_INSPECT(flushed_range) << BATT_INSPECT(flushed_range.size()) + << BATT_INSPECT(committed_range) << BATT_INSPECT(committed_range.size()) + << BATT_INSPECT(last_iteration); log_device.halt(); }}; @@ -121,14 +121,14 @@ inline void run_log_device_benchmark( llfs::SlotUpperBoundAt{durable.lower_bound + trim_trigger}); if (!sync_status.ok()) { - LLFS_LOG_INFO() << BATT_INSPECT(durable.lower_bound); + LLFS_VLOG(1) << BATT_INSPECT(durable.lower_bound); break; } llfs::Status trim_status = log_device.trim(durable.lower_bound + aligned_trim_size); if (!trim_status.ok()) { - LLFS_LOG_INFO() << BATT_INSPECT(durable.lower_bound); + LLFS_VLOG(1) << BATT_INSPECT(durable.lower_bound); break; } diff --git a/src/llfs/ioring_log_device2.hpp b/src/llfs/ioring_log_device2.hpp index e8afd44..ef1c151 100644 --- a/src/llfs/ioring_log_device2.hpp +++ b/src/llfs/ioring_log_device2.hpp @@ -14,6 +14,7 @@ // #include #include +#include #include #include #include @@ -47,6 +48,9 @@ class IoRingLogDriver2 using Self = IoRingLogDriver2; using AlignedUnit = std::aligned_storage_t; using EventLoopTask = typename StorageT::EventLoopTask; + using Metrics = IoRingLogDevice2Metrics; + + //+++++++++++-+-+--+----- --- -- - - - - static constexpr batt::StaticType kTargetTrimPos{}; static constexpr batt::StaticType kCommitPos{}; @@ -70,6 +74,8 @@ class IoRingLogDriver2 StorageT&& storage // ) noexcept; + ~IoRingLogDriver2() noexcept; + //---- Status set_trim_pos(slot_offset_type trim_pos) @@ -130,6 +136,11 @@ class IoRingLogDriver2 //+++++++++++-+-+--+----- --- -- - - - - + const Metrics& metrics() const noexcept + { + return this->metrics_; + } + private: //+++++++++++-+-+--+----- --- -- - - - - @@ -199,7 +210,7 @@ class IoRingLogDriver2 * two writes may be initiated by this function, provided the conditions above are still met after * starting the first write. */ - void start_flush(CommitPos observed_commit_pos); + void start_flush(const CommitPos observed_commit_pos); /** \brief Returns the passed slot range with the lower and upper bounds aligned to the nearest * data page boundary. @@ -282,6 +293,10 @@ class IoRingLogDriver2 //+++++++++++-+-+--+----- --- -- - - - - + /** \brief Diagnostic metrics for this object. + */ + Metrics metrics_; + /** \brief The context passed in at construction time; provides access to the ring buffer. */ LogStorageDriverContext& context_; @@ -374,10 +389,6 @@ class IoRingLogDriver2 */ usize writes_pending_ = 0; - /** \brief The maximum observed value of this->writes_pending_ (high water mark). - */ - usize writes_max_ = 0; - /** \brief Buffer containing the control block structure. */ std::unique_ptr control_block_memory_; @@ -448,6 +459,11 @@ class BasicIoRingLogDevice2 config, options, std::move(storage)} { } + + const IoRingLogDevice2Metrics& metrics() const noexcept + { + return this->driver().impl().metrics(); + } }; /** \brief A fast, durable LogDevice implementation. diff --git a/src/llfs/ioring_log_device2.ipp b/src/llfs/ioring_log_device2.ipp index fc0b371..3afcab3 100644 --- a/src/llfs/ioring_log_device2.ipp +++ b/src/llfs/ioring_log_device2.ipp @@ -13,6 +13,8 @@ #include #include +#include + namespace llfs { //==#==========+==+=+=++=+++++++++++-+-+--+----- --- -- - - - - @@ -34,6 +36,37 @@ inline /*explicit*/ IoRingLogDriver2::IoRingLogDriver2( { BATT_CHECK_GE(this->config_.data_alignment_log2, this->config_.device_page_size_log2); BATT_CHECK_GE(this->data_page_size_, sizeof(PackedLogControlBlock2)); + + using batt::Token; + + // Register all metrics. + // + MetricLabelSet labels{ + MetricLabel{Token{"object_type"}, Token{"llfs_IoRingLogDriver2"}}, + MetricLabel{Token{"log_name"}, Token{this->options_.name}}, + }; + + this->metrics_.export_to(global_metric_registry(), labels); + + global_metric_registry() // + .add("trim_target_pos", this->observed_watch_[Self::kTargetTrimPos], batt::make_copy(labels)) + .add("commit_pos", this->observed_watch_[Self::kCommitPos], batt::make_copy(labels)) + .add("trim_pos", this->trim_pos_, batt::make_copy(labels)) + .add("flush_pos", this->flush_pos_, batt::make_copy(labels)); +} + +//==#==========+==+=+=++=+++++++++++-+-+--+----- --- -- - - - - +// +template +inline IoRingLogDriver2::~IoRingLogDriver2() noexcept +{ + this->metrics_.unexport_from(global_metric_registry()); + + global_metric_registry() // + .remove(this->observed_watch_[Self::kTargetTrimPos]) + .remove(this->observed_watch_[Self::kCommitPos]) + .remove(this->trim_pos_) + .remove(this->flush_pos_); } //==#==========+==+=+=++=+++++++++++-+-+--+----- --- -- - - - - @@ -292,7 +325,7 @@ inline void IoRingLogDriver2::wait_for_slot_offset_change(T observed_v //==#==========+==+=+=++=+++++++++++-+-+--+----- --- -- - - - - // template -inline void IoRingLogDriver2::start_flush(CommitPos observed_commit_pos) +inline void IoRingLogDriver2::start_flush(const CommitPos observed_commit_pos) { // Unflushed data comes after flushed. // @@ -350,20 +383,37 @@ inline void IoRingLogDriver2::start_flush(CommitPos observed_commit_po } } + // If burst mode optimization is enabled, then round slot_range.upper_bound *down* to get the + // aligned upper bound (instead of up, the default); this way, we are less likely to need to + // issue another I/O to fill in partial data in flush_tail_. + // + if (this->flush_tail_ && this->options_.optimize_burst_mode) { + this->metrics_.burst_mode_checked.add(1); + + const usize new_upper_bound = slot_max( + slot_range.lower_bound, + batt::round_down_bits(this->config_.data_alignment_log2, slot_range.upper_bound)); + + if (slot_range.upper_bound != new_upper_bound) { + this->metrics_.burst_mode_applied.add(1); + } + + slot_range.upper_bound = new_upper_bound; + } + // Align to 512-byte boundaries for direct I/O // SlotRange aligned_range = this->get_aligned_range(slot_range); // If this flush would overlap with an ongoing one (at the last device page) then trim the - // aligned_range so it doesn't. + // aligned_range (on the lower end) so it doesn't. // - if (this->flush_tail_) { - if (slot_less_than(aligned_range.lower_bound, this->flush_tail_->upper_bound)) { - aligned_range.lower_bound = this->flush_tail_->upper_bound; - if (aligned_range.empty()) { - flush_upper_bound = this->flush_tail_->upper_bound; - continue; - } + 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; + if (aligned_range.empty()) { + flush_upper_bound = this->flush_tail_->upper_bound; + continue; } } @@ -439,17 +489,21 @@ inline void IoRingLogDriver2::start_flush_write(const SlotRange& slot_ resize_buffer(this->context_.buffer_.get(aligned_range.lower_bound), aligned_range.size()); BATT_CHECK_LE(write_offset + (i64)buffer.size(), this->data_end_) - << "Data to flush extends beyond the end of the storage extent; forgot to handle wrap-around " + << "Data to flush extends beyond the end of the storage extent; forgot to handle " + "wrap-around " "case?"; LLFS_VLOG(1) << " -- async_write_some(offset=" << write_offset << ".." << write_offset + buffer.size() << ", size=" << buffer.size() << ")"; ++this->writes_pending_; - this->writes_max_ = std::max(this->writes_max_, this->writes_pending_); + this->metrics_.max_concurrent_writes.clamp_min(this->writes_pending_); BATT_CHECK_LE(this->writes_pending_, this->options_.max_concurrent_writes); + this->metrics_.total_write_count.add(1); + this->metrics_.flush_write_count.add(1); + this->storage_.async_write_some(write_offset, buffer, this->make_write_handler([this, slot_range, aligned_range]( Self* this_, StatusOr result) { @@ -502,6 +556,9 @@ inline void IoRingLogDriver2::handle_flush_write(const SlotRange& slot }; BATT_CHECK(!flushed_range.empty()); + this->metrics_.bytes_written.add(bytes_written); + this->metrics_.bytes_flushed.add(flushed_range.size()); + LLFS_DVLOG(1) << BATT_INSPECT(flushed_range); // Update this->known_flush_pos_ and this->known_flushed_commit_pos_ to reflect the write. @@ -625,6 +682,9 @@ void IoRingLogDriver2::start_control_block_update( this->writing_control_block_ = true; + this->metrics_.total_write_count.add(1); + this->metrics_.control_block_write_count.add(1); + this->storage_.async_write_some_fixed( this->config_.control_block_offset, this->control_block_buffer_, /*buf_index=*/0, this->make_write_handler([](Self* this_, StatusOr result) { @@ -648,7 +708,11 @@ void IoRingLogDriver2::handle_control_block_update(StatusOr resul return; } - if (BATT_CHECKED_CAST(usize, *result) != this->control_block_buffer_.size()) { + const usize bytes_written = BATT_CHECKED_CAST(usize, *result); + + this->metrics_.bytes_written.add(bytes_written); + + if (bytes_written != this->control_block_buffer_.size()) { LLFS_LOG_ERROR() << "Failed to write entire log control block!"; this->context_.update_error_status(batt::StatusCode::kInternal); return; diff --git a/src/llfs/ioring_log_device2.test.cpp b/src/llfs/ioring_log_device2.test.cpp index bc2b342..d85f340 100644 --- a/src/llfs/ioring_log_device2.test.cpp +++ b/src/llfs/ioring_log_device2.test.cpp @@ -488,35 +488,29 @@ TEST_F(IoringLogDevice2SimTest, Simulation) // TEST(IoringLogDevice2Test, Benchmark) { - llfs::run_log_device_benchmark([&](usize log_size, bool create, auto&& workload_fn) { - //+++++++++++-+-+--+----- --- -- - - - - - // Set configuration and options. - // - llfs::IoRingLogConfig2 config{ - .control_block_offset = 0, - .log_capacity = log_size, - .device_page_size_log2 = 9, - .data_alignment_log2 = 12, - }; - - llfs::LogDeviceRuntimeOptions options{ - .name = "test log", - .flush_delay_threshold = 2 * kMiB, - .max_concurrent_writes = 64, - }; - - const char* file_name = // - std::getenv("LLFS_LOG_DEVICE_FILE"); - - if (!file_name) { - LLFS_LOG_INFO() << "LLFS_LOG_DEVICE_FILE not specified; skipping benchmark test"; - return; - } + //+++++++++++-+-+--+----- --- -- - - - - + // Set configuration and options. + // + llfs::LogDeviceRuntimeOptions options{ + .name = "test log", + .flush_delay_threshold = 128 * kKiB, + .max_concurrent_writes = 64, + .optimize_burst_mode = llfs::read_test_var("LLFS_LOG_DEVICE_BURST", /*default=*/0) != 0, + }; + + const char* file_name = // + std::getenv("LLFS_LOG_DEVICE_FILE"); + + if (!file_name) { + LLFS_LOG_INFO() << "LLFS_LOG_DEVICE_FILE not specified; skipping benchmark test"; + return; + } - std::cout << "LLFS_LOG_DEVICE_FILE=" << batt::c_str_literal(file_name) << std::endl; + std::cout << "LLFS_LOG_DEVICE_FILE=" << batt::c_str_literal(file_name) << std::endl; - LLFS_LOG_INFO() << BATT_INSPECT(file_name); + LLFS_LOG_INFO() << BATT_INSPECT(file_name); + llfs::run_log_device_benchmark([&](usize log_size, bool create, auto&& workload_fn) { //+++++++++++-+-+--+----- --- -- - - - - // Erase any existing file. // @@ -531,6 +525,13 @@ TEST(IoringLogDevice2Test, Benchmark) //+++++++++++-+-+--+----- --- -- - - - - // Create a new log file and size it to the configured capacity. // + llfs::IoRingLogConfig2 config{ + .control_block_offset = 0, + .log_capacity = log_size, + .device_page_size_log2 = 9, + .data_alignment_log2 = 12, + }; + llfs::StatusOr status_or_fd = [&] { if (create) { return llfs::create_file_read_write(file_name, llfs::OpenForAppend{false}); @@ -588,6 +589,11 @@ TEST(IoringLogDevice2Test, Benchmark) // Run the passed workload. // workload_fn(log_device); + + const double write_amplification = + double(log_device.metrics().bytes_written) / double(log_device.metrics().bytes_flushed); + + LLFS_LOG_INFO() << log_device.metrics() << BATT_INSPECT(write_amplification); }); } diff --git a/src/llfs/ioring_log_device2_metrics.cpp b/src/llfs/ioring_log_device2_metrics.cpp new file mode 100644 index 0000000..e413834 --- /dev/null +++ b/src/llfs/ioring_log_device2_metrics.cpp @@ -0,0 +1,61 @@ +//#=##=##=#==#=#==#===#+==#+==========+==+=+=+=+=+=++=+++=+++++=-++++=-+++++++++++ +// +// Part of the LLFS Project, under Apache License v2.0. +// See https://www.apache.org/licenses/LICENSE-2.0 for license information. +// SPDX short identifier: Apache-2.0 +// +//+++++++++++-+-+--+----- --- -- - - - - + +#include +// + +#ifndef LLFS_DISABLE_IO_URING + +#include +#include + +#include + +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)) + +//==#==========+==+=+=++=+++++++++++-+-+--+----- --- -- - - - - +// +void IoRingLogDevice2Metrics::export_to(MetricRegistry& registry, + const MetricLabelSet& labels) noexcept +{ +#define LLFS_EXPORT_METRIC_(name) \ + registry.add(BOOST_PP_STRINGIZE(name), this->name, batt::make_copy(labels)) + + LLFS_EXPORT_METRIC_(bytes_written); + LLFS_EXPORT_METRIC_(bytes_flushed); + LLFS_EXPORT_METRIC_(max_concurrent_writes); + LLFS_EXPORT_METRIC_(burst_mode_checked); + LLFS_EXPORT_METRIC_(burst_mode_applied); + LLFS_EXPORT_METRIC_(total_write_count); + LLFS_EXPORT_METRIC_(flush_write_count); + LLFS_EXPORT_METRIC_(control_block_write_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); +} + +} //namespace llfs + +#endif // LLFS_DISABLE_IO_URING diff --git a/src/llfs/ioring_log_device2_metrics.hpp b/src/llfs/ioring_log_device2_metrics.hpp new file mode 100644 index 0000000..0288970 --- /dev/null +++ b/src/llfs/ioring_log_device2_metrics.hpp @@ -0,0 +1,79 @@ +//#=##=##=#==#=#==#===#+==#+==========+==+=+=+=+=+=++=+++=+++++=-++++=-+++++++++++ +// +// Part of the LLFS Project, under Apache License v2.0. +// See https://www.apache.org/licenses/LICENSE-2.0 for license information. +// SPDX short identifier: Apache-2.0 +// +//+++++++++++-+-+--+----- --- -- - - - - + +#pragma once +#ifndef LLFS_IORING_LOG_DEVICE2_METRICS_HPP +#define LLFS_IORING_LOG_DEVICE2_METRICS_HPP + +#include + +#ifndef LLFS_DISABLE_IO_URING + +#include + +namespace llfs { + +struct IoRingLogDevice2Metrics { + /** \brief Total number of bytes written to storage (control + data), including alignment padding. + */ + CountMetric bytes_written{0}; + + /** \brief Number of logical (data) bytes flushed to storage. This may be greater than + * (flush_pos - trim_pos) since it includes out-of-order ranges. + */ + CountMetric bytes_flushed{0}; + + /** \brief The maximum observed concurrent flush write operations. + */ + CountMetric max_concurrent_writes{0}; + + /** \brief The number of times burst-mode alignment truncation was calculated. + */ + CountMetric burst_mode_checked{0}; + + /** \brief The number of times that the truncated alignment was less than the observed slot upper + * bound (this is a subset of the events counted by this->burst_mode_checked). + */ + CountMetric burst_mode_applied{0}; + + /** \brief The total number of write IOPs initiated by the driver. + */ + CountMetric total_write_count{0}; + + /** \brief The number of flush write IOPs initiated by the driver (this is a subset of the events + * counted by this->total_write_count). + */ + CountMetric flush_write_count{0}; + + /** \brief The number of control block update IOPs initiated by the driver (this is a subset of + * the events counted by this->total_write_count). + */ + CountMetric control_block_write_count{0}; + + //+++++++++++-+-+--+----- --- -- - - - - + + /** \brief Exports all collectors in this object to the passed registry, adding the passed labels. + * + * IMPORTANT: Once export_to has been called, this->unexport_from(registry) must be called before + * this object goes out of scope! + */ + void export_to(MetricRegistry& registry, const MetricLabelSet& labels) noexcept; + + /** \brief Removes all previously exported collectors associated with this object from the passed + * registry. + */ + void unexport_from(MetricRegistry& registry) noexcept; +}; + +std::ostream& operator<<(std::ostream& out, const IoRingLogDevice2Metrics& t); + +} //namespace llfs + +#endif // LLFS_DISABLE_IO_URING + +#endif // LLFS_IORING_LOG_DEVICE2_METRICS_HPP diff --git a/src/llfs/log_device_runtime_options.hpp b/src/llfs/log_device_runtime_options.hpp index daec2f3..18f0103 100644 --- a/src/llfs/log_device_runtime_options.hpp +++ b/src/llfs/log_device_runtime_options.hpp @@ -28,8 +28,9 @@ namespace llfs { struct LogDeviceRuntimeOptions { using Self = LogDeviceRuntimeOptions; - static constexpr usize kDefaultFlushDelayThreshold = 1 * kMiB; + static constexpr usize kDefaultFlushDelayThreshold = 128 * kKiB; static constexpr usize kDefaultMaxConcurrentWrites = 64; + static constexpr usize kDefaultOptimizeBurstMode = true; //+++++++++++-+-+--+----- --- -- - - - - @@ -54,6 +55,8 @@ struct LogDeviceRuntimeOptions { usize max_concurrent_writes = kDefaultMaxConcurrentWrites; + bool optimize_burst_mode = kDefaultOptimizeBurstMode; + //+++++++++++-+-+--+----- --- -- - - - - Self& set_name(std::string_view name) diff --git a/src/llfs/metrics.hpp b/src/llfs/metrics.hpp index e1684b7..e7fc396 100644 --- a/src/llfs/metrics.hpp +++ b/src/llfs/metrics.hpp @@ -19,6 +19,9 @@ using ::batt::CountMetric; using ::batt::global_metric_registry; using ::batt::LatencyMetric; using ::batt::LatencyTimer; +using ::batt::MetricLabel; +using ::batt::MetricLabelSet; +using ::batt::MetricRegistry; #define LLFS_COLLECT_LATENCY BATT_COLLECT_LATENCY #define LLFS_COLLECT_LATENCY_N BATT_COLLECT_LATENCY_N