tools/TTCN3Profiler/ttcn3prof.cc

///////////////////////////////////////////////////////////////////////////////
//                                                                           //
// Copyright (c) 2000-2019 Ericsson Telecom AB                               //
//                                                                           //
// All rights reserved. This program and the accompanying materials          //
// are made available under the terms of the Eclipse Public License v2.0     //
// which accompanies this distribution, and is available at                  //
// https://www.eclipse.org/org/documents/epl-2.0/EPL-2.0.html                                 //
//                                                                           //
///////////////////////////////////////////////////////////////////////////////

#include <time.h>
#include "ttcn3prof.hh"
#include <fcntl.h>
#include <unistd.h>
//#include <errno.h>  //errno
#include <time.h>

int StackDepth::currentDepth=-1;
EPTF__CLL__TTCN3Profiler::EPTF__TTCN3Profiler__CallStackTimerDb StackDepth::callStackTimerDb=NULL_VALUE;

TTCN3PROF_GLOBAL::~TTCN3PROF_GLOBAL() {
  try {
    // this 'if' throws an exception on HC:
    CHARSTRING lockFileName("");
    //fprintf(stdout,"#####EXECUTING PROF GLOBAL DESTRUCTOR ON COMP %s ######\n", (const char*)int2str(self));
    lockFileName=lockFileName+"TTCN3Profiler_Comp"+int2str(self)+".lck";
    //system((const char*)(CHARSTRING("")+"if [ -r "+lockFileName+" ]\nthen\nrm "+lockFileName+"\nfi"));//+";touch RM"+int2str(self)));
    unlink((const char*)lockFileName); // remove the file
    if (MTC_COMPREF==self) {
      //fprintf(stdout,"###### TTCN3Profiler Summary on component %d #######\n",(int)self);
      return;
    }
  } catch(...) {
    // This is only executed on HC:
    CHARSTRING lockFileName("");
    lockFileName=lockFileName+"TTCN3Profiler_Comp_HC_"+int2str((int)::getpid())+".lck";

    CHARSTRING cmd("");
    cmd = "sleep 1;while [ -n \"`find *.lck ! -name \"TTCN3Profiler_Comp_HC_*.lck\" 2> /dev/null`\" ]\ndo sleep 1\ndone;if [ -z \"`find TTCN3Profiler_Comp_HC*.lck 2> /dev/null`\" ]\nthen\ntouch "+lockFileName+"; sleep 1; if [ \""+lockFileName+"\" != \"`find TTCN3Profiler_Comp_HC*.lck | head -1  2> /dev/null`\" ]\nthen\n\\rm "+lockFileName+";fi;fi";
    system((const char*)cmd);

    time_t rawtime;
    time (&rawtime);

    fprintf(stdout,"###### TTCN3Profiler Summary ####### %s", ctime (&rawtime));
    fflush(stdout);
    cmd = "if [ -f \""+lockFileName+"\" ]\nthen\nwhile [ -n \"`find *.lck ! -name \""+lockFileName+"\" 2> /dev/null`\" ]\ndo sleep 1\ndone;./ttcn3prof_gen;\\rm \""+lockFileName+"\";fi";
    system((const char*)cmd);//;touch AAA");
    //fprintf(stdout,"#####EXECUTING PROF GLOBAL DESTRUCTOR ON COMP HC ######\n");
    fprintf(stdout,"###################################\n");
    fflush(stdout);
  }
}

TTCN3PROF ttcn3prof;


double TTCN3PROF::getTime() {
  struct timeval tv;
  gettimeofday(&tv,NULL);
  return tv.tv_sec+tv.tv_usec/1000000.0;
}

void TTCN3PROF::enterFunction(const char* filename,const int& lineno,const char* functionName) {
  if (!EPTF__CLL__TTCN3Profiler::tsp__EPTF__TTCN3Profiler__disabled.is_bound() || EPTF__CLL__TTCN3Profiler::tsp__EPTF__TTCN3Profiler__disabled==true) {
    return;
  }
  
  // Note that the execution time of the last line in a function
  // is measured by using the stack depth.
  // When the call-stack depth increases the data of the previous line
  // is stored in the callStackTimerDb. When the stack depth decreases
  // those entries in callStackTimerDb are measured (and removed)
  // which have longer or equal stack depth as the current stack depth.
  // The execution time of the called function is added to the caller
  // when stack is enabled, otherwise the caller gets the time it takes to
  // jump to the function only (net time).
  // When stack is enabled the 'All call time' statistics will be
  // greater than the value without stack. This is because with stack
  // enabled, the function call times are added multiple times (caller and called).
  executeLine(filename,lineno);
}

