diff --git a/CMakeLists.txt b/CMakeLists.txt index 9d1e422e..09136566 100644 --- a/CMakeLists.txt +++ b/CMakeLists.txt @@ -25,6 +25,7 @@ include(CheckCXXSourceCompiles) option(WITH_TESTS "build with tests" OFF) option(WITH_BENCHMARKS "build with benchmarks" OFF) +option(ENABLE_PERFMON "enable performance monitor in all tools" ON) if(WIN32) set(PREFER_SYSTEM_LIBFMT ON) set(PREFER_SYSTEM_LIBARCHIVE ON) @@ -443,6 +444,7 @@ list( src/dwarfs/option_map.cpp src/dwarfs/options.cpp src/dwarfs/os_access_generic.cpp + src/dwarfs/performance_monitor.cpp src/dwarfs/progress.cpp src/dwarfs/scanner.cpp src/dwarfs/similarity.cpp @@ -788,6 +790,10 @@ foreach(tgt dwarfs dwarfs_compression dwarfs_tool ${BINARY_TARGETS} ${MAIN_TARGE target_compile_definitions(${tgt} PRIVATE DWARFS_USE_EXCEPTION_TRACER) endif() + if(ENABLE_PERFMON) + target_compile_definitions(${tgt} PRIVATE DWARFS_PERFMON_ENABLED=1) + endif() + if("${CMAKE_CXX_COMPILER_ID}" STREQUAL "GNU" OR "${CMAKE_CXX_COMPILER_ID}" STREQUAL "Clang") target_compile_options(${tgt} PRIVATE -Wall -Wextra -pedantic) diff --git a/include/dwarfs/filesystem_v2.h b/include/dwarfs/filesystem_v2.h index 363b6771..7c6facd7 100644 --- a/include/dwarfs/filesystem_v2.h +++ b/include/dwarfs/filesystem_v2.h @@ -51,6 +51,7 @@ struct vfs_stat; class filesystem_writer; class logger; class mmif; +class performance_monitor; class progress; class filesystem_v2 { @@ -60,7 +61,8 @@ class filesystem_v2 { filesystem_v2(logger& lgr, std::shared_ptr mm); filesystem_v2(logger& lgr, std::shared_ptr mm, - const filesystem_options& options, int inode_offset = 0); + const filesystem_options& options, int inode_offset = 0, + std::shared_ptr perfmon = nullptr); static void rewrite(logger& lgr, progress& prog, std::shared_ptr mm, filesystem_writer& writer, rewrite_options const& opts); diff --git a/include/dwarfs/performance_monitor.h b/include/dwarfs/performance_monitor.h new file mode 100644 index 00000000..11f0c903 --- /dev/null +++ b/include/dwarfs/performance_monitor.h @@ -0,0 +1,164 @@ +/* vim:set ts=2 sw=2 sts=2 et: */ +/** + * \author Marcus Holland-Moritz (github@mhxnet.de) + * \copyright Copyright (c) Marcus Holland-Moritz + * + * This file is part of dwarfs. + * + * dwarfs is free software: you can redistribute it and/or modify + * it under the terms of the GNU General Public License as published by + * the Free Software Foundation, either version 3 of the License, or + * (at your option) any later version. + * + * dwarfs is distributed in the hope that it will be useful, + * but WITHOUT ANY WARRANTY; without even the implied warranty of + * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the + * GNU General Public License for more details. + * + * You should have received a copy of the GNU General Public License + * along with dwarfs. If not, see . + */ + +#pragma once + +#include +#include +#include +#include +#include + +namespace dwarfs { + +class performance_monitor { + public: + using timer_id = size_t; + using time_type = uint64_t; + + static std::unique_ptr + create(std::unordered_set const& enabled_namespaces); + + virtual ~performance_monitor() = default; + + virtual time_type now() const = 0; + virtual void add_sample(timer_id id, time_type start) const = 0; + virtual void summarize(std::ostream& os) const = 0; + virtual bool is_enabled(std::string const& ns) const = 0; + virtual timer_id + setup_timer(std::string const& ns, std::string const& name) const = 0; +}; + +class performance_monitor_proxy { + public: + class section_timer { + public: + section_timer() = default; + + section_timer(performance_monitor const* mon, + performance_monitor::timer_id id) + : mon_{mon} + , id_{id} + , start_{mon_->now()} {} + + ~section_timer() { + if (mon_) { + mon_->add_sample(id_, start_); + } + } + + private: + performance_monitor const* mon_{nullptr}; + performance_monitor::timer_id id_; + performance_monitor::time_type start_; + }; + + performance_monitor_proxy() = default; + + performance_monitor_proxy(std::shared_ptr mon, + std::string const& proxy_namespace); + + performance_monitor::timer_id setup_timer(std::string const& name) const { + return mon_ ? mon_->setup_timer(namespace_, name) : 0; + } + + section_timer scoped_section(performance_monitor::timer_id id) const { + return mon_ ? section_timer(mon_.get(), id) : section_timer(); + } + + private: + std::shared_ptr mon_; + std::string namespace_; +}; + +#ifndef DWARFS_PERFMON_ENABLED +#define DWARFS_PERFMON_ENABLED 0 +#endif + +#if DWARFS_PERFMON_ENABLED + +#define PERFMON_ARG(monitor) monitor +#define PERFMON_CREATE(monitor, enabled_namespaces) \ + std::shared_ptr monitor = \ + performance_monitor::create(enabled_namespaces); + +#define PERFMON_PROXY_DECL(instname) performance_monitor_proxy instname; +#define PERFMON_PROXY_INIT(instname, monitor, name_space) \ + , instname { monitor, name_space } +#define PERFMON_TIMER_DECL(id) \ + performance_monitor::timer_id const perfmon_##id##_id_; +#define PERFMON_TIMER_INIT(instname, id) \ + , perfmon_##id##_id_ { instname.setup_timer(#id) } +#define PERFMON_SCOPED_SECTION(instname, id) \ + auto perfmon_scoped_section_ = instname.scoped_section(perfmon_##id##_id_); +#define PERFMON_PROXY_SETUP(instname, monitor, name_space) \ + instname = performance_monitor_proxy(monitor, name_space); + +#define PERFMON_PROXY_INSTNAME perfmon_inst_ + +#define PERFMON_EXT_PROXY_DECL PERFMON_PROXY_DECL(PERFMON_PROXY_INSTNAME) +#define PERFMON_EXT_TIMER_DECL(id) \ + performance_monitor::timer_id perfmon_##id##_id_; +#define PERFMON_EXT_TIMER_SETUP(scope, id) \ + (scope).perfmon_##id##_id_ = (scope).PERFMON_PROXY_INSTNAME.setup_timer(#id); +#define PERFMON_EXT_SCOPED_SECTION(scope, id) \ + auto perfmon_scoped_section_ = \ + (scope).PERFMON_PROXY_INSTNAME.scoped_section( \ + (scope).perfmon_##id##_id_); +#define PERFMON_EXT_PROXY_SETUP(scope, monitor, name_space) \ + PERFMON_PROXY_SETUP((scope).PERFMON_PROXY_INSTNAME, monitor, name_space) + +#define PERFMON_CLS_PROXY_DECL PERFMON_PROXY_DECL(PERFMON_PROXY_INSTNAME) +#define PERFMON_CLS_PROXY_INIT(monitor, name_space) \ + PERFMON_PROXY_INIT(PERFMON_PROXY_INSTNAME, monitor, name_space) +#define PERFMON_CLS_TIMER_DECL(id) PERFMON_TIMER_DECL(id) +#define PERFMON_CLS_TIMER_INIT(id) \ + PERFMON_TIMER_INIT(PERFMON_PROXY_INSTNAME, id) +#define PERFMON_CLS_SCOPED_SECTION(id) \ + PERFMON_SCOPED_SECTION(PERFMON_PROXY_INSTNAME, id) + +#else + +#define PERFMON_ARG(monitor) nullptr +#define PERFMON_CREATE(monitor, enabled_namespaces) + +#define PERFMON_PROXY_DECL(instname) +#define PERFMON_PROXY_INIT(instname, monitor, name_space) +#define PERFMON_TIMER_DECL(id) +#define PERFMON_TIMER_INIT(instname, id) +#define PERFMON_SCOPED_SECTION(instname, id) +#define PERFMON_PROXY_SETUP(instname, monitor, name_space) + +#define PERFMON_EXT_PROXY_DECL +#define PERFMON_EXT_TIMER_DECL(id) +#define PERFMON_EXT_TIMER_SETUP(scope, id) +#define PERFMON_EXT_SCOPED_SECTION(scope, id) +#define PERFMON_EXT_PROXY_SETUP(scope, monitor, name_space) + +#define PERFMON_CLS_PROXY_DECL +#define PERFMON_CLS_PROXY_INIT(monitor, name_space) +#define PERFMON_CLS_TIMER_DECL(id) +#define PERFMON_CLS_TIMER_INIT(id) +#define PERFMON_CLS_SCOPED_SECTION(id) + +#endif + +} // namespace dwarfs diff --git a/src/dwarfs/filesystem_v2.cpp b/src/dwarfs/filesystem_v2.cpp index 64d78f6b..17c31fac 100644 --- a/src/dwarfs/filesystem_v2.cpp +++ b/src/dwarfs/filesystem_v2.cpp @@ -23,6 +23,7 @@ #include #include #include +#include #include #include #include @@ -42,6 +43,7 @@ #include "dwarfs/metadata_v2.h" #include "dwarfs/mmif.h" #include "dwarfs/options.h" +#include "dwarfs/performance_monitor.h" #include "dwarfs/progress.h" #include "dwarfs/worker_group.h" @@ -318,7 +320,8 @@ template class filesystem_ final : public filesystem_v2::impl { public: filesystem_(logger& lgr, std::shared_ptr mm, - const filesystem_options& options, int inode_offset); + const filesystem_options& options, int inode_offset, + std::shared_ptr perfmon); void dump(std::ostream& os, int detail_level) const override; folly::dynamic metadata_as_dynamic() const override; @@ -365,6 +368,22 @@ class filesystem_ final : public filesystem_v2::impl { std::vector meta_buffer_; std::optional> header_; mutable std::unique_ptr fsinfo_; + PERFMON_CLS_PROXY_DECL + PERFMON_CLS_TIMER_DECL(find_path) + PERFMON_CLS_TIMER_DECL(find_inode) + PERFMON_CLS_TIMER_DECL(find_inode_name) + PERFMON_CLS_TIMER_DECL(getattr) + PERFMON_CLS_TIMER_DECL(access) + PERFMON_CLS_TIMER_DECL(opendir) + PERFMON_CLS_TIMER_DECL(readdir) + PERFMON_CLS_TIMER_DECL(dirsize) + PERFMON_CLS_TIMER_DECL(readlink) + PERFMON_CLS_TIMER_DECL(readlink_expected) + PERFMON_CLS_TIMER_DECL(statvfs) + PERFMON_CLS_TIMER_DECL(open) + PERFMON_CLS_TIMER_DECL(read) + PERFMON_CLS_TIMER_DECL(readv_iovec) + PERFMON_CLS_TIMER_DECL(readv_future) }; template @@ -395,12 +414,30 @@ filesystem_info const& filesystem_::get_info() const { } template -filesystem_::filesystem_(logger& lgr, std::shared_ptr mm, - const filesystem_options& options, - int inode_offset) +filesystem_::filesystem_( + logger& lgr, std::shared_ptr mm, const filesystem_options& options, + int inode_offset, + std::shared_ptr perfmon [[maybe_unused]]) : LOG_PROXY_INIT(lgr) , mm_(std::move(mm)) - , parser_(mm_, options.image_offset) { + , parser_(mm_, options.image_offset) + // clang-format off + PERFMON_CLS_PROXY_INIT(perfmon, "filesystem_v2") + PERFMON_CLS_TIMER_INIT(find_path) + PERFMON_CLS_TIMER_INIT(find_inode) + PERFMON_CLS_TIMER_INIT(find_inode_name) + PERFMON_CLS_TIMER_INIT(getattr) + PERFMON_CLS_TIMER_INIT(access) + PERFMON_CLS_TIMER_INIT(opendir) + PERFMON_CLS_TIMER_INIT(readdir) + PERFMON_CLS_TIMER_INIT(dirsize) + PERFMON_CLS_TIMER_INIT(readlink) + PERFMON_CLS_TIMER_INIT(readlink_expected) + PERFMON_CLS_TIMER_INIT(statvfs) + PERFMON_CLS_TIMER_INIT(open) + PERFMON_CLS_TIMER_INIT(read) + PERFMON_CLS_TIMER_INIT(readv_iovec) + PERFMON_CLS_TIMER_INIT(readv_future) { // clang-format on block_cache cache(lgr, mm_, options.block_cache); if (parser_.has_index()) { @@ -481,52 +518,61 @@ void filesystem_::walk_data_order( template std::optional filesystem_::find(const char* path) const { + PERFMON_CLS_SCOPED_SECTION(find_path) return meta_.find(path); } template std::optional filesystem_::find(int inode) const { + PERFMON_CLS_SCOPED_SECTION(find_inode) return meta_.find(inode); } template std::optional filesystem_::find(int inode, const char* name) const { + PERFMON_CLS_SCOPED_SECTION(find_inode_name) return meta_.find(inode, name); } template int filesystem_::getattr(inode_view entry, file_stat* stbuf) const { + PERFMON_CLS_SCOPED_SECTION(getattr) return meta_.getattr(entry, stbuf); } template int filesystem_::access(inode_view entry, int mode, uid_t uid, gid_t gid) const { + PERFMON_CLS_SCOPED_SECTION(access) return meta_.access(entry, mode, uid, gid); } template std::optional filesystem_::opendir(inode_view entry) const { + PERFMON_CLS_SCOPED_SECTION(opendir) return meta_.opendir(entry); } template std::optional> filesystem_::readdir(directory_view dir, size_t offset) const { + PERFMON_CLS_SCOPED_SECTION(readdir) return meta_.readdir(dir, offset); } template size_t filesystem_::dirsize(directory_view dir) const { + PERFMON_CLS_SCOPED_SECTION(dirsize) return meta_.dirsize(dir); } template int filesystem_::readlink(inode_view entry, std::string* buf, readlink_mode mode) const { + PERFMON_CLS_SCOPED_SECTION(readlink) return meta_.readlink(entry, buf, mode); } @@ -534,23 +580,27 @@ template folly::Expected filesystem_::readlink(inode_view entry, readlink_mode mode) const { + PERFMON_CLS_SCOPED_SECTION(readlink_expected) return meta_.readlink(entry, mode); } template int filesystem_::statvfs(vfs_stat* stbuf) const { + PERFMON_CLS_SCOPED_SECTION(statvfs) // TODO: not sure if that's the right abstraction... return meta_.statvfs(stbuf); } template int filesystem_::open(inode_view entry) const { + PERFMON_CLS_SCOPED_SECTION(open) return meta_.open(entry); } template ssize_t filesystem_::read(uint32_t inode, char* buf, size_t size, file_off_t offset) const { + PERFMON_CLS_SCOPED_SECTION(read) if (auto chunks = meta_.get_chunks(inode)) { return ir_.read(buf, size, offset, *chunks); } @@ -560,6 +610,7 @@ ssize_t filesystem_::read(uint32_t inode, char* buf, size_t size, template ssize_t filesystem_::readv(uint32_t inode, iovec_read_buf& buf, size_t size, file_off_t offset) const { + PERFMON_CLS_SCOPED_SECTION(readv_iovec) if (auto chunks = meta_.get_chunks(inode)) { return ir_.readv(buf, size, offset, *chunks); } @@ -570,6 +621,7 @@ template folly::Expected>, int> filesystem_::readv(uint32_t inode, size_t size, file_off_t offset) const { + PERFMON_CLS_SCOPED_SECTION(readv_future) if (auto chunks = meta_.get_chunks(inode)) { return ir_.readv(size, offset, *chunks); } @@ -589,10 +641,11 @@ filesystem_v2::filesystem_v2(logger& lgr, std::shared_ptr mm) filesystem_v2::filesystem_v2(logger& lgr, std::shared_ptr mm, const filesystem_options& options, - int inode_offset) + int inode_offset, + std::shared_ptr perfmon) : impl_(make_unique_logging_object( - lgr, std::move(mm), options, inode_offset)) {} + lgr, std::move(mm), options, inode_offset, std::move(perfmon))) {} void filesystem_v2::rewrite(logger& lgr, progress& prog, std::shared_ptr mm, filesystem_writer& writer, diff --git a/src/dwarfs/performance_monitor.cpp b/src/dwarfs/performance_monitor.cpp new file mode 100644 index 00000000..1c9775e5 --- /dev/null +++ b/src/dwarfs/performance_monitor.cpp @@ -0,0 +1,209 @@ +/* vim:set ts=2 sw=2 sts=2 et: */ +/** + * \author Marcus Holland-Moritz (github@mhxnet.de) + * \copyright Copyright (c) Marcus Holland-Moritz + * + * This file is part of dwarfs. + * + * dwarfs is free software: you can redistribute it and/or modify + * it under the terms of the GNU General Public License as published by + * the Free Software Foundation, either version 3 of the License, or + * (at your option) any later version. + * + * dwarfs is distributed in the hope that it will be useful, + * but WITHOUT ANY WARRANTY; without even the implied warranty of + * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the + * GNU General Public License for more details. + * + * You should have received a copy of the GNU General Public License + * along with dwarfs. If not, see . + */ + +#include +#include +#include +#include +#include + +#ifdef _WIN32 +#include +#else +#include +#endif + +#include +#include + +#include "dwarfs/performance_monitor.h" +#include "dwarfs/util.h" + +namespace dwarfs { + +namespace { + +class single_timer { + public: + static constexpr uint64_t const histogram_interval = 1; + + single_timer(std::string const& name_space, std::string const& name) + : log_hist_{1, 0, 64} + , namespace_{name_space} + , name_{name} { + total_time_.store(0); + } + + void add_sample(uint64_t elapsed) { + total_time_.fetch_add(elapsed); + + if ((samples_.fetch_add(1) % histogram_interval) == 0) { + auto log_time = folly::findLastSet(elapsed); + std::lock_guard lock(log_hist_mutex_); + log_hist_.addValue(log_time); + } + } + + std::string_view get_namespace() const { return namespace_; } + + std::string_view name() const { return name_; } + + uint64_t total_latency() const { return total_time_.load(); } + + void summarize(std::ostream& os, double timebase) const { + if (samples_.load() == 0) { + return; + } + + size_t log_p50, log_p90, log_p99; + { + std::lock_guard lock(log_hist_mutex_); + log_p50 = log_hist_.getPercentileEstimate(0.5); + log_p90 = log_hist_.getPercentileEstimate(0.9); + log_p99 = log_hist_.getPercentileEstimate(0.99); + } + auto samples = samples_.load(); + auto total_time = total_time_.load(); + + auto tot = timebase * total_time; + auto avg = tot / samples; + auto p50 = timebase * (UINT64_C(1) << log_p50); + auto p90 = timebase * (UINT64_C(1) << log_p90); + auto p99 = timebase * (UINT64_C(1) << log_p99); + + os << "[" << namespace_ << "." << name_ << "]\n"; + os << " samples: " << samples << "\n"; + os << " overall: " << time_with_unit(tot) << "\n"; + os << " avg latency: " << time_with_unit(avg) << "\n"; + os << " p50 latency: " << time_with_unit(p50) << "\n"; + os << " p90 latency: " << time_with_unit(p90) << "\n"; + os << " p99 latency: " << time_with_unit(p99) << "\n\n"; + } + + private: + std::atomic samples_; + std::atomic total_time_; + folly::Histogram log_hist_; + std::mutex mutable log_hist_mutex_; + std::string const namespace_; + std::string const name_; +}; + +} // namespace + +class performance_monitor_impl : public performance_monitor { + public: + using timer_id = performance_monitor::timer_id; + using time_type = performance_monitor::time_type; + + performance_monitor_impl(std::unordered_set enabled_namespaces) + : timebase_{get_timebase()} + , enabled_namespaces_{std::move(enabled_namespaces)} {} + + timer_id + setup_timer(std::string const& ns, std::string const& name) const override { + std::lock_guard lock(timers_mx_); + timer_id rv = timers_.size(); + timers_.emplace_back(ns, name); + return rv; + } + + time_type now() const override { +#ifdef _WIN32 + ::LARGE_INTEGER ticks; + ::QueryPerformanceCounter(&ticks); + return ticks.QuadPart; +#else + struct timespec ts; + ::clock_gettime(CLOCK_MONOTONIC_RAW, &ts); + return UINT64_C(1'000'000'000) * ts.tv_sec + ts.tv_nsec; +#endif + } + + void add_sample(timer_id id, time_type start) const override { + auto elapsed = now() - start; + // No need to acquire the mutex here as existing timers + // never move in the deque. + timers_[id].add_sample(elapsed); + } + + void summarize(std::ostream& os) const override { + int count; + + { + std::lock_guard lock(timers_mx_); + count = timers_.size(); + } + + std::vector> ts; + + for (int i = 0; i < count; ++i) { + auto& t = timers_[i]; + ts.emplace_back(t.get_namespace(), t.total_latency(), i); + } + + std::sort(ts.begin(), ts.end(), [](auto const& a, auto const& b) { + return std::get<0>(a) < std::get<0>(b) || + (std::get<0>(a) == std::get<0>(b) && + std::get<1>(a) > std::get<1>(b)); + }); + + for (auto const& t : ts) { + timers_[std::get<2>(t)].summarize(os, timebase_); + } + } + + bool is_enabled(std::string const& ns) const override { + return enabled_namespaces_.find(ns) != enabled_namespaces_.end(); + } + + private: + static double get_timebase() { +#ifdef _WIN32 + ::LARGE_INTEGER freq; + ::QueryPerformanceFrequency(&freq); + return 1.0 / freq.QuadPart; +#else + return 1e-9; +#endif + } + + std::deque mutable timers_; + std::mutex mutable timers_mx_; + double const timebase_; + std::unordered_set const enabled_namespaces_; +}; + +performance_monitor_proxy::performance_monitor_proxy( + std::shared_ptr mon, + std::string const& mon_namespace) + : mon_{mon && mon->is_enabled(mon_namespace) ? std::move(mon) : nullptr} + , namespace_{mon_namespace} {} + +std::unique_ptr performance_monitor::create( + std::unordered_set const& enabled_namespaces) { + return enabled_namespaces.empty() + ? nullptr + : std::make_unique( + std::move(enabled_namespaces)); +} + +} // namespace dwarfs diff --git a/src/dwarfs_main.cpp b/src/dwarfs_main.cpp index e332def2..ab596cf7 100644 --- a/src/dwarfs_main.cpp +++ b/src/dwarfs_main.cpp @@ -34,6 +34,7 @@ #include #include +#include #include #ifndef DWARFS_FUSE_LOWLEVEL @@ -69,6 +70,7 @@ #include "dwarfs/metadata_v2.h" #include "dwarfs/mmap.h" #include "dwarfs/options.h" +#include "dwarfs/performance_monitor.h" #include "dwarfs/tool.h" #include "dwarfs/util.h" #include "dwarfs/version.h" @@ -102,6 +104,9 @@ struct options { char const* cache_tidy_strategy_str{nullptr}; // TODO: const?? -> use string? char const* cache_tidy_interval_str{nullptr}; // TODO: const?? -> use string? char const* cache_tidy_max_age_str{nullptr}; // TODO: const?? -> use string? +#if DWARFS_PERFMON_ENABLED + char const* perfmon_enabled_str{nullptr}; // TODO: const?? -> use string? +#endif int enable_nlink{0}; int readonly{0}; int cache_image{0}; @@ -123,6 +128,19 @@ struct dwarfs_userdata { options opts; stream_logger lgr; filesystem_v2 fs; + std::shared_ptr perfmon; + PERFMON_EXT_PROXY_DECL + PERFMON_EXT_TIMER_DECL(op_init) + PERFMON_EXT_TIMER_DECL(op_lookup) + PERFMON_EXT_TIMER_DECL(op_getattr) + PERFMON_EXT_TIMER_DECL(op_access) + PERFMON_EXT_TIMER_DECL(op_readlink) + PERFMON_EXT_TIMER_DECL(op_open) + PERFMON_EXT_TIMER_DECL(op_read) + PERFMON_EXT_TIMER_DECL(op_readdir) + PERFMON_EXT_TIMER_DECL(op_statfs) + PERFMON_EXT_TIMER_DECL(op_getxattr) + PERFMON_EXT_TIMER_DECL(op_listxattr) }; // TODO: better error handling @@ -147,6 +165,9 @@ constexpr struct ::fuse_opt dwarfs_opts[] = { DWARFS_OPT("no_cache_image", cache_image, 0), DWARFS_OPT("cache_files", cache_files, 1), DWARFS_OPT("no_cache_files", cache_files, 0), +#if DWARFS_PERFMON_ENABLED + DWARFS_OPT("perfmon=%s", perfmon_enabled_str, 0), +#endif FUSE_OPT_END}; std::unordered_map const @@ -159,8 +180,9 @@ std::unordered_map const namespace { constexpr std::string_view pid_xattr{"user.dwarfs.driver.pid"}; +constexpr std::string_view perfmon_xattr{"user.dwarfs.driver.perfmon"}; -} +} // namespace #if DWARFS_FUSE_LOWLEVEL #define dUSERDATA \ @@ -174,6 +196,7 @@ constexpr std::string_view pid_xattr{"user.dwarfs.driver.pid"}; template void op_init_common(void* data) { auto userdata = reinterpret_cast(data); + PERFMON_EXT_SCOPED_SECTION(*userdata, op_init) LOG_PROXY(LoggerPolicy, userdata->lgr); LOG_DEBUG << __func__; @@ -209,6 +232,7 @@ void* op_init(struct fuse_conn_info* /*conn*/, struct fuse_config* /*cfg*/) { template void op_lookup(fuse_req_t req, fuse_ino_t parent, char const* name) { dUSERDATA; + PERFMON_EXT_SCOPED_SECTION(*userdata, op_lookup) LOG_PROXY(LoggerPolicy, userdata->lgr); LOG_DEBUG << __func__ << "(" << parent << ", " << name << ")"; @@ -283,6 +307,7 @@ int op_getattr_common(LogProxy& log_, dwarfs_userdata* userdata, template void op_getattr(fuse_req_t req, fuse_ino_t ino, struct fuse_file_info*) { dUSERDATA; + PERFMON_EXT_SCOPED_SECTION(*userdata, op_getattr) LOG_PROXY(LoggerPolicy, userdata->lgr); LOG_DEBUG << __func__ << "(" << ino << ")"; @@ -302,6 +327,7 @@ void op_getattr(fuse_req_t req, fuse_ino_t ino, struct fuse_file_info*) { template int op_getattr(char const* path, native_stat* st, struct fuse_file_info*) { dUSERDATA; + PERFMON_EXT_SCOPED_SECTION(*userdata, op_getattr) LOG_PROXY(LoggerPolicy, userdata->lgr); LOG_DEBUG << __func__ << "(" << path << ")"; @@ -335,6 +361,7 @@ int op_access_common(LogProxy& log_, dwarfs_userdata* userdata, int mode, template void op_access(fuse_req_t req, fuse_ino_t ino, int mode) { dUSERDATA; + PERFMON_EXT_SCOPED_SECTION(*userdata, op_access) LOG_PROXY(LoggerPolicy, userdata->lgr); LOG_DEBUG << __func__ << "(" << ino << ")"; @@ -351,6 +378,7 @@ void op_access(fuse_req_t req, fuse_ino_t ino, int mode) { template int op_access(char const* path, int mode) { dUSERDATA; + PERFMON_EXT_SCOPED_SECTION(*userdata, op_access) LOG_PROXY(LoggerPolicy, userdata->lgr); LOG_DEBUG << __func__ << "(" << path << ")"; @@ -387,6 +415,7 @@ int op_readlink_common(LogProxy& log_, dwarfs_userdata* userdata, template void op_readlink(fuse_req_t req, fuse_ino_t ino) { dUSERDATA; + PERFMON_EXT_SCOPED_SECTION(*userdata, op_readlink) LOG_PROXY(LoggerPolicy, userdata->lgr); LOG_DEBUG << __func__; @@ -407,6 +436,7 @@ void op_readlink(fuse_req_t req, fuse_ino_t ino) { template int op_readlink(char const* path, char* buf, size_t buflen) { dUSERDATA; + PERFMON_EXT_SCOPED_SECTION(*userdata, op_readlink) LOG_PROXY(LoggerPolicy, userdata->lgr); LOG_DEBUG << __func__; @@ -460,6 +490,7 @@ int op_open_common(LogProxy& log_, dwarfs_userdata* userdata, template void op_open(fuse_req_t req, fuse_ino_t ino, struct fuse_file_info* fi) { dUSERDATA; + PERFMON_EXT_SCOPED_SECTION(*userdata, op_open) LOG_PROXY(LoggerPolicy, userdata->lgr); LOG_DEBUG << __func__; @@ -477,6 +508,7 @@ void op_open(fuse_req_t req, fuse_ino_t ino, struct fuse_file_info* fi) { template int op_open(char const* path, struct fuse_file_info* fi) { dUSERDATA; + PERFMON_EXT_SCOPED_SECTION(*userdata, op_open) LOG_PROXY(LoggerPolicy, userdata->lgr); LOG_DEBUG << __func__; @@ -491,6 +523,7 @@ template void op_read(fuse_req_t req, fuse_ino_t ino, size_t size, file_off_t off, struct fuse_file_info* fi) { dUSERDATA; + PERFMON_EXT_SCOPED_SECTION(*userdata, op_read) LOG_PROXY(LoggerPolicy, userdata->lgr); LOG_DEBUG << __func__; @@ -535,6 +568,7 @@ template int op_read(char const* path, char* buf, size_t size, native_off_t off, struct fuse_file_info* fi) { dUSERDATA; + PERFMON_EXT_SCOPED_SECTION(*userdata, op_read) LOG_PROXY(LoggerPolicy, userdata->lgr); LOG_DEBUG << __func__; @@ -569,6 +603,7 @@ template void op_readdir(fuse_req_t req, fuse_ino_t ino, size_t size, file_off_t off, struct fuse_file_info* /*fi*/) { dUSERDATA; + PERFMON_EXT_SCOPED_SECTION(*userdata, op_readdir) LOG_PROXY(LoggerPolicy, userdata->lgr); LOG_DEBUG << __func__ << "(" << ino << ", " << size << ", " << off << ")"; @@ -637,6 +672,7 @@ int op_readdir(char const* path, void* buf, fuse_fill_dir_t filler, native_off_t off, struct fuse_file_info* /*fi*/, enum fuse_readdir_flags /*flags*/) { dUSERDATA; + PERFMON_EXT_SCOPED_SECTION(*userdata, op_readdir) LOG_PROXY(LoggerPolicy, userdata->lgr); LOG_DEBUG << __func__ << "(" << path << ")"; @@ -726,6 +762,7 @@ int op_statfs_common(LogProxy& log_, dwarfs_userdata* userdata, template void op_statfs(fuse_req_t req, fuse_ino_t /*ino*/) { dUSERDATA; + PERFMON_EXT_SCOPED_SECTION(*userdata, op_statfs) LOG_PROXY(LoggerPolicy, userdata->lgr); LOG_DEBUG << __func__; @@ -744,6 +781,7 @@ void op_statfs(fuse_req_t req, fuse_ino_t /*ino*/) { template int op_statfs(char const* path, native_statvfs* st) { dUSERDATA; + PERFMON_EXT_SCOPED_SECTION(*userdata, op_statfs) LOG_PROXY(LoggerPolicy, userdata->lgr); LOG_DEBUG << __func__ << "(" << path << ")"; @@ -758,6 +796,7 @@ template void op_getxattr(fuse_req_t req, fuse_ino_t ino, char const* name, size_t size) { dUSERDATA; + PERFMON_EXT_SCOPED_SECTION(*userdata, op_getxattr) LOG_PROXY(LoggerPolicy, userdata->lgr); LOG_DEBUG << __func__ << "(" << ino << ", " << name << ", " << size << ")"; @@ -765,14 +804,34 @@ void op_getxattr(fuse_req_t req, fuse_ino_t ino, char const* name, int err = ENODATA; try { - if (ino == FUSE_ROOT_ID && name == pid_xattr) { - auto pidstr = std::to_string(::getpid()); - if (size > 0) { - fuse_reply_buf(req, pidstr.data(), pidstr.size()); - } else { - fuse_reply_xattr(req, pidstr.size()); + if (ino == FUSE_ROOT_ID) { + if (name == pid_xattr) { + auto pidstr = std::to_string(::getpid()); + if (size > 0) { + fuse_reply_buf(req, pidstr.data(), pidstr.size()); + } else { + fuse_reply_xattr(req, pidstr.size()); + } + return; + } else if (name == perfmon_xattr) { +#if DWARFS_PERFMON_ENABLED + std::ostringstream oss; + if (userdata->perfmon) { + userdata->perfmon->summarize(oss); + } else { + oss << "performance monitor is disabled"; + } + auto summary = oss.str(); +#else + auto summary = std::string("no performance monitor support"); +#endif + if (size > 0) { + fuse_reply_buf(req, summary.data(), summary.size()); + } else { + fuse_reply_xattr(req, summary.size()); + } + return; } - return; } } catch (dwarfs::system_error const& e) { LOG_ERROR << e.what(); @@ -788,6 +847,7 @@ void op_getxattr(fuse_req_t req, fuse_ino_t ino, char const* name, template int op_getxattr(char const* path, char const* name, char* value, size_t size) { dUSERDATA; + PERFMON_EXT_SCOPED_SECTION(*userdata, op_getxattr) LOG_PROXY(LoggerPolicy, userdata->lgr); LOG_DEBUG << __func__ << "(" << path << ", " << name << ", " << size << ")"; @@ -821,11 +881,13 @@ int op_getxattr(char const* path, char const* name, char* value, size_t size) { template int op_listxattr(char const* path, char* list, size_t size) { dUSERDATA; + PERFMON_EXT_SCOPED_SECTION(*userdata, op_listxattr) LOG_PROXY(LoggerPolicy, userdata->lgr); LOG_DEBUG << __func__ << "(" << path << ", " << size << ")"; - const std::string all_xattr = std::string(pid_xattr) + '\0'; + const std::string all_xattr = + std::string(pid_xattr) + '\0' + std::string(perfmon_xattr) + '\0'; if (size > 0) { if (size < all_xattr.size()) { @@ -861,6 +923,9 @@ void usage(char const* progname) { << " -o tidy_strategy=NAME (none)|time|swap\n" << " -o tidy_interval=TIME interval for cache tidying (5m)\n" << " -o tidy_max_age=TIME tidy blocks after this time (10m)\n" +#if DWARFS_PERFMON_ENABLED + << " -o perfmon=name[,...] enable performance monitor\n" +#endif << "\n"; #if DWARFS_FUSE_LOWLEVEL && FUSE_USE_VERSION >= 30 @@ -1071,8 +1136,33 @@ void load_filesystem(dwarfs_userdata& userdata) { #endif ; - userdata.fs = filesystem_v2( - userdata.lgr, std::make_shared(opts.fsimage), fsopts, inode_offset); + std::unordered_set perfmon_enabled; +#if DWARFS_PERFMON_ENABLED + if (opts.perfmon_enabled_str) { + folly::splitTo( + ',', opts.perfmon_enabled_str, + std::inserter(perfmon_enabled, perfmon_enabled.begin())); + } +#endif + + userdata.perfmon = performance_monitor::create(perfmon_enabled); + + PERFMON_EXT_PROXY_SETUP(userdata, userdata.perfmon, "fuse") + PERFMON_EXT_TIMER_SETUP(userdata, op_init) + PERFMON_EXT_TIMER_SETUP(userdata, op_lookup) + PERFMON_EXT_TIMER_SETUP(userdata, op_getattr) + PERFMON_EXT_TIMER_SETUP(userdata, op_access) + PERFMON_EXT_TIMER_SETUP(userdata, op_readlink) + PERFMON_EXT_TIMER_SETUP(userdata, op_open) + PERFMON_EXT_TIMER_SETUP(userdata, op_read) + PERFMON_EXT_TIMER_SETUP(userdata, op_readdir) + PERFMON_EXT_TIMER_SETUP(userdata, op_statfs) + PERFMON_EXT_TIMER_SETUP(userdata, op_getxattr) + PERFMON_EXT_TIMER_SETUP(userdata, op_listxattr) + + userdata.fs = + filesystem_v2(userdata.lgr, std::make_shared(opts.fsimage), fsopts, + inode_offset, userdata.perfmon); ti << "file system initialized"; } @@ -1198,6 +1288,12 @@ int dwarfs_main(int argc, char** argv) { return 1; } + SCOPE_EXIT { + if (userdata.perfmon) { + userdata.perfmon->summarize(std::cerr); + } + }; + #if FUSE_USE_VERSION >= 30 #if DWARFS_FUSE_LOWLEVEL return run_fuse(args, fuse_opts, userdata); diff --git a/src/dwarfsextract_main.cpp b/src/dwarfsextract_main.cpp index c3bab841..d77399a5 100644 --- a/src/dwarfsextract_main.cpp +++ b/src/dwarfsextract_main.cpp @@ -32,6 +32,7 @@ #include "dwarfs/logger.h" #include "dwarfs/mmap.h" #include "dwarfs/options.h" +#include "dwarfs/performance_monitor.h" #include "dwarfs/tool.h" #include "dwarfs/util.h" #include "dwarfs_tool_main.h" @@ -43,6 +44,9 @@ namespace dwarfs { int dwarfsextract_main(int argc, sys_char** argv) { std::string filesystem, output, format, cache_size_str, log_level, image_offset; +#if DWARFS_PERFMON_ENABLED + std::string perfmon_str; +#endif size_t num_workers; bool continue_on_error{false}, disable_integrity_check{false}, stdout_progress{false}; @@ -80,6 +84,11 @@ int dwarfsextract_main(int argc, sys_char** argv) { ("log-level,l", po::value(&log_level)->default_value("warn"), "log level (error, warn, info, debug, trace)") +#if DWARFS_PERFMON_ENABLED + ("perfmon", + po::value(&perfmon_str), + "enable performance monitor") +#endif ("help,h", "output help message and exit"); // clang-format on @@ -118,7 +127,19 @@ int dwarfsextract_main(int argc, sys_char** argv) { fsopts.block_cache.disable_block_integrity_check = disable_integrity_check; fsopts.metadata.enable_nlink = true; - filesystem_v2 fs(lgr, std::make_shared(filesystem), fsopts); + std::unordered_set perfmon_enabled; +#if DWARFS_PERFMON_ENABLED + if (!perfmon_str.empty()) { + folly::splitTo( + ',', perfmon_str, + std::inserter(perfmon_enabled, perfmon_enabled.begin())); + } +#endif + std::shared_ptr perfmon = + performance_monitor::create(perfmon_enabled); + + filesystem_v2 fs(lgr, std::make_shared(filesystem), fsopts, 0, + perfmon); filesystem_extractor fsx(lgr); if (format.empty()) { @@ -157,6 +178,10 @@ int dwarfsextract_main(int argc, sys_char** argv) { rv = fsx.extract(fs, fsx_opts) ? 0 : 2; fsx.close(); + + if (perfmon) { + perfmon->summarize(std::cerr); + } } catch (runtime_error const& e) { std::cerr << folly::exceptionStr(e) << "\n"; return 1;