JDK-4485987 : Excessive garbage generation during drag-and-drop and painting in 1.4beta
  • Type: Bug
  • Component: client-libs
  • Sub-Component: 2d
  • Affected Version: 1.4.0
  • Priority: P4
  • Status: Closed
  • Resolution: Not an Issue
  • OS: windows_2000,windows_xp
  • CPU: x86
  • Submitted: 2001-07-30
  • Updated: 2002-06-04
  • Resolved: 2002-06-04
Related Reports
Relates :  
Description

Name: yyT116575			Date: 07/30/2001


java version "1.4.0-beta"
Java(TM) 2 Runtime Environment, Standard Edition (build 1.4.0-beta-b65)
Java HotSpot(TM) Client VM (build 1.4.0-beta-b65, mixed mode)

Existing Swing applications doing a lot of painting and drag-and-drop
on Windows suddenly perform unacceptably when using the 1.4beta runtime.

We produce class libraries to make it easy to build graph/network/diagram
editors.  Users can select one or more graphical objects in a window and
drag them around to reposition them, or to copy them (if the control key
is held down).

The problem occurs only with 1.4.0 beta, on all the Windows platforms
we have tested: Windows 98, Windows NT, and Windows 2000.  Using the
same JAR files with JRE/JDK 1.3.1 or earlier (all the way back to 1.2.0)
performs OK on all the same platforms and machines.

I cannot include source code here, but can point you to some JAR files
that exhibit this problem:  http://www.nwoods.com/temp/JGo/JGo.jar and
Demo1.jar.  Also download star.gif and doc.gif from the same directory.

Run Demo1 (which is an executable JAR) and invoke the "Lots of stuff"
command on the Insert menu.  Select a bunch of objects and drag them
around in a circle.

You'll find that on Windows 2000 after a few seconds everything freezes
for a second or two, and then it recovers and catches up with your mouse
movement.

On Windows 98 the behavior is much worse--it seems the objects you drag
can't keep up at all.

But use JRE 1.3.0 or 1.3.1 on the same machines with this same app, and
everything keeps up with your mouse movement pretty well.

I've tried narrowing down the problem, and found that using drag-and-drop
is partly to blame.  Doing the same operations without using the awt.dnd
mechanisms improves the responsiveness and reduces the frequency of "freezes".
But they still happen.

My guess is that frequent garbage collections of Windows resources are causing
the "freezes".  I couldn't find any documentation on Java runtime changes
that would account for the new behavior with 1.4beta.

If you'd like source code, I can arrange that privately.  I'm also willing to
try to come up with a simple example program, if you can confirm there is
indeed a problem that you need help tracking down.
(Review ID: 129072) 
======================================================================