void StackDepth::addStack(const int& stackLen,const char* filename,const int& lineno) {
  if (currentDepth<=stackLen || filename==NULL) {
    return;
  }
  int callStackSize = currentDepth-1;
  //fprintf(stdout,"\naddStack:currentDepth: %d\n", currentDepth);
  callStackTimerDb[callStackSize].stackLen() = stackLen;
  callStackTimerDb[callStackSize].filename() = filename;
  callStackTimerDb[callStackSize].lineno() = lineno;
  callStackTimerDb[callStackSize].elapsed() = 0;
}

// stop all timers not above the current stack:
void StackDepth::removeStack() {
  //fprintf(stdout,"removeStack:currentDepth: %d\n", currentDepth);
  if (currentDepth<1) {
    return;
  }
  int i=currentDepth-1;

  // if stack level is the same or higher: measure the time:
  const char* prevFile = (const char*)callStackTimerDb[i].filename();
  int prevLine = callStackTimerDb[i].lineno();

  double elapsed = callStackTimerDb[i].elapsed();
  // add elapsed time to the total execution time of the previous line:

  int element = ttcn3prof.findElement(prevFile);
  if (element==-1) {
    // create new element:
    element = ttcn3prof.newElement(prevFile);
  }

  // add the elapsed time to the time of the previous line:
  ttcn3prof.addTime(elapsed,element,prevLine);

  int prevStackLen = callStackTimerDb[i].stackLen();
  ttcn3prof.setPrev(prevStackLen,prevFile,prevLine);
  //fprintf(stdout,"#############removeStack:DONE\n");
}
void StackDepth::updateStackElapsed(const double& elapsed,const int& stackLen) {
  if (EPTF__CLL__TTCN3Profiler::tsp__EPTF__TTCN3Profiler__noAggregate) {
    return;
  }
  //fprintf(stderr,"updateStackElapsed:%f.\n",elapsed);
  for(int i=0; i<stackLen; i++) {
    callStackTimerDb[i].elapsed() = callStackTimerDb[i].elapsed() + elapsed;
    //if (callStackTimerDb[i].filename()!=NULL) {
    //  fprintf(stdout,"++++Aggregating elapsed time to %s:%d: %f.\n",(const char*)callStackTimerDb[i].filename(),(int)callStackTimerDb[i].lineno(),elapsed);
    //}
  }
}

void TTCN3PROF::setPrev(const int& stackLen,const char* filename, const int& lineno) {
  prevStackLen = stackLen;
  if(prevFile!=NULL) {
    if (strcmp(prevFile,filename)!=0) {
      delete [] prevFile;
      prevFile = strdup(filename);
    }
  } else {
    prevFile = strdup(filename);
  };
  prevLine = lineno;
  prevTime = getTime();
  //fprintf(stdout,"Starting measurement:%f.\n",prevTime);
}

void TTCN3PROF::updateLast() {
  if (prevTime==0.0) {
    return;
  }
  double currentTime = getTime();
  //fprintf(stdout,"####Exiting current function at depth %i at time %f.\n",StackDepth::depth(),currentTime);
  double elapsed = currentTime-prevTime;

  int element = findElement(prevFile);
  if (element==-1) {
    // create new element:
    element = newElement(prevFile);
  }
  
  // add the elapsed time to the time of the previous line:
  addTime(elapsed,element,prevLine);
  StackDepth::updateStackElapsed(elapsed, prevStackLen);

  // reset measurement:
  prevTime = 0.0;
}

