From a51a66d7108e4bcdc483cbf65c435185f8a106ec Mon Sep 17 00:00:00 2001 From: Eric Sheng Date: Mon, 6 May 2024 08:44:25 -0700 Subject: [PATCH] [#17993] docdb: Add stack trace tracking framework and I/O stack trace counting Summary: This diff adds a framework for counting occurrences of different stack traces, collected where ever `TrackStackTrace()` is executed. Unique stack traces are only ever symbolized at most once, and counts are collected in thread-local counters, in order to keep overhead moderate. Traces are placed into groups specified at the `TrackStackTrace()` call site, and an optional weight can be specified. Read and write syscalls performed through the abstractions in env.cc/file_system.cc are tracked through this in the kReadIO and kWriteIO groups, and the newly added `/io-stack-traces` server UI endpoint exposes this information, consisting of number of calls and number of bytes read (or written) through each trace. A separate new endpoint, `/debug-stack-traces` has also been added to list tracked stack traces in the kDebugging group, which is intended to be unused in committed code and added temporarily as needed through carefully placed `TrackStackTrace()` calls for debugging or investigation purposes. A third endpoint, `/reset-stack-traces` has been added to reset counters on tracked stack traces. Example output of `/io-stack-traces` endpoint: {img https://github.com/yugabyte/yugabyte-db/assets/6742815/5d29a85c-ba7d-40b3-b306-4655ca34d15c} All stack trace tracking is guarded behind the newly added `track_stack_traces` gflag, which is by default on in debug and off in release due to performance considerations (~5% degradation observed with sysbench). Jira: DB-7054 Test Plan: Jenkins. Also added DebugUtilTest.TestTrackedStackTraces: `./yb_build.sh --cxx-test util_debug-util-test --gtest_filter DebugUtilTest.TestTrackedStackTraces` Reviewers: asrivastava Reviewed By: asrivastava Subscribers: ybase Differential Revision: https://phorge.dev.yugabyte.com/D29116 --- src/yb/server/default-path-handlers.cc | 89 +++++++++++ src/yb/util/CMakeLists.txt | 1 + src/yb/util/debug-util-test.cc | 31 ++++ src/yb/util/env_posix.cc | 5 + src/yb/util/file_system_posix.cc | 4 + src/yb/util/stack_trace.cc | 13 ++ src/yb/util/stack_trace.h | 6 + src/yb/util/stack_trace_tracker.cc | 205 +++++++++++++++++++++++++ src/yb/util/stack_trace_tracker.h | 43 ++++++ 9 files changed, 397 insertions(+) create mode 100644 src/yb/util/stack_trace_tracker.cc create mode 100644 src/yb/util/stack_trace_tracker.h diff --git a/src/yb/server/default-path-handlers.cc b/src/yb/server/default-path-handlers.cc index e931bdf93062..1b401d5d192a 100644 --- a/src/yb/server/default-path-handlers.cc +++ b/src/yb/server/default-path-handlers.cc @@ -83,6 +83,7 @@ #include "yb/util/jsonwriter.h" #include "yb/util/result.h" #include "yb/util/status_log.h" +#include "yb/util/stack_trace_tracker.h" #include "yb/util/url-coding.h" #include "yb/util/version_info.h" #include "yb/util/version_info.pb.h" @@ -99,6 +100,7 @@ DEFINE_RUNTIME_uint32(max_prometheus_metric_entries, UINT32_MAX, "adding a metric with all its entities would exceed the limit, then we will drop them all." "Thus, the actual number of metric entries returned might be smaller than the limit."); +DECLARE_bool(track_stack_traces); DECLARE_bool(TEST_mini_cluster_mode); namespace yb { @@ -669,6 +671,87 @@ static void HandleGetVersionInfo( jw.EndObject(); } +static void IOStackTraceHandler(const Webserver::WebRequest& req, Webserver::WebResponse* resp) { + std::stringstream *output = &resp->output; + + if (!GetAtomicFlag(&FLAGS_track_stack_traces)) { + (*output) << "track_stack_traces must be turned on to use this page."; + return; + } + + Tags tags(false /* as_text */); + + auto traces = GetTrackedStackTraces(); + std::sort(traces.begin(), traces.end(), + [](const auto& left, const auto& right) { return left.weight > right.weight; }); + + (*output) << tags.header << "I/O stack traces" << tags.end_header; + + (*output) << tags.table << tags.row + << tags.table_header << "Type" << tags.end_table_header + << tags.table_header << "Count" << tags.end_table_header + << tags.table_header << "Bytes" << tags.end_table_header + << tags.table_header << "Stack Trace" << tags.end_table_header + << tags.end_row; + for (const auto& entry : traces) { + if (entry.count == 0 || + (entry.group != StackTraceTrackingGroup::kReadIO && + entry.group != StackTraceTrackingGroup::kWriteIO)) { + continue; + } + (*output) << tags.row + << tags.cell + << (entry.group == StackTraceTrackingGroup::kReadIO ? "Read" : "Write") + << tags.end_cell + << tags.cell << entry.count << tags.end_cell + << tags.cell << HumanReadableNumBytes::ToString(entry.weight) << tags.end_cell + << tags.cell << tags.pre_tag << EscapeForHtmlToString(entry.symbolized_trace) + << tags.end_pre_tag << tags.end_cell + << tags.end_row; + } + + (*output) << tags.end_table; +} + +static void DebugStackTraceHandler(const Webserver::WebRequest& req, Webserver::WebResponse* resp) { + std::stringstream *output = &resp->output; + + if (!GetAtomicFlag(&FLAGS_track_stack_traces)) { + (*output) << "track_stack_traces must be turned on to use this page."; + return; + } + + Tags tags(false /* as_text */); + + auto traces = GetTrackedStackTraces(); + std::sort(traces.begin(), traces.end(), + [](const auto& left, const auto& right) { return left.count > right.count; }); + + (*output) << tags.header << "Tracked stack traces" << tags.end_header; + + (*output) << tags.table << tags.row + << tags.table_header << "Count" << tags.end_table_header + << tags.table_header << "Stack Trace" << tags.end_table_header + << tags.end_row; + for (const auto& entry : traces) { + if (entry.count == 0 || entry.group != StackTraceTrackingGroup::kDebugging) { + continue; + } + (*output) << tags.row + << tags.cell << entry.count << tags.end_cell + << tags.cell << tags.pre_tag << EscapeForHtmlToString(entry.symbolized_trace) + << tags.end_pre_tag << tags.end_cell + << tags.end_row; + } + + (*output) << tags.end_table; +} + +static void ResetStackTraceHandler(const Webserver::WebRequest& req, Webserver::WebResponse* resp) { + ResetTrackedStackTraces(); + resp->output << "Tracked stack traces reset."; +} + } // anonymous namespace // Registered to handle "/memz", and prints out memory allocation statistics. @@ -707,6 +790,12 @@ void AddDefaultPathHandlers(Webserver* webserver) { "/api/v1/varz", "Flags", std::bind(&GetFlagsJsonHandler, _1, _2, webserver), false, false); webserver->RegisterPathHandler("/api/v1/version-info", "Build Version Info", HandleGetVersionInfo, false, false); + webserver->RegisterPathHandler("/io-stack-traces", "I/O Stack Traces", + IOStackTraceHandler, true, false); + webserver->RegisterPathHandler("/debug-stack-traces", "Debugging Stack Traces", + DebugStackTraceHandler, true, false); + webserver->RegisterPathHandler("/reset-stack-traces", "Reset Stack Traces", + ResetStackTraceHandler, true, false); AddPprofPathHandlers(webserver); } diff --git a/src/yb/util/CMakeLists.txt b/src/yb/util/CMakeLists.txt index 85021bbfdf78..c2b3ca7637f2 100644 --- a/src/yb/util/CMakeLists.txt +++ b/src/yb/util/CMakeLists.txt @@ -220,6 +220,7 @@ set(UTIL_SRCS spinlock_profiling.cc split.cc stack_trace.cc + stack_trace_tracker.cc stats/iostats_context_imp.cc stats/perf_level_imp.cc status.cc diff --git a/src/yb/util/debug-util-test.cc b/src/yb/util/debug-util-test.cc index 876046a25441..f5c5953797c6 100644 --- a/src/yb/util/debug-util-test.cc +++ b/src/yb/util/debug-util-test.cc @@ -47,6 +47,7 @@ #include "yb/util/debug-util.h" #include "yb/util/debug/long_operation_tracker.h" #include "yb/util/scope_exit.h" +#include "yb/util/stack_trace_tracker.h" #include "yb/util/test_macros.h" #include "yb/util/test_util.h" #include "yb/util/thread.h" @@ -61,6 +62,7 @@ using std::vector; using namespace std::literals; +DECLARE_bool(track_stack_traces); DECLARE_bool(TEST_disable_thread_stack_collection_wait); namespace yb { @@ -565,4 +567,33 @@ TEST_F(DebugUtilTest, YB_DISABLE_TEST_ON_MACOS(TestGetStackTraceWhileCreatingThr } thread_holder.Stop(); } + +TEST_F(DebugUtilTest, TestTrackedStackTraces) { + constexpr size_t kNumIterations = 100; + constexpr size_t kWeight = 10; + + ANNOTATE_UNPROTECTED_WRITE(FLAGS_track_stack_traces) = true; + + for (size_t i = 0; i < kNumIterations; ++i) { + TrackStackTrace(StackTraceTrackingGroup::kDebugging, kWeight); + } + + DumpTrackedStackTracesToLog(StackTraceTrackingGroup::kDebugging); + + auto traces = GetTrackedStackTraces(); + // There may be I/O traces tracked during test setup, but kDebugging should never be in + // checked in code, so we can rely on there only be one kDebugging trace. + bool found_debugging_trace = false; + for (size_t i = 0; i < traces.size(); ++i) { + auto& trace = traces[i]; + if (trace.group == StackTraceTrackingGroup::kDebugging) { + ASSERT_FALSE(found_debugging_trace); + found_debugging_trace = true; + ASSERT_EQ(trace.count, kNumIterations); + ASSERT_EQ(trace.weight, kNumIterations * kWeight); + } + } + ASSERT_TRUE(found_debugging_trace); +} + } // namespace yb diff --git a/src/yb/util/env_posix.cc b/src/yb/util/env_posix.cc index c6338da5e9b3..c94424c3191b 100644 --- a/src/yb/util/env_posix.cc +++ b/src/yb/util/env_posix.cc @@ -64,6 +64,7 @@ #include "yb/util/path_util.h" #include "yb/util/result.h" #include "yb/util/slice.h" +#include "yb/util/stack_trace_tracker.h" #include "yb/util/status.h" #include "yb/util/status_format.h" #include "yb/util/status_log.h" @@ -502,6 +503,7 @@ class PosixWritableFile : public WritableFile { return STATUS_IO_ERROR(filename_, errno); } + TrackStackTrace(StackTraceTrackingGroup::kWriteIO, written); UnwrittenRemaining(&remaining_iov, written, &remaining_count); total_written += written; } @@ -697,6 +699,7 @@ class PosixDirectIOWritableFile final : public PosixWritableFile { } return STATUS_IO_ERROR(filename_, errno); } + TrackStackTrace(StackTraceTrackingGroup::kWriteIO, written); next_write_offset_ += written; UnwrittenRemaining(&remaining_iov, written, &remaining_blocks); @@ -791,6 +794,7 @@ class PosixRWFile final : public RWFile { // An error: return a non-ok status. return STATUS_IO_ERROR(filename_, errno); } + TrackStackTrace(StackTraceTrackingGroup::kReadIO, r); Slice this_result(dst, r); DCHECK_LE(this_result.size(), rem); if (this_result.size() == 0) { @@ -814,6 +818,7 @@ class PosixRWFile final : public RWFile { int err = errno; return STATUS_IO_ERROR(filename_, err); } + TrackStackTrace(StackTraceTrackingGroup::kWriteIO, written); if (PREDICT_FALSE(written != implicit_cast(data.size()))) { return STATUS(IOError, diff --git a/src/yb/util/file_system_posix.cc b/src/yb/util/file_system_posix.cc index 33e9879a3bf0..55c63d4b811f 100644 --- a/src/yb/util/file_system_posix.cc +++ b/src/yb/util/file_system_posix.cc @@ -30,6 +30,7 @@ #include "yb/util/errno.h" #include "yb/util/malloc.h" #include "yb/util/result.h" +#include "yb/util/stack_trace_tracker.h" #include "yb/util/stats/iostats_context_imp.h" #include "yb/util/test_kill.h" #include "yb/util/thread_restrictions.h" @@ -125,6 +126,7 @@ Status PosixSequentialFile::Read(size_t n, Slice* result, uint8_t* scratch) { do { r = fread_unlocked(scratch, 1, n, file_); } while (r == 0 && ferror(file_) && errno == EINTR); + TrackStackTrace(StackTraceTrackingGroup::kReadIO, r); *result = Slice(scratch, r); if (r < n) { if (feof(file_)) { @@ -191,6 +193,7 @@ Status PosixRandomAccessFile::Read(uint64_t offset, size_t n, Slice* result, } break; } + TrackStackTrace(StackTraceTrackingGroup::kReadIO, r); ptr += r; offset += r; left -= r; @@ -306,6 +309,7 @@ Status PosixWritableFile::Append(const Slice& data) { } return STATUS_IO_ERROR(filename_, errno); } + yb::TrackStackTrace(yb::StackTraceTrackingGroup::kWriteIO, done); left -= done; src += done; } diff --git a/src/yb/util/stack_trace.cc b/src/yb/util/stack_trace.cc index 1f975f50f8e4..f7829ec089e9 100644 --- a/src/yb/util/stack_trace.cc +++ b/src/yb/util/stack_trace.cc @@ -21,6 +21,7 @@ #include #endif +#include #include #include "yb/gutil/casts.h" @@ -379,6 +380,18 @@ uint64_t StackTrace::HashCode() const { sizeof(frames_[0]) * num_frames_); } +Result StackTrace::MakeStackTrace(std::string_view frames) { + SCHECK_EQ(frames.size() % sizeof(void *), 0, + InvalidArgument, "frames should contain an array of pointers"); + SCHECK(frames.size() / sizeof(void *) <= kMaxFrames, InvalidArgument, "too many frames"); + + StackTrace s; + s.num_frames_ = narrow_cast(frames.size() / sizeof(void *)); + std::memcpy(s.frames_, frames.data(), s.num_frames_ * sizeof(void *)); + return s; +} + + // ------------------------------------------------------------------------------------------------ Result ThreadStack(ThreadIdForStack tid) { diff --git a/src/yb/util/stack_trace.h b/src/yb/util/stack_trace.h index 4387cb61e92f..e43914ab1ac0 100644 --- a/src/yb/util/stack_trace.h +++ b/src/yb/util/stack_trace.h @@ -116,6 +116,12 @@ class StackTrace { pointer_cast(frames_ + num_frames_)); } + std::string_view as_string_view() const { + return std::string_view(pointer_cast(frames_), sizeof(void *) * num_frames_); + } + + static Result MakeStackTrace(std::string_view frames); + private: enum { // The maximum number of stack frames to collect. diff --git a/src/yb/util/stack_trace_tracker.cc b/src/yb/util/stack_trace_tracker.cc new file mode 100644 index 000000000000..c21b771db21c --- /dev/null +++ b/src/yb/util/stack_trace_tracker.cc @@ -0,0 +1,205 @@ +// Copyright (c) YugaByte, Inc. +// +// Licensed under the Apache License, Version 2.0 (the "License"); you may not use this file except +// in compliance with the License. You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software distributed under the License +// is distributed on an "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express +// or implied. See the License for the specific language governing permissions and limitations +// under the License. +// +#include "yb/util/stack_trace_tracker.h" + +#include +#include +#include + +#include "yb/gutil/stl_util.h" +#include "yb/gutil/thread_annotations.h" + +#include "yb/util/atomic.h" +#include "yb/util/debug-util.h" +#include "yb/util/flags.h" +#include "yb/util/stack_trace.h" +#include "yb/util/unique_lock.h" + +DEFINE_RUNTIME_bool(track_stack_traces, yb::IsDebug(), "Whether to enable stack trace tracking"); + +namespace yb { + +namespace { + +class ThreadStackTraceTracker; + +class GlobalStackTraceTracker { + public: + void RegisterThread(std::thread::id id, ThreadStackTraceTracker* tracker) EXCLUDES(mutex_) { + std::lock_guard lock(mutex_); + thread_trackers_[id] = tracker; + } + + Status UnregisterThread(std::thread::id id) EXCLUDES(mutex_) { + std::lock_guard lock(mutex_); + auto itr = thread_trackers_.find(id); + SCHECK(itr != thread_trackers_.end(), NotFound, "Tracker not registered for thread"); + MergeLocalTracker(itr->second); + thread_trackers_.erase(itr); + return Status::OK(); + } + + std::vector GetTrackedStackTraces() EXCLUDES(mutex_) { + std::lock_guard lock(mutex_); + for (auto& [_, tracker] : thread_trackers_) { + MergeLocalTracker(tracker); + } + + std::vector tracked; + tracked.reserve(traces_.size()); + for (auto& [frames, entry] : traces_) { + if (entry.symbolized_trace.empty()) { + auto s = StackTrace::MakeStackTrace(frames); + if (!s.ok()) { + LOG(ERROR) << "Bad stack trace frames: " + << Slice(frames.data(), frames.size()).ToDebugString(); + } + entry.symbolized_trace = s->Symbolize(); + } + tracked.push_back(entry); + } + return tracked; + } + + void ResetTrackedStackTraces() EXCLUDES(mutex_); + + private: + void MergeLocalTracker(ThreadStackTraceTracker* tracker) REQUIRES(mutex_); + + std::mutex mutex_; + UnorderedStringMap traces_ GUARDED_BY(mutex_); + std::unordered_map thread_trackers_ GUARDED_BY(mutex_); +}; + +static GlobalStackTraceTracker global_tracker; + +// This class is thread local and accessed by one thread only, except for when we +// MergeToGlobal/Reset. +class ThreadStackTraceTracker { + public: + ThreadStackTraceTracker() { + global_tracker.RegisterThread(std::this_thread::get_id(), this); + } + + ~ThreadStackTraceTracker() { + auto id = std::this_thread::get_id(); + auto s = global_tracker.UnregisterThread(id); + if (!s.ok()) { + LOG(WARNING) << s; + } + } + + void Trace(StackTraceTrackingGroup group, size_t weight) EXCLUDES(mutex_) { + StackTrace trace; + trace.Collect(); + + auto key = trace.as_string_view(); + + std::lock_guard lock(mutex_); + auto itr = counts_.find(key); + if (itr == counts_.end()) { + itr = counts_.emplace(key, LocalCounts{ .group = group, .count = 0, .weight = 0 }).first; + } + itr->second.count += 1; + itr->second.weight += weight; + } + + void Reset() EXCLUDES(mutex_) { + std::lock_guard lock(mutex_); + for (auto& [_, counts] : counts_) { + counts.count = 0; + counts.weight = 0; + } + } + + private: + friend class GlobalStackTraceTracker; + + struct LocalCounts { + StackTraceTrackingGroup group; + size_t count; + size_t weight; + }; + + std::mutex mutex_; + UnorderedStringMap counts_ GUARDED_BY(mutex_); +}; + +thread_local ThreadStackTraceTracker thread_tracker; + +void GlobalStackTraceTracker::ResetTrackedStackTraces() { + std::lock_guard lock(mutex_); + for (auto& [_, tracker] : thread_trackers_) { + tracker->Reset(); + } + + // We set count/weight to 0 instead of just clearing the traces_ map to avoid resymbolizing + // traces, and because the entries are likely to be recreated soon after anyways. + for (auto& [_, entry] : traces_) { + entry.count = 0; + entry.weight = 0; + } +} + +void GlobalStackTraceTracker::MergeLocalTracker(ThreadStackTraceTracker* tracker) { + std::lock_guard tracker_lock(tracker->mutex_); + for (auto& [trace, counts] : tracker->counts_) { + auto itr = traces_.find(trace); + if (itr == traces_.end()) { + itr = traces_.emplace(trace, StackTraceEntry{ + .group = counts.group, + .symbolized_trace = "", + .count = 0, + .weight = 0, + }).first; + } + itr->second.count += std::exchange(counts.count, 0); + itr->second.weight += std::exchange(counts.weight, 0); + } +} + +} // namespace + +void TrackStackTrace(StackTraceTrackingGroup group, size_t weight) { + if (GetAtomicFlag(&FLAGS_track_stack_traces)) { + thread_tracker.Trace(group, weight); + } +} + +void ResetTrackedStackTraces() { + global_tracker.ResetTrackedStackTraces(); +} + +std::vector GetTrackedStackTraces() { + return global_tracker.GetTrackedStackTraces(); +} + +void DumpTrackedStackTracesToLog(StackTraceTrackingGroup group) { + auto traces = GetTrackedStackTraces(); + std::sort(traces.begin(), traces.end(), + [](const auto& left, const auto& right) { return left.count > right.count; }); + size_t count = 0; + for (const auto& entry : traces) { + if (entry.count == 0 || entry.group != group) { + continue; + } + LOG(INFO) << "Tracked stack trace: count=" << entry.count << " weight=" << entry.weight + << '\n' << entry.symbolized_trace; + ++count; + } + if (!count) { + LOG(INFO) << "No tracked stack traces in group: " << AsString(group); + } +} + +} // namespace yb diff --git a/src/yb/util/stack_trace_tracker.h b/src/yb/util/stack_trace_tracker.h new file mode 100644 index 000000000000..25d1e71fe9fe --- /dev/null +++ b/src/yb/util/stack_trace_tracker.h @@ -0,0 +1,43 @@ +// Copyright (c) YugaByte, Inc. +// +// Licensed under the Apache License, Version 2.0 (the "License"); you may not use this file except +// in compliance with the License. You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software distributed under the License +// is distributed on an "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express +// or implied. See the License for the specific language governing permissions and limitations +// under the License. +// +#pragma once + +#include +#include + +#include "yb/util/enums.h" + +namespace yb { + +YB_DEFINE_ENUM(StackTraceTrackingGroup, + (kDebugging) // For debugging use via inserted yb::TrackStackTrace() calls. + (kReadIO) // Read I/O syscalls. + (kWriteIO)); // Write I/O syscalls. + +struct StackTraceEntry { + StackTraceTrackingGroup group; + std::string symbolized_trace; + size_t count; + size_t weight; +}; + +void TrackStackTrace( + StackTraceTrackingGroup group = StackTraceTrackingGroup::kDebugging, size_t weight = 1); + +void ResetTrackedStackTraces(); + +std::vector GetTrackedStackTraces(); + +void DumpTrackedStackTracesToLog(StackTraceTrackingGroup group); + +} // namespace yb