Automated-ish Function Tracing in C/C++

Let’s trace, shall we?

TL, DR: I’ve created a small tool to patch C and C++ code to output tracing logs to standard output. Check it out: script, repo with instructions.

Disclaimer: This tool was a one-night project, so, it is not foolproof and may be flawed in many ways, unknown ways. Also, I am really not aware of any (and all) shortcomings that cppclean has. All of these also apply to this tool. Use it at your own discretion :)

I have really mixed feelings in regards to documentation.

I really enjoy documenting. I enjoy (to some extent) writing. I enjoy making diagrams. On the other hand, the documentation work must come in naturally. Otherwise, obligation kills all the fun. I mean, not the obligation of having to do something, as in a task, but the obligation of having to do something in a predetermined way that you may not fully agree with, or find effective at all.

I was requested to create some really detailed sequence diagrams that ended up being basically a full dump of a function trace. The use cases do be described involved some relatively long function call chains. So long that doing it by code analysis was almost time-wise prohibitive.

Doing it quickly was very important so that I could keep my spirits up. I then dug up some ways to automate it.

The Broken Dream

GCC has a really neat feature: the -finstrument-functions compiler flag option. What it does is to instruct GCC to make calls to specific functions whenever a function is called or when a function returns. Such specific calls would pass two arguments: a pointer to the address of the calling function, and a pointer to the address of the called function. Leveraging that information, i.e., the start address of several functions, one could use GNU’s addr2line together with a binary built with debug symbols, i.e. with the -g option, to query the function’s name. You can refer to this page to get more information on it.

It would have been really great if this had worked for me. Turns out that the compiler I use does not support -finstrument-functions . So, I had to reconsider. And start looking elsewhere.

Getting the dust out of printf

The solution I went for was to use printf-based tracing. This is a really long-existing “debugging” tool for when you lack a debugger. To enable tracing, I’ve relied on another compiler feature: the __FUNCTION__ and __PRETTY_FUNCTION__ predefined macros. These predefined preprocessor macros will expand to the function name and the full function’s signature, respectively, when referred to from inside a function.

For better understanding, consider the following:

#include <iostream>
namespace fizz {
    void foo(int bar)
    {
        std::cout << __FUNCTION__ << std::endl <<__PRETTY_FUNCTION__ << std::endl;
        
    }
}
int main()
{
    std::cout << __FUNCTION__ << std::endl <<__PRETTY_FUNCTION__ << std::endl;
    fizz::foo(7);
    return 0;
}

The output is the following:

main
int main()
foo
void fizz::foo(int)

As can be seen, the __PRETTY_FUNCTION__ does a pretty good job, outputting the full function’s signature, including namespaces, which is especially useful when using C++ because of class inheritance.

To shorten this tracing procedure, one could use something like the following:

#define TRACE_ME_IN struct timeval tp ; gettimeofday ( &tp , nullptr ); printf("[%4ld.%4ld] In: %s\n",tp.tv_sec , tp.tv_usec,__PRETTY_FUNCTION__);
#define TRACE_ME_OUT gettimeofday ( &tp , nullptr ); printf("[%4ld.%4ld] Out: %s\n",tp.tv_sec , tp.tv_usec,__PRETTY_FUNCTION__);

And insert calls to TRACE_ME_INat the beginning of each function and TRACE_ME_OUT at the return points. Note the caveat here: a function may have multiple return points. Some may argue that having multiple return points may not be a good practice. But, because it is syntax legal, you really need to handle all return points.

#include <iostream>
#include <sys/time.h>
#define TRACE_ME_IN struct timeval tp ; gettimeofday ( &tp , nullptr ); printf(“[%4ld.%4ld] In: %s\n”,tp.tv_sec , tp.tv_usec,__PRETTY_FUNCTION__);
#define TRACE_ME_OUT gettimeofday ( &tp , nullptr ); printf(“[%4ld.%4ld] Out: %s\n”,tp.tv_sec , tp.tv_usec,__PRETTY_FUNCTION__);
namespace fizz 
{
 void foo(int bar)
 {
   TRACE_ME_IN
   int num = 0;
   while (num++ < 10)
   {
     std::cout << "working on " << num << std::endl;
     if (num > 5)
     {
       TRACE_ME_OUT
       return;
     }
   }
 TRACE_ME_OUT
 }
}
int main()
{
 TRACE_ME_IN
 std::cout << “Calling fizz::foo()” << std::endl;
 fizz::foo(7);
 TRACE_ME_OUT
 return 0;
}

A sample output from this would be:

[1627375106.125899] In: int main()
Calling fizz::foo()
[1627375106.125949] In: void fizz::foo(int)
working on 1
working on 2
working on 3
working on 4
working on 5
working on 6
working on 7
working on 8
working on 9
working on 10
[1627375106.125999] Out: void fizz::foo(int)
[1627375106.126002] Out: int main()

How about big codebases?

Well, this usually is the case. You hardly ever are required to do something hard on a small codebase. At least not using C or C++ :)

Going through each entry and return points on all functions may be cumbersome to do by hand, and at the same time, hard to do by find and replace, especially because:

• void, constructors, and destructor functions may return without return clauses. A simple closing curly brace may be a point of return;
• Not every closing curly brace means a return point;
• Not every opening curly brace means the start of a function;

To automate this task, it is required a very basic C/C++ parser. There is a very cool python tool called cppclean that includes a code parser that generates an Abstract Syntax Tree. From the AST, one can get the functions’ return clauses as well as its beginning and end offsets: it yields all we need!

I’ve created a small tool to automate this and it is available here. The repo also contains some additional that may be of good use.

Using the Tool

First, install the pre-prerequisites: python 3.x and pip. And then, the python dependencies:

python -m pip install cppclean

Copy this file to the target folder and run it. Simple as that :)

A few extra information on how to use the script:

• You can edit outprint and inprint to tweak what is inserted and the entry and exit points;
• You can edit the edit tracedefs for changing as you see fit. Maybe you want to use std::cout instead of printf or even call your favorite logger tool;
• You can pass the --unpatch flag to remove the tracing calls;
• You can pass the--recursive flag to apply iteratively to all files in the current folder.

Wrapping Up

I had a really good time, both writing the tool and this short article. I hope it helps someone out there.

Until the next time!