namhyung / uftrace

Function graph tracer for C/C++/Rust/Python
https://uftrace.github.io/slide/
GNU General Public License v2.0
3.01k stars 441 forks source link

API for recording variables #428

Open honggyukim opened 6 years ago

honggyukim commented 6 years ago

Introduction

uftrace is able to capture function arguments and return values and that is the core feature.

But sometimes, it's also necessary to see some internal variables or even user may want to put a marker to distinguish the point from a long sequence of function calls.

ftrace already has that feature and providing ftrace_printk - https://lwn.net/Articles/292371/

I've designed a prototype to provide similar way to print or capture some variables inside function. The design idea is to provide a simple function that does nothing and just accept a single parameter.

The basic usage is as follows:

  1. include uftrace header file.
  2. call uftrace_print() function with a single argument that can be recorded
    $ cat test.cpp
    #include <uftrace>
    int main()
    {
    uftrace_print(100);
    uftrace_print("Hello");
    }
    
    $ g++ -pg -g test.cpp

$ uftrace --auto-args a.out

DURATION TID FUNCTION

2.130 us [112169] | monstartup(); 1.257 us [112169] | cxa_atexit(); [112169] | main() { 1.437 us [112169] | uftrace_print(100); 314.116 us [112169] | uftrace_print("Hello"); 317.776 us [112169] | } = 0; / main /

It shows the values inside uftrace replay output, but it does nothing when `uftrace` is not used.

$ g++ -pg -g test.cpp

$ ./a.out (... does nothing ...)


