Profiling beyond ExecBlock >> valueWithPossibleArguments: ?

_______________________________________________
Glass mailing list
[hidden email]
http://lists.gemtalksystems.com/mailman/listinfo/glass

_______________________________________________
Glass mailing list
[hidden email]
http://lists.gemtalksystems.com/mailman/listinfo/glass

Mariano,

Which version of GemStone are you using and have you tried this using ProfMonitor instead of ProMonitorTree?

Dale

Hi guys, 

In Quuve we have a huge "rule engine" in which user defined "rules" are evaluated over 10k companies or whatever in order to filter/screen the companies that meet certain conditions.  The rules are the very end have a Smalltalk closure that gets evaluated. 

I am trying to profile some things and what happens is that I can never see what happens inside the "ExecBlock >> valueWithPossibleArguments:". All the profiling stops at this method. For example, say the ProfMonitor tells me that "ExecBlock >> valueWithPossibleArguments:" took 50% of the time, then the tree stops there. I have NO CLUE what took the time inside the closure.

I do get the difference between profiling closures (different instances) vs profiling methods. And I also know that #valueWithPossibleArguments: ends up in a primitive. But still, there may exist a workaround. 

Just to illustrate the issue, try profiling this:

| profMon |

profMon := ProfMonitorTree new.

profMon interval: 10.

 profMon startMonitoring.

[1000 timesRepeat: [Transcript show: 'hola']] valueWithPossibleArguments: #().

profMon

        stopMonitoring;

        gatherResults.

(FileStream

    forceNewFileNamed:

      '/Users/mariano/gemstone'

        , DateAndTime now printString faAsFilename)

    nextPutAll: (profMon reportDownTo: 10);

    cr

You will see that in the resulting file there is NOTHING about the, for example, #show: of the Transcript. The Transcript itself does not appear at all. All you see are lines like:

27.4 5.0 executed code

100.0% (1) executed code [UndefinedObject]

Thanks for any idea, 

--

Mariano
http://marianopeck.wordpress.com

_______________________________________________
Glass mailing list
[hidden email]
http://lists.gemtalksystems.com/mailman/listinfo/glass

_______________________________________________
Glass mailing list
[hidden email]
http://lists.gemtalksystems.com/mailman/listinfo/glass

I just ran your test using tODE (`pf start` and `pf view`) which uses ProfMonitor in GemStone 3.2.9 and I got an answer that makes sense:

aTDProfMonitor
--------------------
TALLYING: execTime
elapsed CPU time: 1710 ms

     total         ms     % class and method name
---------- ---------- ----- ---------------------
      1645     1710.0 100.0 GsNMethod class           >> _gsReturnToC
      1069     1111.2  65.0 STONWriter                >> nextPut:
       990     1029.1  60.2 ExecBlock                 >> value:value:value:value:value:
       989     1028.1  60.1 block in TDClientSourceElementBuilder >> menuActionBlock
       988     1027.0  60.1 TDWindowBuilder           >> handleMenuActions:listElement:actionArg:
       988     1027.0  60.1 TDClientSourceElementBuilder >> doItMenuAction:selectedText:
       988     1027.0  60.1 TDClientSourceElementBuilder >> evaluateString:
       988     1027.0  60.1 CharacterCollection       >> evaluateIn:symbolList:literalVars:
       988     1027.0  60.1 executed code           
       988     1027.0  60.1 ExecBlock                 >> valueWithPossibleArguments:
       988     1027.0  60.1 block in executed code  
       843      876.3  51.2 STONWriter                >> with:do:
       758      788.0  46.1 STONWriter                >> indentedDo:
       746      775.5  45.3 TranscriptProxy class     >> show:
       718      746.4  43.6 Object class              >> new
       698      725.6  42.4 ObjectLogEntry class      >> transcript:object:
       695      722.5  42.2 SequenceableCollection    >> stonOn:
       694      721.4  42.2 ObjectLogEntry            >> initialize
       691      718.3  42.0 STONWriter                >> writeList:

I'll see what I find out using ProfMonitorTree...

Dale

Hi guys, 

In Quuve we have a huge "rule engine" in which user defined "rules" are evaluated over 10k companies or whatever in order to filter/screen the companies that meet certain conditions.  The rules are the very end have a Smalltalk closure that gets evaluated. 

