NPTL Trace Tool

EXAMPLE

Licence

Traces are collected in a binary file during program execution. The ptt_view and the ptt_paje make it possible to convert this binary file into a raw, textual or graphical trace.

Here is an example of the generated outputs corresponding to a simple program.

Source code

#define _XOPEN_SOURCE 600

#include <pthread.h>
#include <stdio.h>

pthread_barrier_t barrier;

void *func (void *arg) {
    sleep (1);
    int ret = pthread_barrier_wait (&barrier);
    if ((ret != 0) && (ret != PTHREAD_BARRIER_SERIAL_THREAD))
        fprintf (stderr, "Error when waiting for barrier\n");
}

int main(int argc, char* argv[]) {	
    pthread_t thread;
    int ret;
	
    if (pthread_barrier_init (&barrier, NULL, 2) != 0) {
        printf ("Error when initializing barrier\n");
        return -1;
    }

    if (pthread_create (&thread, NULL, func, NULL) != 0) {
        printf ("Error when creating thread\n");
        return -1;
    }

    ret = pthread_barrier_wait (&barrier);
    if ((ret != 0) && (ret != PTHREAD_BARRIER_SERIAL_THREAD))
        fprintf (stderr, "Error when waiting for barrier\n");

    if (pthread_join (thread, NULL) != 0) {
        printf ("Error when joining thread\n");
        return -1;
    }
	
    if (pthread_barrier_destroy (&barrier) != 0) {
        printf ("Error when destroying barrier\n");
        return -1;
    }
	
    return 0;
}

This program uses five NPTL functions: pthread_barrier_init, pthread_create, pthread_barrier_wait, pthread_join and pthread_barrier_destroy. Run ptt_trace on this source file to create the binary file needed by ptt_view or ptt_paje.

Raw format

The ptt_view command generates a trace file in a raw format:

#	PTT version 0.90.0.
#	The trace was generated on i686 on Mon, 22 May 2006 10:04:16 +0200.
#	This file is the number 0.
#
#
# timestamp : event-id : process-id : thread-id : arg1 : arg2 : arg3 : arg4 : arg5
#
0000000.016463 : START_USER_FUNC           : 19493 : 0x4014aa90 : 900000
0000000.016581 : BARRIER_INIT_IN           : 19493 : 0x4014aa90 : 0x8049c78 : (nil) : 2
0000000.016581 : BARRIER_INIT              : 19493 : 0x4014aa90 : 0x8049c78 : 2
0000000.016581 : BARRIER_INIT_OUT          : 19493 : 0x4014aa90 : 0x8049c78 : 0
0000000.016585 : THREAD_CREATE_IN          : 19493 : 0x4014aa90 : 0xbf9e2520 : (nil) : 0x8048758 : (nil)
0000000.016598 : THREAD_SET_PD             : 19493 : 0x4014aa90 : 0x4074dbb0
0000000.016614 : THREAD_INIT               : 19493 : 0x4014aa90 : 0x4074dbb0
0000000.016614 : THREAD_CREATE_OUT         : 19493 : 0x4014aa90 : 0
0000000.016616 : BARRIER_WAIT_IN           : 19493 : 0x4014aa90 : 0x8049c78
0000000.016616 : BARRIER_LOCK_REQUIRE      : 19493 : 0x4014aa90 : 0x8049c78 : 0
0000000.016616 : THREAD_STATE_WAIT         : 19493 : 0x4014aa90
0000000.016616 : THREAD_STATE_WAKE         : 19493 : 0x4014aa90
0000000.016616 : BARRIER_LOCK_TAKEN        : 19493 : 0x4014aa90 : 0x8049c78 : 1
0000000.016616 : BARRIER_LEFT_DEC          : 19493 : 0x4014aa90 : 0x8049c78 : 1
0000000.016617 : BARRIER_LOCK_FREE         : 19493 : 0x4014aa90 : 0x8049c78 : 1
0000000.016617 : THREAD_STATE_WAIT_BARRIER : 19493 : 0x4014aa90 : 0x8049c78
0000001.018918 : BARRIER_WAIT_IN           : 19493 : 0x4074dbb0 : 0x8049c78
0000001.018918 : BARRIER_LOCK_REQUIRE      : 19493 : 0x4074dbb0 : 0x8049c78 : 0
0000001.018918 : THREAD_STATE_WAIT         : 19493 : 0x4074dbb0
0000001.018918 : THREAD_STATE_WAKE         : 19493 : 0x4074dbb0
0000001.018918 : BARRIER_LOCK_TAKEN        : 19493 : 0x4074dbb0 : 0x8049c78 : 1
0000001.018919 : BARRIER_LEFT_DEC          : 19493 : 0x4074dbb0 : 0x8049c78 : 0
0000001.018922 : BARRIER_LEFT_INC          : 19493 : 0x4074dbb0 : 0x8049c78 : 1
0000001.018923 : BARRIER_WAIT_OUT          : 19493 : 0x4074dbb0 : 0x8049c78 : -1
0000001.018948 : THREAD_STATE_DEAD         : 19493 : 0x4074dbb0
0000001.018961 : THREAD_STATE_WAKE_BARRIER : 19493 : 0x4014aa90 : 0x8049c78
0000001.018962 : BARRIER_LEFT_INC          : 19493 : 0x4014aa90 : 0x8049c78 : 2
0000001.018962 : BARRIER_LOCK_FREE         : 19493 : 0x4014aa90 : 0x8049c78 : 1
0000001.018963 : BARRIER_WAIT_OUT          : 19493 : 0x4014aa90 : 0x8049c78 : 0
0000001.018965 : THREAD_JOIN_IN            : 19493 : 0x4014aa90 : 0x4074dbb0 : (nil)
0000001.018966 : THREAD_STATE_WAIT         : 19493 : 0x4014aa90
0000001.018967 : THREAD_STATE_WAKE         : 19493 : 0x4014aa90
0000001.018967 : THREAD_JOIN               : 19493 : 0x4014aa90 : 0x4074dbb0 : 16
0000001.018967 : THREAD_JOIN_OUT           : 19493 : 0x4014aa90 : 0
0000001.018969 : BARRIER_DESTROY_IN        : 19493 : 0x4014aa90 : 0x8049c78
0000001.018969 : BARRIER_LOCK_REQUIRE      : 19493 : 0x4014aa90 : 0x8049c78 : 0
0000001.018969 : THREAD_STATE_WAIT         : 19493 : 0x4014aa90
0000001.018970 : THREAD_STATE_WAKE         : 19493 : 0x4014aa90
0000001.018970 : BARRIER_LOCK_TAKEN        : 19493 : 0x4014aa90 : 0x8049c78 : 1
0000001.018970 : BARRIER_DESTROY           : 19493 : 0x4014aa90 : 0x8049c78
0000001.018970 : BARRIER_DESTROY_OUT       : 19493 : 0x4014aa90 : 0x8049c78 : 0
0000001.018976 : END_USER_FUNC             : 19493 : 0x4014aa90

