Repository: kudu Updated Branches: refs/heads/master 416b3018a -> 00815045f
KUDU-2297 (part 3): refactor process-wide stack collection out of /stacks Previously a bunch of logic to collect all the stacks from the process was in the /stacks path handler. This logic is relatively generic and shouldn't be intermingled with the formatting code. In particular I'd like to use it in the diagnostics log, where a different output format is desirable. Change-Id: Ibb7c6edd31254f3d7e0cbef1eaf575bde3570df6 Reviewed-on: http://gerrit.cloudera.org:8080/9329 Tested-by: Todd Lipcon <t...@apache.org> Reviewed-by: Mike Percy <mpe...@apache.org> Project: http://git-wip-us.apache.org/repos/asf/kudu/repo Commit: http://git-wip-us.apache.org/repos/asf/kudu/commit/831483b4 Tree: http://git-wip-us.apache.org/repos/asf/kudu/tree/831483b4 Diff: http://git-wip-us.apache.org/repos/asf/kudu/diff/831483b4 Branch: refs/heads/master Commit: 831483b47fd0e2165c3612811fdbf6337e3891b8 Parents: 416b301 Author: Todd Lipcon <t...@apache.org> Authored: Wed Feb 14 14:43:32 2018 -0800 Committer: Todd Lipcon <t...@apache.org> Committed: Fri Feb 23 23:06:30 2018 +0000 ---------------------------------------------------------------------- src/kudu/server/default_path_handlers.cc | 101 +++++--------------------- src/kudu/server/diagnostics_log.cc | 4 +- src/kudu/util/debug-util-test.cc | 65 +++++++++-------- src/kudu/util/debug-util.cc | 75 +++++++++++++++++++ src/kudu/util/debug-util.h | 59 +++++++++++++++ 5 files changed, 191 insertions(+), 113 deletions(-) ---------------------------------------------------------------------- http://git-wip-us.apache.org/repos/asf/kudu/blob/831483b4/src/kudu/server/default_path_handlers.cc ---------------------------------------------------------------------- diff --git a/src/kudu/server/default_path_handlers.cc b/src/kudu/server/default_path_handlers.cc index b857be5..7574def 100644 --- a/src/kudu/server/default_path_handlers.cc +++ b/src/kudu/server/default_path_handlers.cc @@ -18,17 +18,13 @@ #include "kudu/server/default_path_handlers.h" #include <sys/stat.h> -#include <sys/types.h> #include <cstddef> #include <cstdint> #include <fstream> -#include <iterator> -#include <map> #include <memory> #include <string> #include <unordered_map> -#include <utility> #include <vector> #include <boost/algorithm/string/predicate.hpp> @@ -48,13 +44,12 @@ #include "kudu/gutil/strings/human_readable.h" #include "kudu/gutil/strings/numbers.h" #include "kudu/gutil/strings/split.h" -#include "kudu/gutil/strings/strip.h" #include "kudu/gutil/strings/substitute.h" #include "kudu/server/pprof_path_handlers.h" #include "kudu/server/webserver.h" +#include "kudu/util/array_view.h" #include "kudu/util/debug-util.h" #include "kudu/util/easy_json.h" -#include "kudu/util/env.h" #include "kudu/util/faststring.h" #include "kudu/util/flag_tags.h" #include "kudu/util/flags.h" @@ -157,90 +152,34 @@ static void FlagsHandler(const Webserver::WebRequest& req, // Prints out the current stack trace of all threads in the process. static void StacksHandler(const Webserver::WebRequest& /*req*/, Webserver::PrerenderedWebResponse* resp) { - MonoTime start = MonoTime::Now(); std::ostringstream* output = resp->output; - vector<pid_t> tids; - Status s = ListThreads(&tids); + + StackTraceSnapshot snap; + auto start = MonoTime::Now(); + Status s = snap.SnapshotAllStacks(); if (!s.ok()) { - *output << "Failed to list threads: " << s.ToString(); + *output << "Failed to collect stacks: " << s.ToString(); return; } - struct Info { - pid_t tid; - Status status; - string thread_name; - StackTraceCollector stc; - StackTrace stack; - }; - - // Initially trigger all the stack traces. - vector<Info> infos(tids.size()); - for (int i = 0; i < tids.size(); i++) { - infos[i].tid = tids[i]; - infos[i].status = infos[i].stc.TriggerAsync(tids[i], &infos[i].stack); - } - - // Now collect the thread names while we are waiting on stack trace collection. - for (auto& info : infos) { - // Get the thread's name by reading proc. - // TODO(todd): should we have the dumped thread fill in its own name using - // prctl to avoid having to open and read /proc? Or maybe we should use the - // Kudu ThreadMgr to get the thread names for the cases where we are using - // the kudu::Thread wrapper at least. - faststring buf; - Status s = ReadFileToString(Env::Default(), - Substitute("/proc/self/task/$0/comm", info.tid), - &buf); - if (!s.ok()) { - info.thread_name = "<unknown name>"; - } else { - info.thread_name = buf.ToString(); - StripTrailingNewline(&info.thread_name); - } - } - - // Now actually collect all the stacks. - MonoTime deadline = MonoTime::Now() + MonoDelta::FromSeconds(1); - for (auto& info : infos) { - info.status = info.status.AndThen([&] { - return info.stc.AwaitCollection(deadline); - }); - } + auto dur = MonoTime::Now() - start; - // And group the threads by their stack trace. - std::multimap<string, Info*> grouped_infos; - int num_failed = 0; - for (auto& info : infos) { - if (info.status.ok()) { - grouped_infos.emplace(info.stack.ToHexString(), &info); - } else { - num_failed++; - } - } - MonoDelta dur = MonoTime::Now() - start; - - *output << "Collected stacks from " << grouped_infos.size() << " threads in " + *output << "Collected stacks from " << snap.num_threads() << " threads in " << dur.ToString() << "\n"; - if (num_failed) { - *output << "Failed to collect stacks from " << num_failed << " threads " + if (snap.num_failed()) { + *output << "Failed to collect stacks from " << snap.num_failed() << " threads " << "(they may have exited while we were iterating over the threads)\n"; } *output << "\n"; - for (auto it = grouped_infos.begin(); it != grouped_infos.end();) { - auto end_group = grouped_infos.equal_range(it->first).second; - const auto& stack = it->second->stack; - int num_in_group = std::distance(it, end_group); - if (num_in_group > 1) { - *output << num_in_group << " threads with same stack:\n"; - } - - while (it != end_group) { - const auto& info = it->second; - *output << "TID " << info->tid << "(" << info->thread_name << "):\n"; - ++it; - } - *output << stack.Symbolize() << "\n\n"; - } + snap.VisitGroups([&](ArrayView<StackTraceSnapshot::ThreadInfo> threads) { + if (threads.size() > 1) { + *output << threads.size() << " threads with same stack:\n"; + } + + for (auto& info : threads) { + *output << "TID " << info.tid << "(" << info.thread_name << "):\n"; + } + *output << threads[0].stack.Symbolize() << "\n\n"; + }); } // Registered to handle "/memz", and prints out memory allocation statistics. http://git-wip-us.apache.org/repos/asf/kudu/blob/831483b4/src/kudu/server/diagnostics_log.cc ---------------------------------------------------------------------- diff --git a/src/kudu/server/diagnostics_log.cc b/src/kudu/server/diagnostics_log.cc index fc91a3a..0246347 100644 --- a/src/kudu/server/diagnostics_log.cc +++ b/src/kudu/server/diagnostics_log.cc @@ -15,6 +15,8 @@ // specific language governing permissions and limitations // under the License. +#include "kudu/server/diagnostics_log.h" + #include <cstdint> #include <memory> #include <ostream> @@ -26,7 +28,6 @@ #include "kudu/gutil/ref_counted.h" #include "kudu/gutil/strings/substitute.h" #include "kudu/gutil/walltime.h" -#include "kudu/server/diagnostics_log.h" #include "kudu/util/condition_variable.h" #include "kudu/util/env.h" #include "kudu/util/jsonwriter.h" @@ -38,7 +39,6 @@ #include "kudu/util/status.h" #include "kudu/util/thread.h" - using std::string; using std::unique_ptr; using strings::Substitute; http://git-wip-us.apache.org/repos/asf/kudu/blob/831483b4/src/kudu/util/debug-util-test.cc ---------------------------------------------------------------------- diff --git a/src/kudu/util/debug-util-test.cc b/src/kudu/util/debug-util-test.cc index c51bf0c..a9b841f 100644 --- a/src/kudu/util/debug-util-test.cc +++ b/src/kudu/util/debug-util-test.cc @@ -23,7 +23,6 @@ #include <csignal> #include <cstddef> -#include <memory> #include <ostream> #include <string> #include <vector> @@ -32,6 +31,7 @@ #include <gtest/gtest.h> #include "kudu/gutil/ref_counted.h" +#include "kudu/util/array_view.h" #include "kudu/util/countdown_latch.h" #include "kudu/util/debug-util.h" #include "kudu/util/monotime.h" @@ -149,7 +149,17 @@ TEST_F(DebugUtilTest, TestSignalStackTrace) { // Test which dumps all known threads within this process. // We don't validate the results in any way -- but this verifies that we can // dump library threads such as the libc timer_thread and properly time out. -TEST_F(DebugUtilTest, TestDumpAllThreads) { +TEST_F(DebugUtilTest, TestSnapshot) { + // The test and runtime environment runs various utility threads (for example, + // the kernel stack watchdog, the TSAN runtime thread, the test timeout thread, etc). + // Count them before we start any additional threads for this test. + int initial_thread_count; + { + vector<pid_t> threads; + ASSERT_OK(ListThreads(&threads)); + initial_thread_count = threads.size(); + } + // Start a bunch of sleeping threads. const int kNumThreads = 30; CountDownLatch l(1); @@ -166,34 +176,29 @@ TEST_F(DebugUtilTest, TestDumpAllThreads) { } }); - // Trigger all of the stack traces. - vector<pid_t> tids; - ASSERT_OK(ListThreads(&tids)); - vector<StackTraceCollector> collectors(tids.size()); - vector<StackTrace> traces(tids.size()); - vector<Status> status(tids.size()); - - for (int i = 0; i < tids.size(); i++) { - status[i] = collectors[i].TriggerAsync(tids[i], &traces[i]); - } - - // Collect them all. - MonoTime deadline; - #ifdef THREAD_SANITIZER - // TSAN runs its own separate background thread which blocks all signals and - // thus will cause a timeout here. - deadline = MonoTime::Now() + MonoDelta::FromSeconds(3); - #else - // In normal builds we can expect to get a response from all threads. - deadline = MonoTime::Max(); - #endif - for (int i = 0; i < tids.size(); i++) { - status[i] = status[i].AndThen([&] { - return collectors[i].AwaitCollection(deadline); - }); - LOG(INFO) << "Thread " << tids[i] << ": " << status[i].ToString() - << ": " << traces[i].ToHexString(); - } + StackTraceSnapshot snap; + ASSERT_OK(snap.SnapshotAllStacks()); + int count = 0; + int groups = 0; + snap.VisitGroups([&](ArrayView<StackTraceSnapshot::ThreadInfo> group) { + groups++; + for (auto& info : group) { + count++; + LOG(INFO) << info.tid << " " << info.thread_name; + } + LOG(INFO) << group[0].stack.ToHexString(); + }); + int tsan_threads = 0; +#ifdef THREAD_SANITIZER + // TSAN starts an extra thread of its own. + tsan_threads++; +#endif + ASSERT_EQ(kNumThreads + initial_thread_count, count); + // The threads might not have exactly identical stacks, but + // we should have far fewer groups than the total number + // of threads. + ASSERT_LE(groups, kNumThreads / 2); + ASSERT_EQ(tsan_threads, snap.num_failed()); } TEST_F(DebugUtilTest, Benchmark) { http://git-wip-us.apache.org/repos/asf/kudu/blob/831483b4/src/kudu/util/debug-util.cc ---------------------------------------------------------------------- diff --git a/src/kudu/util/debug-util.cc b/src/kudu/util/debug-util.cc index 128cbdf..e2654f4 100644 --- a/src/kudu/util/debug-util.cc +++ b/src/kudu/util/debug-util.cc @@ -28,11 +28,13 @@ #endif #include <unistd.h> +#include <algorithm> #include <atomic> #include <cerrno> #include <climits> #include <csignal> #include <ctime> +#include <iterator> #include <memory> #include <ostream> #include <string> @@ -53,13 +55,17 @@ #include "kudu/gutil/spinlock.h" #include "kudu/gutil/stringprintf.h" #include "kudu/gutil/strings/numbers.h" +#include "kudu/gutil/strings/strip.h" #include "kudu/gutil/strings/substitute.h" +#include "kudu/util/array_view.h" #include "kudu/util/debug/leak_annotations.h" #ifndef __linux__ #include "kudu/util/debug/sanitizer_scopes.h" #endif #include "kudu/util/debug/unwind_safeness.h" +#include "kudu/util/env.h" #include "kudu/util/errno.h" +#include "kudu/util/faststring.h" #include "kudu/util/monotime.h" #include "kudu/util/scoped_cleanup.h" #include "kudu/util/thread.h" @@ -694,4 +700,73 @@ uint64_t StackTrace::HashCode() const { sizeof(frames_[0]) * num_frames_); } +bool StackTrace::LessThan(const StackTrace& s) const { + return std::lexicographical_compare(frames_, &frames_[num_frames_], + s.frames_, &s.frames_[num_frames_]); +} + +Status StackTraceSnapshot::SnapshotAllStacks() { + vector<pid_t> tids; + RETURN_NOT_OK_PREPEND(ListThreads(&tids), "could not list threads"); + + collectors_.clear(); + collectors_.resize(tids.size()); + infos_.clear(); + infos_.resize(tids.size()); + for (int i = 0; i < tids.size(); i++) { + infos_[i].tid = tids[i]; + infos_[i].status = collectors_[i].TriggerAsync(tids[i], &infos_[i].stack); + } + + // Now collect the thread names while we are waiting on stack trace collection. + for (auto& info : infos_) { + if (!info.status.ok()) continue; + + // Get the thread's name by reading proc. + // TODO(todd): should we have the dumped thread fill in its own name using + // prctl to avoid having to open and read /proc? Or maybe we should use the + // Kudu ThreadMgr to get the thread names for the cases where we are using + // the kudu::Thread wrapper at least. + faststring buf; + Status s = ReadFileToString(Env::Default(), + strings::Substitute("/proc/self/task/$0/comm", info.tid), + &buf); + if (!s.ok()) { + info.thread_name = "<unknown name>"; + } else { + info.thread_name = buf.ToString(); + StripTrailingNewline(&info.thread_name); + } + } + num_failed_ = 0; + MonoTime deadline = MonoTime::Now() + MonoDelta::FromSeconds(1); + for (int i = 0; i < infos_.size(); i++) { + infos_[i].status = infos_[i].status.AndThen([&] { + return collectors_[i].AwaitCollection(deadline); + }); + if (!infos_[i].status.ok()) { + num_failed_++; + CHECK(!infos_[i].stack.HasCollected()) << infos_[i].status.ToString(); + } + } + collectors_.clear(); + + std::sort(infos_.begin(), infos_.end(), [](const ThreadInfo& a, const ThreadInfo& b) { + return a.stack.LessThan(b.stack); + }); + return Status::OK(); +} + +void StackTraceSnapshot::VisitGroups(const StackTraceSnapshot::VisitorFunc& visitor) { + auto group_start = infos_.begin(); + auto group_end = group_start; + while (group_end != infos_.end()) { + do { + ++group_end; + } while (group_end != infos_.end() && group_end->stack.Equals(group_start->stack)); + visitor(ArrayView<ThreadInfo>(&*group_start, std::distance(group_start, group_end))); + group_start = group_end; + } +} + } // namespace kudu http://git-wip-us.apache.org/repos/asf/kudu/blob/831483b4/src/kudu/util/debug-util.h ---------------------------------------------------------------------- diff --git a/src/kudu/util/debug-util.h b/src/kudu/util/debug-util.h index 8ed8f43..4679f36 100644 --- a/src/kudu/util/debug-util.h +++ b/src/kudu/util/debug-util.h @@ -21,6 +21,7 @@ #include <cstdint> #include <cstring> +#include <functional> #include <string> #include <vector> @@ -30,8 +31,10 @@ namespace kudu { +template <typename T> class ArrayView; class MonoTime; class StackTrace; +class StackTraceCollector; namespace stack_trace_internal { struct SignalData; @@ -131,6 +134,9 @@ class StackTrace { num_frames_ * sizeof(frames_[0])); } + // Comparison operator for use in sorting. + bool LessThan(const StackTrace& s) const; + // Collect and store the current stack trace. Skips the top 'skip_frames' frames // from the stack. For example, a value of '1' will skip whichever function // called the 'Collect()' function. The 'Collect' function itself is always skipped. @@ -182,6 +188,59 @@ class StackTrace { void* frames_[kMaxFrames]; }; +// Utility class for gathering a process-wide snapshot of the stack traces +// of all threads. +class StackTraceSnapshot { + public: + // The information about each thread will be gathered in a struct. + struct ThreadInfo { + // The TID of the thread. + int64_t tid; + + // The status of collection. If a thread exits during collection or + // was blocking signals, it's possible to have an error here. + Status status; + + // The name of the thread. + // May be missing if 'status' is not OK. + std::string thread_name; + + // The current stack trace of the thread. + // Always missing if 'status' is not OK. + StackTrace stack; + }; + using VisitorFunc = std::function<void(ArrayView<ThreadInfo> group)>; + + // Snapshot the stack traces of all threads in the process. + // + // NOTE: this may take some time and should not be called in a latency-sensitive + // context. + Status SnapshotAllStacks(); + + // After having collected stacks, visit them, grouped by shared + // stack trace. The visitor function will be called once per group. + // Each group is guaranteed to be non-empty. + // + // Any threads which failed to collect traces are returned as a single group + // having empty stack traces. + // + // REQUIRES: a previous successful call to SnapshotAllStacks(). + void VisitGroups(const VisitorFunc& visitor); + + // Return the number of threads which were interrogated for a stack trace. + // + // NOTE: this includes threads which failed to collect. + int num_threads() const { return infos_.size(); } + + // Return the number of threads which failed to collect a stack trace. + int num_failed() const { return num_failed_; } + + private: + std::vector<StackTraceSnapshot::ThreadInfo> infos_; + std::vector<StackTraceCollector> collectors_; + int num_failed_ = 0; +}; + // Class to collect the stack trace of another thread within this process. // This allows for more advanced use cases than 'DumpThreadStack(tid)' above.