### Examples
Here are more complicated example.
**T1. primitive types**
```cpp
$ cat test-primitive.cpp
#include "uftrace"

void primitive_test()
{
    int a = 10;
    uftrace_print(a);
    uftrace_print(&a);

    int b = 0xcafecafe;
    uftrace_print(b);

    const int ci = 20;
    uftrace_print(ci);

    short s = 30;
    uftrace_print(s);

    char c = 'X';
    uftrace_print(c);

    float f = 3.14f;
    uftrace_print(f);

    double d = 16.04;
    uftrace_print(d);
}

int main()
{
    primitive_test();
}
$ g++ -pg -g -o primitive test-primitive.cpp

$ uftrace --auto-args primitive
# DURATION     TID     FUNCTION
   1.960 us [112285] | __monstartup();
   1.163 us [112285] | __cxa_atexit();
            [112285] | main() {
            [112285] |   primitive_test() {
   1.467 us [112285] |     uftrace_print(10);
   0.270 us [112285] |     uftrace_print(0x7ffe46602090);
   0.213 us [112285] |     uftrace_print(0xcafecafe);
   0.214 us [112285] |     uftrace_print(20);
   0.223 us [112285] |     uftrace_print(30);
   0.260 us [112285] |     uftrace_print('X');
   0.377 us [112285] |     uftrace_print(3.140000);
   0.233 us [112285] |     uftrace_print(16.040000);
   7.526 us [112285] |   } /* primitive_test */
   8.223 us [112285] | } = 0; /* main */

T2. enum types

$ cat test-enum.cpp
#include "uftrace"

enum fruit { APPLE, ORANGE, BANANA };

void enum_test()
{
    uftrace_print(APPLE);

    enum fruit f = BANANA;
    uftrace_print(f);

    f = ORANGE;
    uftrace_print(f);
}

int main()
{
    enum_test();
}
$ g++ -pg -g -o enum test-enum.cpp

$ uftrace --auto-args enum
# DURATION     TID     FUNCTION
   1.893 us [112403] | __monstartup();
   1.184 us [112403] | __cxa_atexit();
            [112403] | main() {
            [112403] |   enum_test() {
   1.973 us [112403] |     uftrace_print(APPLE);
   0.217 us [112403] |     uftrace_print(BANANA);
   0.220 us [112403] |     uftrace_print(ORANGE);
   4.577 us [112403] |   } /* enum_test */
   5.437 us [112403] | } = 0; /* main */

T3. string types

$ cat test-string.cpp
#include "uftrace"

void string_test()
{
    uftrace_print("Hello World!");

    char msg[] = "String is captured!";
    uftrace_print(msg);
}

int main()
{
    string_test();
}
$  g++ -pg -g -o string test-string.cpp

$ uftrace --auto-args string
# DURATION     TID     FUNCTION
   2.133 us [112491] | __monstartup();
   1.153 us [112491] | __cxa_atexit();
            [112491] | main() {
            [112491] |   string_test() {
 320.635 us [112491] |     uftrace_print("Hello World!");
   0.584 us [112491] |     uftrace_print("String is captured!");
 323.829 us [112491] |   } /* string_test */
 324.562 us [112491] | } = 0; /* main */

Implementation

Here is the full implementation of uftrace header file.

$ cat uftrace
// <uftrace> -*- C++ -*-

#ifdef __cplusplus

#if defined(__clang__)
#define DISABLE_OPT __attribute__((optnone))
#elif defined(__GNUC__)
#define DISABLE_OPT __attribute__((optimize(0)))
#else
#define DISABLE_OPT
#endif

template <typename T>
DISABLE_OPT
void uftrace_print(T)
{
}

__attribute__((noinline))
void uftrace_print(const char* s)
{
    volatile const char c = *s;
}

#else // #ifdef __cplusplus

#define uftrace_print(x)

#endif

As shown above, uftrace_print() function does nothing but accepts a single argument. It uses template to distinguish each type but provides one more prototype - void uftrace_print(const char* s) to avoid compiler optimization.

It contains some verbose attribute and macros but it's to handle the difference between gcc and clang.

Please let me know any feedback or some ideas that I can improve it. Thanks!

honggyukim commented 6 years ago

There's nothing to modify uftrace code itself but we have to distribute the above uftrace header file during installation. Then uftrace users can just include it when it's needed.

honggyukim commented 6 years ago

Another goal is to provide multiple arguments using variadic template. I've tested for a while but it doesn't capture any arguments with my current implementation.

template <typename ...Args>
__attribute__((optimize(0)))
void uftrace_print(Args&&... args)
{
}

int main()
{
    int a = 10;
    uftrace_print(a, &a, 'A', "Hi");
}

Variadic template is only supported from C++11.

$ g++ -pg -g -std=c++11 test.cpp

But the replay output shows nothing.

$ uftrace --auto-args a.out
# DURATION     TID     FUNCTION
   2.040 us [113254] | __monstartup();
   1.014 us [113254] | __cxa_atexit();
            [113254] | main() {
   0.237 us [113254] |   uftrace_print();
   1.453 us [113254] | } = 0; /* main */
namhyung commented 6 years ago

Generally I don't want to change user's program and there's similar thing like SDT marker so I'm not sure it's worth doing it in uftrace. If user can change the program he or she can add a dummy function without this, right? Also there seem no way to handle C programs..

honggyukim commented 6 years ago

Generally I don't want to change user's program

I agree. uftrace must not require user to modify their source code, but sometimes, it's needed in my experience.

and there's similar thing like SDT marker so I'm not sure it's worth doing it in uftrace.

There are something that I'm not comfortable on SDT approach.

  1. It requires additional package installation - systemtap-std-dev on ubuntu
  2. STAP_PROBE(uftrace, event) looks more complicated than uftrace_print(value) to general users
  3. It requires additional -E uftrace:event option to uftrace.
  4. It doesn't support value recording yet.

If user can change the program he or she can add a dummy function without this, right?

Right. User can add their dummy function for that but it requires additional attributes to stay the function in binary when optimized. As I wrote it above, the attributes are different between gcc and clang and they might be complicated to general users. Moreover, making a dummy function for string requires some extra code to avoid optimizing the unused string as well.

Also there seem no way to handle C programs..

Right. This approach depends on C++ template so don't handle C programs yet.

I just made a prototype and don't think this is the only solution. But just wanted to make it better and simpler to general users. Thanks for your feedback!

honggyukim commented 5 years ago

I've implemented it in #636 and it works both C and C++ with the same function name uftrace_print. Please take a look at it. Thanks!