Textual format

The ptt_view command used with the -t option generates a trace file in a textual format:

#	PTT version 0.90.0.
#	The trace was generated on i686 on Mon, 22 May 2006 10:04:16 +0200.
#	This file is the number 0.
#
#
0000000.016463 Pid 19493, Thread 0x4014aa90 starts user function, version=900000
0000000.016581 Pid 19493, Thread 0x4014aa90 enters function pthread_barrier_init, barrier=0x8049c78, attribute=(nil), count=2
0000000.016581 Pid 19493, Thread 0x4014aa90 initializes barrier 0x8049c78, left=2
0000000.016581 Pid 19493, Thread 0x4014aa90 leaves function pthread_barrier_init, barrier=0x8049c78, return=0
0000000.016585 Pid 19493, Thread 0x4014aa90 enters function pthread_create, thread=0xbf9e2520, attribute=(nil), start_routine=0x8048758, argument=(nil)
0000000.016598 Pid 19493, Thread 0x4014aa90 sets new thread at address 0x4074dbb0
0000000.016614 Pid 19493, Thread 0x4014aa90 creates thread 0x4074dbb0
0000000.016614 Pid 19493, Thread 0x4014aa90 leaves function pthread_create, return=0
0000000.016616 Pid 19493, Thread 0x4014aa90 enters function pthread_barrier_wait, barrier=0x8049c78
0000000.016616 Pid 19493, Thread 0x4014aa90 requires barrier 0x8049c78, lock=0
0000000.016616 Pid 19493, Thread 0x4014aa90 is blocked
0000000.016616 Pid 19493, Thread 0x4014aa90 is resumed
0000000.016616 Pid 19493, Thread 0x4014aa90 takes barrier 0x8049c78, lock=1
0000000.016616 Pid 19493, Thread 0x4014aa90 decrements barrier 0x8049c78, left=1
0000000.016617 Pid 19493, Thread 0x4014aa90 frees barrier 0x8049c78, lock=1
0000000.016617 Pid 19493, Thread 0x4014aa90 is blocked on barrier 0x8049c78
0000001.018918 Pid 19493, Thread 0x4074dbb0 enters function pthread_barrier_wait, barrier=0x8049c78
0000001.018918 Pid 19493, Thread 0x4074dbb0 requires barrier 0x8049c78, lock=0
0000001.018918 Pid 19493, Thread 0x4074dbb0 is blocked
0000001.018918 Pid 19493, Thread 0x4074dbb0 is resumed
0000001.018918 Pid 19493, Thread 0x4074dbb0 takes barrier 0x8049c78, lock=1
0000001.018919 Pid 19493, Thread 0x4074dbb0 decrements barrier 0x8049c78, left=0
0000001.018922 Pid 19493, Thread 0x4074dbb0 increments barrier 0x8049c78, left=1
0000001.018923 Pid 19493, Thread 0x4074dbb0 leaves function pthread_barrier_wait, barrier=0x8049c78, return=-1
0000001.018948 Pid 19493, Thread 0x4074dbb0 is dead
0000001.018961 Pid 19493, Thread 0x4014aa90 is resumed, barrier=0x8049c78
0000001.018962 Pid 19493, Thread 0x4014aa90 increments barrier 0x8049c78, left=2
0000001.018962 Pid 19493, Thread 0x4014aa90 frees barrier 0x8049c78, lock=1
0000001.018963 Pid 19493, Thread 0x4014aa90 leaves function pthread_barrier_wait, barrier=0x8049c78, return=0
0000001.018965 Pid 19493, Thread 0x4014aa90 enters function pthread_join, thread=0x4074dbb0 thread returns in (nil)
0000001.018966 Pid 19493, Thread 0x4014aa90 is blocked
0000001.018967 Pid 19493, Thread 0x4014aa90 is resumed
0000001.018967 Pid 19493, Thread 0x4014aa90 joins thread 0x4074dbb0 that returned 16
0000001.018967 Pid 19493, Thread 0x4014aa90 leaves function pthread_join, return=0
0000001.018969 Pid 19493, Thread 0x4014aa90 enters function pthread_barrier_destroy, barrier=0x8049c78
0000001.018969 Pid 19493, Thread 0x4014aa90 requires barrier 0x8049c78, lock=0
0000001.018969 Pid 19493, Thread 0x4014aa90 is blocked
0000001.018970 Pid 19493, Thread 0x4014aa90 is resumed
0000001.018970 Pid 19493, Thread 0x4014aa90 takes barrier 0x8049c78, lock=1
0000001.018970 Pid 19493, Thread 0x4014aa90 destroys barrier 0x8049c78
0000001.018970 Pid 19493, Thread 0x4014aa90 leaves function pthread_barrier_destroy, barrier= 0x8049c78, return=0
0000001.018976 Pid 19493, Thread 0x4014aa90 leaves user function

