Improve logging and data path measurements (205333c0) · Commits · hpc / gekkofs

README.md

+9 −0

Original line number	Diff line number	Diff line
		@@ -366,6 +366,15 @@ For the daemon, the `GKFS_DAEMON_LOG_PATH=<path/to/file>` environment variable c
		log file, and the log module can be selected with the `GKFS_DAEMON_LOG_LEVEL={off,critical,err,warn,info,debug,trace}`
		environment variable.

		For rank-heavy jobs, set `GKFS_DAEMON_LOG_PER_PROCESS=ON` and
		`GKFS_PROXY_LOG_PER_PROCESS=ON` to append host, rank, and PID to daemon/proxy
		log paths. Client, daemon, and proxy records include timestamp, PID/TID, host,
		rank, level, and subsystem fields. Set `LIBGKFS_LOG_SAMPLE_RATE`,
		`GKFS_DAEMON_LOG_SAMPLE_RATE`, or `GKFS_PROXY_LOG_SAMPLE_RATE` to sample
		high-frequency debug/trace records; `1` logs every record. Startup summaries
		are printed to stderr. Rotation and disk-usage caps are not provided by this
		configuration.

		# Advanced and experimental features

		## Rename

WIP.md

+24 −4

Original line number	Diff line number	Diff line
		@@ -296,8 +296,12 @@ semantics and no unintended escape from the configured scope.

		### 13. Redesign logging defaults for rank-heavy workloads

		Status: Partial. Per-process defaults and boolean parsing are implemented.
		Structured records, rotation, caps, and scale measurements remain.
		Status: Done for the requested scope. Client, daemon, and proxy logs support
		host/rank/PID/TID/subsystem context, per-process paths, sampled high-frequency
		debug/trace records, and concise stderr startup summaries. The scale helper
		records 1/56/896-client wall time, workload CPU time, maximum RSS, log file count,
		and log bytes.
		Log rotation and disk-usage caps are intentionally excluded.

		Shared client logs can serialize many ranks and resemble a performance hang.
		Default to per-process/rank files at scale, support structured records with
		@@ -324,8 +328,18 @@ Timestamped snapshots now include sampled I/O queue depth and migration
		counters in file/log output and Prometheus gauges. RPC and backend error,
		retry, and latency aggregates are included. Legacy client MessagePack/libzmq
		metrics remain unchanged. Daemon operation/byte totals are included in periodic
		snapshots. Distributed tracing and broader RPC timeout/materialization metrics
		remain.
		snapshots. Mutation state and expand-on-demand fallback/materialization events
		are included in daemon snapshots, with event-time Prometheus counters where
		enabled. Sampled distributed tracing is startup-only (`GKFS_ENABLE_TRACE`,
		`GKFS_TRACE_SAMPLE_RATE`) and carries correlation IDs through Thallium RPCs.
		This is intentionally a protocol upgrade: mixed old/new client, proxy, and
		daemon binaries are unsupported. Broader RPC timeout coverage remains.
		Client endpoint lookups use one bounded retry/jitter policy for startup and
		malleability paths. Client RPC deadlines are now startup-configurable through
		`LIBGKFS_RPC_TIMEOUT_MS` and cover client metadata, data, proxy, and control
		forwarding paths without automatic retries of non-idempotent requests. Remaining
		work is timeout-specific event metrics/traces and an explicit proxy/daemon
		deadline policy.

		Define stable, low-cardinality metrics for operation count/bytes/latency/errors;
		RPC queues, retries, and timeouts; backend latency and cache hits; migration and
		@@ -344,6 +358,12 @@ storms, small-file concurrency, large sequential I/O, and 56+ clients.

		### 17. Reduce copies and allocations in data I/O

		Status: Partial. Proxy read/write staging buffers and one-segment bulk
		descriptors are reused per worker thread with bounded retention. Proxy shutdown
		logs staged bytes, staging-buffer growths, and bulk-descriptor setup counts.
		Daemon snapshots now include bulk write/read byte counters. Benchmark comparison
		and full cross-component allocation metrics remain.

		Profile client, proxy, daemon, and backend separately. Introduce bounded buffer
		pools where ownership is clear, use spans/views for non-owning data, batch
		adjacent chunk requests where semantics permit, and measure alignment, direct

docs/sphinx/users/running.md

+15 −0

Original line number	Diff line number	Diff line
		@@ -219,6 +219,21 @@ For the daemon, the `GKFS_DAEMON_LOG_PATH=<path/to/file>` environment variable c
		log file, and the log module can be selected with the `GKFS_DAEMON_LOG_LEVEL={off,critical,err,warn,info,debug,trace}`
		environment variable whereas `trace` produces the most trace records while `info` is the default value.

		For rank-heavy jobs, use `GKFS_DAEMON_LOG_PER_PROCESS=ON` and
		`GKFS_PROXY_LOG_PER_PROCESS=ON` for host/rank/PID-specific log files. Structured
		records include timestamp, PID/TID, host, rank, level, and subsystem. Use
		`LIBGKFS_LOG_SAMPLE_RATE`, `GKFS_DAEMON_LOG_SAMPLE_RATE`, and
		`GKFS_PROXY_LOG_SAMPLE_RATE` to sample high-frequency debug/trace records.
		Startup summaries are printed to stderr. The scale measurement helper runs a
		workload at 1, 56, and 896 clients:

		```bash
		./scripts/measure_logging_scale.py \
		--command 'srun -n {clients} ./workload /mnt/gekkofs' \
		--log-dir /tmp/gkfs-logging-scale \
		--output /tmp/gkfs-logging-scale.csv
		```

		## Miscellaneous

		### External functions

