Bug 118731 - Dialogs like Format page/ format header open with a annoying delay since 6.2
Summary: Dialogs like Format page/ format header open with a annoying delay since 6.2
Status: RESOLVED FIXED
Alias: None
Product: LibreOffice
Classification: Unclassified
Component: UI (show other bugs)
Version:
(earliest affected)
6.2.0.0.alpha0+
Hardware: All Windows (All)
: medium normal
Assignee: Caolán McNamara
URL:
Whiteboard: target:6.2.0
Keywords: bibisected, regression
Depends on:
Blocks:
 
Reported: 2018-07-12 14:55 UTC by Telesto
Modified: 2018-08-09 14:41 UTC (History)
4 users (show)

See Also:
Crash report or crash signature:


Attachments
VerySleepy measure file for lo-6-1 between the defined breakpoints (89.66 KB, application/zip)
2018-07-18 13:35 UTC, Armin Le Grand (allotropia)
Details
VerySleepy measure file for lo-6-2 between the defined breakpoints (109.32 KB, application/zip)
2018-07-18 13:35 UTC, Armin Le Grand (allotropia)
Details

Note You need to log in before you can comment on or make changes to this bug.
Description Telesto 2018-07-12 14:55:41 UTC
Description:
Dialogs like Format page/ format header open with a annoying delay compared to 6.1b+

Steps to Reproduce:
1. Open Writer
2. Format -> Page

or
1. Insert header (with the blue hoover over button)
2. Format Header (with the blue hoover over button)

Actual Results:
Annoying delay

Expected Results:
Same as in Version: 6.1.0.0.beta1+


Reproducible: Always


User Profile Reset: No



Additional Info:
Found in
Version: 6.2.0.0.alpha0+
Build ID: 8e9d43546c8e46ea635472ddf07f5c183dc13360
CPU threads: 4; OS: Windows 6.3; UI render: default; 
TinderBox: Win-x86@42, Branch:master, Time: 2018-07-12_01:16:00
Locale: nl-NL (nl_NL); Calc: CL

but not in
Version: 6.1.0.0.beta1+
Build ID: da49f4aeb8d5e9a7d2cba8855d911e7cc1d2f1e2
CPU threads: 4; OS: Windows 6.3; UI render: default; 
Locale: nl-NL (nl_NL); Calc: CL
Comment 1 Xisco Faulí 2018-07-13 09:13:38 UTC
I can't reproduce it in

Version: 6.2.0.0.alpha0+
Build ID: 4b345f95ce7cb09011892bf465cfdf3811adaf8e
CPU threads: 4; OS: Linux 4.13; UI render: default; VCL: gtk3; 
Locale: ca-ES (ca_ES.UTF-8); Calc: group threaded

nor in

Version: 6.2.0.0.alpha0+
Build ID: 4b345f95ce7cb09011892bf465cfdf3811adaf8e
CPU threads: 4; OS: Linux 4.13; UI render: default; VCL: x11; 
Locale: ca-ES (ca_ES.UTF-8); Calc: group threaded
Comment 2 Buovjaga 2018-07-13 10:48:43 UTC
With Format - Page in Writer I reproduce it on Windows, but not on Linux. The normal delay is 1 second. The annoying delay is about 2 seconds.

I bibisected it with Win 6.2 repo, but the result seemed incorrect. I noticed the result had two commits rolled into it: https://cgit.freedesktop.org/libreoffice/core/log/?qt=range&q=1e21902106cbe57658bed03ed24d4d0863685cfd...7d275e3ab35b3f9bfd7ff16290393ca027c50355

