Re: Profiling of Seaside code in Quuve

Allen Otis [hidden email] · Tue, 30 May 2017 11:13:47 -0700

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
[hidden email] 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 [hidden email]
> 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