Bug 104813 - FILEOPEN: DOC: performance regression at import time
Summary: FILEOPEN: DOC: performance regression at import time
Status: RESOLVED WORKSFORME
Alias: None
Product: LibreOffice
Classification: Unclassified
Component: Writer (show other bugs)
Version:
(earliest affected)
5.3.0.1 rc
Hardware: All Linux (All)
: medium normal
Assignee: Not Assigned
URL:
Whiteboard:
Keywords: bibisected, bisected, filter:doc, haveBacktrace, perf, regression
: 108307 (view as bug list)
Depends on:
Blocks:
 
Reported: 2016-12-20 12:17 UTC by Xisco Faulí
Modified: 2017-07-10 11:03 UTC (History)
7 users (show)

See Also:
Crash report or crash signature:


Attachments
sample (35.50 KB, application/msword)
2016-12-20 12:17 UTC, Xisco Faulí
Details
bibisect in daily Linux dbgutil bibisect repository (1.92 KB, text/plain)
2016-12-31 18:13 UTC, Terrence Enger
Details
Callgrind output from 5.4 (148.93 KB, application/x-xz)
2017-02-06 19:55 UTC, Buovjaga
Details
Callgrind output from 5.4 (5.85 MB, application/x-xz)
2017-02-14 04:38 UTC, Buovjaga
Details

Note You need to log in before you can comment on or make changes to this bug.
Description Xisco Faulí 2016-12-20 12:17:11 UTC
Created attachment 129808 [details]
sample

Steps:
1. Open attached document

Observed behaviour: Libreoffice hangs at import time

Reproduced in

Version: 5.4.0.0.alpha0+
Build ID: 5a20df55ff829978c880b22e0a1f32c35d0ba30f
CPU Threads: 4; OS Version: Linux 4.8; UI Render: default; VCL: gtk3; 
Locale: ca-ES (ca_ES.UTF-8); Calc: group
Comment 1 Xisco Faulí 2016-12-20 12:17:33 UTC
I can't reproduce it in

Version: 5.2.0.0.alpha1+
Build ID: 5b168b3fa568e48e795234dc5fa454bf24c9805e
CPU Threads: 4; OS Version: Linux 4.8; UI Render: default; 
Locale: ca-ES (ca_ES.UTF-8)
Comment 2 Xisco Faulí 2016-12-20 12:23:28 UTC
Roundtrip timing in

Version: 5.4.0.0.alpha0+
Build ID: 5a20df55ff829978c880b22e0a1f32c35d0ba30f
CPU Threads: 4; OS Version: Linux 4.8; UI Render: default; VCL: gtk3; 
Locale: ca-ES (ca_ES.UTF-8); Calc: group

real	3m34.670s
user	3m34.436s
sys	0m0.080s

and in 

Version: 5.2.0.0.alpha1+
Build ID: 5b168b3fa568e48e795234dc5fa454bf24c9805e
CPU Threads: 4; OS Version: Linux 4.8; UI Render: default; 
Locale: ca-ES (ca_ES.UTF-8)

real	0m0.935s
user	0m0.772s
sys	0m0.060s
Comment 3 Telesto 2016-12-20 16:21:02 UTC
I can't reproduce it:

