R – Flex profiler isn’t showing me what I expect… Am I doin’ it wrong

actionscriptactionscript-3apache-flexflex3profiling

I'm trying to profile the performance of my Flex code, but I'm not getting the results I expect: the wall clock says that my application takes about 30 seconds to load, but when I sort the profiling* results by cumulative time, the numbers don't add up: there is one method, [enterFrameEvent], which has a cumulative time of ~8000ms, then a bunch of methods with an insignificant cumulative time:
screenshot of profiling output http://img.skitch.com/20090728-j1rpxigiceutjw955j35sm74ag.jpg

But even summing up the cumulative timesª leaves ~15 seconds unaccounted for. Where did that time go? Is there something I'm obviously doing wrong?

For a bit more background on my application: the load time is a direct result of data received from an HTTP service. A request for the data is made in the Application's creationComplete handler (the selected row), and when the data arrives from the server it is processed recursively. The methods which do the processing (including the result handler) do appear in the profiler's list of methods, but they have an insignificant runtime (~30ms).

*: I'm profiling by clicking the little "Profile" button in FlexBuilder, letting the application start, then clicking "performance snapshot" button. I've also tried sending the requests in response to a button click: starting the application using the profiler, clicking the "performance snapshot" button, clicking the button (to request the data), waiting for ~30 seconds while the data is processed, then clicking "performance snapshot" again. The results were similar.

Edit: More information: when I say "loading" I mean "my browser is locked up and doesn't respond to anything until it's done". Also, running a memory profile doesn't show anything too unexpected (there is a spike as the application starts, but no significant allocations after that).

Edit 2: Some printf debugging has shown me that, in fact, it is not my result handlers which are taking up all the time – it is something else that executes after they have finished.

ª: yes, I realize this is an entirely nonsensical measurement… But I'm trying to make a point.

PS: Sorry for the terrible JPGification… Skitch doesn't do PNGs :'(

Best Answer

Alright, problem solved.

It turns out that setting an mx:Label's text field requires Ω(n²) time (where 'n' is the length of the string). There are some optimizations which make it faster for "sufficiently short" strings, but given a string which is "sufficiently long", you get to do all that wonderful work.

Needless to say, my strings were "sufficiently long".

Sweet.