[ltt-dev] [RFC] Userspace tracing for people who only use printf

[Matthew Khouzam]

Hello tracing world,
I wrote up a little document on how to use UST for new users. I am 
certain I have some innacuracies in there. The document is written for 
user space programmers that are used to using printf, and if we're lucky 
fprintf. It should be able to start them up.

Comments are appreciated.

Thanks,
Matthew
User Space Tracing for People Who Use Printf


What is UST?

User space tracing is a fast efficient way to obtain a trace of the program you 
are running. The userspace tracer is designed to provide detailed information 
about userspace activity. UST is a port of the LTTng kernel tracer to 
userspace. Like the LTTng kernel tracer, performance is the main goal. Tracing 
does not require system calls or traps. UST instrumentation points may be added 
in any userspace code including signal handlers and libraries.
Code may be instrumented with either markers or tracepoints. A highly efficient 
lockless tracer records these events to a trace buffers. These buffers are 
reaped by a deamon which writes trace data to disk.
High performance is achieved by the use of lockless buffering algorithms, RCU 
and per-cpu buffers. In addition, special care is taken to minimize cache 
impact.
This means that Userspace tracing is ideal for real time systems. It will not 
overwrite events and it does not require any particular synchronization methods.

How do we trace using UST?

UST uses tracepoints or trace markers to trace a program. These tracepoints 
will write a particular message to a given trace file. This file can then be 
read using a viewer such as the TMF plugin for Eclipse or LTTv.

The tracepoints have to be placed in the code. There will be three methods 
detailed herem using trace_mark, using tracepoint and using an external 
library. All three of these methods have specific use cases. To better explain 
it, an example program will be instrumented.

<blink tag>WARNING: The UST api will change in april 2011. The document should 
be updated at that time.</blink tag>

Traditional tracing
The first tracing done by pretty much any programmer is “hello world”. The 
programmer will put printf functions where she needs to see the flow of data. A 
full complete example is shown below. This is an instrumented program. Notice 
all the printf functions for the trace are called by “trace_event”. This 
program will simulate a simple trace where there are several threads sending 
and receiving data. The data may time out. There is also periodic random noise 
added to the trace.
With the original printf implementation, it is essential to have a mutex around 
the actual printf function. This is blocking, and will slow down the execution. 
If the mutex is not present, the outputted trace will be so mangled it would be 
impossible to properly read the data.
#include <stdio.h>
#include <stdlib.h>
#include <pthread.h>
#include <time.h>
#include <ust/marker.h>

//number of sessions
#define NUM_THREADS 10
// number of packets
#define NUM_LOOPS 100UL

void *functionC();
void *noiseFunction();
double random_lag();
pthread_mutex_t mutex1 = PTHREAD_MUTEX_INITIALIZER;
unsigned long  counter = 0;
volatile char done = 0;

void trace_myevent(char *st)
{
      // no need for mutexes
      trace_mark(ust, myevent, "%s", st);
}

int main(int argc, char **argv)
{
 int i = 0;
 int rc[ NUM_THREADS+1];
 pthread_t thread[ NUM_THREADS+1];
 int value[ NUM_THREADS ];
  
 struct timespec start, end;
 clock_gettime( CLOCK_REALTIME , &start) ;
 double dif;
  for( i = 0; i < NUM_THREADS;i++)
 {
      value[i] = i ;
       if( (rc[i]=pthread_create( &thread[i], NULL, &functionC, &value[i])) )
         {
         printf("Thread creation failed: %d\n", rc[i]);
      }
 }
 rc[NUM_THREADS] = pthread_create( &thread[NUM_THREADS], NULL, &noiseFunction, 
NULL);
       

 for( i = 0; i < NUM_THREADS;i++)
 {
    pthread_join( thread[i], NULL);
 }
 done = 1;
  pthread_join( thread[NUM_THREADS], NULL);
 clock_gettime( CLOCK_REALTIME , &end) ;
 dif = ( end.tv_sec - start.tv_sec ) + ( ( end.tv_nsec - start.tv_nsec ) * 
0.000000001 );
 printf(" Runtime = %.2lf sec. \n" , dif);
 exit(0);
}

void *noiseFunction()
{
      int delay;
       char noise_message[80] = "<noise/>";
      while(!done )
       {
              delay = rand() % 100;
               trace_myevent(0UL, noise_message);
              usleep(delay*1000);
      }
}

