Tracing functions in your code

Edit online

You can instruct the compiler to insert calls to user-defined tracing functions to aid in debugging or timing the execution of other functions.

Using tracing functions in your program requires the following steps:
  1. Writing tracing functions
  2. Specifying which functions to trace with the -qfunctrace option
Using the -qfunctrace option causes the compiler to insert calls to these tracing functions at key points in the function body; however, you are responsible for defining these tracing functions. The following list describes at which points the tracing functions are called:
  • The compiler inserts calls to the tracing function at the entry point of a function. The line number passed to the routine is the line number of the first executable statement in the instrumented function.
  • The compiler inserts calls to the tracing function at the exit point of a function. The line number that is passed to the function is the line number of the statement causing the exit in the instrumented function.
  • The catch tracing function is called at the beginning of the C++ catch block when the exception occurs.
You can use the -qnofunctrace compiler option to disable function tracing.

How to write tracing functions

To trace functions in your code, define the following tracing functions:
  • __func_trace_enter is the entry point tracing function.
  • __func_trace_exit is the exit point tracing function.
  • __func_trace_catch is the catch tracing function.
The prototypes of these functions are as follows:
  • void __func_trace_enter(const char *const function_name, const char *const file_name, int line_number, void **const user_data);
  • void __func_trace_exit(const char *const function_name, const char *const file_name, int line_number, void **const user_data);
  • void __func_trace_catch(const char *const function_name, const char *const file_name, int line_number, void **const user_data);
In the preceding tracing functions, the descriptions for their variables are as follows:
  • function_name is the name of the function you want to trace.
  • file_name is the name of the file.
  • line_number is the line number at entry or exit point of the function. This is a 4-byte number.
  • user_data is the address of a static pointer variable. The static pointer variable is generated by the compiler and initialized to NULL; in addition, because the pointer variable is static, its address is the same for all instrumentation calls inside the same function.
Notes:
  • The exit function is not called if the function has an abnormal exit. The abnormal exit can be caused by actions such as raising a signal, throwing a C++ exception, or calling the exit() or abort() functions.
  • The -qfunctrace option does not support setjmp and longjmp. For example, a call to longjmp() that leaves function1 and returns from setjmp() in function2 will have a missing call to __func_trace_exit in function1 and a missing a call to __func_trace_enter in function2.
  • The catch function is called at the point where the C++ exception is caught by user code.
  • To define tracing functions in C++ programs, use the extern "C" linkage directive before your function definition.
  • The function calls are only inserted into the function definition, and if a function is inlined, no tracing is done within the inlined code.
  • If you develop a multithreaded program, make sure the tracing functions have the proper synchronization and do not cause deadlock. Calls to the tracing functions are not thread-safe.
  • If you specify a function that does not exist with the option, the function is ignored.

Rules

The following rules apply when you trace functions in your code:
  • When optimization is enabled, line numbers might not be accurate.
  • The tracing function must not call any instrumented function; otherwise an infinite loop might occur.
  • If you instruct the compiler to trace recursive functions, make sure that your tracing functions can handle recursion.
  • Inlined functions are not instrumented.
  • Tracing functions are not instrumented.
  • Compiler-generated functions are not instrumented, except for the outlined functions generated by optimization . In those cases, the name of the outlined function contains the name of the original user function as prefix.
  • Tracing functions might be called during static initialization. You must be careful that anything used in the tracing functions is initialized before the first possible call to the tracing function.

Examples

The following C example shows how you can trace functions in your code using function prototypes. Assume you want to trace the entry and exit points of function1 and function2, as well as how much time it takes the compiler to trace them in the following code:

Main program file: t1.c
#include <stdio.h>
#include <stdlib.h>
#include <unistd.h>
#include <time.h>
#ifdef __cplusplus
extern "C"
#endif
void __func_trace_enter(const char *function_name, const char *file_name,
                        int line_number, void** const user_data){
   if((*user_data)==NULL)
       (*user_data)=(time_t *)malloc(sizeof(time_t));
   (*(time_t *)*user_data)=time(NULL);
   printf("begin function: name=%s file=%s line=%d\n",function_name,file_name,
          line_number);
}
#ifdef __cplusplus
extern "C"
#endif
void __func_trace_exit(const char *function_name, const char*file_name, 
                       int line_number, void** const user_data){
   printf("end function: name=%s file=%s line=%d. It took %g seconds\n",
          function_name,file_name,line_number, difftime(time(NULL),
          *(time_t *)*user_data));
}
void function2(void){
   sleep(3);
}
void function1(void){
   sleep(5);
   function2();
}
int main(){
   function1();
}
Compile the main program source file as follows:
xlc t1.c -qfunctrace+function1:function2
Run executable a.out to output function trace results: 
begin function: name=function1 file=t.c line=27
begin function: name=function2 file=t.c line=24
end function: name=function2 file=t.c line=25. It took 3 seconds
end function: name=function1 file=t.c line=29. It took 8 seconds
As you see from the preceding example, the user_data parameter is defined to use the system time as basis for time calculation. The following steps explain how user_data is defined to achieve this goal:
  1. The function reserves a memory area for storing the value of user_data.
  2. The system time is used as the value for user_data.
  3. In the __func_trace_exit function, the difftime function uses user_data to calculate time differences. The result is displayed in the form of It took %g seconds in the output.