Version: 5.4.0.0.alpha0+
Build ID: 53edf60c4ce6ed32f87471e018878c40b788005a
CPU Threads: 4; OS Version: Windows 6.19; UI Render: default; 
TinderBox: Win-x86@42, Branch:master, Time: 2016-12-18_06:57:59
Locale: nl-NL (nl_NL); Calc: CL
Comment 4 Xisco Faulí 2016-12-20 17:58:54 UTC
Another document that might be affected by the same problem: attachment 49957 [details]
Comment 5 Telesto 2016-12-20 18:17:50 UTC
(In reply to Xisco Faulí from comment #4)
> Another document that might be affected by the same problem: attachment
> 49957 [details]

After a warning related to macro's ( "This document contains macros.") I'm able to open the file at first glance. But file keeps running at 25% CPU

Version: 5.4.0.0.alpha0+
Build ID: 53edf60c4ce6ed32f87471e018878c40b788005a
CPU Threads: 4; OS Version: Windows 6.19; UI Render: default; 
TinderBox: Win-x86@42, Branch:master, Time: 2016-12-18_06:57:59
Locale: nl-NL (nl_NL); Calc: CL
Comment 6 Buovjaga 2016-12-20 18:42:56 UTC
(In reply to Xisco Faulí from comment #0)
> Created attachment 129808 [details]
> sample
> 
> Steps:
> 1. Open attached document
> 
> Observed behaviour: Libreoffice hangs at import time

Yep it takes a couple of mins to open on Linux, while opens instantly on Win

Arch Linux 64-bit, KDE Plasma 5
Version: 5.4.0.0.alpha0+
Build ID: db9aec4520766c87a09d4cb0238ed06ebaeaaeeb
CPU Threads: 8; OS Version: Linux 4.8; UI Render: default; VCL: kde4; 
Locale: fi-FI (fi_FI.UTF-8); Calc: group
Built on December 18th 2016

Version: 5.4.0.0.alpha0+
Build ID: 53edf60c4ce6ed32f87471e018878c40b788005a
CPU Threads: 4; OS Version: Windows 6.19; UI Render: default; 
TinderBox: Win-x86@39, Branch:master, Time: 2016-12-18_07:01:05
Locale: fi-FI (fi_FI); Calc: group
Comment 7 Terrence Enger 2016-12-31 18:13:42 UTC
Created attachment 130060 [details]
bibisect in daily Linux dbgutil bibisect repository

Working on debian-stretch in the daily Linux dbgutil bibisect
repository, I see that the slowness came into LibreOffice somewhere in
the 68 commits ...

    status   commit    s-h       date
    ------   --------  --------  -------------------
    good     61bf95ee  634589b3  2016-12-11 21:34:40
    bad      c4a4f801  08fa2e93  2016-12-12 23:38:19

In the versions I deemed good, the program renders the document and
becomes responsive after about 10 seconds.  In the bad versions, the
program is still unresponsive after a minute; the one time I waited,
the program was responsive after 15 minutes 26 seconds of CPU time.

I am removing keyword bibisectRequest and adding bibisected.
Comment 8 Aron Budea 2017-02-03 11:08:35 UTC
Fast in 5.3beta2, hangs in 5.3.0.1, adjusting version.
Comment 9 Buovjaga 2017-02-06 19:55:10 UTC
Created attachment 130959 [details]
Callgrind output from 5.4

I got a callgrind, but it took a suspiciously short amount of time compared to how it takes nearly 3 minutes to open the file normally.

Arch Linux 64-bit, KDE Plasma 5
Version: 5.4.0.0.alpha0+
Build ID: 6dce9c6757823b9e89863716ae70ff4e8ddd4e60
CPU Threads: 8; OS Version: Linux 4.9; UI Render: default; VCL: kde4; 
Locale: fi-FI (fi_FI.UTF-8); Calc: group
Built on February 6th 2016
Comment 10 Matúš Kukan 2017-02-11 15:59:01 UTC
(In reply to Buovjaga from comment #9)
> I got a callgrind, but it took a suspiciously short amount of time compared
> to how it takes nearly 3 minutes to open the file normally.

You need to run 'soffice.bin' directly with valgrind. (not 'soffice' script)
Comment 11 Buovjaga 2017-02-13 05:32:45 UTC
(In reply to Matúš Kukan from comment #10)
> (In reply to Buovjaga from comment #9)
> > I got a callgrind, but it took a suspiciously short amount of time compared
> > to how it takes nearly 3 minutes to open the file normally.
> 
> You need to run 'soffice.bin' directly with valgrind. (not 'soffice' script)

Yeah, my bad. Now I tried again and let it run for the night. The file had opened, but was somehow frozen. When I killed LibO, the callgrind file remained 0 bytes.
Comment 12 Matúš Kukan 2017-02-13 19:17:45 UTC
(In reply to Buovjaga from comment #11)
> (In reply to Matúš Kukan from comment #10)
> > You need to run 'soffice.bin' directly with valgrind. (not 'soffice' script)
> 
> Yeah, my bad. Now I tried again and let it run for the night. The file had
> opened, but was somehow frozen. When I killed LibO, the callgrind file
> remained 0 bytes.

Yeah, I also sometimes had empty file after killing :(. But last time pressing Ctrl+C in terminal worked fine.
Have you followed https://wiki.documentfoundation.org/QA/BugReport/Debug_Information#GNU.2FLinux:_How_to_get_a_callgrind_trace ?
Oh, now I see it's not mentioned there.. If you also do 'export OOO_EXIT_POST_STARTUP=1' LibreOffice will quit after opening the file, so you don't have to exit it.
Comment 13 Buovjaga 2017-02-14 04:38:33 UTC
Created attachment 131199 [details]
Callgrind output from 5.4

Thanks to the auto-closing option, I now got a useful callgrind.

Arch Linux 64-bit, KDE Plasma 5
Version: 5.4.0.0.alpha0+
Build ID: ac8197327d3ef4f3c94fb0746393863404df086b
CPU Threads: 8; OS Version: Linux 4.9; UI Render: default; VCL: kde4; 
Locale: fi-FI (fi_FI.UTF-8); Calc: group
Built on February 11th 2016
Comment 14 Xisco Faulí 2017-02-14 16:05:05 UTC
Regression introduced by:

author	Mike Kaganski <mike.kaganski@collabora.com>	2016-12-08 20:01:03 (GMT)
committer	Miklos Vajna <vmiklos@collabora.co.uk>	2016-12-12 08:23:30 (GMT)
commit 6f5024de2e1a5cc533527e45b33d9a415467c48d (patch)
tree de8f7248a9f0361e23dcbb1eacb72f67071d51a9
parent 7740e945e0c74d057c424cced079adc766cc5604 (diff)
tdf#104425 sw: split rows w/large min height (fix layout loop)

Adding Cc: to Mike Kaganski
Comment 15 Xisco Faulí 2017-06-13 15:51:50 UTC
*** Bug 108307 has been marked as a duplicate of this bug. ***
Comment 16 Mike Kaganski 2017-07-07 13:36:39 UTC
The file from bug 108307 seems opening quickly with 5.4.0.1 on Windows. Could you test this one (that seems to affect Linux only) on Linux?
Comment 17 Maxim Britov 2017-07-07 16:47:06 UTC
(In reply to Mike Kaganski from comment #16)
> The file from bug 108307 seems opening quickly with 5.4.0.1 on Windows.
> Could you test this one (that seems to affect Linux only) on Linux?

I can confirm, my file from bug 108307 on 5.3.3.2 open very very long time, but on 5.3.4.2 it is fast. Linux.
Comment 18 Terrence Enger 2017-07-10 00:10:35 UTC
With daily Linux dbgutil bibisect repository version 2017-06-09
running on debian-stretch, I can open and close the attachment to this
bug with 23 seconds CPU used, and the attachment to bug 104813 with
281 CPU seconds.

Reverse bibisect in the same repository shows that the improvement
came somewhere in the 31 commits ...

     status   commit    s-h       date
     ------   --------  --------  -------------------
     slow     6e346ea2  9956849c  2017-05-30 22:16:31
     fast     f4a7464b  06666564  2017-06-01 00:29:40

I am setting status WORKSFORME; anybody who knows the commit
responsible for the fix can set status FIXED.
Comment 19 Xisco Faulí 2017-07-10 11:02:02 UTC
In

Version: 6.0.0.0.alpha0+
Build ID: 7931ef2abbcef22de5cdddd26738e4dd8d1d8ca5
CPU threads: 4; OS: Linux 4.8; UI render: default; VCL: gtk3; 
Locale: ca-ES (ca_ES.UTF-8); Calc: group

it takes

real	0m1.860s
user	0m1.612s
sys	0m0.128s

Adding backportRequest
Comment 20 Xisco Faulí 2017-07-10 11:03:00 UTC
Actually, no need to backport as it's already fixed in 5.3.4