reading ProfMonitor results

I'm often puzzled when reading the results given by ProfMonitor.
For example, the result I include below: it mentions that it has spend 401.67% of its time in the first method that is listed.
401 % ?
Or how should I read this?

Johan

----

STATISTICAL STACK SAMPLING RESULTS
elapsed CPU time:    615 ms
monitoring interval: 10 ms

 total       %   class and method name
------   -----   --------------------------------------
   241  401.67   NPHTTPAPIv1JsonExporter   >> attributeAt:export:ofType: [NPHTTPAPIv1JsonExporter]
   241  401.67   NPHTTPAPIv1JsonExporter   >> attributeAt:with: [NPHTTPAPIv1JsonExporter]
   231  385.00   NPHTTPAPIv1JsonExporter   >> attributeAt:export:ofType: [ComplexBlock]
   221  368.33   NPAPIClassType            >> export:on: [NPAPIClassType]
   207  345.00   Collection                >> do: [Array]
   205  341.67   NPAPICollectionOfType     >> export:on: [NPAPICollectionOfType]
   205  341.67   NPHTTPAPIv1JsonExporter   >> exportCollection:elementsOfType: [NPHTTPAPIv1JsonExporter]
   205  341.67   NPHTTPAPIv1JsonExporter   >> entities:exportedWith: [NPHTTPAPIv1JsonExporter]
   204  340.00   NPHTTPAPIv1JsonExporter   >> entities:exportedWith: [ComplexBlock]
   204  340.00   NPHTTPAPIv1JsonExporter   >> exportCollection:elementsOfType: [ComplexBlock]
   197  328.33   NPHTTPAPIv1JsonExporter   >> export:using: [NPHTTPAPIv1JsonExporter]
   195  325.00   NPHTTPAPIv1JsonExporter   >> for:putAttributes: [NPHTTPAPIv1JsonExporter]
   195  325.00   NPAPIAttributes           >> for:putAllOn: [NPAPIAttributes]
   195  325.00   NPAPIAttributes           >> for:putAllOn: [ComplexBlock]
   194  323.33   NPAPIDictionaryRepresentation >> for:exportOn: [NPAPIDictionaryRepresentation]
   181  301.67   NPAPIValueAttribute       >> for:putOn: [NPAPIBlockValueAttribute]
   150  250.00   NPAPIOneOfType            >> export:on: [NPAPIOneOfType]
   127  211.67   Collection                >> do: [OrderedCollection]
   123  205.00   ExecutableBlock           >> ensure: [ComplexBlock]
    92  153.33   WARequestContext          >> respond: [WAGemStoneRequestContext]
    77  128.33   Collection                >> do: [NPOrderedCollection]
    60  100.00   NPAbstractHTTPAPI         >> withCredentialsToken:withQueryRateCostsDoWithCredentialsAndSessionOrRespondError: [NPHTTPAPIv1]
    60  100.00   NPAbstractHTTPAPI         >> withCredentialsToken:fixedRateTokenCost:variableRateTokenCostFactor:doWithCredentialsAndSessionOrRespondError: [NPHTTPAPIv1]
    60  100.00   NPAbstractHTTPAPI         >> withCredentialsToken:fixedRateTokenCost:variableRateTokenCostFactor:doWithCredentialsAndSessionOrRespondError: [ComplexBlock]
    60  100.00   NPHTTPAPIv1               >> respondResultsOf:type:forObjectsMatchingQuery:scope:token:paginationBaseURL: [ComplexBlock]
    60  100.00   NPHTTPAPIv1               >> makeAvailableAsBookAndRespondFirstPageFrom:type:credentials:inDatabase:paginationBaseURL: [NPHTTPAPIv1]
    60  100.00   NPHTTPAPIv1               >> respondPageAndMakeNextPageAvailableFromBook:inDatabase:paginationBaseURL: [NPHTTPAPIv1]
    60  100.00   NPHTTPAPIv1               >> respondResult:ofType:credentials:inDatabase: [NPHTTPAPIv1]
    60  100.00   NPHTTPAPIv1               >> respondResult:ofType:credentials:inDatabase: [ComplexVCBlock]
    60  100.00   ProfMonitor class         >> monitorBlock: [ProfMonitorTree class]
    60  100.00   ProfMonitor               >> monitorBlock: [ProfMonitorTree]
    60  100.00   NPHTTPAPIv1               >> respondResult:ofType:credentials:inDatabase: [ComplexBlock]
    60  100.00   NPHTTPAPIv1JsonExporter class >> export:ofType:on:forClient:baseURL:inDatabase: [NPHTTPAPIv1JsonExporter class]
    60  100.00   NPHTTPAPIv1JsonExporter   >> exportOne [NPHTTPAPIv1JsonExporter]
    60  100.00   NPAPIDictionaryType       >> export:on: [NPAPIDictionaryType]
    60  100.00   NPHTTPAPIv1JsonExporter   >> exportDictionary:elementsTypeMapping: [NPHTTPAPIv1JsonExporter]
    60  100.00   Dictionary                >> keysAndValuesDo: [Dictionary]
    60  100.00   NPHTTPAPIv1JsonExporter   >> exportDictionary:elementsTypeMapping: [ComplexBlock]
    59   98.33   NPHTTPAPIv1               >> respondResultsOf:type:forObjectsMatchingQuery:scope:token:paginationBaseURL: [NPHTTPAPIv1]
    58   96.67   NPHTTPAPIv1               >> get:ofSome:with:token: [ComplexBlock]
    58   96.67   NPHTTPAPIv1               >> respondResultsFor:forObjectsMatchingQuery:in:token:paginationBaseURL: [NPHTTPAPIv1]
    56   93.33   BlockClosure              >> valueWithPossibleArgs: [ComplexBlock]
    50   83.33   Object                    >> ifNotNil: [NPHTTPResourceSpec]
    45   75.00   NPHTTPAPIv1               >> get:ofSome:with:token: [NPHTTPAPIv1]
    42   70.00   WARoute                   >> sendSelectorWith:to: [WAComplexRoute]
    39   65.00   WARouteResult             >> sendMessageTo: [WARouteResult]
    37   61.67   WARestfulHandler          >> executeResult: [ComplexBlock]
    32   53.33   GRCodecStream             >> json: [GRUtf8CodecStream]
    31   51.67   String                    >> jsonOn: [String]
    31   51.67   String                    >> javascriptOn: [String]
    31   51.67   JSStream class            >> encodeString:on: [JSStream class]
    28   46.67   WARestfulHandler          >> executeResult: [NPHTTPAPIv1]
    26   43.33   GRUtf8CodecStream         >> nextPut: [GRUtf8CodecStream]

