| /////////////////////////////////////////////////////////////////////////////// |
| // // |
| // Copyright (c) 2000-2018 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; |
| } |