[Openmcl-devel] Output from SAM profiler in CCL

[Craig Lanning]

On Wed, 2017-04-19 at 16:46 -0700, R. Matthew Emerson wrote:
> Less than one second of run-time is not very much.
> 
> I wonder whether running the little profiler on a larger
> amount of work would show anything more enlightening.
> 

The original test involved processing 17 pairs of files.  The Lisp
image starts, processes one pair, then exits.  The process repeats for
each pair.

I'll see if I can find one pair that involves loading a larger number
of objects.

Craig

> 
> 
> > 
> > On Apr 19, 2017, at 2:30 PM, Craig Lanning <craig.t.lanning at gmail.c
> > om> wrote:
> > 
> > I just ran it again with (time ...) wrapped around it.
> > 
> > looks like it's just spending about 3.6% of its time in GC.
> > 
> > Craig
> > 
> >  8%  CCL::VALUES-SPECIFIER-TYPE  <no source>
> >  6%  NIL  <no source>
> >  5%  TYPEP  <no source>
> >  4%  SXHASH  <no source>
> >  4%  EEK::EXP-SYMBOL  (defun EXP-SYMBOL (stream char...
> >  3%  CCL::%PARSE-EXPRESSION  <no source>
> > (SAM:PROFILE NIL (EE:EXP-ENGINE :COMPARE :MODE :ARM_SHORTFORM :XML-
> > OUTPUT T :TRIAL_STEPMOD (PATHNAME "/src/sf/stepmod/") :TRIAL_SCHEMA
> > (PATHNAME
> > "/src/sf/CR_itemshape_2_20170330/part1000/data/modules/product_and_
> > manu
> > facturing_information_with_nominal_3d_models/arm.exp")
> > :REFERENCE_STEPMOD (PATHNAME "/src/sf/smrlv6/") :REFERENCE_SCHEMA
> > (PATHNAME
> > "/src/sf/smrlv6/data/modules/product_and_manufacturing_information_
> > with
> > _nominal_3d_models/arm.exp")))
> > took 923,118 microseconds (0.923118 seconds) to run.
> >       33,361 microseconds (0.033361 seconds, 3.61%) of which was
> > spent
> > in GC.
> > During that period, and with 4 available CPU cores,
> >      852,112 microseconds (0.852112 seconds) were spent in user
> > mode
> >       65,065 microseconds (0.065065 seconds) were spent in system
> > mode
> >  18,473,008 bytes of memory allocated.
> >  720 minor page faults, 0 major page faults, 0 swaps.
> > 
> > On Wed, 2017-04-19 at 17:13 -0400, Joshua Kordani wrote:
> > > 
> > > Does (time... show that you're spending much time in gc?
> > > 
> > > 
> > > On 4/19/17 4:41 PM, Craig Lanning wrote:
> > > > 
> > > > 
> > > > Here is the output from comparing one pair of Schema files:
> > > > 
> > > > 13%  CCL::SPECIFIER-TYPE  <no source>
> > > >   8%  CCL::VALUES-SPECIFIER-TYPE  <no source>
> > > >   6%  SXHASH  <no source>
> > > >   5%  EEK::EXP-SYMBOL  (defun EXP-SYMBOL (stream char...
> > > >   4%  NIL  <no source>
> > > >   4%  TYPEP  <no source>
> > > > 
> > > > EEK::EXP-SYMBOL is a function in the custom Lisp Reader that
> > > > builds
> > > > the
> > > > tokens while reading the schema files.
> > > > 
> > > > Is CCL::SPECIFIER-TYPE a function related to dispatching
> > > > methods
> > > > within
> > > > a generic function?  I use a lot of generic functions and
> > > > methods.  Is
> > > > there a way to precompile all of the generic function dispatch
> > > > code?
> > > > 
> > > > Is there anything I can do collect more info?  This doesn't
> > > > look
> > > > very
> > > > useful to me.
> > > > 
> > > > If it was spending a lot of time in methods of a specific
> > > > generic
> > > > function, would that information show up here?
> > > > 
> > > > Craig
>