[Glass] Profiling of Seaside code in Quuve

Tue May 30 12:00:11 PDT 2017

Forgot to mention that Allen's patch will be available in the upcoming 
GemStone 3.4 release as internal bug #46911 "ProfMonitor, hard to commit 
a instance for later report generation".

Dale

On 05/30/2017 11:56 AM, Dale Henrichs wrote:
>
> Allen's answer to Mariano...
>
>
>
> -------- Forwarded Message --------
> Subject: 	Re: Profiling of Seaside code in Quuve
> Date: 	Tue, 30 May 2017 11:13:47 -0700
> From: 	Allen Otis <allen.otis at gemtalksystems.com>
> To: 	Mariano Martinez Peck <marianopeck at gmail.com>
> CC: 	Dale Henrichs <dhenrich at gemtalksystems.com>
>
>
>
> Mariano,
>
> I will try to reply to all of your emails since May 26  with one email .
>
> There is not currently a way to get only the "STATISTICAL SAMPLING RESULTS"
> printed.  You could use something like
>     reportDownTo: 95
> to exclude from the report methods below 95% of total time and thus
> make the report a lot shorter.
>
> I cannot find in the image comments where it says
>     gcTime implies #real
> All the  "gcTime implies" that I find in comments are of the form
>    #gcTime implies default #cpu  and is in units of milliseconds
>
> What version of GemStone are you running ?
>
> How much temp obj memory are you configured for when you run
> out of memory ?
>
> For profiling a web framework, I recommend that your web frame work
> provide a profile method something like this
>
> classmethod: AFrameworkClass
> profile: aBlock
>    "commits an instance of ProfMonitor for later analysis"
>    | p |
>    (p := ProfMonitor new )
>      setOptions: #(gcTime)  ;
>      intervalNs: 200000 . "200 microsec,
>               or replace with a value computed using ProfMonitor
> class>>computeInterval:"
>    p startMonitoring.
>    aBlock value .
>    p stopMonitoring .
>    "At this point p contains the filename to which profile data has
> been written."
>    UserGlobals at: #ProfInstance put: p .
>    System commit
> %
>
> Then in a separate interactive session configured
> with several GB of temp object memory,
>
>    "Read the profile data file and generate the report.
>    (UserGlobals at:#ProfInstance) reportAfterRunDownTo: 5
>
> I would think that 2GB of temp obj memory should be enough
> to analyze a file of 200000 sample points .
> For this example
>     ProfInstance instVarAt: 8
> will return the number of sample points that were written to the file.
>
> And after you are finished with generating the report
> you may want to run
>
>    (UserGlobals at: #ProfInstance) removeFile .
>    UserGlobals removeKey: #ProfInstance .
>    System commit .
>
> There are a couple of problems in the current implementation of ProfMonitor
> that make the above usage difficult to achieve and I have attached a patch
> file to fix those.
>
> Also the instance of ProfMonitor writes the sample file to the gem's current
> directory, so the interactive session needs to run a gem in that same
> directory, or else further edits to  ProfMonitor >> _openFileRead ,
> and the call path from reportAfterRunDownTo: down to  _openFileRead
> may be needed.
>
>
> Allen
>
> On Mon, May 29, 2017 at 6:15 AM, Mariano Martinez Peck
> <marianopeck at gmail.com>  wrote:
> > Hi Allen,
> >
> > Thank you very much for reaching me out. I am very happy reading about
> > #computeInterval: because I have a very nice profiling framework within my
> > application which allows me to profile seaside requests from the web itself.
> > However, one of the problems was that having a fixed interval is not good as
> > I may profile different scenarios that take different time, and so, the
> > numbers of samples may not be good for some scenarios.
> >
> > Before coming back to you with a higher resolution profiling, please allow
> > me to improve my profiling framework with this new idea you gave me.
> >
> > Once again, thanks for your contact.
> >
> > Best regards,
> >
> >
> >
> > On Thu, May 25, 2017 at 8:07 PM, Allen Otis<allen.otis at gemtalksystems.com>
> > wrote:
> >>
> >> Mariano,
> >>
> >> I have been looking at the ProfMonitor output in the file
> >> RequestProfile2017-04-14T15_06_17_65757894515991-04_00.txt
> >> which you sent to Norm Green .
> >>
> >> We have higher resolution profiling methods available now ,
> >> see the class methods with keyword  intervalNs: in ProfMonitor .
> >> The method
> >>   ProfMonitor class >> computeInterval:
> >> will help you determine an appropriate argument to the intervalNs: keyword
> >> .
> >> Would you send us another ProfMonitor output  with high resolution
> >> sampling ?
> >> See my notes below.
> >>
> >> I will be on vacation May 26 - May 29, so won't be looking at a
> >> any new profiling data until next week.
> >>
> >> Allen
> >> --------------------------------------------
> >>
> >> Your previous profiling run had elapsed time of 1394ms
> >>
> >> topaz 1> run
> >> ProfMonitor computeInterval: 1.4
> >> %
> >> 69999
> >>
> >> So I would recommend something like
> >>   intervalNs: 70000
> >> for your next profiling run.
> >> You should have GEM_TEMPOBJ_CACHE_SIZE at least 300MB  for the profiling.
> >> If you have trouble with too many sample points , multiply the
> >> result of   computeInterval:   by 2  or  4 .
> >>
> >> ---------------
> >> These are already in your GemStone image:
> >>
> >> category: 'Estimating'
> >> classmethod: ProfMonitor
> >> computeInterval: unprofiledCpuTimeSeconds
> >>  "Returns an estimated profiling interval in nanoseconds for an execution
> >>   taking the specified amount of cpu time, to yield approximately
> >>   100000 samples . For 100000 samples, GEM_TEMPOBJ_CACHE_SIZE should
> >>   be set to at least 300MB to avoid AlmostOutOfMemory errors during
> >> analysis
> >>   phase."
> >>  | ns |
> >>  ns := (5.0 * unprofiledCpuTimeSeconds / 100000 / 1.0e-9 ) asInteger .
> >>  ns < 1000 ifTrue:[ ns := 1000 ].
> >>  ^ ns
> >> %
> >>
> >> category: 'Quick Profiling'
> >> classmethod: ProfMonitor
> >> monitorBlock: aBlock intervalNs: nanosecondsPerSample
> >>
> >> "Profile the execution of a block and return a formatted report of the
> >> results.
> >>  The nanosecondsPerSample argument gives the CPU time interval
> >>  between samples, and the results are reported down to methods that
> >>  use 3% of the total time"
> >>
> >> ^ self monitorBlock: aBlock
> >>        downTo: 0.03
> >>        intervalNs: nanosecondsPerSample
> >>        options: #()
> >
> >
> >
> >
> > --
> > Mariano
> >http://marianopeck.wordpress.com
>

-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.gemtalksystems.com/mailman/private/glass/attachments/20170530/c9ad082e/attachment.html>