Bug 333286 - [performance] Combo creation is sometimes very slow on gtk
Summary: [performance] Combo creation is sometimes very slow on gtk
Status: RESOLVED FIXED
Alias: None
Product: Platform
Classification: Eclipse Project
Component: SWT (show other bugs)
Version: 3.5.2   Edit
Hardware: PC Linux
: P3 major with 9 votes (vote)
Target Milestone: 3.7 M6   Edit
Assignee: Silenio Quarti CLA
QA Contact:
URL:
Whiteboard:
Keywords:
Depends on:
Blocks:
 
Reported: 2010-12-28 20:04 EST by Sergey Prigogin CLA
Modified: 2011-03-11 11:01 EST (History)
5 users (show)

See Also:


Attachments
Proposed fix (2.91 KB, patch)
2011-02-08 15:38 EST, Sergey Prigogin CLA
no flags Details | Diff
Alternative fix that uses HashSet (2.28 KB, patch)
2011-02-10 13:31 EST, Sergey Prigogin CLA
no flags Details | Diff
Alternative fix that uses HashMap (2.29 KB, patch)
2011-02-10 16:56 EST, Sergey Prigogin CLA
no flags Details | Diff
Alternative fix that uses Hashtable (2.31 KB, patch)
2011-02-23 14:24 EST, Sergey Prigogin CLA
no flags Details | Diff

Note You need to log in before you can comment on or make changes to this bug.
Description Sergey Prigogin CLA 2010-12-28 20:04:23 EST
Opening of Find and other dialogs containing Combo controls on GTK sometimes takes up to 10 seconds. A typical call stack looks like:

"main" prio=10 tid=0x09c78c00 nid=0x3470 runnable [0xffc7c000]
   java.lang.Thread.State: RUNNABLE
	at org.eclipse.swt.internal.gtk.OS._g_list_data(Native Method)
	at org.eclipse.swt.internal.gtk.OS.g_list_data(OS.java:2390)
	at org.eclipse.swt.widgets.Combo.findPopupHandle(Combo.java:584)
	at org.eclipse.swt.widgets.Combo.createHandle(Combo.java:436)
	at org.eclipse.swt.widgets.Widget.createWidget(Widget.java:412)
	at org.eclipse.swt.widgets.Control.createWidget(Control.java:543)
	at org.eclipse.swt.widgets.Scrollable.createWidget(Scrollable.java:152)
	at org.eclipse.swt.widgets.Control.<init>(Control.java:97)
	at org.eclipse.swt.widgets.Scrollable.<init>(Scrollable.java:74)
	at org.eclipse.swt.widgets.Composite.<init>(Composite.java:95)
	at org.eclipse.swt.widgets.Combo.<init>(Combo.java:113)
	at org.eclipse.ui.texteditor.FindReplaceDialog.createInputPanel(FindReplaceDialog.java:589)
	at org.eclipse.ui.texteditor.FindReplaceDialog.createContents(FindReplaceDialog.java:397)
	at org.eclipse.jface.window.Window.create(Window.java:431)
	at org.eclipse.jface.dialogs.Dialog.create(Dialog.java:1089)
	at org.eclipse.ui.texteditor.FindReplaceDialog.create(FindReplaceDialog.java:269)
	at org.eclipse.ui.texteditor.FindReplaceAction$FindReplaceDialogStub.<init>(FindReplaceAction.java:100)
	at org.eclipse.ui.texteditor.FindReplaceAction$FindReplaceDialogStub.<init>(FindReplaceAction.java:85)
	at org.eclipse.ui.texteditor.FindReplaceAction.run(FindReplaceAction.java:353)
	at org.eclipse.jface.action.Action.runWithEvent(Action.java:498)
	at org.eclipse.jface.commands.ActionHandler.execute(ActionHandler.java:119)
	at org.eclipse.core.commands.Command.executeWithChecks(Command.java:476)
	at org.eclipse.core.commands.ParameterizedCommand.executeWithChecks(ParameterizedCommand.java:508)
	at org.eclipse.ui.internal.handlers.HandlerService.executeCommand(HandlerService.java:169)
	at org.eclipse.ui.internal.keys.WorkbenchKeyboard.executeCommand(WorkbenchKeyboard.java:468)
	at org.eclipse.ui.internal.keys.WorkbenchKeyboard.press(WorkbenchKeyboard.java:786)
	at org.eclipse.ui.internal.keys.WorkbenchKeyboard.processKeyEvent(WorkbenchKeyboard.java:885)
	at org.eclipse.ui.internal.keys.WorkbenchKeyboard.filterKeySequenceBindings(WorkbenchKeyboard.java:567)
	at org.eclipse.ui.internal.keys.WorkbenchKeyboard.access$3(WorkbenchKeyboard.java:508)
	at org.eclipse.ui.internal.keys.WorkbenchKeyboard$KeyDownFilter.handleEvent(WorkbenchKeyboard.java:123)
	at org.eclipse.swt.widgets.EventTable.sendEvent(EventTable.java:84)
	at org.eclipse.swt.widgets.Display.filterEvent(Display.java:1524)
	at org.eclipse.swt.widgets.Widget.sendEvent(Widget.java:1257)
	at org.eclipse.swt.widgets.Widget.sendEvent(Widget.java:1282)
	at org.eclipse.swt.widgets.Widget.sendEvent(Widget.java:1267)
	at org.eclipse.swt.widgets.Widget.sendKeyEvent(Widget.java:1294)
	at org.eclipse.swt.widgets.Widget.gtk_key_press_event(Widget.java:730)
	at org.eclipse.swt.widgets.Control.gtk_key_press_event(Control.java:2841)
	at org.eclipse.swt.widgets.Composite.gtk_key_press_event(Composite.java:734)
	at org.eclipse.swt.widgets.Widget.windowProc(Widget.java:1743)
	at org.eclipse.swt.widgets.Control.windowProc(Control.java:4796)
	at org.eclipse.swt.widgets.Display.windowProc(Display.java:4360)
	at (C/C++) [Unknown frame (generated stub/JIT)]([Unknown source])
	at org.eclipse.swt.internal.gtk.OS._gtk_main_do_event(Native Method)
	at org.eclipse.swt.internal.gtk.OS.gtk_main_do_event(OS.java:8168)
	at org.eclipse.swt.widgets.Display.eventProc(Display.java:1238)
	at (C/C++) [Unknown frame (generated stub/JIT)]([Unknown source])
	at org.eclipse.swt.internal.gtk.OS._g_main_context_iteration(Native Method)
	at org.eclipse.swt.internal.gtk.OS.g_main_context_iteration(OS.java:2229)
	at org.eclipse.swt.widgets.Display.readAndDispatch(Display.java:3159)
	at org.eclipse.ui.internal.Workbench.runEventLoop(Workbench.java:2644)
	at org.eclipse.ui.internal.Workbench.runUI(Workbench.java:2606)
	at org.eclipse.ui.internal.Workbench.access$4(Workbench.java:2440)
	at org.eclipse.ui.internal.Workbench$7.run(Workbench.java:683)
	at org.eclipse.core.databinding.observable.Realm.runWithDefault(Realm.java:332)
	at org.eclipse.ui.internal.Workbench.createAndRunWorkbench(Workbench.java:676)
	at org.eclipse.ui.PlatformUI.createAndRunWorkbench(PlatformUI.java:149)
	at org.eclipse.ui.internal.ide.application.IDEApplication.start(IDEApplication.java:115)
	at org.eclipse.equinox.internal.app.EclipseAppHandle.run(EclipseAppHandle.java:196)
	at org.eclipse.core.runtime.internal.adaptor.EclipseAppLauncher.runApplication(EclipseAppLauncher.java:110)
	at org.eclipse.core.runtime.internal.adaptor.EclipseAppLauncher.start(EclipseAppLauncher.java:79)
	at org.eclipse.core.runtime.adaptor.EclipseStarter.run(EclipseStarter.java:369)
	at org.eclipse.core.runtime.adaptor.EclipseStarter.run(EclipseStarter.java:179)
	at (C/C++) [Unknown frame (generated stub/JIT)]([Unknown source])
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:616)
	at org.eclipse.equinox.launcher.Main.invokeFramework(Main.java:619)
	at org.eclipse.equinox.launcher.Main.basicRun(Main.java:574)
	at org.eclipse.equinox.launcher.Main.run(Main.java:1407)

