Re: [abc] mystery of ajhotdraw ???

Prof. Laurie HENDREN wrote:

>Here are some approximate numbers:
>
>Summary total approx gc tm exec. unaccounted
> overhead overhead
>
> aspect version 12.8 sec .62 sec
> naive tracematch 187.8 sec 15.39 sec 147 sec 25 sec
> opt tracematch 53.3 sec 3.65 sec 29 sec 21 sec
>
>
Those numbers are so incredibly different from the ones I'm taking on
cardinal that I took the time to investigate some more.

First of all, I tried to modify the tracematch code so that it didn't do
any locking. Perhaps I didn't do it right (Julian -- does it make sense
to have a debug switch for that? After all, the aspect version doesn't
lock), but that, surprisingly, didn't give any noticeable change in runtime.

Then I tried minimising the window while the benchmark is running.

For TMNoIndex (the only measurement I've taken yet -- Eric technically
has the cardinal lock), the runtime falls from 150s to 40s. Still using
VNC, but programmatically minimising the main window before starting the
animation.

I can only assume that our problem is subtle differences in the AWT/GUI
backend. Merely redirecting output to a VNC server doesn't nullify the
AWT overhead, but minimising the window seemingly does.

Interestingly, the aspectJ version of ajhotdraw ran about as quickly
minimised as non-minimised (7s).

However, if we minimise the window, TMs are only 6 times slower than
aspects, rather than 20-30 times.

The much lower overhead that Laurie measured could be explained with a
more efficient AWT/GUI backend under Windows.

The question is, of course, which numbers to include in the paper. What
do people think? Since it seems clear the overheads are due to calling
AWT's display drawing routines, should we just consistently take
"minimised window" numbers for ajhotdraw? We say we run it on a VNC to
remove the drawing overhead, but my experiment suggests that's not quite
enough.

What do people think?

(Eric: Please do not leave cardinal idle, there are still too many
measurements to take. Either use it or release the lock.)

- P

>
>Naive tracematches allocate a lot more objects, opt tracematches
> allocate fewer, but still pay a gc penalty.
>
>One can identify methods that clearly belong to tracematch
>machinery, which I have summarized under tm exec. overhead.
>
>There is some unaccounted overhead, which seems to come mostly
>from increased execution time of
>
>javax.swing.RepaintManager.addDirtyRegion.
>
>I don't know why this should be, but it seems that by just leaving
>the animation running longer (because of the tm overheads) we also
>get increased overhead due to swing stuff. I can only speculate that
>there are some complex interactions with the low-level AWT
>code that takes care of refreshing the display.
>
>Below are the key methods in the tm opt implementation. Perhaps the
>tm boys can verify that these look like methods that are
>introduced by the tm implementation (except of course the addDirtyRegion
>one and a couple that are jhotdraw methods).
>
> Compiled + native Method
> 37.7% 0 + 1598 javax.swing.RepaintManager.addDirtyRegion
> 6.9% 245 + 48 java.util.HashMap.<init>
> 3.2% 114 + 20
>observdrawchange.Constraint$tracematch$4.addBindingsForSymbolfigureInvalidated
> 3.2% 119 + 15 java.util.LinkedHashMap.createEntry
> 2.7% 86 + 29 java.util.LinkedHashMap.newKeyIterator
> 2.5% 76 + 32 observdrawchange.Constraint$tracematch$4.or
> 2.0% 62 + 22 java.util.LinkedHashMap.init
> 1.7% 71 + 0
>java.util.LinkedHashMap$LinkedHashIterator.hasNext
> 1.5% 65 + 0 org.jhotdraw.standard.AbstractFigure.listener
> 1.5% 65 + 0 vtable chunks
> 1.5% 62 + 0 observdrawchange.Disjunct$tracematch$4.hashCode
> 1.4% 54 + 5 java.util.HashSet.iterator
> 1.4% 58 + 0
>java.util.LinkedHashMap$LinkedHashIterator.<init>
> 1.3% 55 + 0 java.util.HashMap.put
> 1.2% 52 + 0 java.util.HashMap.hash
> 1.0% 42 + 0 org.jhotdraw.contrib.PolygonFigure.bounds
> 1.0% 42 + 0
>java.util.LinkedHashMap$LinkedHashIterator.nextEntry
> 1.0% 41 + 0 java.util.HashMap.removeEntryForKey
> 0.9% 37 + 0 java.lang.Math.max
> 0.8% 35 + 0
>observdrawchange.DrawChangeNotify.tracematch$4$body
> 0.8% 34 + 0 java.awt.Rectangle.add
> 0.8% 27 + 5
>observdrawchange.Disjunct$tracematch$4.addBindingsForSymbolfigureInvalidated
> 0.7% 27 + 1 java.util.AbstractCollection.toArray
> 0.6% 23 + 3
>observdrawchange.DrawChangeNotify.tracematch$4$body_real
> 0.6% 24 + 0 java.util.HashSet.size
> 89.5% 1981 + 1814 Total compiled (including elided)
>
> Stub + native Method
> 6.9% 60 + 232 java.lang.System.identityHashCode
> 1.5% 7 + 55 java.lang.Object.notify
> 0.1% 1 + 5 java.lang.Object.hashCode
> 0.0% 0 + 2 java.lang.Object.notifyAll
> 8.5% 68 + 294 Total stub
>
>
>----------------------------------------------------------
>
>So, in summary, there do seem to be some significant overheads, even
>for the tm opt version, but the direct overheads should only cause
>a 3x to 4x slowdown. There are also some indirect effects that
>I can only speculate about and I think those effects will vary
>depending on the VM implementation and in particular the
>implemenation of the awt stuff.
>
>Comparing the naive tm to the opt tm does show that the opt version
>saves a lot on gc and on direct tm overhead.
>
>I don't think we will be able to say anything more detailed than
>that.
>
>Cheers, Laurie
>
>
>+-----------------------------------------------------------------
>| Laurie Hendren --- laurie.hendren@mcgill.ca
>| Associate Dean (Academic), Faculty of Science,
>| Dawson Hall, McGill University, 853 Sherbrooke St W,
>| Montreal QC H3A 2T6 Canada, 514-398-7179, fax 514-398-1774
>+----------------------------------------------------------------
>| For contact and home page info as Professor, Computer Science:
>| http://www.sable.mcgill.ca/~hendren --- hendren@cs.mcgill.ca
>| Research: http://www.sable.mcgill.ca http://aspectbench.org
>+----------------------------------------------------------------
>
>
>
>
>
>
Received on Mon Mar 13 11:37:48 2006