I started mulling over what traits of the tool could help me better understand the nature of the problems and bugs that arise. Someone here could ask \u2013 \u201cIsn\u2019t it what debuggers were invented for?\u201d. Of course \u2013 debuggers are a huge help providing that you have an access to the environment on which you can freely run the faulty code and debug it line by line which, to my experience, is not always so evident. In many cases the problem is reproducible only on customer\u2019s infrastructure and they won\u2019t allow you to experiment on a living organism. Or you lack the necessary test setup. Or the source of the problem lies in a third-party library and you don\u2019t have access to its source code. Or the problem is simply too complex to debug it traditionally. Whatever the reason is, the alternative approach may be inevitable. I decided to impose the following constraints on the tool that could satisfy my needs:<\/p>\n\n\n\n
- every time the user-defined function is being called, it should be logged to the file;<\/li>
- functions are demangled and presented in logs in a user-friendly way;<\/li>
- logging should be performed out of the box \u2013 without the need for a developer to pollute the code with some extra macros at the beginning of every function;<\/li>
- functions from standard library should be excluded from logging \u2013 we want to avoid the situation when we print hundreds of lines when performing simple operations on the containers;<\/li>
- log the filename and line number from where given function is called;<\/li>
- each function nesting adds an ident, whereas returning from a function removes it \u2013 as a result call stack tree is produced at the runtime giving the visual understanding which function calls which;<\/li>
- the logging mechanism may be activated only if compiled under some debug flag \u2013 this way we will avoid expensive overhead during normal program\u2019s execution;<\/li>
- Linux based.<\/li><\/ul>\n\n\n\n
As painstakingly as I browsed the web, I could only find the solutions that met just the single points of my requirements, none of them had them all, so I decided to write my own micro-framework and call it\u00a0Call Stack Logger.<\/strong><\/p>\n\n\n\n
Starting point<\/strong><\/h2>\n\n\n\n
Firstly, we will have to start from the mechanism that will allow us to invoke certain functions every time we enter or exit any function. This may sound a little similar to Aspect-oriented programming but the difference here is that on-enter and on-exit functions have the signatures already defined by the compiler. I\u2019m talking here about gcc feature called\u00a0function instrumentation<\/strong>. In order to activate it, we have to pass the following compilation flag to gcc:<\/p>\n\n\n
\n-finstrument-functions\n<\/pre><\/div>\n\n\n
Now we are free to define the profiling functions in whatever place suitable for us. I just created\u00a0trace.cpp<\/strong>\u00a0file and put them there:<\/p>\n\n\n
\nextern \"C\" __attribute__((no_instrument_function))\nvoid __cyg_profile_func_enter(void *callee, void *caller) {\n\/\/ Code to be executed just after function entry.\n}\n \nextern \"C\" __attribute__((no_instrument_function))\nvoid __cyg_profile_func_exit(void *callee, void *caller) {\n\/\/ Code to be executed just before function exit.\n}\n<\/pre><\/div>\n\n\nBoth functions have two void pointers as the arguments \u2013\u00a0callee<\/em>\u00a0is a pointer to the function that is currently being called, whereas\u00a0caller<\/em>\u00a0is a call site which points to the location (line of code) from where the function is called. The\u00a0__attribute__((no_instrument_function))<\/strong>\u00a0in the function signature is responsible for excluding the given function from instrumentation. In other words \u2013 we don\u2019t want profiling functions to be instrumented to avoid infinite calls leading to seg faults. To make it look a little more friendly, we can define a macro:<\/p>\n\n\n
\n#ifndef NO_INSTRUMENT\n#define NO_INSTRUMENT __attribute__((no_instrument_function))\n#endif\n<\/pre><\/div>\n\n\n
As the next thing, we will add a simple logging mechanism to save the history of the functions that are being called.<\/p>\n\n\n
\n#include <stdio.h>\n \nstatic FILE *fp_trace;\n \n__attribute__ ((constructor))\nNO_INSTRUMENT\nvoid trace_begin() {\nfp_trace = fopen("trace.out", "a");\n}\n \n__attribute__ ((destructor))\nNO_INSTRUMENT\nvoid trace_end() {\nif(fp_trace != nullptr) {\nfclose(fp_trace);\n}\n}\n<\/pre><\/div>\n\n\nAfter we have our file pointer initialized we can use it inside\u00a0__cyg_profile_func_enter<\/strong>\u00a0function. Let\u2019s just log there the address of the function being called:<\/p>\n\n\n
\nif(fp_trace != nullptr) {\nfprintf(fp_trace, \"enter %p\\n\", callee);\n}\n<\/pre><\/div>\n\n\nAnd some basic example:<\/p>\n\n\n
\n#include <iostream>\n#include <vector>\n#include <algorithm>\n \nclass A {\npublic:\nstatic void foo() {\nstd::cout << "static foo \\n";\nstd::vector<int> vec { 1, 55, 78, 3, 11, 7, 90 };\nstd::sort(vec.begin(), vec.end());\n}\n};\n \nint main() {\n\/\/ Test logging static member methods.\nA::foo();\nreturn 0;\n}\n<\/pre><\/div>\n\n\nThe\u00a0trace.out<\/em>\u00a0file will contain the following:<\/p>\n\n\n
\nenter 0x5602d9622be5\nenter 0x5602d9622f1c\nenter 0x5602d9623084\nenter 0x5602d96233b2\nenter 0x5602d96230fc\nenter 0x5602d962342a\nenter 0x5602d96239b6\nenter 0x5602d9623fa6\n\u2026\n\u2026\n\u2026\n<\/pre><\/div>\n\n\n
Decoding the addresses<\/strong><\/h2>\n\n\n\n
From the output above we are not able to obtain much information as we get only the address of the function that is being called which is not very useful in terms of debugging. Apart from that we can notice a lot of entries in the log file (actually I got 232 lines of those) instead of only 2 \u2013 for main<\/strong> and A::foo()<\/strong>. Why is that? To figure it out we will have to decode those addresses. For that purpose we will need binutils<\/strong> as a prerequisite:<\/p>\n\n\n\n
$ sudo apt install binutils-dev<\/em><\/p>\n\n\n\n
Also we need to add another gcc option in order to have dynamic symbol information in the executable:<\/p>\n\n\n
\n-rdynamic\n<\/pre><\/div>\n\n\n
And link against those two:<\/p>\n\n\n
\n-ldl -lbfd\n<\/pre><\/div>\n\n\n
libdl<\/em> is a Dynamic Link Library which is an interface to the dynamic loader and allows us, among others, to look up the symbols, libbfd<\/em> is Binary File Descriptor library which is used to operate on object files and will be used later.<\/p>\n\n\n\n
Let\u2019s firstly do a simple decoding. Include the headers:<\/p>\n\n\n
\n#include <dlfcn.h> \/\/ for dladdr\n#include <cxxabi.h> \/\/ for __cxa_demangle\n<\/pre><\/div>\n\n\n
and in\u00a0__cyg_profile_func_enter<\/strong>\u00a0define now the following body instead of previous naive logging of the function address:<\/p>\n\n\n
\nif (fp_trace != nullptr) {\nDl_info info;\nif (dladdr(func, &info)) {\nint status;\nconst char* name;\nchar* demangled = abi::__cxa_demangle(info.dli_sname, nullptr, 0, &status);\nif (status == 0) {\nname = demangled ? demangled : \"[not demangled]\";\n} else {\nname = info.dli_sname ? info.dli_sname : \"[no dli_sname]\";\n}\nfprintf(fp_trace, \"%s (%s)\\n\", name, info.dli_fname);\nif (demangled) {\ndelete demangled;\ndemangled = nullptr;\n}\n} else {\nfprintf(fp_trace, \"%s\\n\", \"unknown\");\n}\n}\n<\/pre><\/div>\n\n\nAfter compiling and running the program you\u2019ll see now the following in\u00a0trace.out<\/em>\u00a0file:<\/p>\n\n\n
\nmain (build\/runDemo)\nA::foo() (build\/runDemo)\nstd::allocator::allocator() (build\/runDemo)\n__gnu_cxx::new_allocator::new_allocator() (build\/runDemo)\nstd::vector<int, std::allocator >::vector(std::initializer_list, std::allocator const&) (build\/runDemo)\nstd::_Vector_base<int, std::allocator >::_Vector_base(std::allocator const&) (build\/runDemo)\nstd::_Vector_base<int, std::allocator >::_Vector_impl::_Vector_impl(std::allocator const&) (build\/runDemo)\nstd::allocator::allocator(std::allocator const&) (build\/runDemo)\n__gnu_cxx::new_allocator::new_allocator(__gnu_cxx::new_allocator const&) (build\/runDemo)\nstd::_Vector_base<int, std::allocator >::_Vector_impl_data::_Vector_impl_data() (build\/runDemo)\nstd::initializer_list::end() const (build\/runDemo)\nstd::initializer_list::begin() const (build\/runDemo)\nstd::initializer_list::size() const (build\/runDemo)\nstd::initializer_list::begin() const (build\/runDemo)\nvoid std::vector<int, std::allocator >::_M_range_initialize(int const*, int const*, std::forward_iterator_tag) (build\/runDemo)\nstd::iterator_traits::difference_type std::distance(int const*, int const*) (build\/runDemo)\n\u2026\n\u2026\n\u2026\n<\/pre><\/div>\n\n\n
And again in total 232 lines of decoded functions. All those functions come from a standard library and are linked to all of the operations that are invoked during the creation, memory allocation, initialization, sorting and destruction of the vector that we used in our example. We only wrote and called a 3-line function and got such a huge output in return. That\u2019s definitely too much clutter, we have to do something with it because it totally obfuscates our log file. Besides, in most cases we are not interested in details of what standard functions do, as we trust they do exactly what their names suggest. We want to focus on a business logic that our user-defined functions introduce and confine logging mechanism only to them.<\/p>\n\n\n\n
Exclude standard library from instrumentation<\/strong><\/h2>\n\n\n\n
Happily, gcc provides us with a special instrumentation option:<\/p>\n\n\n
\n-finstrument-functions-exclude-file-list\n<\/pre><\/div>\n\n\n
in which we can list the locations of all the headers from C++ standard that we\u2019d like to exclude from instrumentation, like \/usr\/include, \/usr\/include\/c++, \/usr\/include\/x86_64-linux-gnu\/c++\/10<\/em>, etc.<\/p>\n\n\n\n
Unfortunately those paths may differ depending on Linux OS or gcc version, so to make it easier I wrote the piece of shell script inside Makefile to automatically find and list all of the locations of C++ standard library headers and pass them to\u00a0-finstrument-functions-exclude-file-list:<\/strong><\/p>\n\n\n
\n# Find C++ Standard Library header files to exclude them from instrumentation\nCPP_STD_INCLUDES=$(shell ( `gcc -print-prog-name=cc1plus` -v < \/dev\/null 2>&1 \\\n| LC_ALL=C sed -ne '\/starts here\/,\/End of\/p' \\\n| grep -o '\/[^"]*' ; \\\n`gcc -print-prog-name=cpp` -v < \/dev\/null 2>&1 \\\n| LC_ALL=C sed -ne '\/starts here\/,\/End of\/p' \\\n| grep -o '\/[^"]*' ) \\\n| cat | sort | uniq | tr '\\n' ',' | sed 's\/\\(.*\\),\/\\1 \/' | xargs )\n \n# Exclude tracing functions themselves from instrumentation\nCPP_STD_INCLUDES := "${CPP_STD_INCLUDES},include\/callStack.h"\n \nCXXFLAGS = -g -Wall -rdynamic -std=c++17 -finstrument-functions -finstrument-functions-exclude-file-list=$(CPP_STD_INCLUDES)\n<\/pre><\/div>\n\n\nAfter doing so, recompiling and rerunning the program, we will get the following output:<\/p>\n\n\n
\nmain (build\/runDemo)\nA::foo() (build\/runDemo)\n<\/pre><\/div>\n\n\n
which is much closer to what we want to achieve.<\/p>\n\n\n\n
Improving the solution<\/strong><\/h2>\n\n\n\n
Now we will modify the current solution to introduce further enhancements. Instead of printing binary name we will print the filename and line number from where the function was called as it seems to be much more meaningful information during problem solving. We can also add a timestamp when a particular function is being called. Here is the code responsible for the core mechanism of Call Stack Logger:<\/p>\n\n\n
\n#include "callStack.h"\n#include "prettyTime.h"\n#include "unwinder.h"\n#include <bfd.h>\n#include <cxxabi.h> \/\/ for __cxa_demangle\n#include <dlfcn.h> \/\/ for dladdr\n#include <fstream>\n#include <map>\n#include <memory>\n#include <stdexcept>\n#include <unistd.h>\n \nnamespace {\n \nNO_INSTRUMENT\nstd::string demangle_cxa(const std::string& _cxa) {\nint status;\nstd::unique_ptr<char, void (*)(void*)> realname(\nabi::__cxa_demangle(_cxa.data(), nullptr, nullptr, &status), &free);\nif (status != 0) {\nreturn _cxa;\n}\n \nreturn realname ? std::string(realname.get()) : "";\n}\n \n} \/\/ namespace\n \nnamespace instrumentation {\n \nstruct ResolvedFrame {\nstd::string timestamp;\nstd::optional<void*> callee_address;\nstd::string callee_function_name;\nstd::string caller_filename;\nstd::optional<unsigned int> caller_line_number;\n};\n \nstd::optional<ResolvedFrame> resolve(void* callee_address, void* caller_address) {\nreturn bfdResolver::resolve(callee_address, caller_address);\n}\n \nstd::optional<ResolvedFrame> bfdResolver::resolve(void* callee_address, void* caller_address) {\ncheck_bfd_initialized();\n \nauto maybe_func_name = resolve_function_name(callee_address);\nif (!maybe_func_name) {\nreturn std::nullopt;\n}\nResolvedFrame resolved;\nresolved.callee_function_name = *maybe_func_name;\n \n\/\/ If the code is not changed 6th frame is constant as the execution flow\n\/\/ starting from 6th frame to the top of the stack will look e.g. as follows:\n\/\/ * 6th - instrumentation::FrameUnwinder::unwind_nth_frame\n\/\/ * 5th - bfdResolver::resolve instrumentation::unwind_nth_frame\n\/\/ * 4th - instrumentation::bfdResolver::resolve\n\/\/ * 3rd - instrumentation::resolve\n\/\/ * 2nd - __cyg_profile_func_enter\n\/\/ * 1st - A::foo() --> function we are interested in\n\/\/\n\/\/ Otherwise, if this call flow is altered, frame number must be recalculated.\nCallback callback(caller_address);\nunwind_nth_frame(callback, 6);\n \nauto pair = resolve_filename_and_line(callback.caller);\nresolved.caller_filename = pair.first;\nresolved.caller_line_number = pair.second;\nresolved.timestamp = utils::pretty_time();\n \nreturn std::make_optional(resolved);\n}\n \nstd::optional<std::string> bfdResolver::resolve_function_name(void* address) {\nDl_info info;\ndladdr(address, &info);\nif (info.dli_fbase == nullptr) {\nreturn "<address to object not found>";\n}\n \nif (!ensure_bfd_loaded(info) || s_bfds.find(info.dli_fbase) == s_bfds.end()) {\nreturn "<could not open object file>";\n}\nstoredBfd& currBfd = s_bfds.at(info.dli_fbase);\n \nasection* section = currBfd.abfd->sections;\nconst bool relative = section->vma < static_cast<uintptr_t>(currBfd.offset);\n \nwhile (section != nullptr) {\nconst intptr_t offset = reinterpret_cast<intptr_t>(address) - (relative ? currBfd.offset : 0) - static_cast<intptr_t>(section->vma);\n \nif (offset < 0 || static_cast<size_t>(offset) > section->size) {\nsection = section->next;\ncontinue;\n}\n \nconst char* file;\nconst char* func;\nunsigned line;\nif (bfd_find_nearest_line(currBfd.abfd.get(), section, currBfd.symbols.get(), offset, &file, &func, &line))\n{\nauto demangled = demangle_cxa(func);\nreturn demangled.empty() ? std::nullopt : std::make_optional(demangled);\n}\nreturn demangle_cxa(info.dli_sname != nullptr ? info.dli_sname : "") + " <bfd_error>";\n}\nreturn "<not sectioned address>";\n}\n \nstd::pair<std::string, std::optional<unsigned int>> bfdResolver::resolve_filename_and_line(void* address)\n{\n\/\/ Get path and offset of shared object that contains caller address.\nDl_info info;\ndladdr(address, &info);\nif (info.dli_fbase == nullptr) {\nreturn std::make_pair("<caller address to object not found>", std::nullopt);\n}\n \nif (!ensure_bfd_loaded(info) || s_bfds.find(info.dli_fbase) == s_bfds.end()) {\nreturn std::make_pair("<could not open caller object file>", std::nullopt);\n}\nstoredBfd& currBfd = s_bfds.at(info.dli_fbase);\n \nasection* section = currBfd.abfd->sections;\nconst bool relative = section->vma < static_cast<uintptr_t>(currBfd.offset);\n \nwhile (section != nullptr) {\nconst intptr_t offset = reinterpret_cast<intptr_t>(address) - (relative ? currBfd.offset : 0) - static_cast<intptr_t>(section->vma);\n \nif (offset < 0 || static_cast<size_t>(offset) > section->size) {\nsection = section->next;\ncontinue;\n}\nconst char* file;\nconst char* func;\nunsigned int line = 0;\nif (bfd_find_nearest_line(currBfd.abfd.get(), section, currBfd.symbols.get(), offset, &file, &func, &line))\n{\nif (file != nullptr) {\nreturn std::make_pair(std::string(file), std::make_optional(line));\n}\nreturn std::make_pair(demangle_cxa(func), std::nullopt);\n}\nif (info.dli_sname != nullptr) {\nreturn std::make_pair(demangle_cxa(info.dli_sname) + " <bfd_error>", std::nullopt);\n}\n}\nreturn std::make_pair("<not sectioned address>", std::nullopt);\n}\n \n} \/\/ namespace instrumentation\n<\/pre><\/div>\n\n\nIn the above-provided code some of the parts are omitted such as BFD initialization, unwinder implementation, formatting the resolved frame or generating timestamp. It\u2019s because I didn\u2019t want to litter the article with copy-pasting too much code \u2013 the clue is to show the general idea and how it is realised.<\/p>\n\n\n\n
The\u00a0__cyg_profile_func_enter<\/strong>\u00a0function should also be altered:<\/p>\n\n\n
\nextern \"C\" NO_INSTRUMENT\nvoid __cyg_profile_func_enter(void *callee, void *caller) {\nif(fp_trace != nullptr) {\nauto maybe_resolved = instrumentation::resolve(callee, caller);\nif (!maybe_resolved) { return; }\nfprintf(fp_trace, \"%s\\n\", utils::format(*maybe_resolved).c_str());\n}\n}\n<\/pre><\/div>\n\n\nWe start from resolve<\/strong> function taking both callee and caller addresses. Underneath we in turn call separate functions for callee address (resolve_function_name<\/strong>) and caller address (resolve_filename_and_line<\/strong>) \u2013 since from the first one we can decode class and function name being called and the second one lets us pull out the information about the call site \u2013 the exact place from where the function was called. If we passed callee instead of caller address to resolve_filename_and_line<\/strong> function, it would point to the first line of definition of the called function.<\/p>\n\n\n\n
Both functions use BFD objects to extract vital information. For the efficiency reasons they are stored in a static map and whenever any of them is required, they can be looked up and accessed without the necessity of creating those objects from scratch. Only when no suitable BFD object is found, it is constructed and inserted into the map.<\/p>\n\n\n\n
If resolve_function_name<\/strong> fails to decode function name we are not proceeding to decode filename and line as well as we back off from logging the whole entry.<\/p>\n\n\n\n
It\u2019s also worth mentioning that caller address cannot be resolved in a standard way. There is some kind of bug in instruction pointer value resulting in a wrong call site being returned. Having said that, before passing caller address to resolve_filename_and_line<\/strong> function we firstly have to unwind nth frame, extract its address and only then pass it to resolve_filename_and_line<\/strong>. Fortunately the unwinding depth is constant and for current implementation it is 6. Unwinder uses libunwind<\/em> library to achieve that.<\/p>\n\n\n\n
Now our trace.out file will look as follows:<\/p>\n\n\n
\n[13-06-2021 20:33:49.544] main (called from: \/build\/glibc-S9d2JN\/glibc-2.27\/csu\/..\/csu\/libc-start.c:310)\n[13-06-2021 20:33:49.600] A::foo() (called from: \/home\/ubuntu\/Desktop\/call-stack-logger.8-final-with-identation-ready\/src\/main.cpp:39)\n<\/pre><\/div>\n\n\n
But there is still some room for improvement. To make it much easier to notice the actual flow of execution, we will introduce indentations. We will modify\u00a0__cyg_profile_func_enter<\/strong>\u00a0and add implementation for\u00a0__cyg_profile_func_exit<\/strong>:<\/p>\n\n\n
\nstatic int current_stack_depth = -1;\nstatic bool last_frame_was_resolved = false;\n \nextern \"C\" NO_INSTRUMENT\nvoid __cyg_profile_func_enter(void *callee, void *caller) {\nif(fp_trace != NULL) {\nlast_frame_was_resolved = false;\nauto maybe_resolved = instrumentation::resolve(callee, caller);\nif (!maybe_resolved) { return; }\nlast_frame_was_resolved = true;\ncurrent_stack_depth++;\nfprintf(fp_trace, \"%s\\n\", utils::format(*maybe_resolved, current_stack_depth).c_str());\n}\n}\n \nextern \"C\" NO_INSTRUMENT\nvoid __cyg_profile_func_exit(void *callee, void *caller) {\nif(fp_trace != nullptr && last_frame_was_resolved) {\ncurrent_stack_depth--;\n}\n}\n<\/pre><\/div>\n\n\nWe declare static variable current_stack_depth<\/strong> which is incremented every time a frame is resolved successfully. We also store the information whether the last frame was resolved which is used to decrement current_stack_depth<\/strong> variable when we exit from a function.<\/p>\n\n\n\n
Now we only need to additionally pass this variable into\u00a0utils::format<\/strong>\u00a0function and format the string whatever way we would like it to be printed in the log file.
Only one more thing \u2013 let\u2019s modify a little bit our sample code to better visualize how the\u00a0Call Stack Logger<\/strong>\u00a0prints the entries in the log file:<\/p>\n\n\n\nclass A {\npublic:\nstatic void foo() { std::cout << "static foo \\n"; }\n};\n \nclass B {\npublic:\nvoid foo() {\nstd::cout << "non-static foo \\n";\nstd::vector<int> vec{ 1, 55, 78, 3, 11, 7, 90 };\nstd::sort(vec.begin(), vec.end());\nA::foo();\n}\n};\n \nint fibonacci(int n) {\nif (n <= 1)\nreturn n;\nreturn fibonacci(n - 1) + fibonacci(n - 2);\n}\n \nint main() {\n\/\/ Test logging static member methods.\nA::foo();\n \n\/\/ Test logging non-static member methods with calls to std\n\/\/ functions\/containers (which should not be instrumented).\nB b;\nb.foo();\nfibonacci(6);\nA::foo();\n}\n<\/pre><\/div>\n\n\nAnd here is the final result<\/p>\n\n\n\n
![\"\"](\"https:\/\/sii.pl\/blog\/wp-content\/uploads\/2021\/06\/call-stack-logger-capture-1-1024x778.gif\")
<\/a><\/figure><\/div>\n\n\n\nSummary<\/strong><\/h2>\n\n\n\n
As we can see, the output from the framework clearly visualizes the program\u2019s flow of execution in the form of a tree structure. You may have noticed that as far as caller address is concerned, we only retrieve a filename and a line number from it. We are not decoding the name of the caller function, only the name of the callee function as the tree structure explicitly shows us the whole call hierarchy of the program, so we don\u2019t need to additionally decode it and we are still able to say which function called which.<\/p>\n\n\n\n
The solution introduced in Call Stack Logger<\/strong> may constitute an alternative to the standard debugging in many situations like the one when access to the production environment is limited and it is worth having such a mechanism as a backup in our pool of problem-solving tools.You can access Call Stack Logger<\/strong> on Github under:https:\/\/github.com\/TomaszAugustyn\/call-stack-logger<\/a><\/p>\n\n\n
![\"\"](\"https:\/\/sii.pl\/blog\/wp-content\/uploads\/2021\/06\/call-stack-logger-capture-1.gif\")
<\/a><\/figure><\/div>\n\n\n\n