eclipse-platform / eclipse.platform.swt

Eclipse SWT
https://www.eclipse.org/swt/
Eclipse Public License 2.0
113 stars 133 forks source link

1.3 second UI freezes in at org.eclipse.swt.widgets.Table.setItemCount(Table.java:3652) #208

Open vogella opened 2 years ago

vogella commented 2 years ago

Environment:

Eclipse SDK Version: 2022-06 (4.25) Build id: I20220612-1800 OS: Linux, v.5.15.0-37-generic, x86_64 / gtk 3.24.33, WebKit 2.36.3 Java vendor: Eclipse Adoptium Java runtime version: 17.0.3+7 Java version: 17.0.3

I see long UI freezes coming from the Git History view with regards to Table.setItemCount. Looks like a lot is happening in this method, like removing all items, etc. Can this be improved?

Method code:

public void setItemCount (int count) {
    checkWidget ();
    count = Math.max (0, count);
    if (count == itemCount) return;
    boolean isVirtual = (style & SWT.VIRTUAL) != 0;
    if (!isVirtual) setRedraw (false);
    remove (count, itemCount - 1);
    int length = Math.max (4, (count + 3) / 4 * 4);
    TableItem [] newItems = new TableItem [length];
    System.arraycopy (items, 0, newItems, 0, itemCount);
    items = newItems;
    if (isVirtual) {
        long iter = OS.g_malloc (GTK.GtkTreeIter_sizeof ());
        if (iter == 0) error (SWT.ERROR_NO_HANDLES);
        for (int i=itemCount; i<count; i++) {
            GTK.gtk_list_store_append (modelHandle, iter);
        }
        OS.g_free (iter);
        itemCount = count;
    } else {
        for (int i=itemCount; i<count; i++) {
            new TableItem (this, SWT.NONE, i, true);
        }
    }
    if (!isVirtual) setRedraw (true);
}

