g+
g+ Communities
Argonne National Laboratory

Experimental Physics and
Industrial Control System

1994  1995  1996  1997  1998  1999  2000  2001  2002  2003  2004  2005  2006  2007  2008  2009  2010  2011  <20122013  2014  Index 1994  1995  1996  1997  1998  1999  2000  2001  2002  2003  2004  2005  2006  2007  2008  2009  2010  2011  <20122013  2014 
<== Date ==> <== Thread ==>

Subject: How to profile an EPICS application on Linux
From: Mark Rivers <rivers@cars.uchicago.edu>
To: "tech-talk@aps.anl.gov" <tech-talk@aps.anl.gov>
Date: Mon, 10 Sep 2012 21:17:52 +0000
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



Replies:
Re: How to profile an EPICS application on Linux J. Lewis Muir
Re: How to profile an EPICS application on Linux John A. Priller

Navigate by Date:
Prev: RE: PIXIS-XO 100B Szalata, Zenon M.
Next: Re: camonitor bug for string as array of chars Ralph Lange
Index: 1994  1995  1996  1997  1998  1999  2000  2001  2002  2003  2004  2005  2006  2007  2008  2009  2010  2011  <20122013  2014 
Navigate by Thread:
Prev: RE: PIXIS-XO 100B Szalata, Zenon M.
Next: Re: How to profile an EPICS application on Linux J. Lewis Muir
Index: 1994  1995  1996  1997  1998  1999  2000  2001  2002  2003  2004  2005  2006  2007  2008  2009  2010  2011  <20122013  2014 
ANJ, 18 Nov 2013 Valid HTML 4.01! · Home · News · About · Base · Modules · Extensions · Distributions · Download ·
· EPICSv4 · IRMIS · Talk · Bugs · Documents · Links · Licensing ·