The stacks seems to indicate that the Combo.findPopupHandle can be very slow.
Comment 1 Felipe Heidrich CLA 2011-01-04 11:39:30 EST
The method to find the popup handle is O^2. But it should not be a problem because the size of the list should be very small (the list returned by gtk_window_list_toplevels()). 

 
Would you be able to add System.currentTimeMillis() before and after the call to Combo.findPopupHandle in Combo.createHandle and see how much time it is taking ? (the problem doesn't happen to me or I would test it myself).

(you will need to checkout SWT from HEAD and self-host eclipse, see http://eclipse.org/swt/cvs.php)

I don't think the time is there.
Comment 2 Sergey Prigogin CLA 2011-01-06 18:36:30 EST
Here is a call stack with the native part:
    at (C/C++) __kernel_vsyscall( ())
    at (C/C++) Monitor::ILock(Thread*)( (/usr/local/buildtools/java/jdk6-google-v3/bin/../jre/lib/i386/client/libjvm.so))
    at (C/C++) Monitor::lock_without_safepoint_check(Thread*)( (/usr/local/buildtools/java/jdk6-google-v3/bin/../jre/lib/i386/client/libjvm.so))
    at (C/C++) Monitor::lock_without_safepoint_check()( (/usr/local/buildtools/java/jdk6-google-v3/bin/../jre/lib/i386/client/libjvm.so))
    at (C/C++) SafepointSynchronize::block(JavaThread*)( (/usr/local/buildtools/java/jdk6-google-v3/bin/../jre/lib/i386/client/libjvm.so))
    at (C/C++) JavaThread::check_safepoint_and_suspend_for_native_trans(JavaThread*)( (/usr/local/buildtools/java/jdk6-google-v3/bin/../jre/lib/i386/client/libjvm.so))
    at (C/C++) JavaThread::check_special_condition_for_native_trans(JavaThread*)( (/usr/local/buildtools/java/jdk6-google-v3/bin/../jre/lib/i386/client/libjvm.so))
    at org.eclipse.swt.internal.gtk.OS._g_list_next(Native Method)
    at org.eclipse.swt.internal.gtk.OS.g_list_next(OS.java:2442)
    at org.eclipse.swt.widgets.Combo.findPopupHandle(Combo.java:589)
    at org.eclipse.swt.widgets.Combo.createHandle(Combo.java:436)
    at org.eclipse.swt.widgets.Widget.createWidget(Widget.java:412)
    at org.eclipse.swt.widgets.Control.createWidget(Control.java:543)
    at org.eclipse.swt.widgets.Scrollable.createWidget(Scrollable.java:152)
    at org.eclipse.swt.widgets.Control.<init>(Control.java:97)
    at org.eclipse.swt.widgets.Scrollable.<init>(Scrollable.java:74)
    at org.eclipse.swt.widgets.Composite.<init>(Composite.java:95)
    at org.eclipse.swt.widgets.Combo.<init>(Combo.java:113)
    at org.eclipse.ui.texteditor.FindReplaceDialog.createInputPanel(FindReplaceDialog.java:589)
    at org.eclipse.ui.texteditor.FindReplaceDialog.createContents(FindReplaceDialog.java:397)
    at org.eclipse.jface.window.Window.create(Window.java:431)

I added instrumentation to Combo.findPopupHandle, but wasn't able to reproduce the problem with instrumented code. In fact, the problem is quite hard to reproduce in 3.6.1. When the Find dialog is fast, the number of inner loop iterations in Combo.findPopupHandle is in 1000-2000 range and the time in the method doesn't exceed 1 millisecond.

The above stack shows that JVM delays exits from some (or all?) of the JNI calls made by OS.g_list_data due to safepoints. Safepoints should normally be used to run GC that was previously delayed due to an in-progress JNI call. This was observed in Eclipse that was showing plenty of available memory, and it remains a mystery what could cause those safepoints to trigger.

Another instance of Eclipse on the same machine would behave just fine. The slowness goes away after an Eclipse restart.
Comment 3 Sergey Prigogin CLA 2011-01-06 22:23:12 EST
Somebody explained to me that safepoints are also used for blocking all threads to print their stack traces with a SIGQUIT.
Comment 4 Felipe Heidrich CLA 2011-01-07 11:41:53 EST
What VM are you using ?

Does the problem happen with a SUN or a IBM VM ?
Comment 5 Sergey Prigogin CLA 2011-01-07 13:00:02 EST
(In reply to comment #4)
> What VM are you using ?

OpenJDK VM built from source.

> Does the problem happen with a SUN or a IBM VM ?

Good question, but I don't know the answer to it.
Comment 6 Sergey Prigogin CLA 2011-01-18 03:05:37 EST
The problem is reproducible by invoking the Find dialog a large number of times. To do that modify FindReplaceAction.run() method to add a loop to it:

	public void run() {
		if (fTarget == null)
			return;

		long t = 0;
		for (int i = 1; i <= 10000; i++) {
			final FindReplaceDialog dialog;
			final boolean isEditable;

			if(fShell == null) {
				if (fgFindReplaceDialogStub != null) {
					Shell shell= fWorkbenchPart.getSite().getShell();
					fgFindReplaceDialogStub.checkShell(shell);
				}
				if (fgFindReplaceDialogStub == null)
					fgFindReplaceDialogStub= new FindReplaceDialogStub(fWorkbenchPart.getSite());
	
				if (fWorkbenchPart instanceof ITextEditorExtension2)
					isEditable= ((ITextEditorExtension2) fWorkbenchPart).isEditorInputModifiable();
				else
					isEditable= fTarget.isEditable();
	
				dialog= fgFindReplaceDialogStub.getDialog();
	
			} else {
				if (fgFindReplaceDialogStubShell != null) {
					fgFindReplaceDialogStubShell.checkShell(fShell);
				}
				if (fgFindReplaceDialogStubShell == null)
					fgFindReplaceDialogStubShell= new FindReplaceDialogStub(fShell);
	
				isEditable= fTarget.isEditable();
				dialog= fgFindReplaceDialogStubShell.getDialog();
			}
	
			dialog.updateTarget(fTarget, isEditable, true);
			long t0 = System.currentTimeMillis();
			dialog.open();
			t += System.currentTimeMillis() - t0;
			if (i % 100 == 0) {
				System.out.println(i + "\t" + (t / 100));
				t = 0;
			}
			try {
				Thread.sleep(10);
			} catch (InterruptedException e) {
			}
			dialog.close();
		}
	}

Run Eclipse with the modified code and hit Ctrl+F. Here is the timing I got on the Console:
100	44
200	69
300	94
400	126
500	153
600	184
700	220
800	248
900	276
1000	305
1100	341
1200	372
1300	410
1400	451
1500	500
1600	487
1700	517
1800	548
1900	578
2000	615
2100	635
2200	667
2300	703
2400	733
2500	775
2600	815
2700	858
2800	909
2900	969
3000	1040
3100	982
3200	970
3300	1006
3400	1027
3500	1055
3600	1088
3700	1121
3800	1151
3900	1181
4000	1213
4100	1249
4200	1277
4300	1310
4400	1342
4500	1370
4600	1410
4700	1442
4800	1484
4900	1514
5000	1553
5100	1593
5200	1629
5300	1667
5400	1715
5500	1751
5600	1798
5700	1857
5800	1911
5900	1976
6000	2052
6100	2075
6200	1870
6300	1904
6400	1935
6500	1964
6600	2000
6700	2027
6800	2057
6900	2087
7000	2122
7100	2159
7200	2189
7300	2221
7400	2252
7500	2288
7600	2322
7700	2352
7800	2377
7900	2414
8000	2453
8100	2483
8200	2512
8300	2548
8400	2577
8500	2610
8600	2645
8700	2671
8800	2710
...

The dialog takes longer and longer to open with each subsequent invocation. It looks like there is a resource leak somewhere.
Comment 7 Sergey Prigogin CLA 2011-01-22 20:13:00 EST
It looks like adding a loop to FindReplaceAction.run() did not reproduce the original problem. The slowness accumulated toward the end of the loop disappears in the beginning of the second invocation. Time spent in Combo.findPopupHandle() doesn't grow and neither does the number of iterations inside it:

100	in open: 44, in findPopupHandle: 0.339, numOuterLoops: 93, numInnerLoops:2207
200	in open: 76, in findPopupHandle: 0.369, numOuterLoops: 93, numInnerLoops:2207
300	in open: 104, in findPopupHandle: 0.379, numOuterLoops: 93, numInnerLoops:2207
400	in open: 132, in findPopupHandle: 0.372, numOuterLoops: 93, numInnerLoops:2207
500	in open: 164, in findPopupHandle: 0.378, numOuterLoops: 93, numInnerLoops:2207
600	in open: 197, in findPopupHandle: 0.369, numOuterLoops: 93, numInnerLoops:2207
700	in open: 268, in findPopupHandle: 0.358, numOuterLoops: 93, numInnerLoops:2207
800	in open: 266, in findPopupHandle: 0.359, numOuterLoops: 93, numInnerLoops:2207
900	in open: 286, in findPopupHandle: 0.348, numOuterLoops: 93, numInnerLoops:2207
1000	in open: 322, in findPopupHandle: 0.310, numOuterLoops: 93, numInnerLoops:2207
100	in open: 59, in findPopupHandle: 0.315, numOuterLoops: 93, numInnerLoops:2207
200	in open: 82, in findPopupHandle: 0.366, numOuterLoops: 93, numInnerLoops:2207
300	in open: 112, in findPopupHandle: 0.360, numOuterLoops: 93, numInnerLoops:2207
400	in open: 143, in findPopupHandle: 0.373, numOuterLoops: 93, numInnerLoops:2207
500	in open: 172, in findPopupHandle: 0.372, numOuterLoops: 93, numInnerLoops:2207
600	in open: 209, in findPopupHandle: 0.376, numOuterLoops: 93, numInnerLoops:2207
700	in open: 243, in findPopupHandle: 0.359, numOuterLoops: 93, numInnerLoops:2207
800	in open: 262, in findPopupHandle: 0.355, numOuterLoops: 93, numInnerLoops:2207
900	in open: 294, in findPopupHandle: 0.331, numOuterLoops: 93, numInnerLoops:2207
1000	in open: 329, in findPopupHandle: 0.294, numOuterLoops: 93, numInnerLoops:2207
Comment 8 Felipe Heidrich CLA 2011-01-27 15:11:08 EST
Sergey, it seems to me that your invetigation shows that the problem is not in Combo.findPopupHandle(), but somewhere else in the code. Agreed ?
Comment 9 Sergey Prigogin CLA 2011-01-27 15:31:22 EST
(In reply to comment #8)
> Sergey, it seems to me that your invetigation shows that the problem is not in
> Combo.findPopupHandle(), but somewhere else in the code. Agreed ?

Unfortunately, the experiment described in comment #6 failed to reproduce the original problem. The only evidence that I currently have points to Combo.findPopupHandle() since it's always at the top of the stack when slowness occurs.
Comment 10 Sergey Prigogin CLA 2011-01-27 15:43:47 EST
Users who report this problem say that it usually manifests itself after using Eclipse for a day or more and gradually becomes worse over time. In order to make progress I would need installable Eclipse with an instrumentation in Combo and FindReplaceDialog. Any suggestions on how to build such Eclipse installation will be appreciated. If you can build such Eclipse for me, that will be appreciated even more.
Comment 11 Felipe Heidrich CLA 2011-01-27 16:10:22 EST
When you self-host eclipse the problem did not happen, correct ?
(self-hosting eclipse definitely the easiest option)

You can try this:
Get SWT from the CVS:
http://www.eclipse.org/swt/cvs.php

Go to the eclipse/plugin folder of the eclipse install you use, find the file containing the words "swt.gtk.linux". For example:
org.eclipse.swt.gtk.linux.x86_3.7.0.v3721.jar
(note: I'm assuming you are on linux-gtk)
Write down v3721

-Change the code you need to change to org.eclipse.swt-

Now select org.eclipse.swt.gtk.linux.x86 and run Export->Deployable plug-ins and fragments, click next
in the Options tab, in the Qualifier replacement fields enter "v3721" (or whatever you have in your install)
Export to whatever place you want

If you did everything right, at this point the fragment you exported and the fragment in eclipse/plugin have exact the same filename.

Close Eclipse

replace the fragment file in eclipse/plugin with the ond you just build (it is a good idea to keep the old one around as a backup)

Start Eclipse

You code should be running now.

Note: if you need to repeat the process, make sure to refresh org.eclipse.swt.gtk.linux.x86 (F5) and delete any temp folder that was left behind from the previous iteration.

Last thing, make sure you are using a 3.7 eclipse build, otherwise you will have to download SWT from the correct branch . 

Good luck
Comment 12 Sergey Prigogin CLA 2011-02-08 15:38:51 EST
Created attachment 188547 [details]
Proposed fix

A log obtained by running instrumented code for several days in an environment that exhibited gradual increase of time to open Find/Replace dialog proved that the slowness is caused by gradual growth of the number of top-level window handles combined with N^2 behavior of the Combo.findPopupHandle algorithm. A fragment from the Eclipse log showing degradation of findPopupHandle speed is included below.

The cause of the growth of the number of the top-level window handles remains unclear, but it's for sure not related to Combo or Find/Replace dialog. Repeated invocations of Find/Replace dialog don't result in any top-level window growth.

The proposed fix replaces N^2 algorithm in findPopupHandle with an N*log(N) one. Please apply the patch to HEAD and 3.6 maintenance branch.

Here is a log obtained using instrumented code:

!ENTRY org.eclipse.ui.workbench.texteditor 1 0 2011-02-04 11:41:23.153
!MESSAGE Time in Combo.findPopupHandle: 0.70382 + 0.504486 msec outer loops: 64 + 65 inner loops: 2079 + 2144

!ENTRY org.eclipse.ui.workbench.texteditor 1 0 2011-02-04 11:41:28.018
!MESSAGE Time in Combo.findPopupHandle: 0.552775 + 0.470339 msec outer loops: 64 + 65 inner loops: 2079 + 2144

!ENTRY org.eclipse.ui.workbench.texteditor 1 0 2011-02-04 11:45:59.427
!MESSAGE Time in Combo.findPopupHandle: 0.586754 + 0.60385 msec outer loops: 73 + 74 inner loops: 2700 + 2774

!ENTRY org.eclipse.ui.workbench.texteditor 1 0 2011-02-04 11:50:17.573
!MESSAGE Time in Combo.findPopupHandle: 0.844459 + 0.856986 msec outer loops: 87 + 88 inner loops: 3827 + 3915

!ENTRY org.eclipse.ui.workbench.texteditor 1 0 2011-02-04 13:45:15.682
!MESSAGE Time in Combo.findPopupHandle: 5.743974 + 4.232741 msec outer loops: 228 + 229 inner loops: 26105 + 26334

!ENTRY org.eclipse.ui.workbench.texteditor 1 0 2011-02-04 13:45:19.109
!MESSAGE Time in Combo.findPopupHandle: 5.674502 + 5.294383 msec outer loops: 228 + 229 inner loops: 26105 + 26334

!ENTRY org.eclipse.ui.workbench.texteditor 1 0 2011-02-04 13:46:11.380
!MESSAGE Time in Combo.findPopupHandle: 5.753875 + 5.092774 msec outer loops: 229 + 230 inner loops: 26334 + 26564

!ENTRY org.eclipse.ui.workbench.texteditor 1 0 2011-02-04 13:46:31.940
!MESSAGE Time in Combo.findPopupHandle: 5.771018 + 4.613617 msec outer loops: 229 + 230 inner loops: 26334 + 26564

!ENTRY org.eclipse.ui.workbench.texteditor 1 0 2011-02-04 18:19:54.273
!MESSAGE Time in Combo.findPopupHandle: 10.531566 + 9.235847 msec outer loops: 258 + 259 inner loops: 33410 + 33669

!ENTRY org.eclipse.ui.workbench.texteditor 1 0 2011-02-07 10:42:20.172
!MESSAGE Time in Combo.findPopupHandle: 1275.310276 + 1270.053502 msec outer loops: 4103 + 4104 inner loops: 8419355 + 8423459

!ENTRY org.eclipse.ui.workbench.texteditor 1 0 2011-02-07 10:42:29.627
!MESSAGE Time in Combo.findPopupHandle: 1275.063752 + 1270.03027 msec outer loops: 4103 + 4104 inner loops: 8419355 + 8423459

!ENTRY org.eclipse.ui.workbench.texteditor 1 0 2011-02-07 10:43:08.034
!MESSAGE Time in Combo.findPopupHandle: 1268.991701 + 1298.227755 msec outer loops: 4105 + 4106 inner loops: 8427564 + 8431670

!ENTRY org.eclipse.ui.workbench.texteditor 1 0 2011-02-07 10:44:55.054
!MESSAGE Time in Combo.findPopupHandle: 1274.64511 + 1289.060228 msec outer loops: 4107 + 4108 inner loops: 8435777 + 8439885

!ENTRY org.eclipse.ui.workbench.texteditor 1 0 2011-02-07 11:28:46.762
!MESSAGE Time in Combo.findPopupHandle: 1302.127604 + 1296.670187 msec outer loops: 4151 + 4152 inner loops: 8617475 + 8621627

!ENTRY org.eclipse.ui.workbench.texteditor 1 0 2011-02-07 11:28:54.740
!MESSAGE Time in Combo.findPopupHandle: 1312.515112 + 1296.240555 msec outer loops: 4151 + 4152 inner loops: 8617475 + 8621627

!ENTRY org.eclipse.ui.workbench.texteditor 1 0 2011-02-07 11:29:09.703
!MESSAGE Time in Combo.findPopupHandle: 1314.381552 + 1297.669609 msec outer loops: 4151 + 4152 inner loops: 8617475 + 8621627

!ENTRY org.eclipse.ui.workbench.texteditor 1 0 2011-02-07 14:13:12.044
!MESSAGE Time in Combo.findPopupHandle: 1406.994394 + 1401.372501 msec outer loops: 4314 + 4315 inner loops: 9307454 + 9311769

!ENTRY org.eclipse.ui.workbench.texteditor 1 0 2011-02-07 14:48:02.886
!MESSAGE Time in Combo.findPopupHandle: 1432.996206 + 1425.342154 msec outer loops: 4349 + 4350 inner loops: 9459074 + 9463424

!ENTRY org.eclipse.ui.workbench.texteditor 1 0 2011-02-07 14:48:09.018
!MESSAGE Time in Combo.findPopupHandle: 1424.90836 + 1422.453288 msec outer loops: 4350 + 4351 inner loops: 9463424 + 9467775

!ENTRY org.eclipse.ui.workbench.texteditor 1 0 2011-02-07 14:48:14.294
!MESSAGE Time in Combo.findPopupHandle: 1428.745218 + 1430.349728 msec outer loops: 4350 + 4351 inner loops: 9463424 + 9467775

!ENTRY org.eclipse.ui.workbench.texteditor 1 0 2011-02-07 14:48:19.635
!MESSAGE Time in Combo.findPopupHandle: 1436.90682 + 1419.971149 msec outer loops: 4350 + 4351 inner loops: 9463424 + 9467775

!ENTRY org.eclipse.ui.workbench.texteditor 1 0 2011-02-07 14:48:24.124
!MESSAGE Time in Combo.findPopupHandle: 1427.418267 + 1421.643446 msec outer loops: 4350 + 4351 inner loops: 9463424 + 9467775

!ENTRY org.eclipse.ui.workbench.texteditor 1 0 2011-02-07 14:48:29.068
!MESSAGE Time in Combo.findPopupHandle: 1427.4939 + 1421.687756 msec outer loops: 4350 + 4351 inner loops: 9463424 + 9467775

!ENTRY org.eclipse.ui.workbench.texteditor 1 0 2011-02-07 14:48:33.793
!MESSAGE Time in Combo.findPopupHandle: 1435.074987 + 1419.199909 msec outer loops: 4350 + 4351 inner loops: 9463424 + 9467775

!ENTRY org.eclipse.ui.workbench.texteditor 1 0 2011-02-07 14:48:38.339
!MESSAGE Time in Combo.findPopupHandle: 1430.646401 + 1425.57739 msec outer loops: 4350 + 4351 inner loops: 9463424 + 9467775

!ENTRY org.eclipse.ui.workbench.texteditor 1 0 2011-02-07 14:48:43.459
!MESSAGE Time in Combo.findPopupHandle: 1439.646882 + 1432.821219 msec outer loops: 4351 + 4352 inner loops: 9467775 + 9472127

!ENTRY org.eclipse.ui.workbench.texteditor 1 0 2011-02-07 14:48:48.007
!MESSAGE Time in Combo.findPopupHandle: 1437.17538 + 1439.110053 msec outer loops: 4351 + 4352 inner loops: 9467775 + 9472127

!ENTRY org.eclipse.ui.workbench.texteditor 1 0 2011-02-07 14:48:52.824
!MESSAGE Time in Combo.findPopupHandle: 1439.246859 + 1421.355412 msec outer loops: 4351 + 4352 inner loops: 9467775 + 9472127

!ENTRY org.eclipse.ui.workbench.texteditor 1 0 2011-02-07 14:48:57.471
!MESSAGE Time in Combo.findPopupHandle: 1430.130983 + 1421.431814 msec outer loops: 4351 + 4352 inner loops: 9467775 + 9472127

!ENTRY org.eclipse.ui.workbench.texteditor 1 0 2011-02-07 14:49:02.054
!MESSAGE Time in Combo.findPopupHandle: 1436.704049 + 1422.822119 msec outer loops: 4351 + 4352 inner loops: 9467775 + 9472127

!ENTRY org.eclipse.ui.workbench.texteditor 1 0 2011-02-07 15:00:44.208
!MESSAGE Time in Combo.findPopupHandle: 1457.002608 + 1457.260379 msec outer loops: 4362 + 4363 inner loops: 9515702 + 9520065

!ENTRY org.eclipse.ui.workbench.texteditor 1 0 2011-02-07 15:00:50.890
!MESSAGE Time in Combo.findPopupHandle: 1444.24202 + 1431.896826 msec outer loops: 4363 + 4364 inner loops: 9520065 + 9524429

!ENTRY org.eclipse.ui.workbench.texteditor 1 0 2011-02-07 15:15:37.390
!MESSAGE Time in Combo.findPopupHandle: 1451.705802 + 1441.41943 msec outer loops: 4377 + 4378 inner loops: 9581252 + 9585630

!ENTRY org.eclipse.ui.workbench.texteditor 1 0 2011-02-07 15:15:42.366
!MESSAGE Time in Combo.findPopupHandle: 1450.281432 + 1443.960753 msec outer loops: 4377 + 4378 inner loops: 9581252 + 9585630

!ENTRY org.eclipse.ui.workbench.texteditor 1 0 2011-02-07 15:15:47.337
!MESSAGE Time in Combo.findPopupHandle: 1457.679146 + 1446.670451 msec outer loops: 4377 + 4378 inner loops: 9581252 + 9585630

!ENTRY org.eclipse.ui.workbench.texteditor 1 0 2011-02-07 15:15:52.596
!MESSAGE Time in Combo.findPopupHandle: 1454.880976 + 1444.530352 msec outer loops: 4378 + 4379 inner loops: 9585630 + 9590009
Comment 13 Felipe Heidrich CLA 2011-02-08 16:04:39 EST
(In reply to comment #12)
> The cause of the growth of the number of the top-level window handles remains
> unclear, 

IMO, the real but is why so many top-level window handles ?

> but it's for sure not related to Combo or Find/Replace dialog.

Maybe, everytime application create a combo, swt creates a gtkcombo, and gtkcombo creates a top-level window to put the popup list. It means that if the application leaks a combo, it also leaks a window.

That would explain the real problem.

Using the Sleak tool (http://www.eclipse.org/swt/tools.php) it should be easy to find out where the leak is.
Comment 14 Sergey Prigogin CLA 2011-02-08 16:40:31 EST
(In reply to comment #13)
> (In reply to comment #12)
> > The cause of the growth of the number of the top-level window handles remains
> > unclear, 
> 
> IMO, the real but is why so many top-level window handles ?

On my machine window handles don't grow. It only happens on some machines, but I don't know what is special about them.

> > but it's for sure not related to Combo or Find/Replace dialog.
> 
> Maybe, everytime application create a combo, swt creates a gtkcombo, and
> gtkcombo creates a top-level window to put the popup list. It means that if the
> application leaks a combo, it also leaks a window.
> 
> That would explain the real problem.

Not so simple. Repeated invocations of Find/Replace dialog don't cause growth of window handles.

> 
> Using the Sleak tool (http://www.eclipse.org/swt/tools.php) it should be easy
> to find out where the leak is.

Thanks for the pointer. I will investigate the source of the window handle growth, but please apply my patch regardless since the N*log(N) is definitely better than N^2.
Comment 15 Felipe Heidrich CLA 2011-02-08 16:57:15 EST
(In reply to comment #14)
> but please apply my patch regardless since the N*log(N) is definitely
> better than N^2.

Definitely, I will assign someone to work on this problem. Note that you are using Array.sort which we can not use. Check Control#sort(int[]) it is a shell sort, it should to the trick.

My problem is that this fix will only "hide" the real problem.
Comment 16 Sergey Prigogin CLA 2011-02-08 17:09:33 EST
(In reply to comment #15)
> (In reply to comment #14)
> > but please apply my patch regardless since the N*log(N) is definitely
> > better than N^2.
> 
> Definitely, I will assign someone to work on this problem. Note that you are
> using Array.sort which we can not use. Check Control#sort(int[]) it is a shell
> sort, it should to the trick.

I trust you to replace Arrays.sort with Control.sort in my patch. Is HashSet allowed in SWT? If so, it can be used instead of sorting. Use of HashSet would require boxing of window handles, but the running time would be linear.

> My problem is that this fix will only "hide" the real problem.

It won't hide the real problem since slowness of Find/Replace didn't provide us with a pointer to the real problem, only indirect evidence. The real problem should and will be investigated using the Sleak tool.
Comment 17 Sergey Prigogin CLA 2011-02-09 18:53:38 EST
(In reply to comment #14)
> Using the Sleak tool (http://www.eclipse.org/swt/tools.php) it should be easy
> to find out where the leak is.

I don't see any any window handles in Sleak, only Colors, Cursors, Fonts, Images and TextLayouts.
Comment 18 Sergey Prigogin CLA 2011-02-10 13:31:14 EST
Created attachment 188711 [details]
Alternative fix that uses HashSet

This patch uses hash lookup that gives findPopupHandle O(N) complexity. According to my measurements, this code is slightly faster even for relatively small numbers of top level windows. The speed advantage will grow with the number of windows.
Comment 19 Sergey Prigogin CLA 2011-02-10 13:33:52 EST
Dear Felipe, Remy and Silenio,

Helios SR2 is quickly approaching. Please apply one of proposed fixes to 3.6 maintenance branch ASAP.
Comment 20 Felipe Heidrich CLA 2011-02-10 15:17:32 EST
Sorry Sergey,  I wasted your time:
"Sleak is a simple tool that monitors SWT graphics resources."

I still think that we have a leak somewhere (whatelse could explain the number of windows going up).

We can't use HashSet for the same reason why we can't use Arrays, please use just java 1.2 (CLDC) in widgets.

At this point to include any code in 3.6.2 is required approval from the PMC, usually only code that has being tested (in HEAD) for some time is included in the maintenance branch. You will also need to explain the benefits and risks for your code to the PMC.
Comment 21 Sergey Prigogin CLA 2011-02-10 16:34:50 EST
(In reply to comment #20)
> I still think that we have a leak somewhere (whatelse could explain the number
> of windows going up).

What is your suggestion for debugging the leak?

> We can't use HashSet for the same reason why we can't use Arrays, please use
> just java 1.2 (CLDC) in widgets.

HashSet.java says:
 * @author  Josh Bloch
 * @author  Neal Gafter
 ...
 * @since   1.2

Notice that I asked you whether HashSet was allowed in comment #16, but haven't received any answer. If HashSet is truly not allowed, what about HashMap? It's already used by several swt classes.

> At this point to include any code in 3.6.2 is required approval from the PMC.

Was it also the case on February 8, when the first patch was submitted?
Comment 22 Sergey Prigogin CLA 2011-02-10 16:56:52 EST
Created attachment 188725 [details]
Alternative fix that uses HashMap
Comment 23 Nitin Dahyabhai CLA 2011-02-10 17:08:36 EST
The JavaDoc you cite comes from a JRE that is a superset of CLDC; its comments refer to when the class became part of a JavaSE implementation.  JavaSE is a superset of CLDC, so it can run code intended for CLDC.  The opposite isn't true.

If you look at the CLDC 1.1 JavaDoc (and I'm not saying 1.1 is the correct version) online, you'll get a better idea of which classes are actually available for you to use in a patch: http://download.oracle.com/javame/config/cldc/ref-impl/cldc1.1/jsr139/java/util/package-summary.html .
Comment 24 Sergey Prigogin CLA 2011-02-10 17:17:13 EST
(In reply to comment #23)

This doesn't answer my question whether HashMap is allowed or not.
Comment 25 Remy Suen CLA 2011-02-10 18:01:41 EST
(In reply to comment #21)> > At this point to include any code in 3.6.2 is required approval from the PMC.
> 
> Was it also the case on February 8, when the first patch was submitted?

Yes. We were already in RC4 phase by then.
http://www.eclipse.org/eclipse/development/plans/freeze_plan_3_6_2.php
Comment 26 Sergey Prigogin CLA 2011-02-22 18:10:24 EST
Is there something that prevents the latest patch to be applied to head? If so, what is it?
Comment 27 Silenio Quarti CLA 2011-02-23 14:04:50 EST
I had a quick look at the patch and saw two problems:

1) HashMap cannot be used since it is not in JDK 1.1. We should use java.util.Hashtable or glib's hash table (g_hash_table_new()).

2) C pointers can not be store in java.lang.Integer when running in 64 bit platforms. The best option to solve this is to use glib's hash table. We could use org.eclipse.swt.internal.LONG (not sure it implements equals/hashCode properly). Or use java.lang.Long all the time.
Comment 28 Sergey Prigogin CLA 2011-02-23 14:24:14 EST
Created attachment 189628 [details]
Alternative fix that uses Hashtable

I hope this fix is acceptable.
Comment 29 Silenio Quarti CLA 2011-02-28 18:45:17 EST
I am cleaning up the patch and I believe it is worth releasing it even though it might hide a more serious bug (leak of top level windows).

Before I release the patch, I wonder if you could do some debugging for me in the environment that exhibited gradual increase of handles. I want to determine if there is a leak and if the leak is in SWT or application code. The fact that there are more than 4000 live top level windows is quite suspicious.

Please could you change findPopupHandle() as follow and run until you get the bad performance? The print outs should give me a better indication of what is happenning.

int /*long*/ findPopupHandle (int /*long*/ oldList) {
	int /*long*/ hdl = 0;
	int /*long*/ currentList = OS.gtk_window_list_toplevels();
	int /*long*/ oldFromList = oldList;
	int /*long*/ newFromList = currentList;
	boolean isFound;
	int widgetCount = 0;
	int topLevelCount = 0;
	int comboCount = 0;
	int shellCount = 0;
	int tooltipCount = 0;
	while (newFromList != 0) {
		int /*long*/ newToplevel = OS.g_list_data(newFromList);
//		if (false) {
//			int /*long*/ name = OS.G_OBJECT_TYPE_NAME(newToplevel);
//			if (name != 0) {
//				byte[] b = new byte[(int)OS.strlen(name)];
//				OS.memmove (b, name, b.length);
//				System.out.println(new String(b));
//			}
//		}
		topLevelCount++;
		if (true) {
			Widget widget = display.getWidget(newToplevel);
			if (widget != null) widgetCount++;
			if (widget instanceof Shell) {
				shellCount++;
//				Shell shell = (Shell)widget;
//				System.out.println(shell.getText());
			}
			if (widget instanceof Combo) {
				comboCount++;
			}
			if (widget instanceof ToolTip) {
				tooltipCount++;
			}
//			if (widget != null) {
//				System.out.println(widget.getClass());
		}
		isFound = false;
		oldFromList = oldList;
		while (oldFromList != 0) {
			int /*long*/ oldToplevel = OS.g_list_data(oldFromList);
			if (newToplevel == oldToplevel) {
				isFound = true;
				break;
			}
			oldFromList = OS.g_list_next(oldFromList);
		}
		if (!isFound) {
			hdl = newToplevel;
			break;
		}
		newFromList = OS.g_list_next(newFromList);
	}
	System.out.println("TOPLEVEL_COUNT=" + topLevelCount + 
			" WIDGET_COUNT=" + widgetCount +
			" COMBO_COUNT=" + comboCount +
			" SHELL_COUNT=" + shellCount +
			" TOOLTIP_COUNT=" + tooltipCount);
	OS.g_list_free(oldList);
	OS.g_list_free(currentList);
	return hdl;
}
Comment 30 Sergey Prigogin CLA 2011-02-28 19:02:30 EST
(In reply to comment #29)
I'm glad that you came to a conclusion to submit the patch.

We did find window handle leaks in two of our in-house plug-ins and confirmed that there was no other leak once the offending plug-ins were fixed. The leaks were caused by missing dispose() calls. This incident shows a need for a tool to detect and debug window handle leaks. I'm going to file a separate feature request to build such a tool.
Comment 31 Sergey Prigogin CLA 2011-02-28 19:18:58 EST
Created bug 338493 for a tool to debug window leaks.
Comment 32 Silenio Quarti CLA 2011-03-01 10:43:00 EST
Good to know you found the leak. I agree a leak tool for widgets would be useful (Sleak only catches graphics right).

It turns out that the new popup handle is always the last handle in the new top level list. So it is possible to write a N algorithm by just looping backwards in that list.

Fixed > 20110301.