Graphical format

The ptt_paje command generates a trace file which format is Pajé compliant: Pajé turns this trace file into the following space-time diagram.

Click to view

Alias

In order to make the trace easier to read, aliases can be used instead of NPTL objects addresses and thread IDs. This is done by including the PTT file alias.h in the source code of the program and by using the three following macros:

FILE *alias_init (char *filename): create a file containing couples address-alias. This file will be used by ptt_view.
void new_thread_alias (FILE *fd, char *thread_name): add in the file fd a couple thread_ID-thread_name.
void new_object_alias (FILE *fd, void *object_ad, char *object_name): add in the file fd a couple object_address-object_name.

For example, the following instructions can be added to the preceeding program:

#define _XOPEN_SOURCE 600

#include <pthread.h>
#include <stdio.h>
#include "alias.h"

pthread_barrier_t barrier;
FILE *fd;

void *func (void *arg) {
    new_thread_alias (fd, "func");
    sleep (1);
    int ret = pthread_barrier_wait (&barrier);
    if ((ret != 0) && (ret != PTHREAD_BARRIER_SERIAL_THREAD))
        fprintf (stderr, "Error when waiting for barrier\n");
}

int main(int argc, char* argv[]) {	
    pthread_t thread;
    int ret;
	
    fd = alias_init ("alias");
    new_thread_alias (fd, "main");
    new_object_alias (fd, &barrier, "my_barrier");

    if (pthread_barrier_init (&barrier, NULL, 2) != 0) {
        printf ("Error when initializing barrier\n");
        return -1;
    }

    if (pthread_create (&thread, NULL, func, NULL) != 0) {
        printf ("Error when creating thread\n");
        return -1;
    }

    ret = pthread_barrier_wait (&barrier);
    if ((ret != 0) && (ret != PTHREAD_BARRIER_SERIAL_THREAD))
        fprintf (stderr, "Error when waiting for barrier\n");

    if (pthread_join (thread, NULL) != 0) {
        printf ("Error when joining thread\n");
        return -1;
    }
	
    if (pthread_barrier_destroy (&barrier) != 0) {
        printf ("Error when destroying barrier\n");
        return -1;
    }
	
    return 0;
}