Stack Trace

    at org.eclipse.swt.internal.gtk.GTK.gtk_list_store_clear(Native Method)
    at org.eclipse.swt.widgets.Table.removeAll(Table.java:2812)
    at org.eclipse.swt.widgets.Table.remove(Table.java:2703)
    at org.eclipse.swt.widgets.Table.setItemCount(Table.java:3652)
    at org.eclipse.jface.viewers.TableViewer.doSetItemCount(TableViewer.java:231)
    at org.eclipse.jface.viewers.AbstractTableViewer.internalVirtualRefreshAll(AbstractTableViewer.java:646)
    at org.eclipse.jface.viewers.AbstractTableViewer.internalRefresh(AbstractTableViewer.java:620)
    at org.eclipse.jface.viewers.AbstractTableViewer.internalRefresh(AbstractTableViewer.java:610)
    at org.eclipse.jface.viewers.AbstractTableViewer.lambda$0(AbstractTableViewer.java:572)
    at org.eclipse.jface.viewers.AbstractTableViewer$$Lambda$1107/0x00000008015751b8.run(Unknown Source)
    at org.eclipse.jface.viewers.StructuredViewer.preservingSelection(StructuredViewer.java:1398)
    at org.eclipse.jface.viewers.StructuredViewer.preservingSelection(StructuredViewer.java:1359)
    at org.eclipse.jface.viewers.AbstractTableViewer.inputChanged(AbstractTableViewer.java:572)
    at org.eclipse.jface.viewers.ContentViewer.setInput(ContentViewer.java:282)
    at org.eclipse.jface.viewers.StructuredViewer.setInput(StructuredViewer.java:1632)
    at org.eclipse.egit.ui.internal.history.GitHistoryPage.clearViewers(GitHistoryPage.java:1835)
    at org.eclipse.egit.ui.internal.history.GitHistoryPage.lambda$6(GitHistoryPage.java:2558)
    at org.eclipse.egit.ui.internal.history.GitHistoryPage$$Lambda$1415/0x0000000801739d08.run(Unknown Source)
    at org.eclipse.egit.core.UnitOfWork.execute(UnitOfWork.java:96)
    at org.eclipse.egit.ui.internal.history.GitHistoryPage.initAndStartRevWalk(GitHistoryPage.java:2512)
    at org.eclipse.egit.ui.internal.history.GitHistoryPage.inputSet(GitHistoryPage.java:2132)
    at org.eclipse.egit.ui.internal.history.GitHistoryPage.inputSet(GitHistoryPage.java:1991)
    at org.eclipse.team.ui.history.HistoryPage.setInput(HistoryPage.java:54)
    at org.eclipse.egit.ui.internal.history.GitHistoryPage.setInput(GitHistoryPage.java:1981)
    at org.eclipse.team.internal.ui.history.GenericHistoryView.getPageRec(GenericHistoryView.java:650)
    at org.eclipse.ui.part.PageBookView.partActivated(PageBookView.java:694)
    at org.eclipse.team.internal.ui.history.GenericHistoryView.showHistoryPageFor(GenericHistoryView.java:626)
    at org.eclipse.team.internal.ui.history.GenericHistoryView.showLastSelectedElement(GenericHistoryView.java:565)
    at org.eclipse.team.internal.ui.history.GenericHistoryView$1.selectionChanged(GenericHistoryView.java:406)
    at org.eclipse.ui.internal.e4.compatibility.SelectionService.notifyListeners(SelectionService.java:266)
    at org.eclipse.ui.internal.e4.compatibility.SelectionService.handlePostSelectionChanged(SelectionService.java:123)
    at org.eclipse.ui.internal.e4.compatibility.SelectionService.lambda$2(SelectionService.java:78)
    at org.eclipse.ui.internal.e4.compatibility.SelectionService$$Lambda$344/0x0000000801063780.selectionChanged(Unknown Source)
    at org.eclipse.e4.ui.internal.workbench.SelectionAggregator$3.run(SelectionAggregator.java:163)
    at org.eclipse.core.runtime.SafeRunner.run(SafeRunner.java:45)
    at org.eclipse.e4.ui.internal.workbench.SelectionAggregator.notifyPostListeners(SelectionAggregator.java:160)
    at org.eclipse.e4.ui.internal.workbench.SelectionAggregator$6.lambda$0(SelectionAggregator.java:250)
    at org.eclipse.e4.ui.internal.workbench.SelectionAggregator$6$$Lambda$1089/0x0000000801544480.run(Unknown Source)
    at org.eclipse.e4.core.contexts.RunAndTrack.runExternalCode(RunAndTrack.java:59)
    at org.eclipse.e4.ui.internal.workbench.SelectionAggregator$6.changed(SelectionAggregator.java:250)
    at org.eclipse.e4.core.internal.contexts.TrackableComputationExt.update(TrackableComputationExt.java:105)
    at org.eclipse.e4.core.internal.contexts.EclipseContext.runAndTrack(EclipseContext.java:338)
    at org.eclipse.e4.ui.internal.workbench.SelectionAggregator.track(SelectionAggregator.java:236)
    at org.eclipse.e4.ui.internal.workbench.SelectionAggregator.setPart(SelectionAggregator.java:114)
    at jdk.internal.reflect.GeneratedMethodAccessor57.invoke(Unknown Source)
    at java.base@17.0.3/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.base@17.0.3/java.lang.reflect.Method.invoke(Method.java:568)
    at org.eclipse.e4.core.internal.di.MethodRequestor.execute(MethodRequestor.java:58)
    at org.eclipse.e4.core.internal.contexts.ContextObjectSupplier$ContextInjectionListener.update(ContextObjectSupplier.java:95)
    at org.eclipse.e4.core.internal.contexts.TrackableComputationExt.update(TrackableComputationExt.java:103)
    at org.eclipse.e4.core.internal.contexts.EclipseContext.processScheduled(EclipseContext.java:356)
    at org.eclipse.e4.core.internal.contexts.EclipseContext.set(EclipseContext.java:372)
    at org.eclipse.e4.core.internal.contexts.EclipseContext.activate(EclipseContext.java:659)
    at org.eclipse.e4.core.internal.contexts.EclipseContext.activateBranch(EclipseContext.java:668)
    at org.eclipse.e4.ui.internal.workbench.PartActivationHistory.activate(PartActivationHistory.java:58)
    at org.eclipse.e4.ui.internal.workbench.PartServiceImpl.activate(PartServiceImpl.java:761)
    at org.eclipse.e4.ui.internal.workbench.PartServiceImpl.activate(PartServiceImpl.java:680)
    at org.eclipse.e4.ui.internal.workbench.PartServiceImpl.activate(PartServiceImpl.java:675)
    at org.eclipse.e4.ui.internal.workbench.PartServiceImpl.showPart(PartServiceImpl.java:1252)
    at org.eclipse.ui.internal.WorkbenchPage.showPart(WorkbenchPage.java:1247)
    at org.eclipse.ui.internal.WorkbenchPage.busyShowView(WorkbenchPage.java:1235)
    at org.eclipse.ui.internal.WorkbenchPage.lambda$11(WorkbenchPage.java:4228)
    at org.eclipse.ui.internal.WorkbenchPage$$Lambda$1439/0x00000008017077b0.run(Unknown Source)
    at org.eclipse.swt.custom.BusyIndicator.showWhile(BusyIndicator.java:74)
    at org.eclipse.ui.internal.WorkbenchPage.showView(WorkbenchPage.java:4226)
    at org.eclipse.ui.internal.WorkbenchPage.showView(WorkbenchPage.java:4208)
    at org.eclipse.ui.internal.quickaccess.providers.ViewElement.execute(ViewElement.java:93)
    at org.eclipse.ui.internal.quickaccess.QuickAccessDialog$1$$Lambda$2465/0x0000000801d72d40.run(Unknown Source)
    at org.eclipse.swt.widgets.RunnableLock.run(RunnableLock.java:40)
    at org.eclipse.swt.widgets.Synchronizer.runAsyncMessages(Synchronizer.java:132)
    at org.eclipse.swt.widgets.Display.runAsyncMessages(Display.java:5000)
    at org.eclipse.swt.widgets.Display.readAndDispatch(Display.java:4480)
    at org.eclipse.e4.ui.internal.workbench.swt.PartRenderingEngine$5.run(PartRenderingEngine.java:1155)
    at org.eclipse.core.databinding.observable.Realm.runWithDefault(Realm.java:338)
    at org.eclipse.e4.ui.internal.workbench.swt.PartRenderingEngine.run(PartRenderingEngine.java:1046)
    at org.eclipse.e4.ui.internal.workbench.E4Workbench.createAndRunUI(E4Workbench.java:155)
    at org.eclipse.ui.internal.Workbench.lambda$3(Workbench.java:644)
    at org.eclipse.ui.internal.Workbench$$Lambda$160/0x0000000800dd2d40.run(Unknown Source)
    at org.eclipse.core.databinding.observable.Realm.runWithDefault(Realm.java:338)
    at org.eclipse.ui.internal.Workbench.createAndRunWorkbench(Workbench.java:551)
    at org.eclipse.ui.PlatformUI.createAndRunWorkbench(PlatformUI.java:156)
    at org.eclipse.ui.internal.ide.application.IDEApplication.start(IDEApplication.java:152)
    at org.eclipse.equinox.internal.app.EclipseAppHandle.run(EclipseAppHandle.java:203)
    at org.eclipse.core.runtime.internal.adaptor.EclipseAppLauncher.runApplication(EclipseAppLauncher.java:136)
    at org.eclipse.core.runtime.internal.adaptor.EclipseAppLauncher.start(EclipseAppLauncher.java:104)
    at org.eclipse.core.runtime.adaptor.EclipseStarter.run(EclipseStarter.java:402)
    at org.eclipse.core.runtime.adaptor.EclipseStarter.run(EclipseStarter.java:255)
    at java.base@17.0.3/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at java.base@17.0.3/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77)
    at java.base@17.0.3/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.base@17.0.3/java.lang.reflect.Method.invoke(Method.java:568)
    at app//org.eclipse.equinox.launcher.Main.invokeFramework(Main.java:659)
    at app//org.eclipse.equinox.launcher.Main.basicRun(Main.java:596)
    at app//org.eclipse.equinox.launcher.Main.run(Main.java:1467)
    at app//org.eclipse.equinox.launcher.Main.main(Main.java:1440)