I am trying to profile some things and what happens is that I can never see what happens inside the "ExecBlock >> valueWithPossibleArguments:". All the profiling stops at this method. For example, say the ProfMonitor tells me that "ExecBlock >> valueWithPossibleArguments:" took 50% of the time, then the tree stops there. I have NO CLUE what took the time inside the closure.

I do get the difference between profiling closures (different instances) vs profiling methods. And I also know that #valueWithPossibleArguments: ends up in a primitive. But still, there may exist a workaround. 

Just to illustrate the issue, try profiling this:

| profMon |

profMon := ProfMonitorTree new.

profMon interval: 10.

 profMon startMonitoring.

[1000 timesRepeat: [Transcript show: 'hola']] valueWithPossibleArguments: #().

profMon

        stopMonitoring;

        gatherResults.

(FileStream

    forceNewFileNamed:

      '/Users/mariano/gemstone'

        , DateAndTime now printString faAsFilename)

    nextPutAll: (profMon reportDownTo: 10);

    cr

You will see that in the resulting file there is NOTHING about the, for example, #show: of the Transcript. The Transcript itself does not appear at all. All you see are lines like:

27.4 5.0 executed code

100.0% (1) executed code [UndefinedObject]

Thanks for any idea, 

--

Mariano
http://marianopeck.wordpress.com

_______________________________________________
Glass mailing list
[hidden email]
http://lists.gemtalksystems.com/mailman/listinfo/glass

_______________________________________________
Glass mailing list
[hidden email]
http://lists.gemtalksystems.com/mailman/listinfo/glass

if you use `reportDownTo: 1` you will get more interesting information:

| profMon |
  profMon := ProfMonitorTree new.
  profMon interval: 10.
  profMon startMonitoring.
  [ 100 timesRepeat: [ Transcript show: 'hola' ] ]
    valueWithPossibleArguments: #().
  profMon
    stopMonitoring;
    gatherResults.
  profMon reportDownTo: 1

'================
STATISTICAL SAMPLING RESULTS
elapsed CPU time:    143 ms
monitoring interval: 10.0 ms

 tally       %   class and method name
------   -----   --------------------------------------
     1   25.00   executed code           
     1   25.00   Object                    >> _doesNotUnderstand:args:envId:reason:
     1   25.00   executed code           
     1   25.00   KeyValueDictionary        >> keysAndValuesDo:
     0    0.00   19 other methods
     4  100.00   Total


================
STATISTICAL STACK SAMPLING RESULTS
elapsed CPU time:    143 ms
monitoring interval: 10.0 ms

 total       %   class and method name
------   -----   --------------------------------------
     4  100.00   GsNMethod class           >> _gsReturnToC
     2   50.00   ExecBlock                 >> value:value:value:value:value:
     2   50.00   block in TDClientSourceElementBuilder >> menuActionBlock
     2   50.00   TDWindowBuilder           >> handleMenuActions:listElement:actionArg:
     2   50.00   TDClientSourceElementBuilder >> printItMenuAction:selectedText:
     2   50.00   TDClientSourceElementBuilder >> evaluateString:
     2   50.00   CharacterCollection       >> evaluateIn:symbolList:literalVars:
     2   50.00   executed code           
     2   50.00   ExecBlock                 >> valueWithPossibleArguments:
     2   50.00   block in executed code  
     2   50.00   TranscriptProxy class     >> show:
     2   50.00   KeyValueDictionary        >> keysAndValuesDo:
     1   25.00   executed code           
     1   25.00   Object                    >> _doesNotUnderstand:args:envId:reason:
     1   25.00   executed code           
     1   25.00   ObjectLogEntry class      >> transcript:object:
     1   25.00   Object class              >> new
     1   25.00   ObjectLogEntry            >> initialize
     1   25.00   System class              >> gemVersionReport
     1   25.00   System class              >> _serverVersionReport:
     1   25.00   block in System class     >> _serverVersionReport:
     1   25.00   StringKeyValueDictionary  >> at:put:
     1   25.00   KeyValueDictionary        >> rebuildTable:
     4  100.00   Total


================
STATISTICAL METHOD SENDERS RESULTS
elapsed CPU time:    143 ms
monitoring interval: 10.0 ms

     %       %                     Parent
  self  total   total  local  Method
  Time   Time      ms    %         Child
------ ------  ------  -----  -----------

=    0.0  100.0   143.0    0.0  GsNMethod class >> _gsReturnToC
                   35.8   25.0       executed code
                   35.8   25.0       executed code
                   71.5   50.0       ExecBlock    >> value:value:value:value:value:
-----------------------------------------------------

                   71.5  100.0       GsNMethod class >> _gsReturnToC
=    0.0   50.0    71.5    0.0  ExecBlock    >> value:value:value:value:value:
                   71.5  100.0       block in TDClientSourceElementBuilder >> menuActionBlock
-----------------------------------------------------

                   71.5  100.0       ExecBlock    >> value:value:value:value:value:
=    0.0   50.0    71.5    0.0  block in TDClientSourceElementBuilder >> menuActionBlock
                   71.5  100.0       TDWindowBuilder >> handleMenuActions:listElement:actionArg:
-----------------------------------------------------

                   71.5  100.0       block in TDClientSourceElementBuilder >> menuActionBlock
=    0.0   50.0    71.5    0.0  TDWindowBuilder >> handleMenuActions:listElement:actionArg:
                   71.5  100.0       TDClientSourceElementBuilder >> printItMenuAction:selectedText:
-----------------------------------------------------

                   71.5  100.0       TDWindowBuilder >> handleMenuActions:listElement:actionArg:
=    0.0   50.0    71.5    0.0  TDClientSourceElementBuilder >> printItMenuAction:selectedText:
                   71.5  100.0       TDClientSourceElementBuilder >> evaluateString:
-----------------------------------------------------

                   71.5  100.0       TDClientSourceElementBuilder >> printItMenuAction:selectedText:
=    0.0   50.0    71.5    0.0  TDClientSourceElementBuilder >> evaluateString:
                   71.5  100.0       CharacterCollection >> evaluateIn:symbolList:literalVars:
-----------------------------------------------------

                   71.5  100.0       TDClientSourceElementBuilder >> evaluateString:
=    0.0   50.0    71.5    0.0  CharacterCollection >> evaluateIn:symbolList:literalVars:
                   71.5  100.0       executed code
-----------------------------------------------------

                   71.5  100.0       CharacterCollection >> evaluateIn:symbolList:literalVars:
=    0.0   50.0    71.5    0.0  executed code
                   71.5  100.0       ExecBlock    >> valueWithPossibleArguments:
-----------------------------------------------------

                   71.5  100.0       executed code
=    0.0   50.0    71.5    0.0  ExecBlock    >> valueWithPossibleArguments:
                   71.5  100.0       block in executed code
-----------------------------------------------------

                   71.5  100.0       ExecBlock    >> valueWithPossibleArguments:
=    0.0   50.0    71.5    0.0  block in executed code
                   71.5  100.0       TranscriptProxy class >> show:
-----------------------------------------------------

                   71.5  100.0       block in executed code
=    0.0   50.0    71.5    0.0  TranscriptProxy class >> show:
                   35.8   50.0       Object       >> _doesNotUnderstand:args:envId:reason:
                   35.8   50.0       ObjectLogEntry class >> transcript:object:
-----------------------------------------------------

                   35.8   50.0       System class >> _serverVersionReport:
                   35.8   50.0       KeyValueDictionary >> rebuildTable:
=   25.0   50.0    71.5   50.0  KeyValueDictionary >> keysAndValuesDo:
                   35.8   50.0       block in System class >> _serverVersionReport:
-----------------------------------------------------

                   35.8  100.0       GsNMethod class >> _gsReturnToC
=   25.0   25.0    35.8  100.0  executed code
-----------------------------------------------------

                   35.8  100.0       TranscriptProxy class >> show:
=   25.0   25.0    35.8  100.0  Object       >> _doesNotUnderstand:args:envId:reason:
-----------------------------------------------------

                   35.8  100.0       GsNMethod class >> _gsReturnToC
=   25.0   25.0    35.8  100.0  executed code
-----------------------------------------------------

                   35.8  100.0       TranscriptProxy class >> show:
=    0.0   25.0    35.8    0.0  ObjectLogEntry class >> transcript:object:
                   35.8  100.0       Object class >> new
-----------------------------------------------------

                   35.8  100.0       ObjectLogEntry class >> transcript:object:
=    0.0   25.0    35.8    0.0  Object class >> new
                   35.8  100.0       ObjectLogEntry >> initialize
-----------------------------------------------------

                   35.8  100.0       Object class >> new
=    0.0   25.0    35.8    0.0  ObjectLogEntry >> initialize
                   35.8  100.0       System class >> gemVersionReport
-----------------------------------------------------

                   35.8  100.0       ObjectLogEntry >> initialize
=    0.0   25.0    35.8    0.0  System class >> gemVersionReport
                   35.8  100.0       System class >> _serverVersionReport:
-----------------------------------------------------

                   35.8  100.0       System class >> gemVersionReport
=    0.0   25.0    35.8    0.0  System class >> _serverVersionReport:
                   35.8  100.0       KeyValueDictionary >> keysAndValuesDo:
-----------------------------------------------------

                   35.8  100.0       KeyValueDictionary >> keysAndValuesDo:
=    0.0   25.0    35.8    0.0  block in System class >> _serverVersionReport:
                   35.8  100.0       StringKeyValueDictionary >> at:put:
-----------------------------------------------------

                   35.8  100.0       block in System class >> _serverVersionReport:
=    0.0   25.0    35.8    0.0  StringKeyValueDictionary >> at:put:
                   35.8  100.0       KeyValueDictionary >> rebuildTable:
-----------------------------------------------------

                   35.8  100.0       StringKeyValueDictionary >> at:put:
=    0.0   25.0    35.8    0.0  KeyValueDictionary >> rebuildTable:
                   35.8  100.0       KeyValueDictionary >> keysAndValuesDo:
-----------------------------------------------------




================
STACK SAMPLING TREE RESULTS
elapsed CPU time:    143 ms
monitoring interval: 10.0 ms

 100.0% (1) executed code        [UndefinedObject]
 100.0% (1) executed code        [UndefinedObject]
 100.0% (2) ExecBlock            >> value:value:value:value:value:
   100.0% (2) block in TDClientSourceElementBuilder >> menuActionBlock [ExecBlock]
      100.0% (2) TDWindowBuilder      >> handleMenuActions:listElement:actionArg: [TDWorkspaceClientElementBuilder]
         100.0% (2) TDClientSourceElementBuilder >> printItMenuAction:selectedText: [TDWorkspaceClientElementBuilder]
            100.0% (2) TDClientSourceElementBuilder >> evaluateString: [TDWorkspaceClientElementBuilder]
               100.0% (2) CharacterCollection  >> evaluateIn:symbolList:literalVars: [String]
                  100.0% (2) executed code        [UndefinedObject]
                     100.0% (2) ExecBlock            >> valueWithPossibleArguments: [ExecBlock0]
                        100.0% (2) block in executed code [ExecBlock0]
                           100.0% (2) TranscriptProxy class >> show:
                               50.0% (1) ObjectLogEntry class >> transcript:object:
                                |  50.0% (1) Object class         >> new [ObjectLogEntry class]
                                |     50.0% (1) ObjectLogEntry       >> initialize
                                |        50.0% (1) System class         >> gemVersionReport
                                |           50.0% (1) System class         >> _serverVersionReport:
                                |              50.0% (1) KeyValueDictionary   >> keysAndValuesDo: [StringKeyValueDictionary]
                                |                 50.0% (1) block in System class >> _serverVersionReport: [ExecBlock2]
                                |                    50.0% (1) StringKeyValueDictionary >> at:put:
                                |                       50.0% (1) KeyValueDictionary   >> rebuildTable: [StringKeyValueDictionary]
                                |                          50.0% (1) KeyValueDictionary   >> keysAndValuesDo: [StringKeyValueDictionary]
                               50.0% (1) Object               >> _doesNotUnderstand:args:envId:reason: [ClientForwarder]


'

| profMon |

profMon := ProfMonitorTree new.

profMon interval: 10.

 profMon startMonitoring.

[1000 timesRepeat: [Transcript show: 'hola']] valueWithPossibleArguments: #().

profMon

        stopMonitoring;

        gatherResults.

(FileStream

    forceNewFileNamed:

      '/Users/mariano/gemstone'

        , DateAndTime now printString faAsFilename)

    nextPutAll: (profMon reportDownTo: 10);

    cr

_______________________________________________
Glass mailing list
[hidden email]
http://lists.gemtalksystems.com/mailman/listinfo/glass