The following C++ example shows how tracing functions are called. The following example traces class myStack and function foo:

Main program file: t2.cpp
#include <iostream>
#include <vector>
#include <stdexcept>
#include <stdio.h>
#include <stdlib.h>
#include <unistd.h>
#include <time.h>
extern "C"
void __func_trace_enter(const char *function_name, const char *file_name,
                        int line_number, void** const user_data){
  if((*user_data)==NULL)
    (*user_data)=(time_t *)malloc(sizeof(time_t));
  (*(time_t *)*user_data)=time(NULL);
  printf("enter function: name=%s file=%s line=%d\n",function_name,file_name,
         line_number);
}
extern "C"
void __func_trace_exit(const char *function_name, const char*file_name,
                       int line_number, void** const user_data){
  printf("exit function: name=%s file=%s line=%d. It took %g seconds\n",
         function_name, file_name, line_number, difftime(time(NULL),
         *(time_t *)*user_data));
}
extern "C"
void __func_trace_catch(const char *function_name, const char*file_name,
                        int line_number, void** const user_data){
  printf("catch function: name=%s file=%s line=%d. It took %g seconds\n",
         function_name, file_name,line_number, difftime(time(NULL),
         *(time_t *)*user_data));
}

template <typename T> class myStack{
  private:
  std::vector<T> elements;
  public:
  void push(T const&);
  void pop();
};

template <typename T>
void myStack<T>::push(T const& value){
  sleep(3);
  std::cout<< "\tpush(" << value << ")" <<std::endl;
  elements.push_back(value);
}
template <typename T>
void myStack<T>::pop(){
  sleep(5);
  std::cout<< "\tpop()" <<std::endl;
  if(elements.empty()){
    throw std::out_of_range("myStack is empty");
  } 
  elements.pop_back();
}
void foo(){
  myStack<int> intValues;
  myStack<float> floatValues;
  myStack<double> doubleValues;
  intValues.push(4);
  floatValues.push(5.5f);
  try{
    intValues.pop();
    floatValues.pop();
    doubleValues.pop(); // cause exception
  } catch(std::exception const& e){
    std::cout<<"\tException: "<<e.what()<<std::endl;
  }
  std::cout<<"\tdone"<<std::endl;
}

int main(){
  foo();
}
Compile the main program source file as follows:
xlC t2.cpp -qfunctrace+myStack:foo
Run executable a.out to output function trace results:
enter function: name=_Z3foov file=t2.cpp line=56
enter function: name=_ZN7myStackIiEC2Ev file=t2.cpp line=32
exit function: name=_ZN7myStackIiEC2Ev file=t2.cpp line=32. It took 0 seconds
enter function: name=_ZN7myStackIfEC2Ev file=t2.cpp line=32
exit function: name=_ZN7myStackIfEC2Ev file=t2.cpp line=32. It took 0 seconds
enter function: name=_ZN7myStackIdEC2Ev file=t2.cpp line=32
exit function: name=_ZN7myStackIdEC2Ev file=t2.cpp line=32. It took 0 seconds
enter function: name=_ZN7myStackIiE4pushERKi file=t2.cpp line=42
        push(4)
exit function: name=_ZN7myStackIiE4pushERKi file=t2.cpp line=45. It took 3 seconds
enter function: name=_ZN7myStackIfE4pushERKf file=t2.cpp line=42
        push(5.5)
exit function: name=_ZN7myStackIfE4pushERKf file=t2.cpp line=45. It took 3 seconds
enter function: name=_ZN7myStackIiE3popEv file=t2.cpp line=48
        pop()
exit function: name=_ZN7myStackIiE3popEv file=t2.cpp line=54. It took 5 seconds
enter function: name=_ZN7myStackIfE3popEv file=t2.cpp line=48
        pop()
exit function: name=_ZN7myStackIfE3popEv file=t2.cpp line=54. It took 5 seconds
enter function: name=_ZN7myStackIdE3popEv file=t2.cpp line=48
        pop()
catch function: name=_Z3foov file=t2.cpp line=65. It took 21 seconds
        Exception: myStack is empty
        done
enter function: name=_ZN7myStackIdED2Ev file=t2.cpp line=34
exit function: name=_ZN7myStackIdED2Ev file=t2.cpp line=32. It took 0 seconds
enter function: name=_ZN7myStackIfED2Ev file=t2.cpp line=34
exit function: name=_ZN7myStackIfED2Ev file=t2.cpp line=32. It took 0 seconds
enter function: name=_ZN7myStackIiED2Ev file=t2.cpp line=34
exit function: name=_ZN7myStackIiED2Ev file=t2.cpp line=32. It took 0 seconds
exit function: name=_Z3foov file=t2.cpp line=69. It took 21 seconds

Related information

  • For details about the -qfunctrace compiler option, see -qfunctrace in the XL C/C++ Compiler Reference.