Johan,

I believe the "extra counting" comes because the method is recursive ... In that particular summary table we are measuring the "total time spent in method and all methods called by that method" .. . I think the detail tables (next section) don't have this problem because they are not trying to accumulate totals ...

Dale

----- Original Message -----
| From: "Johan Brichau" <[hidden email]>
| To: "GemStone Seaside beta discussion" <[hidden email]>
| Sent: Sunday, April 14, 2013 10:26:03 AM
| Subject: [GS/SS Beta] reading ProfMonitor results
|
| I'm often puzzled when reading the results given by ProfMonitor.
| For example, the result I include below: it mentions that it has spend
| 401.67% of its time in the first method that is listed.
| 401 % ?
| Or how should I read this?
|
| Johan
|
| ----
|
| STATISTICAL STACK SAMPLING RESULTS
| elapsed CPU time:    615 ms
| monitoring interval: 10 ms
|
|  total       %   class and method name
| ------   -----   --------------------------------------
|    241  401.67   NPHTTPAPIv1JsonExporter   >> attributeAt:export:ofType:
|    [NPHTTPAPIv1JsonExporter]
|    241  401.67   NPHTTPAPIv1JsonExporter   >> attributeAt:with:
|    [NPHTTPAPIv1JsonExporter]
|    231  385.00   NPHTTPAPIv1JsonExporter   >> attributeAt:export:ofType:
|    [ComplexBlock]
|    221  368.33   NPAPIClassType            >> export:on: [NPAPIClassType]
|    207  345.00   Collection                >> do: [Array]
|    205  341.67   NPAPICollectionOfType     >> export:on:
|    [NPAPICollectionOfType]
|    205  341.67   NPHTTPAPIv1JsonExporter   >>
|    exportCollection:elementsOfType: [NPHTTPAPIv1JsonExporter]
|    205  341.67   NPHTTPAPIv1JsonExporter   >> entities:exportedWith:
|    [NPHTTPAPIv1JsonExporter]
|    204  340.00   NPHTTPAPIv1JsonExporter   >> entities:exportedWith:
|    [ComplexBlock]
|    204  340.00   NPHTTPAPIv1JsonExporter   >>
|    exportCollection:elementsOfType: [ComplexBlock]
|    197  328.33   NPHTTPAPIv1JsonExporter   >> export:using:
|    [NPHTTPAPIv1JsonExporter]
|    195  325.00   NPHTTPAPIv1JsonExporter   >> for:putAttributes:
|    [NPHTTPAPIv1JsonExporter]
|    195  325.00   NPAPIAttributes           >> for:putAllOn: [NPAPIAttributes]
|    195  325.00   NPAPIAttributes           >> for:putAllOn: [ComplexBlock]
|    194  323.33   NPAPIDictionaryRepresentation >> for:exportOn:
|    [NPAPIDictionaryRepresentation]
|    181  301.67   NPAPIValueAttribute       >> for:putOn:
|    [NPAPIBlockValueAttribute]
|    150  250.00   NPAPIOneOfType            >> export:on: [NPAPIOneOfType]
|    127  211.67   Collection                >> do: [OrderedCollection]
|    123  205.00   ExecutableBlock           >> ensure: [ComplexBlock]
|     92  153.33   WARequestContext          >> respond:
|     [WAGemStoneRequestContext]
|     77  128.33   Collection                >> do: [NPOrderedCollection]
|     60  100.00   NPAbstractHTTPAPI         >>
|     withCredentialsToken:withQueryRateCostsDoWithCredentialsAndSessionOrRespondError:
|     [NPHTTPAPIv1]
|     60  100.00   NPAbstractHTTPAPI         >>
|     withCredentialsToken:fixedRateTokenCost:variableRateTokenCostFactor:doWithCredentialsAndSessionOrRespondError:
|     [NPHTTPAPIv1]
|     60  100.00   NPAbstractHTTPAPI         >>
|     withCredentialsToken:fixedRateTokenCost:variableRateTokenCostFactor:doWithCredentialsAndSessionOrRespondError:
|     [ComplexBlock]
|     60  100.00   NPHTTPAPIv1               >>
|     respondResultsOf:type:forObjectsMatchingQuery:scope:token:paginationBaseURL:
|     [ComplexBlock]
|     60  100.00   NPHTTPAPIv1               >>
|     makeAvailableAsBookAndRespondFirstPageFrom:type:credentials:inDatabase:paginationBaseURL:
|     [NPHTTPAPIv1]
|     60  100.00   NPHTTPAPIv1               >>
|     respondPageAndMakeNextPageAvailableFromBook:inDatabase:paginationBaseURL:
|     [NPHTTPAPIv1]
|     60  100.00   NPHTTPAPIv1               >>
|     respondResult:ofType:credentials:inDatabase: [NPHTTPAPIv1]
|     60  100.00   NPHTTPAPIv1               >>
|     respondResult:ofType:credentials:inDatabase: [ComplexVCBlock]
|     60  100.00   ProfMonitor class         >> monitorBlock: [ProfMonitorTree
|     class]
|     60  100.00   ProfMonitor               >> monitorBlock: [ProfMonitorTree]
|     60  100.00   NPHTTPAPIv1               >>
|     respondResult:ofType:credentials:inDatabase: [ComplexBlock]
|     60  100.00   NPHTTPAPIv1JsonExporter class >>
|     export:ofType:on:forClient:baseURL:inDatabase: [NPHTTPAPIv1JsonExporter
|     class]
|     60  100.00   NPHTTPAPIv1JsonExporter   >> exportOne
|     [NPHTTPAPIv1JsonExporter]
|     60  100.00   NPAPIDictionaryType       >> export:on:
|     [NPAPIDictionaryType]
|     60  100.00   NPHTTPAPIv1JsonExporter   >>
|     exportDictionary:elementsTypeMapping: [NPHTTPAPIv1JsonExporter]
|     60  100.00   Dictionary                >> keysAndValuesDo: [Dictionary]
|     60  100.00   NPHTTPAPIv1JsonExporter   >>
|     exportDictionary:elementsTypeMapping: [ComplexBlock]
|     59   98.33   NPHTTPAPIv1               >>
|     respondResultsOf:type:forObjectsMatchingQuery:scope:token:paginationBaseURL:
|     [NPHTTPAPIv1]
|     58   96.67   NPHTTPAPIv1               >> get:ofSome:with:token:
|     [ComplexBlock]
|     58   96.67   NPHTTPAPIv1               >>
|     respondResultsFor:forObjectsMatchingQuery:in:token:paginationBaseURL:
|     [NPHTTPAPIv1]
|     56   93.33   BlockClosure              >> valueWithPossibleArgs:
|     [ComplexBlock]
|     50   83.33   Object                    >> ifNotNil: [NPHTTPResourceSpec]
|     45   75.00   NPHTTPAPIv1               >> get:ofSome:with:token:
|     [NPHTTPAPIv1]
|     42   70.00   WARoute                   >> sendSelectorWith:to:
|     [WAComplexRoute]
|     39   65.00   WARouteResult             >> sendMessageTo: [WARouteResult]
|     37   61.67   WARestfulHandler          >> executeResult: [ComplexBlock]
|     32   53.33   GRCodecStream             >> json: [GRUtf8CodecStream]
|     31   51.67   String                    >> jsonOn: [String]
|     31   51.67   String                    >> javascriptOn: [String]
|     31   51.67   JSStream class            >> encodeString:on: [JSStream
|     class]
|     28   46.67   WARestfulHandler          >> executeResult: [NPHTTPAPIv1]
|     26   43.33   GRUtf8CodecStream         >> nextPut: [GRUtf8CodecStream]