Tuesday, July 10, 2007

Profiling of System Calls by ACC

I've written the following program to profile system calls by using Aspect C.
Put this file (profile.acc) inside the src directory, ACC will automatically weave it with the original code, and then compile it.

#include
#include "xt_defs.h"

#undef PROFILE_DEBUG

/*
* profile_get_time
* Return: current time in micro seconds
*/
inline long profile_get_time( )
{
struct timeval current_time;
gettimeofday(¤t_time,0);
return (current_time.tv_sec)*1000000+current_time.tv_usec;
}

/*
* profile i/o function: pread
* we record its execution time when pread is called
*/

long profile_pread_access_time=0;
long profile_pread_freq=0;

int around(): call($ pread(...)) {

long start_time = profile_get_time();

int val = proceed();

profile_pread_access_time += profile_get_time()-start_time;
profile_pread_freq ++;

#ifdef PROFILE_DEBUG
printf(" %s %s in function %s of file %s \n",
this->kind,this->targetName,this->funcName,this->fileName);
#endif

return val;
}

/*
* profile i/o function: pwrite
* we record its execution time when pwrite is called
*/

long profile_pwrite_access_time=0;
long profile_pwrite_freq=0;

int around(): call($ pwrite(...)) {

long start_time = profile_get_time();

int val = proceed();

profile_pwrite_access_time += profile_get_time()-start_time;
profile_pwrite_freq ++;

#ifdef PROFILE_DEBUG
printf(" %s %s in function %s of file %s \n",
this->kind,this->targetName,this->funcName,this->fileName);
#endif

return val;
}

/*
* profile memory function: malloc
* we record its execution time when malloc is called
*/

long profile_malloc_access_time=0;
long profile_malloc_freq=0;

int around(): call($ malloc(...)) {

long start_time = profile_get_time();

int val = proceed();

profile_malloc_access_time += profile_get_time()-start_time;
profile_malloc_freq ++;

#ifdef PROFILE_DEBUG
printf(" %s %s in function %s of file %s \n",
this->kind,this->targetName,this->funcName,this->fileName);
#endif

return val;
}

/*
* profile memory function: calloc
* we record its execution time when calloc is called
*/

long profile_calloc_access_time=0;
long profile_calloc_freq=0;

int around(): call($ calloc(...)) {

long start_time = profile_get_time();

int val = proceed();

profile_calloc_access_time += profile_get_time()-start_time;
profile_calloc_freq ++;

#ifdef PROFILE_DEBUG
printf(" %s %s in function %s of file %s \n",
this->kind,this->targetName,this->funcName,this->fileName);
#endif

return val;
}

/*
* profile memory function: realloc
* we record its execution time when realloc is called
*/

long profile_realloc_access_time=0;
long profile_realloc_freq=0;

int around(): call($ realloc(...)) {

long start_time = profile_get_time();

int val = proceed();

profile_realloc_access_time += profile_get_time()-start_time;
profile_realloc_freq ++;

#ifdef PROFILE_DEBUG
printf(" %s %s in function %s of file %s \n",
this->kind,this->targetName,this->funcName,this->fileName);
#endif

return val;
}

/*
* profile lock function: pthread_mutex_lock
* we record its execution time when pthread_mutex_lock is called
*/

long profile_pthread_mutex_lock_access_time=0;
long profile_pthread_mutex_lock_freq=0;

int around(): call($ pthread_mutex_lock(...)) {

long start_time = profile_get_time();

int val = proceed();

profile_pthread_mutex_lock_access_time += profile_get_time()-start_time;
profile_pthread_mutex_lock_freq ++;

#ifdef PROFILE_DEBUG
printf(" %s %s in function %s of file %s \n",
this->kind,this->targetName,this->funcName,this->fileName);
#endif

return val;
}


/*
* profile lock function: pthread_rwlock_rdlock
* we record its execution time when pthread_rwlock_rdlock is called
*/

long profile_pthread_rwlock_rdlock_access_time=0;
long profile_pthread_rwlock_rdlock_freq=0;

int around(): call($ pthread_rwlock_rdlock(...)) {

long start_time = profile_get_time();

int val = proceed();

profile_pthread_rwlock_rdlock_access_time += profile_get_time()-start_time;
profile_pthread_rwlock_rdlock_freq ++;

#ifdef PROFILE_DEBUG
printf(" %s %s in function %s of file %s \n",
this->kind,this->targetName,this->funcName,this->fileName);
#endif

return val;
}

/*
* profile lock function: pthread_rwlock_wrlock
* we record its execution time when pthread_rwlock_wrlock is called
*/

long profile_pthread_rwlock_wrlock_access_time=0;
long profile_pthread_rwlock_wrlock_freq=0;

int around(): call($ pthread_rwlock_wrlock(...)) {

long start_time = profile_get_time();

int val = proceed();

profile_pthread_rwlock_wrlock_access_time += profile_get_time()-start_time;
profile_pthread_rwlock_wrlock_freq ++;

#ifdef PROFILE_DEBUG
printf(" %s %s in function %s of file %s \n",
this->kind,this->targetName,this->funcName,this->fileName);
#endif

return val;
}

/*
* Print out all results of profiling
* when xt_create_thread("TempForEnd", &err, TRUE) is executed in pbxt_end
*/

void printProfileResult()
{
printf("System_call\tTotal_Execution_Time\tTotal_Call_Times\n");
printf("pread %d %d\n",profile_pread_access_time,profile_pread_freq);
printf("pwrite %d %d\n",profile_pwrite_access_time,profile_pwrite_freq);

printf("malloc %d %d\n",profile_malloc_access_time,profile_malloc_freq);
printf("calloc %d %d\n",profile_calloc_access_time,profile_calloc_freq);
printf("realloc %d %d\n",profile_realloc_access_time,profile_realloc_freq);

printf("pthread_mutex_lock %d %d\n",profile_pthread_mutex_lock_access_time,profile_pthread_mutex_lock_freq);
printf("pthread_rwlock_rdlock %d %d\n",profile_pthread_rwlock_rdlock_access_time,profile_pthread_rwlock_rdlock_freq);
printf("pthread_rwlock_wrlock %d %d\n",profile_pthread_rwlock_wrlock_access_time,profile_pthread_rwlock_wrlock_freq);
}

/*
* Print out all results of profiling
* when xt_create_thread("TempForEnd", &err, TRUE) is executed in pbxt_end
*/
after(c_char *name): execution($ xt_create_thread(...)) && args(name,...)
{
#ifdef PROFILE_DEBUG
printf(" %s %s in function %s of file %s \n",
this->kind,this->targetName,this->funcName,this->fileName);
#endif
printf("End Name %s\n",name);
if(strcmp(name,"TempForEnd")==0){
//it is called by pbxt_end
printProfileResult();
}
}

No comments: