Folks,
I have an EPICS IOC application that is taking a lot of CPU time and I want to figure out where it is spending its time. The IOC is running on Linux, and it seems like the Linux "gprof" tool should do what I want.
I added the following lines to my application Makefile, and also changed CONFIG to STATIC_BUILD=YES.
USR_CPPFLAGS_Linux += -pg
USR_CFLAGS_Linux += -pg
USR_LDFLAGS_Linux += -pg
The application creates the gmon.out file as expected. The problem is that the output of gprof seems to have the number of calls to each function correctly, but does not have execution times.
corvette:quadEM/iocBoot/iocTest>gprof -b ../../bin/linux-x86/quadEMTestApp gmon.out | more
Flat profile:
Each sample counts as 0.01 seconds.
% cumulative self self total
time seconds seconds calls Ts/call Ts/call name
100.00 0.01 0.01 yyerror
0.00 0.01 0.00 25739421 0.00 0.00 getAddr
0.00 0.01 0.00 11866294 0.00 0.00 paramList::getParameter(int)
0.00 0.01 0.00 7586090 0.00 0.00 paramVal::isDefined()
0.00 0.01 0.00 3706973 0.00 0.00 getTraceMask
0.00 0.01 0.00 3403295 0.00 0.00 paramVal::getStatus()
0.00 0.01 0.00 2237527 0.00 0.00 paramList::getInteger(int, int*)
0.00 0.01 0.00 2237526 0.00 0.00 paramVal::getInteger()
0.00 0.01 0.00 2235123 0.00 0.00 interruptEnd
0.00 0.01 0.00 2235122 0.00 0.00 interruptStart
0.00 0.01 0.00 2143477 0.00 0.00 paramVal::hasValueChanged()
0.00 0.01 0.00 2143477 0.00 0.00 paramList::registerParameterChange(paramVal*, int)
0.00 0.01 0.00 2136839 0.00 0.00 paramVal::resetValueChanged()
0.00 0.01 0.00 2136838 0.00 0.00 paramList::setFlag(int)
0.00 0.01 0.00 2136837 0.00 0.00 paramVal::setValueChanged()
0.00 0.01 0.00 2136836 0.00 0.00 paramVal::setDefined(bool)
0.00 0.01 0.00 1169154 0.00 0.00 asynPortDriver::getIntegerParam(int, int, int*)
0.00 0.01 0.00 1071776 0.00 0.00 paramVal::setInteger(int)
0.00 0.01 0.00 1071776 0.00 0.00 paramList::setInteger(int, int)
0.00 0.01 0.00 1071775 0.00 0.00 asynPortDriver::setIntegerParam(int, int, int)
0.00 0.01 0.00 1071721 0.00 0.00 asynPortDriver::callParamCallbacks(int, int)
0.00 0.01 0.00 1071719 0.00 0.00 paramList::callCallbacks(int)
0.00 0.01 0.00 1071701 0.00 0.00 asynPortDriver::setDoubleParam(int, int, double)
0.00 0.01 0.00 1071701 0.00 0.00 paramVal::setDouble(double)
0.00 0.01 0.00 1071700 0.00 0.00 paramList::setDouble(int, double)
0.00 0.01 0.00 1071673 0.00 0.00 asynPortDriver::callParamCallbacks(int)
0.00 0.01 0.00 1068372 0.00 0.00 paramList::int32Callback(int, int)
0.00 0.01 0.00 1068362 0.00 0.00 paramVal::getDouble()
0.00 0.01 0.00 1068362 0.00 0.00 paramList::getDouble(int, double*)
0.00 0.01 0.00 1068356 0.00 0.00 paramList::float64Callback(int, int)
0.00 0.01 0.00 1068349 0.00 0.00 interruptCallbackAverage
0.00 0.01 0.00 389732 0.00 0.00 asynPortDriver::getIntegerParam(int, int*)
0.00 0.01 0.00 97846 0.00 0.00 createAsynUser
0.00 0.01 0.00 97724 0.00 0.00 queueRequest
0.00 0.01 0.00 97706 0.00 0.00 duplicateAsynUser
0.00 0.01 0.00 97705 0.00 0.00 disconnect
0.00 0.01 0.00 97682 0.00 0.00 freeAsynUser
0.00 0.01 0.00 97679 0.00 0.00 lockPort
0.00 0.01 0.00 97676 0.00 0.00 asynPortDriver::lock()
0.00 0.01 0.00 97676 0.00 0.00 asynPortDriver::unlock()
0.00 0.01 0.00 97675 0.00 0.00 unlockPort
0.00 0.01 0.00 97667 0.00 0.00 lockPortCallback
0.00 0.01 0.00 97570 0.00 0.00 readIt
0.00 0.01 0.00 97444 0.00 0.00 readIt
0.00 0.01 0.00 97425 0.00 0.00 asynPortDriver::getParamStatus(int, int, asynStatus*)
0.00 0.01 0.00 97425 0.00 0.00 asynStatus asynPortDriver::doCallbacksArray<int, asynInt32ArrayInterrupt>(int*, unsigned int, int, int, void*)
0.00 0.01 0.00 97425 0.00 0.00 asynPortDriver::doCallbacksInt32Array(int*, unsigned int, int, int)
0.00 0.01 0.00 97425 0.00 0.00 drvQuadEM::computePositions(int*)
0.00 0.01 0.00 97424 0.00 0.00 paramList::getStatus(int, asynStatus*)
0.00 0.01 0.00 10835 0.00 0.00 paramVal::nameEquals(char const*)
0.00 0.01 0.00 999 0.00 0.00 getPortName
0.00 0.01 0.00 988 0.00 0.00 readIt
0.00 0.01 0.00 988 0.00 0.00 readIt
0.00 0.01 0.00 970 0.00 0.00 callInterruptUsers
0.00 0.01 0.00 584 0.00 0.00 paramList::findParam(char const*, int*)
0.00 0.01 0.00 462 0.00 0.00 asynPortDriver::createParam(int, char const*, asynParamType, int*)
0.00 0.01 0.00 462 0.00 0.00 paramVal::paramVal(char const*, asynParamType)
0.00 0.01 0.00 462 0.00 0.00 paramVal::paramVal(char const*)
0.00 0.01 0.00 462 0.00 0.00 paramList::createParam(char const*, asynParamType, int*)
0.00 0.01 0.00 396 0.00 0.00 findInterface
0.00 0.01 0.00 371 0.00 0.00 processAiAverage
0.00 0.01 0.00 192 0.00 0.00 asynPortDriver::getAddress(asynUser*, int*)
0.00 0.01 0.00 184 0.00 0.00 memMalloc
0.00 0.01 0.00 158 0.00 0.00 connectDevice
0.00 0.01 0.00 144 0.00 0.00 flushIt
0.00 0.01 0.00 144 0.00 0.00 flushIt
0.00 0.01 0.00 144 0.00 0.00 flushIt
0.00 0.01 0.00 141 0.00 0.00 writeIt
0.00 0.01 0.00 141 0.00 0.00 writeIt
0.00 0.01 0.00 140 0.00 0.00 writeIt
0.00 0.01 0.00 128 0.00 0.00 writeRead
0.00 0.01 0.00 122 0.00 0.00 asynPortDriver::drvUserCreate(asynUser*, char const*, char const**, unsigned int*)
0.00 0.01 0.00 122 0.00 0.00 asynPortDriver::findParam(int, char const*, int*)
0.00 0.01 0.00 122 0.00 0.00 drvUserCreate
0.00 0.01 0.00 94 0.00 0.00 drvAHxxx::writeReadMeter()
0.00 0.01 0.00 85 0.00 0.00 asynPortDriver::setIntegerParam(int, int)
0.00 0.01 0.00 65 0.00 0.00 canBlock
0.00 0.01 0.00 65 0.00 0.00 parseLink
0.00 0.01 0.00 65 0.00 0.00 skipWhite
0.00 0.01 0.00 52 0.00 0.00 getCallbackValue
0.00 0.01 0.00 45 0.00 0.00 connect
0.00 0.01 0.00 45 0.00 0.00 initCommon
0.00 0.01 0.00 42 0.00 0.00 asynPortDriver::createParam(char const*, asynParamType, int*)
0.00 0.01 0.00 30 0.00 0.00 setInputEos
0.00 0.01 0.00 30 0.00 0.00 setInputEos
0.00 0.01 0.00 29 0.00 0.00 addInterruptUser
0.00 0.01 0.00 29 0.00 0.00 createInterruptNode
0.00 0.01 0.00 29 0.00 0.00 getInterruptPvt
0.00 0.01 0.00 28 0.00 0.00 drvAHxxx::setAcquire(int)
0.00 0.01 0.00 27 0.00 0.00 asynPortDriver::callParamCallbacks()
0.00 0.01 0.00 26 0.00 0.00 announceExceptionOccurred
...
Does anyone with gprof experience know why I am not getting the execution times in these functions?
Thanks,
Mark