void *functionC(int *id)
{
 long i = 0 ;
  char send_message[100];
 char recv_message[100];
  char timeout_message[100];
  int thread_id = *id;
  double seed;
  double delay;
  double delay2;
  double timeout_delay = 150000;

 for(i = 0; i < NUM_LOOPS ; i++)
  {
      sprintf(send_message, "<send><session id=\"%d\"/><packet 
id=\"%ld\"/></send>",thread_id, i );
      sprintf(recv_message, "<recv><session id=\"%d\"/><packet 
id=\"%ld\"/></recv>",thread_id, i );
      sprintf(timeout_message, "<timeout><session id=\"%d\"/><packet 
id=\"%ld\"/></timeout>",thread_id, i );
      trace_ust_myevent( i , send_message );
       seed = random_lag()* 50000.0;
      delay2 = rand() % 1000 * 100;
      if( seed > timeout_delay )
       {
              usleep(timeout_delay);
              trace_myevent( i , timeout_message );
      }
      else
      {
              delay = seed;
              usleep( (int)delay);
              trace_myevent( i ,recv_message);
      }
      usleep(delay2);
 }
}

// this gives a nice lag distribution
double random_lag()
{
      double ret_val = 1024.0 / ((rand( ) % 1024) + 1.0) ;
       return ret_val;
}