void TTCN3PROF::executeLine(const char* filename, const int& lineno) {
  if (!EPTF__CLL__TTCN3Profiler::tsp__EPTF__TTCN3Profiler__disabled.is_bound() || EPTF__CLL__TTCN3Profiler::tsp__EPTF__TTCN3Profiler__disabled==true) {
    return;
  }
  double currentTime = getTime();
  //fprintf(stdout,"--Executing: %s:%d at %f.\n",filename,lineno,currentTime);
  int currentStackLen=StackDepth::depth();

  //fprintf(stdout,"currentStackLen:%d, prevStackLen: %d.\n",currentStackLen,prevStackLen);

  // if stack level is the same or higher: current line should be measured:
  double elapsed = currentTime-prevTime;
  // add elapsed time to the total execution time of the previous line:

  int element = findElement(prevFile);
  if (element==-1) {
    // create new element:
    element = newElement(prevFile);
  }
  
  // add the elapsed time to the time of the previous line:
  addTime(elapsed,element,prevLine);

  //if (currentStack!=NULL) {
  //  fprintf(stderr,"stack: %s.\n",currentStack);
  //}
  // prev line should not be measured, because it is still running: we are in longer stack level
  if (prevTime==0.0 || currentStackLen>prevStackLen) {
    // create new item in call stack:
    StackDepth::addStack(prevStackLen,prevFile,prevLine);
  }

  // add elapsed time to call stack:
  StackDepth::updateStackElapsed(elapsed, prevStackLen);

  // store current location to prev location and start measurement:
  setPrev(currentStackLen,filename,lineno);
}


int TTCN3PROF::findElement(const char* filename) {
  for(int i=0; i<profilerDb.size_of(); ++i) {
    if (profilerDb[i].filename()==filename) {
      return i;
    }
  }
  return -1; // not found
}

int TTCN3PROF::newElement(const char* filename) {
  int size(profilerDb.size_of());
  profilerDb[size].filename() = filename;
  profilerDb[size].times() = NULL_VALUE;
  return size;
}

void TTCN3PROF::addTime(double elapsed, const int& element, const int& lineno) {
  if (lineno==-1) {
    return;
  }
  // set 0 for the unknown lines:
  if (profilerDb[element].times().size_of()<=lineno) {
    for(int i=profilerDb[element].times().size_of(); i<=lineno; ++i) {
      profilerDb[element].times()[i] = 0.0;
    }
  }
  // increase the time of the line in the current file:
  //fprintf(stdout,"++Adding elapsed time to location %s:%d: %f secs\n",(const char*)profilerDb[element].filename(),lineno,elapsed);
  profilerDb[element].times()[lineno] = profilerDb[element].times()[lineno] + elapsed;
  //fprintf(stdout,"%s:%d: execution took %f secs\n",(const char*)profilerDb[element].filename(),lineno,elapsed);
}

void TTCN3PROF::writeToFile(const char* data) {
  CHARSTRING selfIdStr("HC");
  try {
    // this 'if' throws an exception on HC:
    selfIdStr=int2str(self);
  } catch(...) {
  }

  CHARSTRING filename=moduleName+"_"+selfIdStr+".prof";

  int fd = open (filename, O_APPEND | O_WRONLY | O_CREAT, S_IRUSR | S_IWUSR | S_IRGRP | S_IROTH);
  if (fd<0) {
    fprintf(stderr,"Cannot open target file: %s\n",(const char*)filename);
    return;
  }
  int bytes = write (fd, (const void *) data, strlen(data));
  if (bytes<0) {
    fprintf(stderr,"Cannot write data to target file: %s\n",(const char*)filename);
    return;
  }
  // flush the data:
  fsync(fd);
  close(fd);
}

void TTCN3PROF::printStat() {
  if(prevFile==NULL) {
    return; // do not generate anything if no info is available
  }  
  CHARSTRING lockFileName("");
  CHARSTRING selfIdStr("HC");
  try {
    // this 'if' throws an exception on HC:
    selfIdStr=int2str(self);
    lockFileName=lockFileName+"TTCN3Profiler_Comp"+int2str(self)+".lck";
    system((const char*)(CHARSTRING("touch ")+lockFileName));
  } catch(...) {
  }
  CHARSTRING profileStat = ""
  "###################################################\n"
  "#########  Profile statistics on comp "+selfIdStr+"  ########\n"
  "###################################################\n"
  + EPTF__CLL__TTCN3Profiler::f__EPTF__TTCN3Profiler__printStat(profilerDb,codeLines)
  +"##################  EOF Profile   ###############\n";
  writeToFile(profileStat);
  //if (lockFileName!="") {
    //system((const char*)(CHARSTRING("rm ")+lockFileName));
    //system((const char*)(CHARSTRING("touch RM_")+lockFileName+prevFile+"_"));
  //}
  //fprintf(stdout,"%s\n",(const char*)coverageStat);
  //fprintf(stdout,"###### TTCN3Profiler enabled ######\n");
  //fprintf(stdout,"#####EXECUTING PROF LOCAL DESTRUCTOR FOR MODULE %s on COMP %s ######\n", (const char*)moduleName, (const char*)selfIdStr);
};

