Bug 549644 - [GTK3] Shell dispose slowdown
Summary: [GTK3] Shell dispose slowdown
Status: NEW
Alias: None
Product: Platform
Classification: Eclipse Project
Component: SWT (show other bugs)
Version: 4.13   Edit
Hardware: PC Linux
: P3 normal (vote)
Target Milestone: ---   Edit
Assignee: Platform-SWT-Inbox CLA
QA Contact:
URL:
Whiteboard: RHT
Keywords: triaged
Depends on:
Blocks:
 
Reported: 2019-07-29 15:57 EDT by Patrick Tasse CLA
Modified: 2019-12-16 14:54 EST (History)
4 users (show)

See Also:


Attachments
Snippet (1.10 KB, text/x-java)
2019-07-29 15:57 EDT, Patrick Tasse CLA
no flags Details
ComboSnippet (1.69 KB, text/x-java)
2019-07-31 10:22 EDT, Patrick Tasse CLA
no flags Details
MenuItemSnippet (2.41 KB, text/x-java)
2019-08-01 15:32 EDT, Patrick Tasse CLA
no flags Details

Note You need to log in before you can comment on or make changes to this bug.
Description Patrick Tasse CLA 2019-07-29 15:57:07 EDT
Created attachment 279428 [details]
Snippet

GTK version: 3.22.30
SWT version: 4928

With the fix from Bug 547227, SWTBot unit tests are sometimes able to complete on GTK3 successfully. However sometimes the build still fails with Tycho return code 137.

Running a loop to continuously create and dispose a ControlExample in a Shell shows that the dispose gets progressively slower.

Doing this with the SWTBot ControlExample (a modified copy) crashes the build after less than 700 iterations, with the dispose time starting around 300 ms and ending around 2,300 ms:

https://ci.eclipse.org/swtbot/job/swtbot-gerrit/1071/console

By comparison, the same code with GTK2 on 2018-09 target platform crashes after more than 13,000 iterations, but the dispose time is stable around 50 ms throughout:

https://ci.eclipse.org/swtbot/job/swtbot-gerrit/1070/console

The slowdown problem can be reproduced locally using the original ControlExample from SWT. See the included snippet.

Profiling this snippet shows that the majority of the time is spent in GTK._gtk_widget_destroy[native] for the Shell itself.

main	100,341 ms (100%)	100,341 ms (100%)
+SnippetControlExampleDispose.main ()	100,341 ms (100%)	100,341 ms (100%)
 +org.eclipse.swt.widgets.Shell.dispose ()	64,397 ms (64.2%)	64,397 ms (64.2%)
  +org.eclipse.swt.widgets.Widget.dispose ()	64,397 ms (64.2%)	64,397 ms (64.2%)
   +org.eclipse.swt.widgets.Control.release ()	64,397 ms (64.2%)	64,397 ms (64.2%)
    +org.eclipse.swt.widgets.Widget.release ()	64,397 ms (64.2%)	64,397 ms (64.2%)
     +org.eclipse.swt.widgets.Widget.destroyWidget ()	61,443 ms (61.2%)	61,443 ms (61.2%)
      +org.eclipse.swt.internal.gtk.GTK.gtk_widget_destroy ()	61,443 ms (61.2%)	61,443 ms (61.2%)
       +org.eclipse.swt.internal.gtk.GTK._gtk_widget_destroy[native] ()	61,443 ms (61.2%)	61,443 ms (61.2%)
     +org.eclipse.swt.widgets.Shell.releaseChildren ()	2,954 ms (2.9%)	2,954 ms (2.9%)
 +org.eclipse.swt.examples.controlexample.ControlExample.<init> ()	35,103 ms (35%)	35,103 ms (35%)
 +org.eclipse.swt.widgets.Shell.<init> ()	840 ms (0.8%)	840 ms (0.8%)
Comment 1 Eric Williams CLA 2019-07-29 16:20:01 EDT
Interesting, can you provide the modified ControlExample?
Comment 2 Patrick Tasse CLA 2019-07-29 16:34:36 EDT
It can be found here:

https://git.eclipse.org/c/swtbot/org.eclipse.swtbot.git/tree/org.eclipse.swt.examples

