Tools for visualizing nested tracing events

[Grzegorz Kossakowski]

Hi,

I created an aspect that allows you to see how much scalac spends calculating given type by intercepting calls to LazyType.complete. You can find it here: https://github.com/gkossakowski/scalac-aspects

I decided to give it a go against compiling Scala library. Here's what you need to do to get it working:

rm lib/extra/aspects.jar && ln -s Temporary Path/scalac-aspects.N1634TdV/aspects.jar lib/extra/aspects.jar

export ANT_OPTS="$ANT_OPTS -javaagent:$HOME/aspectj1.7/lib/aspectjweaver.jar"

ant quick.lib > quick-lib-timings

Where Temporary Path is printed by scalac-aspects script.

You need to cleanup quick-lib-timings output to get raw data. Then I did:

sort -nr -k 2 quick-lib-timings | head

   6156427   407517  scala.collection.parallel.ParSeqLike.view                                         source-/Users/grek/scala/scala/src/library/scala/collection/parallel/ParSeqLike.scala,line-327,offset=14012 

   5560684   334546  scala.collection.parallel.ParSeqLike.toString                                     source-/Users/grek/scala/scala/src/library/scala/collection/parallel/ParSeqLike.scala,line-322,offset=13876 

   5560984   333943  scala.collection.parallel.ParIterableLike.toString                                source-/Users/grek/scala/scala/src/library/scala/collection/parallel/ParIterableLike.scala,line-354,offset=15279  

   5901514   254850  scala.collection.parallel.ParIterableLike.view                                    source-/Users/grek/scala/scala/src/library/scala/collection/parallel/ParIterableLike.scala,line-844,offset=36659  

   5914662   233409  scala.collection.parallel.anon$1.seq                                              source-/Users/grek/scala/scala/src/library/scala/collection/parallel/ParIterableLike.scala,line-848,offset=36858  

   5925677   221659  scala.collection.IterableLike.view                                                source-/Users/grek/scala/scala/src/library/scala/collection/IterableLike.scala,line-299,offset=9822 

   5944196   198424  scala.collection.IterableLike.view                                                source-/Users/grek/scala/scala/src/library/scala/collection/IterableLike.scala,line-294,offset=9659

It's interesting to see that type defined in ParSeqLike.toString takes 0.3s to compute. Let's see what other events occurred during that type completion:

awk -v startTime=5560684 -v duration=334546 '($1 >= startTime && $1 < startTime+duration) { print }' quick-lib-timings

You can find the output here: https://gist.github.com/4498894

Now you can see the challenge. Completing type in ParSeqLike.toString triggers completion of 528 other types. Alternatively, you could think that some nested events occur while other event occurs. In order to get any sense of such data we need some tool to visualize events and their nested structure. In the past I used to hack Speed Tracer Chrome extension to display my own events instead of browser events. However, the extension appears to be broken at the moment.

I tried to find other, easy to use tool that could offer functionality similar to Speed Tracer when it comes to visualizing events but I couldn't find one.

I thought I'd ping performance oriented folks hanging around here to see if they can share so ideas how to deal with this. Also, if there's anybody with Javascript-fu that is feeling like hacking something simple that could visualize nested events that would be great too.

I have to leave this at this stage because I'm busy with other work.

--
Grzegorz Kossakowski

[Malcolm]

http://www.softwareishard.com/blog/har-viewer/

This tool works well with a pretty simple transform on your raw output. 

[iulian dragos]

On Thu, Jan 10, 2013 at 3:36 AM, Grzegorz Kossakowski <grzegorz.k...@gmail.com> wrote:

Hi,

I created an aspect that allows you to see how much scalac spends calculating given type by intercepting calls to LazyType.complete. You can find it here: https://github.com/gkossakowski/scalac-aspects

Greg, I'm happy you got to bring it to this point. I'm very interested in using this (or something similar) to show timings in Eclipse. I think we could annotate methods (or lines) based on how much time it took to type-check them. Either have a small bubble on the left gutter with the time it took to typecheck that method, or color the background based on (relative) timings for each line. If compilation times are high, you'd get some idea where the time is spent, and maybe add an explicit type.

I had a look at your code, and I think it's a good start, but it's does not exactly fit what I described above (I think lazy types are only a subset of the situations where timings are interesting to collect). The good news is that it's easy to run aspects at class load-time in Eclipse. The next step is to identify a few more join points. Another issue is their fragility, as these aspects depend on internal methods that might change tomorrow. Everything points to making this feature part of a separate plugin.

--
« Je déteste la montagne, ça cache le paysage »
Alphonse Allais