void TTCN3PROF::log(const char *fmt, ...) 
{
    TTCN_Logger::begin_event(TTCN_DEBUG);
    va_list pvar;
    va_start(pvar, fmt);
    TTCN_Logger::log_event_va_list(fmt, pvar);
//    fprintf(stdout,fmt, pvar);
//    fprintf(stdout,"\n");
    va_end(pvar);
    TTCN_Logger::end_event();
}

void EPTF__CLL__TTCN3Profiler::f__EPTF__TTCN3Profiler__system(const CHARSTRING& pl__command) {
  TTCN3PROF::log("TTCN3Profiler: Executing command: %s",(const char*)pl__command);
  system((const char*)pl__command);
  TTCN3PROF::log("TTCN3Profiler: Command finished %s",(const char*)pl__command);
}


#define cs_0 ""
#define cs_3 "\n"
#define cs_7 "\nAvgTimePerLine in file "
#define cs_4 "\nCode lines     in file "
#define cs_6 "\nExecution time in file "
#define cs_10 "\nOverall time per line: "
#define cs_8 "\nTotal code lines     : "
#define cs_9 "\nTotal execution time : "
#define cs_2 ":"
#define cs_1 ":\t"
#define cs_5 ": "

CHARSTRING EPTF__CLL__TTCN3Profiler::f__EPTF__TTCN3Profiler__printStat(const EPTF__TTCN3ProfilerDb& pl__profilerDb, const INTEGER& pl__codeLines)
{
TTCN_Location current_location("EPTF_CLL_TTCN3Profiler.ttcn", 21, TTCN_Location::LOCATION_FUNCTION, "f_EPTF_TTCN3Profiler_printStat");
current_location.update_lineno(22);
/* EPTF_CLL_TTCN3Profiler.ttcn, line 22 */
CHARSTRING vl__profilerStat(cs_0);
current_location.update_lineno(23);
/* EPTF_CLL_TTCN3Profiler.ttcn, line 23 */
FLOAT vl__usage;
current_location.update_lineno(24);
/* EPTF_CLL_TTCN3Profiler.ttcn, line 24 */
INTEGER vl__totalCodeLines(0);
current_location.update_lineno(25);
/* EPTF_CLL_TTCN3Profiler.ttcn, line 25 */
FLOAT vl__totalUsedTimes(0.0);
{
INTEGER i(0);
current_location.update_lineno(26);
/* EPTF_CLL_TTCN3Profiler.ttcn, line 26 */
for ( ; ; ) {
current_location.update_lineno(26);
/* EPTF_CLL_TTCN3Profiler.ttcn, line 26 */
if (!(i < pl__profilerDb.size_of())) break;
{
current_location.update_lineno(27);
/* EPTF_CLL_TTCN3Profiler.ttcn, line 27 */
if ((pl__profilerDb[i].times().size_of() == 0)) {
current_location.update_lineno(28);
/* EPTF_CLL_TTCN3Profiler.ttcn, line 28 */
goto tmp_0;
}
current_location.update_lineno(30);
/* EPTF_CLL_TTCN3Profiler.ttcn, line 30 */
FLOAT vl__usedtimes(0.0);
current_location.update_lineno(31);
/* EPTF_CLL_TTCN3Profiler.ttcn, line 31 */
CHARSTRING vl__filename(pl__profilerDb[i].filename());
{
INTEGER l(0);
current_location.update_lineno(32);
/* EPTF_CLL_TTCN3Profiler.ttcn, line 32 */
for ( ; ; ) {
current_location.update_lineno(32);
/* EPTF_CLL_TTCN3Profiler.ttcn, line 32 */
if (!(l < pl__profilerDb[i].times().size_of())) break;
{
current_location.update_lineno(33);
/* EPTF_CLL_TTCN3Profiler.ttcn, line 33 */
FLOAT vl__time(pl__profilerDb[i].times()[l]);
current_location.update_lineno(34);
/* EPTF_CLL_TTCN3Profiler.ttcn, line 34 */
if ((vl__time == 0.0)) {
current_location.update_lineno(35);
/* EPTF_CLL_TTCN3Profiler.ttcn, line 35 */
goto tmp_1;
}
current_location.update_lineno(37);
/* EPTF_CLL_TTCN3Profiler.ttcn, line 37 */
vl__profilerStat = ((((((vl__profilerStat + float2str(vl__time)) + cs_1) + vl__filename) + cs_2) + int2str(l)) + cs_3);
current_location.update_lineno(40);
/* EPTF_CLL_TTCN3Profiler.ttcn, line 40 */
if ((vl__time > 0.0)) {
current_location.update_lineno(41);
/* EPTF_CLL_TTCN3Profiler.ttcn, line 41 */
vl__usedtimes = (vl__usedtimes + vl__time);
}
}
tmp_1:
current_location.update_lineno(32);
/* EPTF_CLL_TTCN3Profiler.ttcn, line 32 */
l = (l + 1);
}
}
current_location.update_lineno(44);
/* EPTF_CLL_TTCN3Profiler.ttcn, line 44 */
INTEGER vl__codeLines(pl__codeLines);
current_location.update_lineno(45);
/* EPTF_CLL_TTCN3Profiler.ttcn, line 45 */
if ((vl__codeLines < 1)) {
current_location.update_lineno(46);
/* EPTF_CLL_TTCN3Profiler.ttcn, line 46 */
vl__codeLines = pl__profilerDb[i].times().size_of();
}
current_location.update_lineno(48);
/* EPTF_CLL_TTCN3Profiler.ttcn, line 48 */
vl__usage = (vl__usedtimes / int2float(vl__codeLines));
current_location.update_lineno(49);
/* EPTF_CLL_TTCN3Profiler.ttcn, line 49 */
vl__profilerStat = ((((vl__profilerStat + cs_4) + vl__filename) + cs_5) + int2str(vl__codeLines));
current_location.update_lineno(50);
/* EPTF_CLL_TTCN3Profiler.ttcn, line 50 */
vl__profilerStat = ((((vl__profilerStat + cs_6) + vl__filename) + cs_5) + float2str(vl__usedtimes));
current_location.update_lineno(51);
/* EPTF_CLL_TTCN3Profiler.ttcn, line 51 */
vl__profilerStat = (((((vl__profilerStat + cs_7) + vl__filename) + cs_5) + float2str(vl__usage)) + cs_3);
current_location.update_lineno(53);
/* EPTF_CLL_TTCN3Profiler.ttcn, line 53 */
vl__totalUsedTimes = (vl__totalUsedTimes + vl__usedtimes);
current_location.update_lineno(54);
/* EPTF_CLL_TTCN3Profiler.ttcn, line 54 */
vl__totalCodeLines = (vl__totalCodeLines + vl__codeLines);
}
tmp_0:
current_location.update_lineno(26);
/* EPTF_CLL_TTCN3Profiler.ttcn, line 26 */
i = (i + 1);
}
}
current_location.update_lineno(57);
/* EPTF_CLL_TTCN3Profiler.ttcn, line 57 */
if ((vl__totalCodeLines == 0)) {
current_location.update_lineno(58);
/* EPTF_CLL_TTCN3Profiler.ttcn, line 58 */
vl__usage = 0.0;
}
else {
current_location.update_lineno(60);
/* EPTF_CLL_TTCN3Profiler.ttcn, line 60 */
vl__usage = (vl__totalUsedTimes / int2float(vl__totalCodeLines));
}
current_location.update_lineno(63);
/* EPTF_CLL_TTCN3Profiler.ttcn, line 63 */
vl__profilerStat = ((vl__profilerStat + cs_8) + int2str(vl__totalCodeLines));
current_location.update_lineno(64);
/* EPTF_CLL_TTCN3Profiler.ttcn, line 64 */
vl__profilerStat = ((vl__profilerStat + cs_9) + float2str(vl__totalUsedTimes));
current_location.update_lineno(65);
/* EPTF_CLL_TTCN3Profiler.ttcn, line 65 */
vl__profilerStat = (((vl__profilerStat + cs_10) + float2str(vl__usage)) + cs_3);
current_location.update_lineno(67);
/* EPTF_CLL_TTCN3Profiler.ttcn, line 67 */
return vl__profilerStat;
}