Comments
EVALUATION Steve.Wilson@eng, who leads the java performance team, recently sent an email with the results of analyses by his team showing that GC is substantially slower in merlin. (I believe it was sent to the hotspot gc team alias). More objects are being created, but also GC itself is significantly slower. Also, the drop in performance was not limited to GUI applications. Not using dnd would speed things up, of course, since it reduces the number of classes loaded, and therefore objects created. However, it seems that the primary problem is the speed of the GC, not the number of objects created. The AWT and Drag&Drop groups have already taken a cut at reducing the classes loaded. While there are still more classes loaded in merlin than in kestrel, improvement was achieved in merlin. It is unlikely that further improvement can be achieved in AWT/dnd without fairly heroic efforts. Reassigning to hotspot/gc. If further information or consultation is needed, please contact me and/or the performance team. eric.hawkes@eng 2001-07-30 This is an interesting bug, but I don't think it's a HotSpot garbage collector bug. Or maybe not only a GC bug. I tried running Demo1 with JDK-1.4.0-beta3_b83 on my WindohsNT4.0 P3/700, with some GC tracing on. I double-clicked on "Lots of stuff" button, selected it all and started dragging it in a 1-inch circle about one cycle per second. The log is attached as JDK-1.4.0_beta3_b83.20011017.1030.out.Z I'm running with "-XX:+PrintGC -XX:+PrintGCTimeStamps", so I can see when and for how long the GC runs. At the beginning, everything is fine: 13.3586: [GC 1367K->947K(1984K), 0.0044864 secs] 17.3416: [GC 1457K->1004K(1984K), 0.0120449 secs] 17.6487: [GC 1516K->1159K(1984K), 0.0039715 secs] 17.9146: [GC 1671K->1322K(1984K), 0.0038623 secs] 18.1706: [GC 1834K->1491K(2112K), 0.0035709 secs] 18.1743: [Full GC 1491K->1411K(2112K), 0.1379540 secs] 18.5943: [GC 1923K->1586K(2932K), 0.0030115 secs] 18.8355: [GC 2098K->1750K(2932K), 0.0056573 secs] 19.0782: [GC 2262K->1918K(2932K), 0.0039081 secs] 19.2751: [GC 2430K->2094K(2932K), 0.0042486 secs] 19.4912: [GC 2606K->2259K(2932K), 0.0037441 secs] 19.6868: [GC 2771K->2418K(2932K), 0.0037361 secs] 19.6907: [Full GC 2418K->1291K(2932K), 0.1438595 secs] with scavenges being pretty frequent (this app must allocate a lot of memory), but nicely short. The occasional full collections are somewhat longer, but nothin like the "second or two" that the bug reports. What I notice is that over time, the heap is growing -- accumulating live objects -- so that by 120.192: [Full GC 48900K->48900K(52176K), 0.6037507 secs] 127.361: [GC 52620K->50068K(65088K), 0.2132036 secs] 129.142: [GC 54164K->51351K(65088K), 0.0289039 secs] 130.739: [GC 55447K->52586K(65088K), 0.0278297 secs] 132.341: [GC 56682K->53838K(65088K), 0.1731274 secs] 134.059: [GC 57934K->55113K(65088K), 0.0277639 secs] 135.181: [GC 59209K->57257K(65088K), 0.0422020 secs] 136.797: [Full GC 61353K->58533K(65088K), 0.6907703 secs] 144.595: [Full GC 62629K->59745K(65088K), 0.6906430 secs] 152.588: [Full GC 63841K->59645K(65088K), 0.9870209 secs] 160.591: [Full GC 63740K->60921K(65088K), 0.7040751 secs] 168.64: [Full GC 65087K->62205K(65088K), 0.7174136 secs] 176.132: [Full GC 65087K->63075K(65088K), 0.7127823 secs] 182.777: [Full GC 65087K->63617K(65088K), 0.7451168 secs] 189.572: [Full GC 65087K->64058K(65088K), 0.7166995 secs] 196.361: [Full GC 65087K->64371K(65088K), 0.7156091 secs] 202.273: [Full GC 65087K->64583K(65088K), 0.7093661 secs] 208.167: [Full GC 65087K->64714K(65088K), 0.7151142 secs] 214.116: [Full GC 65087K->64826K(65088K), 0.7380867 secs] 220.077: [Full GC 65087K->64897K(65088K), 0.7123367 secs] 220.875: [Full GC 65087K->64945K(65088K), 0.7147857 secs] 221.667: [Full GC 65087K->64985K(65088K), 0.7127580 secs] 222.419: [Full GC 65080K->65017K(65088K), 0.7150324 secs] we have filled the heap, and the GC is in total panic trying to recover space. But still none of the collections (even the full collections) are more than a second. Meanwhile, the visual pauses on the screen are several seconds long (harder to quantify since I don't have them in a log). Then at 223.135: [Full GC 65017K->26173K(65088K), 0.8350996 secs] the heap collapses, freeing up more than half of the space. I don't know what caused that, but it probably wasn't GC, unless the program uses SoftReferences and we've finally given up on them. Maybe we should give up on them sooner? That happens repeatedly. Here's the next one, somewhat more than a minute later: 263.848: [GC 59094K->56248K(65088K), 0.0238328 secs] 265.646: [GC 60344K->57492K(65088K), 0.0239223 secs] 267.436: [Full GC 61588K->58150K(65088K), 1.1306831 secs] 275.745: [Full GC 62242K->56348K(65088K), 1.3062633 secs] 283.736: [GC 60443K->57625K(65088K), 0.0165898 secs] 285.55: [Full GC 61721K->58905K(65088K), 0.9885005 secs] 293.763: [Full GC 63001K->60166K(65088K), 0.9857537 secs] 301.784: [Full GC 64256K->61429K(65088K), 0.9939400 secs] 321.661: [Full GC 65085K->29264K(65088K), 0.4734692 secs] After these collapses things are more or less back to normal as far as the GC is concerned, but the program is pausing for longer and longer, and I notice (with the NT performance monitor) that we are spending the "hung" times at 100% CPU utilization, in "system" time, not user time. We are talking 5, 10, even 20 second pauses here. That finally affects the GC as the heap fills up again and we need cycles to collect: 358.742: [GC 60165K->57296K(65088K), 0.0238184 secs] 360.253: [Full GC 61392K->58575K(65088K), 0.4105780 secs] 362.177: [Full GC 62671K->59810K(65088K), 0.4089723 secs] 369.472: [Full GC 63906K->61020K(65088K), 0.4114047 secs] 376.491: [Full GC 65073K->61199K(65088K), 0.6362641 secs] 378.616: [Full GC 65087K->62273K(65088K), 0.4382115 secs] 384.794: [Full GC 65080K->63503K(65088K), 0.4446712 secs] 385.862: [Full GC 65087K->63957K(65088K), 0.4432204 secs] 392.415: [Full GC 65087K->63864K(65088K), 25.5868926 secs] 418.639: [Full GC 65087K->64102K(65088K), 15.3510196 secs] 434.527: [Full GC 65087K->39776K(65088K), 35.4741985 secs] Those are ridiculous collection times! Something else is using up all the cycles on the machine. After that, the program got a java.lang.ArrayIndexOutOfBoundsException at sun.awt.font.AdvanceCache.get(AdvanceCache.java:158) at java.awt.font.TextLayout$OptInfo.getAdvance(TextLayout.java:251) at java.awt.font.TextLayout$OptInfo.getLogicalBounds(TextLayout.java:264) at sun.awt.font.Decoration$DecorationImpl.drawTextAndEmbellishments(Decoration.java:243) at sun.awt.font.Decoration$DecorationImpl.drawTextAndDecorations(Decoration.java:273) at java.awt.font.TextLayout$OptInfo.draw(TextLayout.java:301) at java.awt.font.TextLayout.draw(TextLayout.java:2663) at sun.java2d.SunGraphics2D.drawString(SunGraphics2D.java:2621) at com.nwoods.jgo.JGoText.paint(com/nwoods/jgo/JGoText) at com.nwoods.jgo.JGoView.paintDocumentObjects(com/nwoods/jgo/JGoView) at com.nwoods.jgo.JGoView.paintView(com/nwoods/jgo/JGoView) at com.nwoods.jgo.JGoView.onPaintComponent(com/nwoods/jgo/JGoView) at com.nwoods.jgo.JGoView$JGoViewCanvas.paintComponent(com/nwoods/jgo/JGoView$JGoViewCanvas) at javax.swing.JComponent.paint(JComponent.java:807) 471.444: [GC 43871K->40899K(65088K), 0.0636467 secs] at javax.swing.JComponent.paintWithOffscreenBuffer(JComponent.java:4737) at javax.swing.JComponent.paintDoubleBuffered(JComponent.java:4690) at javax.swing.JComponent._paintImmediately(JComponent.java:4634) at javax.swing.JComponent.paintImmediately(JComponent.java:4466) at javax.swing.RepaintManager.paintDirtyRegions(RepaintManager.java:407) at javax.swing.SystemEventQueueUtilities$ComponentWorkRequest.run(SystemEventQueueUtilities.java:120) at java.awt.event.InvocationEvent.dispatch(InvocationEvent.java:181) at java.awt.EventQueue.dispatchEvent(EventQueue.java:446) at java.awt.EventDispatchThread.pumpOneEventForHierarchy(EventDispatchThread.java:193) at java.awt.EventDispatchThread.pumpEventsForHierarchy(EventDispatchThread.java:147) at java.awt.EventDispatchThread.pumpEvents(EventDispatchThread.java:141) at java.awt.EventDispatchThread.pumpEvents(EventDispatchThread.java:133) at java.awt.EventDispatchThread.run(EventDispatchThread.java:101) Though the GC -- I'm happy to see -- is chugging along with 63 millisecond minor collection of a 40MB heap. I could use some help figuring out what else is going on with this application. Please nominate an AWT/Swing engineer to help out. ###@###.### 2001-10-17 I just tried this again on my WindohsNT4.0 PII/700 box with Java(TM) 2 Runtime Environment, Standard Edition (build 1.4.0-rc-b90) and it's much worse than it was before. Not for GC, but for responsiveness. I double-clicked "Lots of stuff", selected it all, and started dragging it around in a circle. The display froze after a fraction of a second, but my CPU was 100% busy (75% system, 25% user?) for about 5 seconds. There is some GC activity in there, but it isn't much: semeru $ $deployed/JDK-1.4.0-beta_refresh/bin/java -showversion -XX:+PrintGC -XX:+PrintGCTimeStamps -cp "Demo1.jar;JGo.jar" com.nwoods.jgo.examples.demo1.Demo1 java version "1.4.0-rc" Java(TM) 2 Runtime Environment, Standard Edition (build 1.4.0-rc-b90) Java HotSpot(TM) Client VM (build 1.4.0-rc-b90, mixed mode) 9.52066e-007: [GC 505K->154K(1984K), 0.0045714 secs] 0.345418: [GC 666K->155K(1984K), 0.0037944 secs] 0.851816: [GC 667K->330K(1984K), 0.0071307 secs] 1.78041: [GC 842K->463K(1984K), 0.0073727 secs] 2.70122: [GC 973K->603K(1984K), 0.0151432 secs] 6.54176: [GC 1112K->720K(1984K), 0.0117705 secs] 10.3428: [GC 1229K->837K(1984K), 0.0093618 secs] 10.3834: [Full GC 922K->850K(1984K), 0.1210096 secs] 16.7419: [GC 1362K->911K(1984K), 0.0104077 secs] 51.5071: [GC 1423K->951K(1984K), 0.0062492 secs] 55.5915: [GC 1463K->985K(1984K), 0.0077738 secs] 87.2213: [GC 1493K->1122K(1984K), 0.0044442 secs] 112.164: [GC 1634K->1259K(1984K), 0.0037092 secs] 127.175: [GC 1765K->1412K(1984K), 0.0039299 secs] 147.269: [GC 1924K->1500K(2112K), 0.0048534 secs] 147.274: [Full GC 1500K->1016K(2112K), 0.1661642 secs] 155.427: [GC 1528K->1048K(2272K), 0.0050416 secs] 160.184: [GC 1560K->1061K(2272K), 0.0035546 secs] 172.17: [GC 1573K->1137K(2272K), 0.0031788 secs] 186.399: [GC 1649K->1277K(2272K), 0.0038277 secs] I think the lack of GC activity is due to not much actually happening, since we don't seem to really be dragging the objects around on the screen. I'm bumping the priority on this bug, since dragging seems unusable. ###@###.### 2002-01-07 I tried walking through the rc builds (b85 through b90). I can get it to hang for multiple seconds outside of the GC. Sometimes it does hang inside the GC, and when it does, it seems to always hang for 80 seconds. Is that a timeout on something? ###@###.### 2002-01-07 I put a timer in the GC code, and if it exceeded my tolerance (20 seconds!) it prints out all the thread stacks, using the VM internal pss() method. Here's the first sample I got: [Full GC317.009: [phase 1 "Executing pss" Full thread dump Java HotSpot(TM) Client VM (1.4-internal-debug mixed mode): "Thread-33" prio=7 tid=0x04EC45A8 nid=0x799 runnable [53bf000..53bfd58] Thread state: _thread_in_native Thread: 0x04EC45A8 [0x799] State: _at_safepoint pc: 0x00000000 1 - sun.awt.windows.WDragSourceContextPeer.doDragDrop(Native Method) 2 - sun.awt.windows.WDragSourceContextPeer$1.run(WDragSourceContextPeer.java:96) "Thread-2" prio=5 tid=0x007646C8 nid=0x621 waiting on monitor [0..6fa5c] Thread state: _thread_blocked Thread: 0x007646C8 [0x621] State: _at_safepoint pc: 0x00000000 "TimerQueue" daemon prio=5 tid=0x007F8568 nid=0x1d5 waiting on monitor [4dcf000..4dcfd58] Thread state: _thread_blocked Thread: 0x007F8568 [0x1d5] State: _at_safepoint pc: 0x00000000 1 - java.lang.Object.wait(Native Method) 2 - javax.swing.TimerQueue.run(TimerQueue.java:231) 3 - java.lang.Thread.run(Thread.java:536) "AWT-EventQueue-0" prio=7 tid=0x007C36E8 nid=0x5e0 waiting on monitor [2b9f000..2b9fd58] Thread state: _thread_blocked Thread: 0x007C36E8 [0x5e0] State: _at_safepoint pc: 0x00000000 1 - com.nwoods.jgo.JGoObject.copyNewValueForRedo 2 - com.nwoods.jgo.JGoDrawable.copyNewValueForRedo 3 - com.nwoods.jgo.JGoPort.copyNewValueForRedo 4 - com.nwoods.jgo.JGoDocument.copyNewValueForRedo 5 - com.nwoods.jgo.JGoDocumentChangedEdit.<init> 6 - com.nwoods.jgo.JGoUndoManager.documentChanged 7 - com.nwoods.jgo.JGoDocument.-�� 8 - com.nwoods.jgo.JGoDocument.fireUpdate 9 - com.nwoods.jgo.JGoObject.update 10 - com.nwoods.jgo.JGoObject.setBoundingRect 11 - com.nwoods.jgo.JGoArea.geometryChange 12 - com.nwoods.jgo.examples.BasicNode.geometryChange(BasicNode.java:169) 13 - com.nwoods.jgo.JGoObject.setBoundingRect 14 - com.nwoods.jgo.JGoArea.setBoundingRect 15 - com.nwoods.jgo.JGoView.moveSelection 16 - com.nwoods.jgo.JGoGridView.moveSelection 17 - com.nwoods.jgo.JGoView.doMoveSelection 18 - com.nwoods.jgo.JGoView.doMouseMove 19 - com.nwoods.jgo.JGoView.onDragOver 20 - com.nwoods.jgo.JGoView$JGoViewCanvas.dragOver 21 - java.awt.dnd.DropTarget.dragOver(DropTarget.java:351) 22 - sun.awt.dnd.SunDropTargetContextPeer.processMotionMessage(SunDropTargetContextPeer.java:484) 23 - sun.awt.dnd.SunDropTargetContextPeer.access$600(SunDropTargetContextPeer.java:52) 24 - sun.awt.dnd.SunDropTargetContextPeer$EventDispatcher.dispatchMotionEvent(SunDropTargetContextPeer.java:781) 25 - sun.awt.dnd.SunDropTargetContextPeer$EventDispatcher.dispatchEvent(SunDropTargetContextPeer.java:738) 26 - sun.awt.dnd.SunDropTargetEvent.dispatch(SunDropTargetEvent.java:29) 27 - java.awt.Component.dispatchEventImpl(Component.java:3384) 28 - java.awt.Container.dispatchEventImpl(Container.java:1437) 29 - java.awt.Component.dispatchEvent(Component.java:3367) 30 - java.awt.LightweightDispatcher.retargetMouseEvent(Container.java:3214) 31 - java.awt.LightweightDispatcher.processDropTargetEvent(Container.java:3000) 32 - java.awt.LightweightDispatcher.dispatchEvent(Container.java:2854) 33 - java.awt.Container.dispatchEventImpl(Container.java:1423) 34 - java.awt.Window.dispatchEventImpl(Window.java:1566) 35 - java.awt.Component.dispatchEvent(Component.java:3367) 36 - java.awt.Even
11-06-2004

EVALUATION tQueue.dispatchEvent(EventQueue.java:445) 37 - java.awt.EventDispatchThread.pumpOneEventForHierarchy(EventDispatchThread.java:190) 38 - java.awt.EventDispatchThread.pumpEventsForHierarchy(EventDispatchThread.java:144) 39 - java.awt.EventDispatchThread.pumpEvents(EventDispatchThread.java:138) 40 - java.awt.EventDispatchThread.pumpEvents(EventDispatchThread.java:130) 41 - java.awt.EventDispatchThread.run(EventDispatchThread.java:98) "AWT-Shutdown" prio=5 tid=0x007C3C18 nid=0x4e4 waiting on monitor [2b5f000..2b5fd58] Thread state: _thread_blocked Thread: 0x007C3C18 [0x4e4] State: _at_safepoint pc: 0x00000000 1 - java.lang.Object.wait(Native Method) 2 - java.lang.Object.wait(Object.java:426) 3 - sun.awt.AWTAutoShutdown.run(AWTAutoShutdown.java:259) 4 - java.lang.Thread.run(Thread.java:536) "AWT-Windows" daemon prio=7 tid=0x00790058 nid=0x45d runnable [e2bf000..e2bfd58] Thread state: _thread_in_native Thread: 0x00790058 [0x45d] State: _at_safepoint pc: 0x00000000 1 - sun.awt.windows.WToolkitThreadBlockedHandler.startSecondaryEventLoop(Native Method) 2 - sun.awt.windows.WToolkitThreadBlockedHandler.enter(WDataTransferer.java:296) 3 - sun.awt.dnd.SunDropTargetContextPeer.handleMotionMessage(SunDropTargetContextPeer.java:432) C frame (sp=0xe2bf5f0, fp=0xe2bf620, pc=0xa5020a~Stub::call_stub) BufferBlob used for StubRoutines (1) 4 - sun.awt.windows.WToolkit.eventLoop(Native Method) 5 - sun.awt.windows.WToolkit.run(WToolkit.java:240) 6 - java.lang.Thread.run(Thread.java:536) "Signal Dispatcher" daemon prio=10 tid=0x00776878 nid=0x3c2 runnable [0..0] Thread state: _thread_blocked Thread: 0x00776878 [0x3c2] State: _at_safepoint pc: 0x00000000 "Finalizer" daemon prio=9 tid=0x0076EA48 nid=0x754 waiting on monitor [dd9f000..dd9fd58] Thread state: _thread_blocked Thread: 0x0076EA48 [0x754] State: _at_safepoint pc: 0x00000000 1 - java.lang.Object.wait(Native Method) 2 - java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:111) 3 - java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:127) 4 - java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:159) "Reference Handler" daemon prio=10 tid=0x0076D3E8 nid=0x557 waiting on monitor [dd5f000..dd5fd58] Thread state: _thread_blocked Thread: 0x0076D3E8 [0x557] State: _at_safepoint pc: 0x00000000 1 - java.lang.Object.wait(Native Method) 2 - java.lang.Object.wait(Object.java:426) 3 - java.lang.ref.Reference$ReferenceHandler.run(Reference.java:113) "VM Thread" prio=5 tid=0x0076B168 nid=0x715 runnable "VM Periodic Task Thread" prio=10 tid=0x00775048 nid=0x681 waiting on monitor "Suspend Checker Thread" prio=10 tid=0x00776CB8 nid=0x19a runnable maybe that will help someone decide if those native threads should be running while we are collecting garbage. Remember that threads in native code aren't stopped unless they try to access the Java heap. I have no idea whether the culprit thread was actually running when I got these traces: it might be that pss() had to wait for it to stop hogging the CPU before it could examine the thread stacks. ###@###.### 2002-01-07 Dave Stoutamire came by and suggested using -XX:-UseThreadPriorities, which turns off all attempts to use (or abuse) native thread priorities. That makes it work much better. He couldn't tell me if it was thread priorities adjusted by the JVM or by the application. But it gives us someplace to look. (And it means it's *not* a GC problem.) It would be good to get an AWT engineer on this. ###@###.### 2002-01-07 Since most of the stack traces above involve Drag&Drop, I'll reassign to that subcategory. ###@###.### 2002-01-07 Name: dsR10078 Date: 02/21/2002 I reproduced the bug with JDK1.4.1-b01 on WinNT 4.0 2xPII-266 using the attached Demo1 application. Then i run Demo1 with "-XX:+PrintGC -XX:+PrintGCTimeStamps" and every time when a noticeable freeze during drag occurs GC reports a full collection. The time taken by full collections increases as the heap size grows. Here are the typical excerpts from the output: ... 31.1829: [Full GC 3040K->3040K(3608K), 0.3856353 secs] ... 42.198: [Full GC 5138K->2843K(5756K), 0.4407300 secs] ... 57.0031: [Full GC 5119K->4987K(5756K), 0.5051938 secs] ... 172.653: [Full GC 8398K->4031K(9148K), 0.6090240 secs] ... 187.523: [Full GC 8530K->8530K(9276K), 0.6176770 secs] ... 205.529: [Full GC 14398K->7397K(15500K), 0.7767437 secs] ... 226.088: [Full GC 14452K->14074K(15628K), 1.0384652 secs] ... 257.462: [Full GC 23990K->11192K(25636K), 1.3112636 secs] ... 296.885: [Full GC 24092K->24092K(25764K), 1.2518174 secs] ... 353.984: [Full GC 41031K->20906K(43796K), 1.9113233 secs] I also profiled the event dispatch thread to measure times taken to process each AWT event. During the drag only three event types are posted to the AWT event queue: 1.SunDropTargetEvents used to dispatch drag notifications to the DropTargetListeners. 2.PeerEvents used to dispatch drag notifications to the DragSourceListeners. 3.InvocationEvents used to repaint the objects being dragged. For each AWT event i printed the time passed after the previous event was processed and the time taken to process this event. The time taken to process one event typically doesn't exceed 50ms. Each visible freeze during drag manifests as a reported time delay typically more than 400ms during processing of an AWT event or between two AWT events. Here are the lines in the debug output that correspond to the drag freezes: EventDispatchThread: before processing sun.awt.PeerEvent : 0ms EventDispatchThread: processed : 0ms 236.343: [GC 5395K->5005K(5644K), 0.0102408 secs] 236.354: [Full GC 5005K->4959K(5644K), 0.4692658 secs] EventDispatchThread: before processing sun.awt.PeerEvent : 485ms EventDispatchThread: before processing java.awt.event.InvocationEvent : 0ms EventDispatchThread: processed : 78ms EventDispatchThread: before processing sun.awt.dnd.SunDropTargetEvent : 0ms 361.052: [GC 8909K->8424K(9100K), 0.0100221 secs] 361.063: [Full GC 8424K->4087K(9100K), 0.6011629 secs] EventDispatchThread: processed : 625ms EventDispatchThread: before processing java.awt.event.InvocationEvent : 0ms EventDispatchThread: processed : 62ms EventDispatchThread: before processing sun.awt.PeerEvent : 0ms EventDispatchThread: processed : 15ms EventDispatchThread: before processing java.awt.event.InvocationEvent : 0ms 466.366: [GC 8960K->8463K(9228K), 0.0104575 secs] 466.378: [Full GC 8463K->8463K(9228K), 0.5999580 secs] EventDispatchThread: processed : 672ms EventDispatchThread: before processing sun.awt.dnd.SunDropTargetEvent : 0ms EventDispatchThread: processed : 16ms EventDispatchThread: before processing java.awt.event.InvocationEvent : 0ms EventDispatchThread: processed : 62ms 583.264: [GC 15052K->14228K(15388K), 0.0142552 secs] 583.279: [Full GC 14228K->7446K(15388K), 0.7545804 secs] EventDispatchThread: before processing sun.awt.PeerEvent : 782ms EventDispatchThread: processed : 0ms EventDispatchThread: before processing sun.awt.PeerEvent : 0ms EventDispatchThread: processed : 15ms The debug output indicates that the full scavenge is the only cause of the slow down in AWT events processing that manifests as a drag freeze. I used memory profiler to find out why full collections are so frequent during the drag. The java heap is frequently exhausted, the dominating memory consumers are: * float arrays allocated at com.nwoods.jgo.JGoView.paintView(); * Rectangles allocated at com.nwoods.jgo.JGoView.moveSelection(); * com.nwoods.jgo.JGoDocumentChangedEdit instances allocated at com.nwoods.jgo.JGoView.moveSelection(). The suspicius point is that com.nwoods.jgo.JGoDocumentChangedEdit instances created by JGoUndoManager on each drag over notification are never collected. When running javatip114 (from http://www.javaworld.com/javaworld/javatips/javatip114/javatip114.zip) with JDK1.4.1-b01 the problem manifests only on Win9X. I was unable to reproduce drag freezes on WinNT or Win2000. Debug output indicates that the performance regression from 1.3.1 to 1.4.1 is mostly caused by the painting code in DropTargetListener.dragOver(). Attached is a modified version of CTree.java which includes debug output and logs obtained by running the modified CTree on Win98 SE with 1.4.1-b01 and 1.3.1-b24 respectively. Note that there is no noticeable difference in delays between the sequential calls to DropTargetListener.dragOver(), but for some reason 1.4.1 sometimes takes much more time to execute the painting code in dragOver(). ###@###.### 2002-02-21 ====================================================================== Name: dsR10078 Date: 02/28/2002 I reproduced the same drag freezes on WinNT with 1.3.1-b24. Using -XX:+PrintGC option i verified that each freeze correspond to a full garbage collection. The only difference is that freezes happen much more frequently on 1.4 than on 1.3.1. In my environment GC performs a full collection every 10-15 seconds during drag with 1.4. With 1.3.1 the first full collection during the drag starts usually happens after 20 seconds, the next 30-35 seconds later, the third 50-60 seconds later. Then i run the JGo with -Xms64m to investigate the influence of the initial Java heap size. 1-2 second drag freezes do not manifest, but there are still some noticeable delays and -XX:+PrintGC indicates that they happen when GC performs regular collections. With -Xincgc even these minor delays disappear, but with this option the ArrayIndexOutOfBoundsException listed above readily manifests and interrupts the drag. In my environment running JGo with -XX:-UseThreadPriorities doesn't have any effect, the drag freezes are still reproducible and still coincide with full collections. Further profiling of JGo application shows that most of Rectangle instances allocated during the drag are also created by JGoUndoManager on each drag over notification and stored and stored in a Vector so that they cannot be collected. The possible reason why the full collections on 1.4 happen more frequently than on 1.3.1 resides in the most prominent memory consumer: float arrays allocated inside com.nwoods.jgo.JGoView.paintView(). These arrays are referenced from latinAdvances and kanaAdvances of sun.awt.font.AdvanceCache. Allocation stack traces are similar to the following: sun.awt.font.NativeFontWrapper.getGlyphInfo(NativeFontWrapper.java:Native method) sun.awt.font.StandardGlyphVector.getGlyphInfo(StandardGlyphVector.java:1041) sun.awt.font.AdvanceCache.initLatinAdvances(AdvanceCache.java:172) sun.awt.font.AdvanceCache.<init>(AdvanceCache.java:206) sun.awt.font.AdvanceCache.get(AdvanceCache.java:162) java.awt.font.TextLayout$OptInfo.getAdvance(TextLayout.java:248) java.awt.font.TextLayout$OptInfo.getLogicalBounds(TextLayout.java:261) sun.awt.font.Decoration$DecorationImpl.drawTextAndEmbellishments(Decoration.java:243) sun.awt.font.Decoration$DecorationImpl.drawTextAndDecorations(Decoration.java:273) java.awt.font.TextLayout$OptInfo.draw(TextLayout.java:298) java.awt.font.TextLayout.draw(TextLayout.java:2660) sun.java2d.SunGraphics2D.drawString(SunGraphics2D.java:2618) com.nwoods.jgo.JGoText.paint(com/nwoods/jgo/JGoText:Unknown line) [...] To summarize the results: 1.Drag freezes reproducible with JGo application: * reproducible with 1.3.1 and 1.4 on Win98, WinNT and Win2000; * caused by GC full collections. The full scavenges are caused by the Java heap exhaustion. There are two main reasons why Java heap gets exhaused so frequently during the drag: * float arrays allocated in 2D for painting; * Rectangle and JGoDocumentChangedEdit instances allocated by JGoUndoManager on each drag over notification. 2.Drag freezes reproducible with javatip114: * reproducible with 1.4 on Win98, not reproducible with 1.3.1, not reproducible on WinNT and Win2000; * caused by occasional slow execution of painting code during the drag. I suggest to reassign the bug to the 2D team, so that they can investigate if something can be done to reduce memory footprint caused by the float arrays referenced from sun.awt.font.AdvanceCache. This would make full GC scavenges not so frequent and thus drag freezes not so visible. Additionally the occasional slowdown in the execution of painting code on Win98 should be investigated. ###@###.### 2002-02-28 ====================================================================== After speaking with ###@###.###, reassigning to 2D. We'll continue to track this bug in case there is any assistance we can provide. ###@###.### 2002-03-04 I don't believe the pauses have anything to do with garbage collection or 2D. At least, not anymore. In 1.4.1 b10 2D fixed bug 4525841: RAS: (2D) should attempt to reduce or eliminate use of finalizers which greatly reduced the number of FullGCs happening because of Java2D. With this fix the JGo application doesn't produce any FullGC, and partial gc's are under 0.008 seconds (P4 1.5Ghz), but the pauses are still there. Another observation: the bug doesn't manifest on Solaris/Linux at all. With ddraw disabled on Windows, the rendering code being used is the same as on Unix platforms (the only difference being the way the pixels get delivered to the screen), yet on windows the pauses are still present. The pauses affect not only rendering, but the whole app, which becomes frosen (it doesn't respond), which leads to the conlclusion that it could be some kind of event-related issue. When I tried to debug the app in MSVC, and stopped the app during one of the pauses, all methods on the thread stacks were awt/dnd-related, none of the rendering code was present. So I'm inclined to believe that this is more of a dnd issue rather than 2D. ###@###.### 2002-05-08 Unfortunately Bugtraq cannot store very long evaluations like this one. My part is attached under the name 'eval2.txt' ###@###.### 2002-05-13 The DnD part of the problem is described in bug 4669873: DnD on jdk1.4.x for Windows freezes app for couple of seconds. Since the remaining pauses in the JGo app are due to the applicaiton leaking resources and forcing FullGCs (see Comments for more info), I'm closing this bug as not a bug. ###@###.### 2002-06-04 Note: 4669873 has been fixed in 1.4.1. ###@###.### 2002-07-23
04-06-2002