object loading performance

Previous Topic Next Topic
 
classic Classic list List threaded Threaded
2 messages Options
Reply | Threaded
Open this post in threaded view
|

object loading performance

David Faught
As long as I was playing with making an example for the Skeletal
Animation project, I thought that I would profile the model and
skeleton loading process, since for bigger models it seems to take a
long time.  Here are the statements in the world #initialize method
that did the profile:


        fileName := FileDirectory pathFromURI:
'Content/exampleAvatars/Blender/Cube.mesh.xml'.
MessageTally spyOn: [
        mesh := (TLoadOgreMesh initializeWithFileName: fileName scale: 0.4) frame.
].

and here is the report for the simple model I have been playing with:

 - 9239 tallies, 9302 msec.

**Tree**
74.7% {6949ms} EventSensor>>installEventTickler
  |74.7% {6949ms} EventSensor>>eventTickler
  |  74.7% {6949ms} Delay>>wait
  |    74.7% {6949ms} Semaphore>>wait
22.6% {2102ms} TLoadOgreMesh class>>initializeWithFileName:scale:
  |22.6% {2102ms} TLoadOgreMesh>>initializeWithFileName:scale:
  |  22.5% {2093ms} TLoadOgreMesh>>parseStream:
  |    22.5% {2093ms} XMLDOMParser class>>parseDocumentFrom:
  |      22.5% {2093ms} XMLDOMParser class(SAXHandler class)>>parseDocumentFrom:
  |        22.5% {2093ms} XMLDOMParser(SAXHandler)>>parseDocument
  |          22.3% {2074ms} SAXDriver(XMLTokenizer)>>nextEntity
  |            16.7% {1553ms} SAXDriver(XMLTokenizer)>>nextNode
  |              |16.6% {1544ms} SAXDriver(XMLTokenizer)>>nextTag
  |              |  8.9% {828ms}
SAXDriver(XMLTokenizer)>>nextAttributeInto:namespaces:
  |              |    |5.7% {530ms} SAXDriver(XMLTokenizer)>>nextAttributeValue
  |              |    |  4.0% {372ms} primitives
  |              |  2.1% {195ms} SAXDriver(XMLTokenizer)>>nextName
  |            5.3% {493ms} SAXDriver(XMLTokenizer)>>nextWhitespace
  |              2.8% {260ms} WriteStream>>nextPut:
  |                2.7% {251ms} primitives
2.4% {223ms} TMessageRouterClient(Object)>>fork:at:

**Leaves**
76.5% {7116ms} Semaphore>>wait
4.0% {372ms} SAXDriver(XMLTokenizer)>>nextAttributeValue
3.3% {307ms} SAXDriver(XMLTokenizer)>>next
3.0% {279ms} WriteStream>>nextPut:

**Memory**
        old +1,777,420 bytes
        young +198,080 bytes
        used +1,975,500 bytes
        free +441,240 bytes

**GCs**
        full 1 totalling 1,475ms (16.0% uptime), avg 1475.0ms
        incr 461 totalling 535ms (6.0% uptime), avg 1.0ms
        tenures 46 (avg 10 GCs/tenure)
        root table 0 overflows


I don't understand why most of the time is spent in Semaphore>>wait.
Why is that?
Reply | Threaded
Open this post in threaded view
|

Re: object loading performance

Andreas.Raab
 > I don't understand why most of the time is spent in Semaphore>>wait.
 > Why is that?

See the discussion starting here:

http://lists.squeakfoundation.org/pipermail/vm-dev/2007-June/001410.html

The problem is that profiling doesn't actually measure what is going on
with very odd side effects.

Cheers,
   - Andreas

David Faught wrote:

> As long as I was playing with making an example for the Skeletal
> Animation project, I thought that I would profile the model and
> skeleton loading process, since for bigger models it seems to take a
> long time.  Here are the statements in the world #initialize method
> that did the profile:
>
>
> fileName := FileDirectory pathFromURI:
> 'Content/exampleAvatars/Blender/Cube.mesh.xml'.
> MessageTally spyOn: [
> mesh := (TLoadOgreMesh initializeWithFileName: fileName scale: 0.4) frame.
> ].
>
> and here is the report for the simple model I have been playing with:
>
>  - 9239 tallies, 9302 msec.
>
> **Tree**
> 74.7% {6949ms} EventSensor>>installEventTickler
>   |74.7% {6949ms} EventSensor>>eventTickler
>   |  74.7% {6949ms} Delay>>wait
>   |    74.7% {6949ms} Semaphore>>wait
> 22.6% {2102ms} TLoadOgreMesh class>>initializeWithFileName:scale:
>   |22.6% {2102ms} TLoadOgreMesh>>initializeWithFileName:scale:
>   |  22.5% {2093ms} TLoadOgreMesh>>parseStream:
>   |    22.5% {2093ms} XMLDOMParser class>>parseDocumentFrom:
>   |      22.5% {2093ms} XMLDOMParser class(SAXHandler class)>>parseDocumentFrom:
>   |        22.5% {2093ms} XMLDOMParser(SAXHandler)>>parseDocument
>   |          22.3% {2074ms} SAXDriver(XMLTokenizer)>>nextEntity
>   |            16.7% {1553ms} SAXDriver(XMLTokenizer)>>nextNode
>   |              |16.6% {1544ms} SAXDriver(XMLTokenizer)>>nextTag
>   |              |  8.9% {828ms}
> SAXDriver(XMLTokenizer)>>nextAttributeInto:namespaces:
>   |              |    |5.7% {530ms} SAXDriver(XMLTokenizer)>>nextAttributeValue
>   |              |    |  4.0% {372ms} primitives
>   |              |  2.1% {195ms} SAXDriver(XMLTokenizer)>>nextName
>   |            5.3% {493ms} SAXDriver(XMLTokenizer)>>nextWhitespace
>   |              2.8% {260ms} WriteStream>>nextPut:
>   |                2.7% {251ms} primitives
> 2.4% {223ms} TMessageRouterClient(Object)>>fork:at:
>
> **Leaves**
> 76.5% {7116ms} Semaphore>>wait
> 4.0% {372ms} SAXDriver(XMLTokenizer)>>nextAttributeValue
> 3.3% {307ms} SAXDriver(XMLTokenizer)>>next
> 3.0% {279ms} WriteStream>>nextPut:
>
> **Memory**
> old +1,777,420 bytes
> young +198,080 bytes
> used +1,975,500 bytes
> free +441,240 bytes
>
> **GCs**
> full 1 totalling 1,475ms (16.0% uptime), avg 1475.0ms
> incr 461 totalling 535ms (6.0% uptime), avg 1.0ms
> tenures 46 (avg 10 GCs/tenure)
> root table 0 overflows
>
>
> I don't understand why most of the time is spent in Semaphore>>wait.
> Why is that?
>