se the -a alias_filename option of ptt_view to visualize the trace with aliases:

#	PTT version 0.90.0.
#	The trace was generated on i686 on Mon, 22 May 2006 10:04:16 +0200.
#	This file is the number 0.
#
#
0000000.016463 Pid 19493, Thread main starts user function, version=900000
0000000.016581 Pid 19493, Thread main enters function pthread_barrier_init, barrier=my_barrier, attribute=(nil), count=2
0000000.016581 Pid 19493, Thread main initializes barrier my_barrier, left=2
0000000.016581 Pid 19493, Thread main leaves function pthread_barrier_init, barrier=my_barrier, return=0
0000000.016585 Pid 19493, Thread main enters function pthread_create, thread=0xbf9e2520, attribute=(nil), start_routine=0x8048758, argument=(nil)
0000000.016598 Pid 19493, Thread main sets new thread at address func
0000000.016614 Pid 19493, Thread main creates thread func
0000000.016614 Pid 19493, Thread main leaves function pthread_create, return=0
0000000.016616 Pid 19493, Thread main enters function pthread_barrier_wait, barrier=my_barrier
0000000.016616 Pid 19493, Thread main requires barrier my_barrier, lock=0
0000000.016616 Pid 19493, Thread main is blocked
0000000.016616 Pid 19493, Thread main is resumed
0000000.016616 Pid 19493, Thread main takes barrier my_barrier, lock=1
0000000.016616 Pid 19493, Thread main decrements barrier my_barrier, left=1
0000000.016617 Pid 19493, Thread main frees barrier my_barrier, lock=1
0000000.016617 Pid 19493, Thread main is blocked on barrier my_barrier
0000001.018918 Pid 19493, Thread func enters function pthread_barrier_wait, barrier=my_barrier
0000001.018918 Pid 19493, Thread func requires barrier my_barrier, lock=0
0000001.018918 Pid 19493, Thread func is blocked
0000001.018918 Pid 19493, Thread func is resumed
0000001.018918 Pid 19493, Thread func takes barrier my_barrier, lock=1
0000001.018919 Pid 19493, Thread func decrements barrier my_barrier, left=0
0000001.018922 Pid 19493, Thread func increments barrier my_barrier, left=1
0000001.018923 Pid 19493, Thread func leaves function pthread_barrier_wait, barrier=my_barrier, return=-1
0000001.018948 Pid 19493, Thread func is dead
0000001.018961 Pid 19493, Thread main is resumed, barrier=my_barrier
0000001.018962 Pid 19493, Thread main increments barrier my_barrier, left=2
0000001.018962 Pid 19493, Thread main frees barrier my_barrier, lock=1
0000001.018963 Pid 19493, Thread main leaves function pthread_barrier_wait, barrier=my_barrier, return=0
0000001.018965 Pid 19493, Thread main enters function pthread_join, thread=func thread returns in (nil)
0000001.018966 Pid 19493, Thread main is blocked
0000001.018967 Pid 19493, Thread main is resumed
0000001.018967 Pid 19493, Thread main joins thread func that returned 16
0000001.018967 Pid 19493, Thread main leaves function pthread_join, return=0
0000001.018969 Pid 19493, Thread main enters function pthread_barrier_destroy, barrier=my_barrier
0000001.018969 Pid 19493, Thread main requires barrier my_barrier, lock=0
0000001.018969 Pid 19493, Thread main is blocked
0000001.018970 Pid 19493, Thread main is resumed
0000001.018970 Pid 19493, Thread main takes barrier my_barrier, lock=1
0000001.018970 Pid 19493, Thread main destroys barrier my_barrier
0000001.018970 Pid 19493, Thread main leaves function pthread_barrier_destroy, barrier= my_barrier, return=0
0000001.018976 Pid 19493, Thread main leaves user function

Contention analysis

Applying ptt_contention to the binary file created by ptt_trace gives information about contention in this program:

elapsed time: 1.002513s
_________________________contention per thread_________________________
thread    main               : 1.002346s    100%   99.9% (elapsed time)
thread    func               : 0.000000s      0%      0% (elapsed time)
TOTAL     (global contention): 1.002346s    100%

__________contention per NPTL objects___________
barrier   my_barrier         : 1.002344s    100%
TOTAL                        : 1.002344s    100%

Note that the -a alias_filename option was also used here. We clearly see that a second is spent by the main thread waiting at the barrier.

Page hosted by :

NPTL Trace Tool

EXAMPLE

Home

User Manual

Goals
Trace events
Inside
Example

Internals

Forum

Download