From f3c6fc6771e78aa6db8a5984434dad1b7c88350f Mon Sep 17 00:00:00 2001 From: iphydf Date: Mon, 27 Apr 2020 02:57:21 +0000 Subject: Add execution trace option for debugging. Use `cmake -DEXECUTION_TRACE=ON` to use it. --- CMakeLists.txt | 12 +++- testing/BUILD.bazel | 10 ++- testing/trace.cc | 198 ++++++++++++++++++++++++++++++++++++++++++++++++++++ 3 files changed, 217 insertions(+), 3 deletions(-) create mode 100644 testing/trace.cc diff --git a/CMakeLists.txt b/CMakeLists.txt index f108e2b1..73f66cf1 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 34f2d44c..5a2a0194 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 00000000..ecd31726 --- /dev/null +++ b/testing/trace.cc @@ -0,0 +1,198 @@ +/* SPDX-License-Identifier: GPL-3.0-or-later + * Copyright © 2020 The TokTok team. + */ +#include +#include + +#include +#include +#include +#include +#include +#include +#include +#include + +#define LOG_TO_STDOUT 0 + +/** + * This file contains the support code for using -finstrument-functions. + * + * If you link this into a program, e.g. a test program, that was compiled with + * -finstrument-functions, it will print an indented execution trace. E.g.: + * + * @code + * int g() { return 0; } + * int f() { return g(); } + * int main() { return f(); } + * @endcode + * + * Compiling the above with instrumentation and linking it with this file will + * result in the following output: + * + * @verbatim + * -> main + * -> f + * -> g + * <- g + * <- f + * <- main + * @endverbatim + * + * There are a few filter options you can apply below. Note that you'll need + * addr2line in your PATH for this to work. + */ +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; +}; + +/** + * This array lists functions that should *not* appear in the trace. + */ +constexpr CString exclusions[] = { + "__bswap_32", "logger_callback_log", "make_family", "make_proto", "make_socktype", +}; + +/** + * This array lists source files that *should* appear in the trace. + * + * If this array is empty, all files are traced. + */ +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::array result; + ssize_t const count = readlink("/proc/self/exe", result.data(), result.size()); + assert(count > 0); + return count > 0 ? std::string(result.data(), count) : "/proc/self/exe"; + }(); + +#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 (std::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); +} -- cgit v1.2.3