Using trace markers
The trace marker is the simplest method to use UST. The only method changed was 
“trace_ust_myevent” it now calls trace_mark(ust, myevent, “5s”,st). A 
simple find and replace of “printf(“ with “trace_mark(ust, event_name” 
and adding “#include <ust/marker.h> at the beginning of the file and 
compiling with the flag “-lust” will allow you to use UST in 3 simple steps.
#include <stdio.h>
#include <stdlib.h>
#include <pthread.h>
#include <time.h>
#include <ust/marker.h>

//number of sessions
#define NUM_THREADS 10
// number of packets
#define NUM_LOOPS 100UL

void *functionC();
void *noiseFunction();
double random_lag();
pthread_mutex_t mutex1 = PTHREAD_MUTEX_INITIALIZER;
unsigned long  counter = 0;
volatile char done = 0;

notrace void trace_ust_myevent(char *st)
{
      // no need for mutexes
      trace_mark(ust, myevent, "%s", st);
}

int main(int argc, char **argv)
{
 int i = 0;
 int rc[ NUM_THREADS+1];
 pthread_t thread[ NUM_THREADS+1];
 int value[ NUM_THREADS ];
  
 struct timespec start, end;
 clock_gettime( CLOCK_REALTIME , &start) ;
 double dif;
  for( i = 0; i < NUM_THREADS;i++)
 {
      value[i] = i ;
       if( (rc[i]=pthread_create( &thread[i], NULL, &functionC, &value[i])) )
         {
         printf("Thread creation failed: %d\n", rc[i]);
      }
 }
 rc[NUM_THREADS] = pthread_create( &thread[NUM_THREADS], NULL, &noiseFunction, 
NULL);
       

 for( i = 0; i < NUM_THREADS;i++)
 {
    pthread_join( thread[i], NULL);
 }
 done = 1;
  pthread_join( thread[NUM_THREADS], NULL);
 clock_gettime( CLOCK_REALTIME , &end) ;
 dif = ( end.tv_sec - start.tv_sec ) + ( ( end.tv_nsec - start.tv_nsec ) * 
0.000000001 );
 printf(" Runtime = %.2lf sec. \n" , dif);
 exit(0);
}

void *noiseFunction()
{
      int delay;
       char noise_message[80] = "<noise/>";
      while(!done )
       {
              delay = rand() % 100;
               trace_ust_myevent(0UL, noise_message);
              usleep(delay*1000);
      }
}

void *functionC(int *id)
{
 long i = 0 ;
  char send_message[100];
 char recv_message[100];
  char timeout_message[100];
  int thread_id = *id;
  double seed;
  double delay;
  double delay2;
  double timeout_delay = 150000;

 for(i = 0; i < NUM_LOOPS ; i++)
  {
      sprintf(send_message, "<send><session id=\"%d\"/><packet 
id=\"%ld\"/></send>",thread_id, i );
      sprintf(recv_message, "<recv><session id=\"%d\"/><packet 
id=\"%ld\"/></recv>",thread_id, i );
      sprintf(timeout_message, "<timeout><session id=\"%d\"/><packet 
id=\"%ld\"/></timeout>",thread_id, i );
      trace_ust_myevent( i , send_message );
       seed = random_lag()* 50000.0;
      delay2 = rand() % 1000 * 100;
      if( seed > timeout_delay )
       {
              usleep(timeout_delay);
              trace_ust_myevent( i , timeout_message );
      }
      else
      {
              delay = seed;
              usleep( (int)delay);
              trace_ust_myevent( i ,recv_message);
      }
      usleep(delay2);
 }
}

// this gives a nice lag distribution
double random_lag()
{
      double ret_val = 1024.0 / ((rand( ) % 1024) + 1.0) ;
       return ret_val;
}



Using trace points
Trace points are a much more powerful way of tracing an application. With a 
tracepoint, you can specify much more than what is in a tracemark and in a 
formatted way. The tracepoint however uses a tracemark as it can be seen in 
ust_myevent_probe. First the programmer must include <ust/marker.h> and 
<ust/tracepoint.h>. Then they must use the marcos “DECLARE_TRACE” and 
“DEFINE_TRACE”. They must then define the tracepoint function with the 
“notrace” directive in front. Inside the function a tracemark may be called 
to trace an event. (several may be called to for a more elaborate event). Note: 
the function name is the first argument of DECLARE_TRACE followed by _probe. 
Similar to the way kernel trace points are done. The function to call to use 
the trace point is “trace_” + the first argument of DECLARE_TRACE.
#include <stdio.h>
#include <stdlib.h>
#include <pthread.h>
#include <time.h>
#include <ust/marker.h>
#include <ust/tracepoint.h>

//number of sessions
#define NUM_THREADS 10
// number of packets
#define NUM_LOOPS 100UL


void *functionC();
void *noiseFunction();
double random_lag();
pthread_mutex_t mutex1 = PTHREAD_MUTEX_INITIALIZER;
unsigned long  counter = 0;
volatile char done = 0;

// Declare the macro "trace_ust_myevent ( char *st )"
// and the trace point to be the function "ust_myevent_probe(void *data, char 
*st)"
DECLARE_TRACE(ust_myevent, TP_PROTO( char *st ), TP_ARGS( st ));

// Instantiate the trace
DEFINE_TRACE(ust_myevent);

// notice the name of the function
notrace void ust_myevent_probe(void *data,  char *st)
{
      // no need for mutexes
      trace_mark_tp(ust, myevent, ust_myevent, ust_myevent_probe, "%s", st);
}

int main(int argc, char **argv)
{
 int i = 0;
 int rc[ NUM_THREADS+1];
 pthread_t thread[ NUM_THREADS+1];
 int value[ NUM_THREADS ];
  
 struct timespec start, end;
clock_gettime( CLOCK_REALTIME , &start) ;
 double dif;
  for( i = 0; i < NUM_THREADS;i++)
 {
      value[i] = i ;
       if( (rc[i]=pthread_create( &thread[i], NULL, &functionC, &value[i])) )
         {
         printf("Thread creation failed: %d\n", rc[i]);
      }
 }
 rc[NUM_THREADS] = pthread_create( &thread[NUM_THREADS], NULL, &noiseFunction, 
NULL);
       

 for( i = 0; i < NUM_THREADS;i++)
 {
    pthread_join( thread[i], NULL);
 }
 done = 1;
  pthread_join( thread[NUM_THREADS], NULL);
 clock_gettime( CLOCK_REALTIME , &end) ;
 dif = ( end.tv_sec - start.tv_sec ) + ( ( end.tv_nsec - start.tv_nsec ) * 
0.000000001 );
 printf(" Runtime = %.2lf sec. \n" , dif);
 exit(0);
}

void *noiseFunction()
{
      int delay;
       char noise_message[80] = "<noise/>";
      while(!done )
       {
              delay = rand() % 100;
               trace_ust_myevent(0UL, noise_message);
              usleep(delay*1000);
      }
}

void *functionC(int *id)
{
 long i = 0 ;
  char send_message[100];
 char recv_message[100];
  char timeout_message[100];
  int thread_id = *id;
  double seed;
  double delay;
  double delay2;
  double timeout_delay = 150000;

 for(i = 0; i < NUM_LOOPS ; i++)
  {
      sprintf(send_message, "<send><session id=\"%d\"/><packet 
id=\"%ld\"/></send>",thread_id, i );
      sprintf(recv_message, "<recv><session id=\"%d\"/><packet  
id=\"%ld\"/></recv>",thread_id, i );
      sprintf(timeout_message, "<timeout><session id=\"%d\"/><packet 
id=\"%ld\"/></timeout>",thread_id, i );
      trace_ust_myevent( i , send_message );
       seed = random_lag()* 50000.0;
      delay2 = rand() % 1000 * 100;
      if( seed > timeout_delay )
       {
              usleep(timeout_delay);
              trace_ust_myevent( i , timeout_message );
      }
      else
      {
              delay = seed;
              usleep( (int)delay);
              trace_ust_myevent( i ,recv_message);
      }
      usleep(delay2);
 }
}

// this gives a nice lag distribution
double random_lag()
{
      double ret_val = 1024.0 / ((rand( ) % 1024) + 1.0) ;
       return ret_val;
}
      



Using UST markers explained

A marker placed in code provides a means to write to a trace file. This will 
run when tracing is enabled.

How to use UST markers

    *

      include <ust/markers.h>
    *

      call trace_mark( channelname, eventname, formatted string)
    *

      Link with libust.so (-lust)


UST marker functions
trace_mark is a way to write generic events to a tracefile, it takes several 
arguments:  <channel>, <name>, <format>, <args>.
<channel> determines where an event is written. It is a string but should not 
be quoted, treat it as you would a file name, alphanumeric characters only. 
There are no checks done for bad names
<name> the name of the event, an unquoted string.
<format>+<args> A C formatted string and the argument list. Identical to printf.


Using UST Tracepoints explained

A tracepoint placed in code provides a hook to call a function (probe) that you 
can provide at runtime. A tracepoint can be "on" (a probe is connected to it) 
or "off" (no probe is attached). When a tracepoint is "off" it has no effect, 
except for adding a tiny time penalty (checking a condition for a branch) and 
space penalty (adding a few bytes for the function call at the end of the 
instrumented function and adds a data structure in a separate section).  When a 
tracepoint is "on", the function  you provide is called each time the 
tracepoint is executed, in the execution context of the caller.  When the 
function provided ends its execution, it returns to the caller (continuing from 
the tracepoint site).

Example :
printf( “Checkpoint %n passed\n” , checkpoint_number);



beccomes
trace_mark( checkpoint, passed, “Checkpoint %n passed” , checkpoint_number);




How to use UST tracepoints

    *

      include <ust/marker.h>
    *

      include <ust/tracepoint.h>
    *

      DECLARE_TRACE(<tracename> , <prototype>, <arguments>);
    *

      DEFINE_TRACE(<tracename>);
    *

      Declare a function <tracename>_probe(<arguments>)
    *

      Call the function trace_<tracename>
    *

      Link with libust.so (-lust)


Tracepoint functions
DECLARE_TRACE basically declares the prototype for the trace. It takes 
<tracename> <prototype> and <arguments> as parameters. DECLARE_TRACE should be 
called in every file being traced.
<tracename> is a trace name. It will generate the prototype for the probe 
function and the function calling the probe function.
<prototype> is the prototype, it uses the TP_PROTO macro. TP_PROTO receives an 
argument list, each element being the next one in the probe function. Note: the 
first argument in the probe function is always void* data, this is private data 
reserved for the tracer.
<arguments> is a list of the arguments, it uses the TP_ARGS macro. TP_ARGS 
receives the names of the variables.
example
DECLARE_TRACE( foo, TP_PROTO( int bar, const time_t *t ) , TP_ARGS( bar , t) );


will create
foo_probe( void* data, int bar, const time_t *t)


and
trace_foo( int bar, const time_t *t) ;


trace_foo will essentially run as the following.
trace_foo(int bar, const time_t *t)
{
    if( tracepoint_is_enabled )
    {
       foo_probe( &private_trace_context, bar, t );
    }
}


Note: it is a very bad practice to run code in tracepoint probes, their 
execution order is inherently random and will not run when the program is not 
being traced.
DEFINE_TRACE defines a trace. It is used to instantiate a trace and should only 
be run once in a program. It takes <tracename> as an argument.
<tracename>_probe is the function to be called. It contains a trace_mark_tp() 
call to write the event to a tracefile. The programmer must put the notrace 
directive before this function to exclude it from tracing itself. The 
trace_mark_tp() behaves like a trace_mark function, but can contain a 
tracepoint callback.
foo_probe( void * data, int bar, const time_t *t)
{
    trace_mark_tp( foo, bar, foo_probe, “%n\t%a %Y-%m-%d %H:%M:%S %Z",  bar, 
*t);
}



References:
http://www.mjmwired.net/kernel/Documentation/trace/tracepoints.txt
http://lttng.org/files/ust/manual/ust.html
_______________________________________________
ltt-dev mailing list
ltt-dev@lists.casi.polymtl.ca
http://lists.casi.polymtl.ca/cgi-bin/mailman/listinfo/ltt-dev