vogella commented 2 years ago

cc @jukzi

jukzi commented 2 years ago

i don't have linux

SyntevoAlex commented 2 years ago

@vogella please surround code blocks with three backticks ```

SyntevoAlex commented 2 years ago

I already improved performance significantly in https://bugs.eclipse.org/bugs/show_bug.cgi?id=575787#c3 How many items are being added?

vogella commented 2 years ago

I already improved performance significantly in https://bugs.eclipse.org/bugs/show_bug.cgi?id=575787#c3 How many items are being added?

If I open the history view in a debug session and open eclipse.platform.ui I see that org.eclipse.jface.viewers.TableViewer.doSetItemCount(TableViewer.java:231) is called multiple times, the largest value I see it 10001 as count. Adding @tomaswolf (main EGit developer) who might share more on the logic here.

SyntevoAlex commented 2 years ago

I tested this snippet on my Ubuntu 22.04

final Display display = new Display();
final Shell shell = new Shell(display);
shell.setLayout (new GridLayout (1, true));

Table table = new Table(shell, SWT.VIRTUAL);
table.setLayoutData(new GridData(SWT.FILL, SWT.FILL, true, true));

shell.pack();
shell.open();

for (int i = 0; i < 100; i++) {
    if ((i % 2) == 0) {
        final long start = System.currentTimeMillis();
        {
            table.setItemCount(10_000);
        }
        final long end = System.currentTimeMillis();
        System.out.println("table.setItemCount: " + (end - start) + " ms");
    } else {
        final long start = System.currentTimeMillis();
        {
            table.setItemCount(0);
        }
        final long end = System.currentTimeMillis();
        System.out.println("table.removeAll:    " + (end - start) + " ms");
    }
}

while (!shell.isDisposed()) {
    if (!display.readAndDispatch()) {
        display.sleep();
    }
}

display.dispose();

and the results are

table.setItemCount: 48 ms
table.removeAll:    71 ms

This looks fast enough to me. So I don't think that the problem is in SWT, at least not with what I currently know.

iloveeclipse commented 2 years ago

@SyntevoAlex : I assume the problem is when the tree items are really created / removed before setItemCount() is called. The snippet is fast because it doesn't crate/remove any item.

SyntevoAlex commented 2 years ago

OK, here's a more realistic snippet:

final Display display = new Display();
final Shell shell = new Shell(display);
shell.setLayout (new GridLayout (1, true));

Table table = new Table(shell, SWT.VIRTUAL);
table.setLayoutData(new GridData(SWT.FILL, SWT.FILL, true, true));

final int[] iteration = new int[1];
table.addListener(SWT.SetData, event -> ((Item)event.item).setText("Row:" + iteration[0] + ":" + event.index));

Runnable runCreateItems = () -> {
    iteration[0]++;

    // setItemCount()
    {
        final long start = System.currentTimeMillis();
        {
            table.setItemCount(10_000);
        }
        final long end = System.currentTimeMillis();
        System.out.println("table.setItemCount: " + (end - start) + " ms");
    }

    // Force items to be cached
    {
        final long start = System.currentTimeMillis();
        {
            for (int iItem = 0; iItem < table.getItemCount(); iItem++) {
                table.getItem(iItem);
            }
        }
        final long end = System.currentTimeMillis();
        System.out.println("table.getItem:      " + (end - start) + " ms");
    }
};

Runnable runDeleteItems = () -> {
    final long start = System.currentTimeMillis();
    {
        table.setItemCount(0);
    }
    final long end = System.currentTimeMillis();
    System.out.println("table.removeAll:    " + (end - start) + " ms");
};

Button btnCreateItems = new Button(shell, 0);
btnCreateItems.setText("Create items");
btnCreateItems.addListener(SWT.Selection, e -> {
    runCreateItems.run();
});

Button btnDeleteItems = new Button(shell, 0);
btnDeleteItems.setText("Delete items");
btnDeleteItems.addListener(SWT.Selection, e -> {
    runDeleteItems.run();
});

Button btnBoth = new Button(shell, 0);
btnBoth.setText("Do both");
btnBoth.addListener(SWT.Selection, e -> {
    runDeleteItems.run();
    runCreateItems.run();
});

runCreateItems.run();

shell.setSize(300, 500);
shell.open();

while (!shell.isDisposed()) {
    if (!display.readAndDispatch()) {
        display.sleep();
    }
}

display.dispose();

When I click on Do both, the first iteration is slow (~2800ms), and since the second, the times are like:

table.removeAll:    157 ms
table.setItemCount: 149 ms
table.getItem:      12 ms

In Java, all time is spent in a single call to gtk_list_store_clear().

When native profiling, it looks like this

  - 60,96% gtk_list_store_remove
   - 60,56% g_signal_emit
    - g_signal_emit_valist
     - 60,41% signal_emit_unlocked_R
      - 60,27% g_closure_invoke
       - 60,02% gtk_tree_view_row_deleted.lto_priv.0
        - 41,05% gtk_tree_view_real_set_cursor.lto_priv.0
         - 34,59% _gtk_tree_view_accessible_add_state
          - 34,55% create_cell.lto_priv.0
           - 13,34% set_cell_data.lto_priv.0
            - 12,70% gtk_cell_area_apply_attributes
             - 12,57% g_signal_emit
              - g_signal_emit_valist
               - 12,30% _gtk_marshal_VOID__OBJECT_BOXED_BOOLEAN_BOOLEANv
                - 11,85% gtk_cell_area_box_apply_attributes
                 - 11,65% gtk_cell_area_real_apply_attributes
                  - 10,83% g_hash_table_foreach
                   - 10,69% apply_cell_attributes
                    + 5,08% g_object_set_property
                    - 1,76% fn19_5
                     - 1,70% callback
                      + 0,95% jni_CallLongMethodV
                    + 1,22% g_object_get
                    + 1,09% g_object_thaw_notify
           + 6,74% g_object_notify
           + 5,76% gtk_container_cell_accessible_update_cache
           + 5,57% gtk_renderer_cell_accessible_new
           + 0,94% gtk_accessible_set_widget
           + 0,84% gtk_container_cell_accessible_new
         + 5,59% _gtk_tree_selection_internal_select_node
         0,56% g_signal_emit_by_name
        - 15,61% _gtk_tree_view_accessible_remove
           - 13,88% iter_remove_or_steal
            - 13,84% cell_info_free
             - 5,34% g_object_unref
              + 1,85% 0x7fb2e007b122
              + 0,87% gtk_text_cell_accessible_finalize
                0,60% g_object_notify_queue_freeze.lto_priv.0
             + 3,57% gtk_container_cell_accessible_remove_child
             + 3,48% gtk_accessible_set_widget
             + 1,21% g_object_notify
           + 1,51% g_signal_emit_by_name
        + 1,35% gtk_widget_queue_resize

That is, it spends a lot of time reacting to row-deleted events. It's also related to gtk_tree_view_accessible.

SyntevoAlex commented 2 years ago

I can't explain why it becomes faster after first iteration. Unfortunately I can't spend time debugging it further.