include/client/env.hpp

+1 −0

Original line number	Diff line number	Diff line
		@@ -58,6 +58,7 @@ static constexpr auto LOG_SYSCALL_FILTER = ADD_PREFIX("LOG_SYSCALL_FILTER");
		static constexpr auto LOG_OUTPUT = ADD_PREFIX("LOG_OUTPUT");
		static constexpr auto LOG_PER_PROCESS = ADD_PREFIX("LOG_PER_PROCESS");
		static constexpr auto LOG_OUTPUT_TRUNC = ADD_PREFIX("LOG_OUTPUT_TRUNC");
		static constexpr auto LOG_SAMPLE_RATE = ADD_PREFIX("LOG_SAMPLE_RATE");
		static constexpr auto CWD = ADD_PREFIX("CWD");
		static constexpr auto HOSTS_FILE = ADD_PREFIX("HOSTS_FILE");
		static constexpr auto FORWARDING_MAP_FILE = ADD_PREFIX("FORWARDING_MAP_FILE");

include/client/logging.hpp

+46 −4

Original line number	Diff line number	Diff line
		@@ -48,6 +48,7 @@
		#include <client/make_array.hpp>
		#include <client/syscalls.hpp>
		#include <optional>
		#include <atomic>
		#include <fmt/format.h>
		#include <fmt/ostream.h>

		@@ -401,6 +402,13 @@ struct logger {

		~logger();

		std::string
		context() const {
		return fmt::format("pid={} host={} rank={}",
		static_cast<long long>(::getpid()), log_hostname_,
		log_rank_);
		}

		template <typename... Args>
		inline void
		log(log_level level, const char* const func, const int lineno,
		@@ -409,11 +417,21 @@ struct logger {
		if(!(level & log_mask_)) {
		return;
		}
		if(!!(level & log::debug) && log_sample_rate_ > 1 &&
		log_sample_counter_->fetch_add(1, std::memory_order_relaxed) %
		log_sample_rate_ !=
		0) {
		return;
		}

		static_buffer buffer;
		detail::format_timestamp_to(buffer);
		fmt::format_to(std::back_inserter(buffer), "[{}] [{}] ",
		log_process_id_, lookup_level_name(level));
		fmt::format_to(
		std::back_inserter(buffer),
		"[pid={}] [tid={}] [host={}] [rank={}] [subsystem=client] "
		"[level={}] ",
		static_cast<long long>(::getpid()), log_process_id_,
		log_hostname_, log_rank_, lookup_level_name(level));

		if(!!(level & log::debug)) {
		fmt::format_to(std::back_inserter(buffer), "<{}():{}> ", func,
		@@ -431,6 +449,12 @@ struct logger {
		if(!(level & log_mask_)) {
		return 0;
		}
		if(!!(level & log::debug) && log_sample_rate_ > 1 &&
		log_sample_counter_->fetch_add(1, std::memory_order_relaxed) %
		log_sample_rate_ !=
		0) {
		return 0;
		}

		// we use buffer views to compose the logging messages to
		// avoid copying buffers as much as possible
		@@ -456,8 +480,12 @@ struct logger {

		static_buffer prefix;
		detail::format_timestamp_to(prefix);
		fmt::format_to(std::back_inserter(prefix), "[{}] [{}] ",
		log_process_id_, lookup_level_name(level));
		fmt::format_to(
		std::back_inserter(prefix),
		"[pid={}] [tid={}] [host={}] [rank={}] [subsystem=client] "
		"[level={}] ",
		static_cast<long long>(::getpid()), log_process_id_,
		log_hostname_, log_rank_, lookup_level_name(level));

		char buffer[max_buffer_size];
		const int n = vsnprintf(buffer, sizeof(buffer), fmt, ap);
		@@ -521,6 +549,11 @@ struct logger {

		int log_fd_;
		int log_process_id_;
		std::string log_hostname_;
		std::string log_rank_;
		uint64_t log_sample_rate_{1};
		std::shared_ptr<std::atomic<uint64_t>> log_sample_counter_{
		std::make_shared<std::atomic<uint64_t>>(0)};
		log_level log_mask_;

		#ifdef GKFS_DEBUG_BUILD
		@@ -550,6 +583,15 @@ get_global_logger() {
		return logger::global_logger();
		}

		static inline std::string
		global_context() {
		const auto& logger = get_global_logger();
		if(!logger) {
		return "pid=unknown host=unknown rank=unknown";
		}
		return logger->context();
		}

		static inline void
		destroy_global_logger() {
		logger::global_logger().reset();