Still, checking out the first bad vs. the last good I definitely see the delay appearing.
Comment 3 Telesto 2018-07-13 11:39:02 UTC
(In reply to Buovjaga from comment #2)
> With Format - Page in Writer I reproduce it on Windows, but not on Linux.
> The normal delay is 1 second. The annoying delay is about 2 seconds.
> 
> I bibisected it with Win 6.2 repo, but the result seemed incorrect. I
> noticed the result had two commits rolled into it:
> https://cgit.freedesktop.org/libreoffice/core/log/
> ?qt=range&q=1e21902106cbe57658bed03ed24d4d0863685cfd...
> 7d275e3ab35b3f9bfd7ff16290393ca027c50355
> 
> Still, checking out the first bad vs. the last good I definitely see the
> delay appearing.

I get the same bibisect results based on Read/Write access. Prior to these commits only read access for dialog opening. Afterwards also Write access. It's not limited to Writer, so SOSAW080?
Comment 4 Buovjaga 2018-07-13 11:45:42 UTC
Adding Cc: to Armin Le Grand
Comment 5 Armin Le Grand (allotropia) 2018-07-18 13:09:26 UTC
lo-6-2: 14s
lo-6-1: 6s
Measuring with two breakpoints:
C:\lo\work06_lo-6-1\sw\source\uibase\app\docst.cxx : 6-1:821/870 6-2:820/868
Indeed a huge slowdown...
Comment 6 Armin Le Grand (allotropia) 2018-07-18 13:33:57 UTC
Using VerySleepy between Breakpoints:

Statistics for lo-6-1:

Filename: C:\lo\work06_lo-6-1\instdir\program\soffice.bin
Duration: 20.469000
Date: Wed Jul 18 15:10:36 2018
Samples: 13560

Statistics for lo-6-2 (master):

Duration: 34.234000
Date: Wed Jul 18 15:17:02 2018
Samples: 23136

Looking at
SwDocShell::Edit	2.05s	20.46s	0.67%	6.67%

I can follow both paths down to
vcl::Window::get_ungrouped_preferred_size	0.00s	15.59s	0.00%	5.08%

with lo-6-2 using ChildCalls:
VclContainer::GetOptimalSize	44.22s	41.00%	vcllo	c:\lo\work01\vcl\source\window\layout.cxx	45	0x51e3c9ca
SystemWindow::GetOptimalSize	29.05s	26.93%	vcllo	c:\lo\work01\vcl\source\window\syswin.cxx	1065	0x51ec570c
TabControl::GetOptimalSize	29.00s	26.89%	vcllo	c:\lo\work01\vcl\source\control\tabctrl.cxx	2163	0x51fb460a
TabPage::GetOptimalSize	2.27s	2.11%	vcllo	c:\lo\work01\vcl\source\window\tabpage.cxx	187	0x51ecae8e
FixedText::GetOptimalSize	1.55s	1.44%	vcllo	c:\lo\work01\vcl\source\control\fixed.cxx	351	0x51f7b225
ImplBorderWindow::GetOptimalSize	0.65s	0.61%	vcllo	c:\lo\work01\vcl\source\window\brdwin.cxx	2063	0x51d7535e
PushButton::GetOptimalSize	0.47s	0.44%	vcllo	c:\lo\work01\vcl\source\control\button.cxx	1679	0x51f39ab3
CheckBox::GetOptimalSize	0.22s	0.21%	vcllo	c:\lo\work01\vcl\source\control\button.cxx	3728	0x51f39a95
SpinField::GetOptimalSize	0.22s	0.20%	vcllo	c:\lo\work01\vcl\source\control\spinfld.cxx	928	0x51fab21b
RadioButton::GetOptimalSize	0.14s	0.13%	vcllo	c:\lo\work01\vcl\source\control\button.cxx	2909	0x51f39ad3
Edit::GetOptimalSize	0.05s	0.05%	vcllo	c:\lo\work01\vcl\source\control\edit.cxx	2747	0x51f5b6db

and lo-6-1 using ChildCalls:
VclContainer::GetOptimalSize	32.16s	47.89%	vcllo	c:\lo\work06_lo-6-1\vcl\source\window\layout.cxx	45	0x51adec5a
SystemWindow::GetOptimalSize	14.36s	21.38%	vcllo	c:\lo\work06_lo-6-1\vcl\source\window\syswin.cxx	1065	0x51b6df7c
TabControl::GetOptimalSize	14.30s	21.29%	vcllo	c:\lo\work06_lo-6-1\vcl\source\control\tabctrl.cxx	2163	0x51c66c4a
TabPage::GetOptimalSize	2.53s	3.76%	vcllo	c:\lo\work06_lo-6-1\vcl\source\window\tabpage.cxx	187	0x51b7352e
FixedText::GetOptimalSize	1.84s	2.74%	vcllo	c:\lo\work06_lo-6-1\vcl\source\control\fixed.cxx	351	0x51c298f1
ImplBorderWindow::GetOptimalSize	0.71s	1.06%	vcllo	c:\lo\work06_lo-6-1\vcl\source\window\brdwin.cxx	2063	0x51a082ae
PushButton::GetOptimalSize	0.52s	0.78%	vcllo	c:\lo\work06_lo-6-1\vcl\source\control\button.cxx	1680	0x51be6333
SpinField::GetOptimalSize	0.31s	0.46%	vcllo	c:\lo\work06_lo-6-1\vcl\source\control\spinfld.cxx	928	0x51c5c91b
CheckBox::GetOptimalSize	0.30s	0.44%	vcllo	c:\lo\work06_lo-6-1\vcl\source\control\button.cxx	3735	0x51be6315
RadioButton::GetOptimalSize	0.11s	0.16%	vcllo	c:\lo\work06_lo-6-1\vcl\source\control\button.cxx	2910	0x51be6353
Edit::GetOptimalSize	0.03s	0.04%	vcllo	c:\lo\work06_lo-6-1\vcl\source\control\edit.cxx	2749	0x51c0a61b

This shows that most time - and more time - is spent in that area.
There is *no* DrawingLayer stuff involved, FYI.
Adding Caolan to CC, he may know why that layouting stuff got slower in master compared to lo-6-1...
Comment 7 Armin Le Grand (allotropia) 2018-07-18 13:35:11 UTC
Created attachment 143615 [details]
VerySleepy measure file for lo-6-1 between the defined breakpoints
Comment 8 Armin Le Grand (allotropia) 2018-07-18 13:35:27 UTC
Created attachment 143616 [details]
VerySleepy measure file for lo-6-2 between the defined breakpoints
Comment 9 Armin Le Grand (allotropia) 2018-07-18 13:37:34 UTC
@Caolan: Seems as if the layouting got slower for some reason. I can only guess, but maybe you have an idea...? I see no DrawingLayer involved (so probably not SOSAW080), but never say never ... :-)
Comment 10 Armin Le Grand (allotropia) 2018-07-25 17:38:27 UTC
Took out tdf#116979 relation due to no DrawingLayer involved.
Comment 11 Telesto 2018-07-31 20:35:47 UTC
Also happening in Impress when opening the Edit Style dialog
Comment 12 Caolán McNamara 2018-08-07 15:25:06 UTC
I see no slowdown under Linux so its hard for me to be certain, but I can see that is is plausible that the bisect is right...