Make sure you don't have the original one in your workspace when trying to import this one as a project.
Comment 3 Eric Williams CLA 2019-07-30 16:22:48 EDT
(In reply to Patrick Tasse from comment #2)
> It can be found here:
> 
> https://git.eclipse.org/c/swtbot/org.eclipse.swtbot.git/tree/org.eclipse.swt.
> examples
> 
> Make sure you don't have the original one in your workspace when trying to
> import this one as a project.

Thanks, I've been able to make do with the original ControlExample.

It looks like the Browser tab is causing the slowdown, and possibly Combo. Combo alone definitely grows over time, but not as markedly as Browser. I haven't bisected properly but I suspect the issue to be related to bug 530678. If I uncomment some of the g_object_ref() calls made in that change, the situation definitely improves.

I'll continue to investigate, and address this issue for M3.
Comment 4 Patrick Tasse CLA 2019-07-31 10:22:14 EDT
Created attachment 279462 [details]
ComboSnippet

Thanks for the update.

Here's a snippet for Combo, in case it helps.
Comment 5 Eric Williams CLA 2019-07-31 13:18:15 EDT
Thank for the ComboSnippet. I looked into it more and I don't think Combo is the culprit here -- its disposal times are in line with other widgets.

I benchmarked every ControlExample tab individually, each one for 1000 iterations. Browser takes the longest, starting at ~7ms per dispose and ending at ~19ms per dispose. Most other widgets seem to take ~5ms longer per dispose at the end, than they did when they started.

I tried running with GTK2, and the dispose time is not constant like in the Gerrit job. It grows, just not quite as fast as GTK3.

I'll keep investigating.
Comment 6 Patrick Tasse CLA 2019-07-31 14:54:11 EDT
Below is the output of ComboSnippet on my local machine... It's an odd shape, it seems inconclusive...

About the BrowserTab, one thing to note is that we don't have it at all in our modified SWTBot ControlExample. So there must be another culprit.

I'll try to run my debug patch using only one widget's Tab per loop, is that how you identified the BrowserTab?

shell.dispose() for Shell {} with 1000 Combo [1]...	 950 ms ==========
shell.dispose() for Shell {} with 1000 Combo [2]...	1012 ms ===========
shell.dispose() for Shell {} with 1000 Combo [3]...	1155 ms ============
shell.dispose() for Shell {} with 1000 Combo [4]...	1311 ms ==============
shell.dispose() for Shell {} with 1000 Combo [5]...	1357 ms ==============
shell.dispose() for Shell {} with 1000 Combo [6]...	1352 ms ==============
shell.dispose() for Shell {} with 1000 Combo [7]...	1500 ms ===============
shell.dispose() for Shell {} with 1000 Combo [8]...	1525 ms ================
shell.dispose() for Shell {} with 1000 Combo [9]...	1656 ms =================
shell.dispose() for Shell {} with 1000 Combo [10]...	1704 ms ==================
shell.dispose() for Shell {} with 1000 Combo [11]...	1442 ms ===============
shell.dispose() for Shell {} with 1000 Combo [12]...	1609 ms =================
shell.dispose() for Shell {} with 1000 Combo [13]...	1771 ms ==================
shell.dispose() for Shell {} with 1000 Combo [14]...	1851 ms ===================
shell.dispose() for Shell {} with 1000 Combo [15]...	1604 ms =================
shell.dispose() for Shell {} with 1000 Combo [16]...	1738 ms ==================
shell.dispose() for Shell {} with 1000 Combo [17]...	1682 ms =================
shell.dispose() for Shell {} with 1000 Combo [18]...	1724 ms ==================
shell.dispose() for Shell {} with 1000 Combo [19]...	1377 ms ==============
shell.dispose() for Shell {} with 1000 Combo [20]...	1936 ms ====================
shell.dispose() for Shell {} with 1000 Combo [21]...	1497 ms ===============
shell.dispose() for Shell {} with 1000 Combo [22]...	2039 ms =====================
shell.dispose() for Shell {} with 1000 Combo [23]...	1610 ms =================
shell.dispose() for Shell {} with 1000 Combo [24]...	1990 ms ====================
shell.dispose() for Shell {} with 1000 Combo [25]...	1490 ms ===============
shell.dispose() for Shell {} with 1000 Combo [26]...	1660 ms =================
shell.dispose() for Shell {} with 1000 Combo [27]...	1695 ms =================
shell.dispose() for Shell {} with 1000 Combo [28]...	1810 ms ===================
shell.dispose() for Shell {} with 1000 Combo [29]...	1796 ms ==================
shell.dispose() for Shell {} with 1000 Combo [30]...	1827 ms ===================
shell.dispose() for Shell {} with 1000 Combo [31]...	2073 ms =====================
shell.dispose() for Shell {} with 1000 Combo [32]...	1803 ms ===================
shell.dispose() for Shell {} with 1000 Combo [33]...	1954 ms ====================
shell.dispose() for Shell {} with 1000 Combo [34]...	1996 ms ====================
shell.dispose() for Shell {} with 1000 Combo [35]...	1739 ms ==================
shell.dispose() for Shell {} with 1000 Combo [36]...	2340 ms ========================
shell.dispose() for Shell {} with 1000 Combo [37]...	1867 ms ===================
shell.dispose() for Shell {} with 1000 Combo [38]...	1942 ms ====================
shell.dispose() for Shell {} with 1000 Combo [39]...	2058 ms =====================
shell.dispose() for Shell {} with 1000 Combo [40]...	1622 ms =================
Comment 7 Eric Williams CLA 2019-07-31 15:06:40 EDT
(In reply to Patrick Tasse from comment #6)
> Below is the output of ComboSnippet on my local machine... It's an odd
> shape, it seems inconclusive...

Yes, I had the same conclusion.

 
> About the BrowserTab, one thing to note is that we don't have it at all in
> our modified SWTBot ControlExample. So there must be another culprit.

I don't think it's Browser either, there is some other overarching issue causing the bug. Even running ControlExample without BrowserTab shows the bug.

 
> I'll try to run my debug patch using only one widget's Tab per loop, is that
> how you identified the BrowserTab?

Yes, I commented out the tabs in ControlExample and ran the snippet with one tab enabled at a time.
Comment 8 Patrick Tasse CLA 2019-08-01 15:32:46 EDT
Created attachment 279474 [details]
MenuItemSnippet

Winner winner, chicken dinner?

Using a stripped-down Tab from the ControlExample, I was able to reproduce the slowdown or not, by only commenting-in or -out the 3 MenuItem constructors in Tab.createEventConsolePopup(). The ControlExample has 100 instances of this same tab.

// 3 x MenuItem(SWT.PUSH)
ControlExample[  0] with 100 Stripped-Down Tab 	create 1265 ms	dispose  689 ms
ControlExample[  1] with 100 Stripped-Down Tab 	create 1195 ms	dispose  751 ms
::
ControlExample[ 19] with 100 Stripped-Down Tab 	create 1217 ms	dispose  912 ms
ControlExample[ 20] with 100 Stripped-Down Tab 	create 1246 ms	dispose  847 ms
::
ControlExample[ 39] with 100 Stripped-Down Tab 	create 1269 ms	dispose 1566 ms
ControlExample[ 40] with 100 Stripped-Down Tab 	create 1378 ms	dispose 1380 ms

// 0 x MenuItem(SWT.PUSH)
ControlExample[  0] with 100 Stripped-Down Tab 	create 1274 ms	dispose  696 ms
ControlExample[  1] with 100 Stripped-Down Tab 	create 1193 ms	dispose  768 ms
::
ControlExample[ 19] with 100 Stripped-Down Tab 	create 1155 ms	dispose  646 ms
ControlExample[ 20] with 100 Stripped-Down Tab 	create 1201 ms	dispose  648 ms
::
ControlExample[ 39] with 100 Stripped-Down Tab 	create 1172 ms	dispose  698 ms
ControlExample[ 40] with 100 Stripped-Down Tab 	create 1201 ms	dispose  666 ms

I include a snippet, I'm not sure why the slowdown is not as steep as with the ControlExample, but it definitely seems to be growing over time.

It doesn't seem to happen unless the popup menu is added to a Group (or to a child of that Group)?
Comment 9 Eric Williams CLA 2019-08-01 15:48:46 EDT
(In reply to Patrick Tasse from comment #8)
> Created attachment 279474 [details]
> MenuItemSnippet
> 
> Winner winner, chicken dinner?
> 
> Using a stripped-down Tab from the ControlExample, I was able to reproduce
> the slowdown or not, by only commenting-in or -out the 3 MenuItem
> constructors in Tab.createEventConsolePopup(). The ControlExample has 100
> instances of this same tab.
> 
> // 3 x MenuItem(SWT.PUSH)
> ControlExample[  0] with 100 Stripped-Down Tab 	create 1265 ms	dispose  689
> ms
> ControlExample[  1] with 100 Stripped-Down Tab 	create 1195 ms	dispose  751
> ms
> ::
> ControlExample[ 19] with 100 Stripped-Down Tab 	create 1217 ms	dispose  912
> ms
> ControlExample[ 20] with 100 Stripped-Down Tab 	create 1246 ms	dispose  847
> ms
> ::
> ControlExample[ 39] with 100 Stripped-Down Tab 	create 1269 ms	dispose 1566
> ms
> ControlExample[ 40] with 100 Stripped-Down Tab 	create 1378 ms	dispose 1380
> ms
> 
> // 0 x MenuItem(SWT.PUSH)
> ControlExample[  0] with 100 Stripped-Down Tab 	create 1274 ms	dispose  696
> ms
> ControlExample[  1] with 100 Stripped-Down Tab 	create 1193 ms	dispose  768
> ms
> ::
> ControlExample[ 19] with 100 Stripped-Down Tab 	create 1155 ms	dispose  646
> ms
> ControlExample[ 20] with 100 Stripped-Down Tab 	create 1201 ms	dispose  648
> ms
> ::
> ControlExample[ 39] with 100 Stripped-Down Tab 	create 1172 ms	dispose  698
> ms
> ControlExample[ 40] with 100 Stripped-Down Tab 	create 1201 ms	dispose  666
> ms
> 
> I include a snippet, I'm not sure why the slowdown is not as steep as with
> the ControlExample, but it definitely seems to be growing over time.
> 
> It doesn't seem to happen unless the popup menu is added to a Group (or to a
> child of that Group)?

Well that is very strange but a super valuable clue, thanks for investigating! I see some g_object_ref() calls in Menu/MenuItem that may not be needed or are not being disposed of properly. I'll take a look tomorrow.
Comment 10 Eric Williams CLA 2019-08-02 14:20:36 EDT
(In reply to Patrick Tasse from comment #8)
> Created attachment 279474 [details]
> MenuItemSnippet


Does this snippet reproduce the issue for you? All the times output by this snippet are pretty flat for me.

I can confirm that commenting out those portions of ControlExample's createEventConsolePopup() does fix the bug, though.
Comment 11 Patrick Tasse CLA 2019-08-02 14:44:07 EDT
This is the output for me, for the last group.

The dispose time seems to increase slightly over time but there is a lot of jitter. Oddly, it's the creation time that looks to be increasing regularly.

It's really boggling to me that with so many more MenuItem instances (100x100) we don't clearly see the issue, while with the ControlExmple (100x3) it is very apparent. There must be some other factor in play with the ControlExample...

gtk version: 3.22.30
SWT version: 4928

Shell with 100 TabItem with popup Menu with 100 MenuItem [  1]	create 3015 ms	dispose  198 ms	====================
Shell with 100 TabItem with popup Menu with 100 MenuItem [  2]	create 3463 ms	dispose  205 ms	=====================
Shell with 100 TabItem with popup Menu with 100 MenuItem [  3]	create 3650 ms	dispose  230 ms	=======================
Shell with 100 TabItem with popup Menu with 100 MenuItem [  4]	create 3885 ms	dispose  213 ms	======================
Shell with 100 TabItem with popup Menu with 100 MenuItem [  5]	create 4000 ms	dispose  236 ms	========================
Shell with 100 TabItem with popup Menu with 100 MenuItem [  6]	create 4164 ms	dispose  235 ms	========================
Shell with 100 TabItem with popup Menu with 100 MenuItem [  7]	create 4191 ms	dispose  251 ms	==========================
Shell with 100 TabItem with popup Menu with 100 MenuItem [  8]	create 4491 ms	dispose  253 ms	==========================
Shell with 100 TabItem with popup Menu with 100 MenuItem [  9]	create 4176 ms	dispose  292 ms	==============================
Shell with 100 TabItem with popup Menu with 100 MenuItem [ 10]	create 4179 ms	dispose  309 ms	===============================
Shell with 100 TabItem with popup Menu with 100 MenuItem [ 11]	create 4172 ms	dispose  250 ms	=========================
Shell with 100 TabItem with popup Menu with 100 MenuItem [ 12]	create 4248 ms	dispose  255 ms	==========================
Shell with 100 TabItem with popup Menu with 100 MenuItem [ 13]	create 4247 ms	dispose  250 ms	=========================
Shell with 100 TabItem with popup Menu with 100 MenuItem [ 14]	create 4235 ms	dispose  253 ms	==========================
Shell with 100 TabItem with popup Menu with 100 MenuItem [ 15]	create 4408 ms	dispose  264 ms	===========================
Shell with 100 TabItem with popup Menu with 100 MenuItem [ 16]	create 4633 ms	dispose  292 ms	==============================
Shell with 100 TabItem with popup Menu with 100 MenuItem [ 17]	create 4459 ms	dispose  278 ms	============================
Shell with 100 TabItem with popup Menu with 100 MenuItem [ 18]	create 4513 ms	dispose  302 ms	===============================
Shell with 100 TabItem with popup Menu with 100 MenuItem [ 19]	create 4485 ms	dispose  292 ms	==============================
Shell with 100 TabItem with popup Menu with 100 MenuItem [ 20]	create 4498 ms	dispose  294 ms	==============================
Shell with 100 TabItem with popup Menu with 100 MenuItem [ 21]	create 4518 ms	dispose  293 ms	==============================
Shell with 100 TabItem with popup Menu with 100 MenuItem [ 22]	create 4540 ms	dispose  247 ms	=========================
Shell with 100 TabItem with popup Menu with 100 MenuItem [ 23]	create 4892 ms	dispose  277 ms	============================
Shell with 100 TabItem with popup Menu with 100 MenuItem [ 24]	create 4795 ms	dispose  263 ms	===========================
Shell with 100 TabItem with popup Menu with 100 MenuItem [ 25]	create 4591 ms	dispose  245 ms	=========================
Shell with 100 TabItem with popup Menu with 100 MenuItem [ 26]	create 4552 ms	dispose  280 ms	============================
Shell with 100 TabItem with popup Menu with 100 MenuItem [ 27]	create 4673 ms	dispose  272 ms	============================
Shell with 100 TabItem with popup Menu with 100 MenuItem [ 28]	create 4983 ms	dispose  267 ms	===========================
Shell with 100 TabItem with popup Menu with 100 MenuItem [ 29]	create 4720 ms	dispose  255 ms	==========================
Shell with 100 TabItem with popup Menu with 100 MenuItem [ 30]	create 4738 ms	dispose  277 ms	============================
Shell with 100 TabItem with popup Menu with 100 MenuItem [ 31]	create 4761 ms	dispose  291 ms	==============================
Shell with 100 TabItem with popup Menu with 100 MenuItem [ 32]	create 4777 ms	dispose  294 ms	==============================
Shell with 100 TabItem with popup Menu with 100 MenuItem [ 33]	create 4824 ms	dispose  299 ms	==============================
Shell with 100 TabItem with popup Menu with 100 MenuItem [ 34]	create 4828 ms	dispose  290 ms	=============================
Shell with 100 TabItem with popup Menu with 100 MenuItem [ 35]	create 4985 ms	dispose  299 ms	==============================
Shell with 100 TabItem with popup Menu with 100 MenuItem [ 36]	create 5107 ms	dispose  339 ms	==================================
Shell with 100 TabItem with popup Menu with 100 MenuItem [ 37]	create 5116 ms	dispose  305 ms	===============================
Shell with 100 TabItem with popup Menu with 100 MenuItem [ 38]	create 5103 ms	dispose  311 ms	================================
Shell with 100 TabItem with popup Menu with 100 MenuItem [ 39]	create 4948 ms	dispose  326 ms	=================================
Shell with 100 TabItem with popup Menu with 100 MenuItem [ 40]	create 5218 ms	dispose  312 ms	================================
Shell with 100 TabItem with popup Menu with 100 MenuItem [ 41]	create 4988 ms	dispose  297 ms	==============================
Shell with 100 TabItem with popup Menu with 100 MenuItem [ 42]	create 5123 ms	dispose  300 ms	==============================
Shell with 100 TabItem with popup Menu with 100 MenuItem [ 43]	create 5073 ms	dispose  305 ms	===============================
Shell with 100 TabItem with popup Menu with 100 MenuItem [ 44]	create 5391 ms	dispose  336 ms	==================================
Shell with 100 TabItem with popup Menu with 100 MenuItem [ 45]	create 5485 ms	dispose  280 ms	============================
Shell with 100 TabItem with popup Menu with 100 MenuItem [ 46]	create 5340 ms	dispose  317 ms	================================
Shell with 100 TabItem with popup Menu with 100 MenuItem [ 47]	create 5269 ms	dispose  301 ms	===============================
Shell with 100 TabItem with popup Menu with 100 MenuItem [ 48]	create 5450 ms	dispose  284 ms	=============================
Shell with 100 TabItem with popup Menu with 100 MenuItem [ 49]	create 5056 ms	dispose  255 ms	==========================
Shell with 100 TabItem with popup Menu with 100 MenuItem [ 50]	create 5173 ms	dispose  301 ms	===============================
Shell with 100 TabItem with popup Menu with 100 MenuItem [ 51]	create 5204 ms	dispose  257 ms	==========================
Shell with 100 TabItem with popup Menu with 100 MenuItem [ 52]	create 5143 ms	dispose  263 ms	===========================
Shell with 100 TabItem with popup Menu with 100 MenuItem [ 53]	create 5108 ms	dispose  262 ms	===========================
Shell with 100 TabItem with popup Menu with 100 MenuItem [ 54]	create 5247 ms	dispose  289 ms	=============================
Shell with 100 TabItem with popup Menu with 100 MenuItem [ 55]	create 5219 ms	dispose  286 ms	=============================
Shell with 100 TabItem with popup Menu with 100 MenuItem [ 56]	create 5204 ms	dispose  270 ms	===========================
Shell with 100 TabItem with popup Menu with 100 MenuItem [ 57]	create 5198 ms	dispose  261 ms	===========================
Shell with 100 TabItem with popup Menu with 100 MenuItem [ 58]	create 5460 ms	dispose  281 ms	=============================
Shell with 100 TabItem with popup Menu with 100 MenuItem [ 59]	create 5507 ms	dispose  286 ms	=============================
Shell with 100 TabItem with popup Menu with 100 MenuItem [ 60]	create 5342 ms	dispose  307 ms	===============================
Shell with 100 TabItem with popup Menu with 100 MenuItem [ 61]	create 5571 ms	dispose  304 ms	===============================
Shell with 100 TabItem with popup Menu with 100 MenuItem [ 62]	create 5348 ms	dispose  299 ms	==============================
Shell with 100 TabItem with popup Menu with 100 MenuItem [ 63]	create 5406 ms	dispose  292 ms	==============================
Shell with 100 TabItem with popup Menu with 100 MenuItem [ 64]	create 5407 ms	dispose  306 ms	===============================
Shell with 100 TabItem with popup Menu with 100 MenuItem [ 65]	create 5475 ms	dispose  300 ms	==============================
Shell with 100 TabItem with popup Menu with 100 MenuItem [ 66]	create 5595 ms	dispose  301 ms	===============================
Shell with 100 TabItem with popup Menu with 100 MenuItem [ 67]	create 5491 ms	dispose  300 ms	==============================
Shell with 100 TabItem with popup Menu with 100 MenuItem [ 68]	create 5493 ms	dispose  301 ms	===============================
Shell with 100 TabItem with popup Menu with 100 MenuItem [ 69]	create 5496 ms	dispose  299 ms	==============================
Shell with 100 TabItem with popup Menu with 100 MenuItem [ 70]	create 5582 ms	dispose  304 ms	===============================
Shell with 100 TabItem with popup Menu with 100 MenuItem [ 71]	create 5613 ms	dispose  300 ms	==============================
Shell with 100 TabItem with popup Menu with 100 MenuItem [ 72]	create 5761 ms	dispose  310 ms	===============================
Shell with 100 TabItem with popup Menu with 100 MenuItem [ 73]	create 5588 ms	dispose  304 ms	===============================
Shell with 100 TabItem with popup Menu with 100 MenuItem [ 74]	create 5619 ms	dispose  337 ms	==================================
Shell with 100 TabItem with popup Menu with 100 MenuItem [ 75]	create 5655 ms	dispose  303 ms	===============================
Shell with 100 TabItem with popup Menu with 100 MenuItem [ 76]	create 5643 ms	dispose  316 ms	================================
Shell with 100 TabItem with popup Menu with 100 MenuItem [ 77]	create 5555 ms	dispose  305 ms	===============================
Shell with 100 TabItem with popup Menu with 100 MenuItem [ 78]	create 5622 ms	dispose  310 ms	===============================
Shell with 100 TabItem with popup Menu with 100 MenuItem [ 79]	create 5739 ms	dispose  329 ms	=================================
Shell with 100 TabItem with popup Menu with 100 MenuItem [ 80]	create 6265 ms	dispose  354 ms	====================================
Shell with 100 TabItem with popup Menu with 100 MenuItem [ 81]	create 5926 ms	dispose  331 ms	==================================
Shell with 100 TabItem with popup Menu with 100 MenuItem [ 82]	create 5659 ms	dispose  302 ms	===============================
Shell with 100 TabItem with popup Menu with 100 MenuItem [ 83]	create 5636 ms	dispose  297 ms	==============================
Shell with 100 TabItem with popup Menu with 100 MenuItem [ 84]	create 5695 ms	dispose  312 ms	================================
Shell with 100 TabItem with popup Menu with 100 MenuItem [ 85]	create 5739 ms	dispose  305 ms	===============================
Shell with 100 TabItem with popup Menu with 100 MenuItem [ 86]	create 5653 ms	dispose  306 ms	===============================
Shell with 100 TabItem with popup Menu with 100 MenuItem [ 87]	create 5747 ms	dispose  306 ms	===============================
Shell with 100 TabItem with popup Menu with 100 MenuItem [ 88]	create 5575 ms	dispose  308 ms	===============================
Shell with 100 TabItem with popup Menu with 100 MenuItem [ 89]	create 5674 ms	dispose  322 ms	=================================
Shell with 100 TabItem with popup Menu with 100 MenuItem [ 90]	create 5786 ms	dispose  352 ms	====================================
Shell with 100 TabItem with popup Menu with 100 MenuItem [ 91]	create 5923 ms	dispose  382 ms	=======================================
Shell with 100 TabItem with popup Menu with 100 MenuItem [ 92]	create 5804 ms	dispose  347 ms	===================================
Shell with 100 TabItem with popup Menu with 100 MenuItem [ 93]	create 5761 ms	dispose  352 ms	====================================
Shell with 100 TabItem with popup Menu with 100 MenuItem [ 94]	create 5714 ms	dispose  332 ms	==================================
Shell with 100 TabItem with popup Menu with 100 MenuItem [ 95]	create 5706 ms	dispose  274 ms	============================
Shell with 100 TabItem with popup Menu with 100 MenuItem [ 96]	create 5673 ms	dispose  288 ms	=============================
Shell with 100 TabItem with popup Menu with 100 MenuItem [ 97]	create 6660 ms	dispose  339 ms	==================================
Shell with 100 TabItem with popup Menu with 100 MenuItem [ 98]	create 5908 ms	dispose  292 ms	==============================
Shell with 100 TabItem with popup Menu with 100 MenuItem [ 99]	create 5826 ms	dispose  282 ms	=============================
Shell with 100 TabItem with popup Menu with 100 MenuItem [100]	create 5660 ms	dispose  281 ms	=============================
Comment 12 Eric Williams CLA 2019-08-13 15:31:57 EDT
If I comment out the creation lines for "boxHandle" in MenuItem.createItem(), the bug goes away. I tried some other combinations, but something about creating a GtkBox in a Menu is causing the slowdown. Will continue to investigate.
Comment 13 Eric Williams CLA 2019-08-15 16:31:44 EDT
Another discovery: if I swap out the GtkBox created in MenuItem for an SwtFixed container, the bug goes away.
Comment 14 Eric Williams CLA 2019-08-27 08:13:28 EDT
I haven't made any progress on this sadly, it will be a 4.14 item.
Comment 15 Simeon Andreev CLA 2019-09-09 08:29:10 EDT
Hi Eric,

as you suggested I've ran some of the snippets attached here, I do notice increased memory consumption while the JVM heap doesn't grow. So I think GTK+ objects pile up; I've tried the ControlExample and the Combo snippets, both show this.

Are there any GTK+ debug options that I can use here, to print GTK objects statistics (or any GTK statistics)? It would be good to know if some GTK widgets are not being cleaned properly.

Best regards and thanks,
Simeon
Comment 16 Eric Williams CLA 2019-09-09 09:35:04 EDT
(In reply to Simeon Andreev from comment #15)
> Hi Eric,
> 
> as you suggested I've ran some of the snippets attached here, I do notice
> increased memory consumption while the JVM heap doesn't grow. So I think
> GTK+ objects pile up; I've tried the ControlExample and the Combo snippets,
> both show this.

If you comment out the lines mentioned in comment 8, does it still reproduce?

 
> Are there any GTK+ debug options that I can use here, to print GTK objects
> statistics (or any GTK statistics)? It would be good to know if some GTK
> widgets are not being cleaned properly.

IIRC hunting leaks in GTK is tricky due to the way they free a lot of memory on exit -- meaning valgrind will report lots of false positives. Best case is to find a native snippet that reproduces the leak, and then proceed to file a bug upstream. WRT object statistics, you can use GtkInspector to see instance counts, and I think there is an "instance-count" compile-time debug option for GLib, which may/may not be useful.

For GTK, you can see a list of debug options here: https://developer.gnome.org/gtk3/stable/gtk-running.html#GTK-Debug-Options
Comment 17 Simeon Andreev CLA 2019-09-09 09:56:46 EDT
(In reply to Eric Williams from comment #16)
> 
> If you comment out the lines mentioned in comment 8, does it still reproduce?

Could you be more precise? Do you mean:

diff --git a/examples/org.eclipse.swt.examples/src/org/eclipse/swt/examples/controlexample/Tab.java b/examples/org.eclipse.swt.examples/src/org/eclipse/swt/examples/controlexample/Tab.java
index 702c092a9f..fde6aab8df 100644
--- a/examples/org.eclipse.swt.examples/src/org/eclipse/swt/examples/controlexample/Tab.java
+++ b/examples/org.eclipse.swt.examples/src/org/eclipse/swt/examples/controlexample/Tab.java
@@ -733,22 +733,22 @@ abstract class Tab {
         * Create the event console popup menu.
         */
        void createEventConsolePopup () {
-               Menu popup = new Menu (shell, SWT.POP_UP);
-               eventConsole.setMenu (popup);
-
-               MenuItem cut = new MenuItem (popup, SWT.PUSH);
-               cut.setText (ControlExample.getResourceString("MenuItem_Cut"));
-               cut.addListener (SWT.Selection, event -> eventConsole.cut ());
-               MenuItem copy = new MenuItem (popup, SWT.PUSH);
-               copy.setText (ControlExample.getResourceString("MenuItem_Copy"));
-               copy.addListener (SWT.Selection, event -> eventConsole.copy ());
-               MenuItem paste = new MenuItem (popup, SWT.PUSH);
-               paste.setText (ControlExample.getResourceString("MenuItem_Paste"));
-               paste.addListener (SWT.Selection, event -> eventConsole.paste ());
-               new MenuItem (popup, SWT.SEPARATOR);
-               MenuItem selectAll = new MenuItem (popup, SWT.PUSH);
-               selectAll.setText(ControlExample.getResourceString("MenuItem_SelectAll"));
-               selectAll.addListener (SWT.Selection, event -> eventConsole.selectAll ());
+//             Menu popup = new Menu (shell, SWT.POP_UP);
+//             eventConsole.setMenu (popup);
+//
+//             MenuItem cut = new MenuItem (popup, SWT.PUSH);
+//             cut.setText (ControlExample.getResourceString("MenuItem_Cut"));
+//             cut.addListener (SWT.Selection, event -> eventConsole.cut ());
+//             MenuItem copy = new MenuItem (popup, SWT.PUSH);
+//             copy.setText (ControlExample.getResourceString("MenuItem_Copy"));
+//             copy.addListener (SWT.Selection, event -> eventConsole.copy ());
+//             MenuItem paste = new MenuItem (popup, SWT.PUSH);
+//             paste.setText (ControlExample.getResourceString("MenuItem_Paste"));
+//             paste.addListener (SWT.Selection, event -> eventConsole.paste ());
+//             new MenuItem (popup, SWT.SEPARATOR);
+//             MenuItem selectAll = new MenuItem (popup, SWT.PUSH);
+//             selectAll.setText(ControlExample.getResourceString("MenuItem_SelectAll"));
+//             selectAll.addListener (SWT.Selection, event -> eventConsole.selectAll ());
        }
 
        /**

If so, I can still see the increased dispose time and the increasing memory. So I guess you mean comment some other lines? 

> Best case is to find a native snippet that reproduces the leak, and then proceed to file a bug upstream.

I'll try with the inspector; unfortunately it takes a long while until the leak becomes clear (due to how much the JVM heap varies in the first 1-2 days of running). So finding out which view and then which elements are responsible will take forever like this.
Comment 18 Eric Williams CLA 2019-09-09 15:31:44 EDT
(In reply to Simeon Andreev from comment #17)
> (In reply to Eric Williams from comment #16)
> > 
> > If you comment out the lines mentioned in comment 8, does it still reproduce?
> 
> Could you be more precise? Do you mean:
> 
> diff --git
> a/examples/org.eclipse.swt.examples/src/org/eclipse/swt/examples/
> controlexample/Tab.java
> b/examples/org.eclipse.swt.examples/src/org/eclipse/swt/examples/
> controlexample/Tab.java
> index 702c092a9f..fde6aab8df 100644
> ---
> a/examples/org.eclipse.swt.examples/src/org/eclipse/swt/examples/
> controlexample/Tab.java
> +++
> b/examples/org.eclipse.swt.examples/src/org/eclipse/swt/examples/
> controlexample/Tab.java
> @@ -733,22 +733,22 @@ abstract class Tab {
>          * Create the event console popup menu.
>          */
>         void createEventConsolePopup () {
> -               Menu popup = new Menu (shell, SWT.POP_UP);
> -               eventConsole.setMenu (popup);
> -
> -               MenuItem cut = new MenuItem (popup, SWT.PUSH);
> -               cut.setText
> (ControlExample.getResourceString("MenuItem_Cut"));
> -               cut.addListener (SWT.Selection, event -> eventConsole.cut
> ());
> -               MenuItem copy = new MenuItem (popup, SWT.PUSH);
> -               copy.setText
> (ControlExample.getResourceString("MenuItem_Copy"));
> -               copy.addListener (SWT.Selection, event -> eventConsole.copy
> ());
> -               MenuItem paste = new MenuItem (popup, SWT.PUSH);
> -               paste.setText
> (ControlExample.getResourceString("MenuItem_Paste"));
> -               paste.addListener (SWT.Selection, event ->
> eventConsole.paste ());
> -               new MenuItem (popup, SWT.SEPARATOR);
> -               MenuItem selectAll = new MenuItem (popup, SWT.PUSH);
> -              
> selectAll.setText(ControlExample.getResourceString("MenuItem_SelectAll"));
> -               selectAll.addListener (SWT.Selection, event ->
> eventConsole.selectAll ());
> +//             Menu popup = new Menu (shell, SWT.POP_UP);
> +//             eventConsole.setMenu (popup);
> +//
> +//             MenuItem cut = new MenuItem (popup, SWT.PUSH);
> +//             cut.setText
> (ControlExample.getResourceString("MenuItem_Cut"));
> +//             cut.addListener (SWT.Selection, event -> eventConsole.cut
> ());
> +//             MenuItem copy = new MenuItem (popup, SWT.PUSH);
> +//             copy.setText
> (ControlExample.getResourceString("MenuItem_Copy"));
> +//             copy.addListener (SWT.Selection, event -> eventConsole.copy
> ());
> +//             MenuItem paste = new MenuItem (popup, SWT.PUSH);
> +//             paste.setText
> (ControlExample.getResourceString("MenuItem_Paste"));
> +//             paste.addListener (SWT.Selection, event ->
> eventConsole.paste ());
> +//             new MenuItem (popup, SWT.SEPARATOR);
> +//             MenuItem selectAll = new MenuItem (popup, SWT.PUSH);
> +//            
> selectAll.setText(ControlExample.getResourceString("MenuItem_SelectAll"));
> +//             selectAll.addListener (SWT.Selection, event ->
> eventConsole.selectAll ());
>         }
>  
>         /**

Correct.


 
> If so, I can still see the increased dispose time and the increasing memory.
> So I guess you mean comment some other lines? 

Interesting, I can't comment about the memory but on my machine commenting out those lines results in the dispose time staying constant after about 30 iterations.
Comment 19 Simeon Andreev CLA 2019-09-10 02:48:03 EDT
I'm on GTK 3.22.10, maybe this matters? My SWT is on latest master.
Comment 20 Eric Williams CLA 2019-09-16 11:07:26 EDT
(In reply to Simeon Andreev from comment #19)
> I'm on GTK 3.22.10, maybe this matters? My SWT is on latest master.

Very interesting, I just tried with 3.22.5 and the bug still reproduces when commenting out the Menu construction.

This is a nice clue because now I can bisect GTK.
Comment 21 Eric Williams CLA 2019-09-16 16:12:15 EDT
Bisection reveals that they fixed a memory leak in GTK3 late into 3.22. Here is the commit: https://gitlab.gnome.org/GNOME/gtk/commit/c0c23f7d447d5d94468abbc0717aaff342fc14c7

Simeon, this might be the memory leak you're chasing. I suggest compiling GTK3 with that patch applied and run that in your product to check.
Comment 22 Simeon Andreev CLA 2019-09-17 02:30:51 EDT
(In reply to Eric Williams from comment #21)
> Bisection reveals that they fixed a memory leak in GTK3 late into 3.22. Here
> is the commit:
> https://gitlab.gnome.org/GNOME/gtk/commit/
> c0c23f7d447d5d94468abbc0717aaff342fc14c7
> 
> Simeon, this might be the memory leak you're chasing. I suggest compiling
> GTK3 with that patch applied and run that in your product to check.

Thanks, I'll try as soon as I'm able!
Comment 23 Eric Williams CLA 2019-11-12 11:52:52 EST
Didn't get any closer this time, moving into 4.15.
Comment 24 Eric Williams CLA 2019-12-16 14:54:08 EST
I won't have time to get to this one, sorry.