RE: How to profile an EPICS application on Linux

[Mark Rivers <rivers@cars.uchicago.edu>]

Hi John,

Thanks that is really useful.  I used the commands:

valgrind --tool=callgrind ../../bin/linux-x86_64/quadEMTestApp st.cmd.AH501

and then

kcachegrind

That is a very nice GUI indeed.

Both tools appear to be installed by default on our Fedora Core 15 system.

I have one question.  I ran the IOC for a while, then I wanted to exit it and look at the statistics that had been collected. However, when I typed "exit" at the iocsh prompt nothing happened.  Valgrind was still using almost 100 of a CPU.  I waited for a minute or so, then killed it with ^C.  That seemed to be OK, since there was a callgrind.out.nnnn file that kcachegrind could read.  But is this normal, why did I have to kill it with ^C?

Thanks,
Mark


-----Original Message-----
From: tech-talk-bounces@aps.anl.gov [mailto:tech-talk-bounces@aps.anl.gov] On Behalf Of John A. Priller
Sent: Wednesday, September 12, 2012 7:07 AM
To: tech-talk@aps.anl.gov
Subject: Re: How to profile an EPICS application on Linux

I've been using valgrind/callgrind to gather performance data:

<http://valgrind.org/docs/manual/cl-manual.html>

There's a very nice GUI tool for viewing the results:

<http://kcachegrind.sourceforge.net/html/Home.html>

These are all available as packages for Debian/Ubuntu (the flavor of 
Linux we use for soft IOCs).

On 9/10/2012 5:17 PM, Mark Rivers wrote:
> 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
>
>

-- 
John A. Priller            | Phone : (517) 908-7375
MSU Cyclotron Laboratory   | Fax   : (517) 908-7126
640 S. Shaw Lane rm 1300D  | Email : priller@nscl.msu.edu
East Lansing, MI 48824     | Web   : http://www.nscl.msu.edu/~priller/