From cfb4b4c7cfaf3956d59fd4a5459e0690eb31eb74 Mon Sep 17 00:00:00 2001 From: iphydf Date: Mon, 27 Apr 2020 02:57:21 +0000 Subject: [PATCH] Add execution trace option for debugging. Use `cmake -DEXECUTION_TRACE=ON` to use it. --- CMakeLists.txt | 12 +++- testing/BUILD.bazel | 10 ++- testing/trace.cc | 171 ++++++++++++++++++++++++++++++++++++++++++++ 3 files changed, 190 insertions(+), 3 deletions(-) create mode 100644 testing/trace.cc diff --git a/CMakeLists.txt b/CMakeLists.txt index f108e2b10e..73f66cf1f3 100644 --- a/CMakeLists.txt +++ b/CMakeLists.txt @@ -82,6 +82,11 @@ else() message(STATUS "Supported C++ compiler features = ${CMAKE_CXX_COMPILE_FEATURES}") endif() +option(EXECUTION_TRACE "Print a function trace during execution (for debugging)" OFF) +if(EXECUTION_TRACE) + set(CMAKE_C_FLAGS "${CMAKE_C_FLAGS} -finstrument-functions") +endif() + set(MIN_LOGGER_LEVEL "" CACHE STRING "Logging level to use (TRACE, DEBUG, INFO, WARNING, ERROR)") if(MIN_LOGGER_LEVEL) if(("${MIN_LOGGER_LEVEL}" STREQUAL "TRACE") OR @@ -360,9 +365,14 @@ unit_test(toxcore util) # ################################################################################ -add_library(misc_tools +set(misc_tools_SOURCES testing/misc_tools.c testing/misc_tools.h) +if(EXECUTION_TRACE) + set(misc_tools_SOURCES ${misc_tools_SOURCES} + testing/trace.cc) +endif() +add_library(misc_tools ${misc_tools_SOURCES}) target_link_modules(misc_tools toxcore) set(TEST_TIMEOUT_SECONDS "" CACHE STRING "Limit runtime of each test to the number of seconds specified") diff --git a/testing/BUILD.bazel b/testing/BUILD.bazel index 34f2d44cb2..5a2a019400 100644 --- a/testing/BUILD.bazel +++ b/testing/BUILD.bazel @@ -1,5 +1,4 @@ -load("@rules_cc//cc:defs.bzl", "cc_binary") -load("//tools:no_undefined.bzl", "cc_library") +load("@rules_cc//cc:defs.bzl", "cc_binary", "cc_library") cc_library( name = "misc_tools", @@ -9,6 +8,13 @@ cc_library( deps = ["//c-toxcore/toxcore"], ) +cc_library( + name = "trace", + srcs = ["trace.cc"], + visibility = ["//c-toxcore:__subpackages__"], + alwayslink = True, +) + cc_binary( name = "DHT_test", srcs = ["DHT_test.c"], diff --git a/testing/trace.cc b/testing/trace.cc new file mode 100644 index 0000000000..430db9bc2b --- /dev/null +++ b/testing/trace.cc @@ -0,0 +1,171 @@ +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include + +#define LOG_TO_STDOUT 0 + +namespace { + +class CString { + char const *str_; + +public: + // cppcheck-suppress noExplicitConstructor + constexpr CString(char const *str) + : str_ (str) {} + + friend bool operator<(CString lhs, CString rhs) { + return strcmp(lhs.str_, rhs.str_) < 0; + } +}; + +template +bool contains(CString const (&array)[N], std::string const &str) { + return std::binary_search(array, array + N, str.c_str()); +} + +struct Symbol { + std::string const name; + std::string const file; +}; + +constexpr CString exclusions[] = { + "__bswap_32", + "logger_callback_log", + "make_family", + "make_proto", + "make_socktype", +}; + +constexpr CString filter_sources[] = { + "onion.c", + "onion_announce.c", + "onion_client.c", +}; + +class ExecutionTrace { + using Process = std::unique_ptr; + using File = std::unique_ptr; + + std::string const exe = []() -> std::string { + std::array result; + ssize_t const count = readlink( + "/proc/self/exe", result.data(), result.size()); + assert(count > 0); + return std::string(result.data(), count > 0 ? count : 0); + }(); + +#if LOG_TO_STDOUT + File const log_file{stdout, std::fclose}; +#else + File const log_file{std::fopen("trace.log", "w"), std::fclose}; +#endif + unsigned nesting = 0; + std::map symbols; + + static std::string sh(std::string cmd) { + std::string result; + Process pipe(popen(cmd.c_str(), "r"), pclose); + if (!pipe) { + return ""; + } + std::array buffer; + while (fgets(buffer.data(), buffer.size(), pipe.get()) != nullptr) { + result += buffer.data(); + } + return result; + } + + Symbol const &resolve(void *fn) { + // Already in the cache. + auto const found = symbols.find(fn); + if (found != symbols.end()) { + return found->second; + } + + // 0x<64 bit number>\0 + std::array addr; + std::snprintf(addr.data(), addr.size(), + "0x%lx", static_cast(reinterpret_cast(fn))); + + std::string const output = sh("addr2line -fs -e " + exe + " " + addr.data()); + + std::size_t const newline = output.find_first_of('\n'); + std::size_t const colon = output.find_first_of(':'); + + std::string const sym = output.substr(0, newline); + std::string const file = output.substr(newline + 1, colon - (newline + 1)); + + auto const inserted = symbols.insert({fn, {sym, file}}); + return inserted.first->second; + } + + void indent() const { + for (unsigned i = 0; i < nesting; i++) { + std::fputc(' ', log_file.get()); + } + } + + void print(char const *prefix, Symbol const &sym) { + indent(); + std::fprintf(log_file.get(), "%s %s (%s)\n", prefix, sym.name.c_str(), sym.file.c_str()); + } + + static bool excluded(Symbol const &sym) { + if (sizeof(filter_sources) != 0) { + if (!contains(filter_sources, sym.file)) { + return true; + } + } + return contains(exclusions, sym.name); + } + +public: + void enter(void *fn) { + Symbol const &sym = resolve(fn); + if (!excluded(sym)) { + print("->", sym); + ++nesting; + } + } + + void exit(void *fn) { + Symbol const &sym = resolve(fn); + if (!excluded(sym)) { + --nesting; + print("<-", sym); + } + } +}; + +// We leak this one. +static ExecutionTrace *trace; + +} // namespace + +extern "C" +void __cyg_profile_func_enter (void *this_fn, void *call_site) + __attribute__((__no_instrument_function__)); +void __cyg_profile_func_enter (void *this_fn, void *call_site) +{ + if (trace == nullptr) { + trace = new ExecutionTrace(); + } + trace->enter(this_fn); +} + +extern "C" +void __cyg_profile_func_exit (void *this_fn, void *call_site) + __attribute__((__no_instrument_function__)); +void __cyg_profile_func_exit (void *this_fn, void *call_site) +{ + assert(trace != nullptr); + trace->exit(this_fn); +}