Taking SvxXRectPreview::SetAttributes in svx/source/dialog/dlgctrl.cxx that ends up calling XFillBitmapItem::checkForUniqueItem going on to call XPropertyList::Load in both 6-1 and master. In 6.1 however it takes the early return because maPath was empty, while in master maPath is not empty, its file:///.../instdir/program/../share/palette;file:///.../instdir/user/config and so now in master .../instdir/program/../share/palette/standard.sob ends up getting loaded and lots on IO action as its unzipped and parsed.

so I think its the case in 6.1 that the models for the previews in the dialogs in question here are created in svx/source/dialog/dlgctrl.cxx and have an empty aTablePath which in 6.1 causes the standard.so* files not to be parsed by those preview models while now they are always parsed, plausibly explaining the delay and the bibisect results. In which case https://gerrit.libreoffice.org/#/c/58693/ would make a difference (if that's something we should do?)
Comment 13 Commit Notification 2018-08-08 09:27:11 UTC
Caolán McNamara committed a patch related to this issue.
It has been pushed to "master":

http://cgit.freedesktop.org/libreoffice/core/commit/?id=674416a2f16dfa050a23f2b1f0b749214ea1f2a6

tdf#118731 delay on showing dialogs that create SdrModels

It will be available in 6.2.0.

The patch should be included in the daily builds available at
http://dev-builds.libreoffice.org/daily/ in the next 24-48 hours. More
information about daily builds can be found at:
http://wiki.documentfoundation.org/Testing_Daily_Builds

Affected users are encouraged to test the fix and report feedback.
Comment 14 Caolán McNamara 2018-08-08 09:29:44 UTC
can the original reporters see if that solves the problem and report back ?
Comment 15 Telesto 2018-08-09 09:07:29 UTC
The delay is gone ;-). Thanks Caolán

Version: 6.2.0.0.alpha0+ (x64)
Build ID: 0a1a4ffb4f87adff7fbbbc60202b6a0e42fedd0c
CPU threads: 4; OS: Windows 6.3; UI render: default; 
TinderBox: Win-x86_64@42, Branch:master, Time: 2018-08-08_23:17:46
Locale: nl-NL (nl_NL); Calc: CL
Comment 16 Timur 2018-08-09 09:38:46 UTC
Confirm gone.
Comment 17 Caolán McNamara 2018-08-09 14:41:52 UTC
we'll call that fixed then, no need for 6-1 backport I believe as its master only.