Profiling Code

Anyone good at deciphering message tally results...

 - 2074 tallies, 2084 msec.

**Tree**
99.8% {2080ms} WBBookingEngine>>renderBodyWithSearchOn:
  91.1% {1899ms} WBBookingEngine>>renderSearchForm:
    |88.1% {1836ms} WBBookingEngine>>renderSecondarySearchesOn:
    |  |87.4% {1821ms} WBBookingEngine>>renderCitiesNearbyOn:
    |  |  87.4% {1821ms} WADivTag(WATagBrush)>>with:
    |  |    87.4% {1821ms} WADivTag(WABrush)>>with:
    |  |      87.4% {1821ms} WARenderCanvas(WACanvas)>>nest:
    |  |        87.4% {1821ms} WARenderCanvas(WACanvas)>>flush
    |  |          87.4% {1821ms} WASelectTag(WABrush)>>close
    |  |            87.4% {1821ms} WASelectTag(WATagBrush)>>with:
    |  |              87.4% {1821ms} WASelectTag>>before
    |  |                87.4% {1821ms} WASelectTag(WACollectionTag)>>before
    |  |                  87.4% {1821ms}
WASelectTag>>renderListItem:labelled:
    |  |                    87.0% {1813ms} WAOptionTag>>selected:
    |2.8% {58ms} WBBookingEngine>>renderPrimarySearchOn:
  8.7% {181ms} WBBookingEngine>>renderPropertiesOn:
    7.8% {163ms} WARenderCanvas(WACanvas)>>render:
      7.8% {163ms} WBPropertyView(WAComponent)>>renderOn:
        7.8% {163ms} WBPropertyView(WAPresenter)>>renderWithContext:
          7.8% {163ms} WBPropertyView>>renderContentOn:
            4.0% {83ms} WBPropertyView>>renderContentButtonsOn:

**Leaves**
87.0% {1813ms} WAOptionTag>>selected:

**Memory**
        old +279,808 bytes
        young -140,580 bytes
        used +139,228 bytes
        free -139,228 bytes

**GCs**
        full 0 totalling 0ms (0.0% uptime)
        incr 49 totalling 13ms (1.0% uptime), avg 0.0ms
        tenures 2 (avg 24 GCs/tenure)
        root table 0 overflows

I'm having a hard time believing that 87% of my render time is spent in a
method that looks like this...

WAOptionTag>>selected: aBoolean
        self attributes at: 'selected' put: aBoolean

Any ideas?

Ramon Leon
http://onsmalltalk.com

_______________________________________________
seaside mailing list
[hidden email]
http://lists.squeakfoundation.org/cgi-bin/mailman/listinfo/seaside

On Fri, 1 Feb 2008 15:41:41 -0700
"Ramon Leon" <[hidden email]> wrote:

> I'm having a hard time believing that 87% of my render time is spent in a
> method that looks like this...
>
> WAOptionTag>>selected: aBoolean
> self attributes at: 'selected' put: aBoolean
>
> Any ideas?

How often is it called?

If in doubt, go for printf debugging:

WAOptionTag>>selected: aBoolean
        Timestamp now out
        self attributes at: 'selected' put: aBoolean
        Timestamp now out

where out displays its receiver on the Transcript.

Just to get things started :-)

s.
_______________________________________________
seaside mailing list
[hidden email]
http://lists.squeakfoundation.org/cgi-bin/mailman/listinfo/seaside

On 2/1/08, Ramon Leon <[hidden email]> wrote:

> I'm having a hard time believing that 87% of my render time is spent in a
> method that looks like this...
>
> WAOptionTag>>selected: aBoolean
>         self attributes at: 'selected' put: aBoolean

Do you consistently get this same trace, or was this a one time thing?

If the Squeak VM wasn't the active process for a while, all of the
wall clock time until it became active again will be attributed to
whichever method it happened to be in at the time it was suspended.

Avi
_______________________________________________
seaside mailing list
[hidden email]
http://lists.squeakfoundation.org/cgi-bin/mailman/listinfo/seaside

It's very consistent, but I think I've figured it out, it's a SoapHref proxy
#becomeReal getting triggered by the #selected:.  Not sure why that doesn't
show up in the profiler, but I think that's what taking up the time.

Ramon Leon
http://onsmalltalk.com

_______________________________________________
seaside mailing list
[hidden email]
http://lists.squeakfoundation.org/cgi-bin/mailman/listinfo/seaside

"Ramon Leon" <[hidden email]> wrote

>> > WAOptionTag>>selected: aBoolean
>> >         self attributes at: 'selected' put: aBoolean
> It's very consistent, but I think I've figured it out, it's a SoapHref
> proxy
> #becomeReal getting triggered by the #selected:.  Not sure why that
> doesn't
> show up in the profiler, but I think that's what taking up the time.

Is something within the #at:put: triggering it? Synchronously? Then I'd be
quite interested to know why it does not show up. I thought I saw some
possibly similar anamoly recently but wrote it off to my not understanding
the profiler.

- Sophie



_______________________________________________
seaside mailing list
[hidden email]
http://lists.squeakfoundation.org/cgi-bin/mailman/listinfo/seaside

Hi Ramon,

        maybe a primitive is envolved? MessageTally wont see details about
them,

        cheers,

Sebastian Sastre

 

_______________________________________________
seaside mailing list
[hidden email]
http://lists.squeakfoundation.org/cgi-bin/mailman/listinfo/seaside