Bug 130822 - 819-pages text ODT with many footnotes continuously slower to open (see Comment 21 and Flamegraph)
Summary: 819-pages text ODT with many footnotes continuously slower to open (see Comme...
Status: NEW
Alias: None
Product: LibreOffice
Classification: Unclassified
Component: Writer (show other bugs)
Version:
(earliest affected)
4.1 all versions
Hardware: All All
: low minor
Assignee: Not Assigned
URL:
Whiteboard:
Keywords: bibisected, bisected, notBibisectable, perf, regression
Depends on:
Blocks: File-Opening
  Show dependency treegraph
 
Reported: 2020-02-20 20:19 UTC by Timur
Modified: 2021-09-24 18:44 UTC (History)
4 users (show)

See Also:
Crash report or crash signature:
Regression By:


Attachments
perf flamegraph (427.03 KB, application/x-bzip)
2020-05-11 16:38 UTC, Julien Nabet
Details
perf flamegraph (263.55 KB, application/x-bzip)
2021-09-23 20:01 UTC, Julien Nabet
Details

Note You need to log in before you can comment on or make changes to this bug.
Description Timur 2020-02-20 20:19:03 UTC
819-pages ODT attachment 121138 [details] from bug 96337 and bug 129529 is slower to open in LO than OO. 
TBD where slowness/regression started and if there's a dump. 
Note:can be tested up to 6.1 and again from 6.4.2 and 7.0+.
Comment 1 Xisco Faulí 2020-02-21 10:44:36 UTC
it takes

real	1m33,423s
user	1m31,368s
sys	0m1,715s

in

Version: 7.0.0.0.alpha0+
Build ID: d7cab304e7dd22fd12443a1ee3b6a9c463bf9a3d
CPU threads: 4; OS: Linux 4.19; UI render: default; VCL: gtk3; 
Locale: en-US (en_US.UTF-8); UI-Language: en-US
Calc: threaded
Comment 2 Xisco Faulí 2020-02-21 10:47:46 UTC
it takes

real	1m58,616s
user	1m55,730s
sys	0m1,395s

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 3 Xisco Faulí 2020-02-21 10:51:58 UTC
it takes

real	3m28,258s
user	3m25,841s
sys	0m1,318s


in

Version: 4.3.0.0.alpha1+
Build ID: c15927f20d4727c3b8de68497b6949e72f9e6e9e
Comment 4 Xisco Faulí 2020-02-21 10:54:03 UTC
and

real	1m22,377s
user	1m19,975s
sys	0m1,623s

in

Version 4.1.0.0.alpha0+ (Build ID: efca6f15609322f62a35619619a6d5fe5c9bd5a)

@Timur, why is it tagged as a regression ?
Comment 5 Timur 2020-02-21 11:18:32 UTC
My experience in Windows is that OO 3.3 took less to open compared to LO 6.1 where worked before (0:28 to 0:58 on my slow system).
I'm waiting master Windows build to retest. 

@Xisco: I don't know why you confirmed so I set back Unconfirmed. Linux difference is rather small 4.1 vs. 7.0+. Please also test OO.
Comment 6 Xisco Faulí 2020-02-21 14:55:25 UTC
(In reply to Timur from comment #5)
> @Xisco: I don't know why you confirmed so I set back Unconfirmed. Linux
> difference is rather small 4.1 vs. 7.0+. Please also test OO.

I confirmed it because there a performance issue anyway, either it's a regression or not...
Comment 7 Roman Kuznetsov 2020-02-23 14:00:19 UTC
I got a freeze when tried open the file in

Версия: 7.0.0.0.alpha0+ (x64)
ID сборки: cf96cb11e2a46c452a273ded1c66c556118983cf
Потоков ЦП: 4; ОС: Windows 10.0 Build 17763; Отрисовка ИП: GL; VCL: win; 
Локаль: ru-RU (ru_RU); Язык интерфейса: ru-RU
Calc: threaded
Comment 8 Timur 2020-03-13 09:22:14 UTC
Linux same system
7.0+ master (freeze on use!): 
real	3m37,224s
user	3m33,357s
sys	0m2,495s

6.4 master (updated for backport)
real	1m40,897s
user	0m49,369s
sys	0m3,134s

6.3 master (with fix for fileopen): bibisect not updated for backport, Xisco please do

6.2 master: cannot open because of bug 129529 

6.2. oldest:
real	1m21,481s
user	0m47,346s
sys	0m1,680s

6.1 master:
real	1m0,293s
user	0m44,543s
sys	0m1,423s

5.4 master 
real	1m1,815s
user	0m39,828s
sys	0m1,607s

5.2 master (5.2. oldest gives an error):
real	0m51,385s
user	0m43,079s
sys	0m0,930s

4.1 oldest:
real	0m46,111s
user	0m27,321s
sys	0m1,979s

3.5 oldest:
real	0m29,374s
user	0m18,330s
sys	0m1,284s


There's continuous slowing down. So not sure if bibisect is possible.
Biggest issue now is freeze in 7.0+ with freeze on use: scroll beginning-bottom 3 times. I don't see it in 6.4+.
Comment 9 Timur 2020-03-18 12:07:19 UTC
Xisco, can this be bibisected in 7.0+ if older couldn't be open?
Comment 10 Timur 2020-05-11 11:08:46 UTC
I don't see freeze now in Windows. I bibisected it: 

For Roman's source, bibisect commit is eae8f3cfc609556df2ee5111225db1fd45ef2361.
Current bibisect master source is 017f90788c330d2e35a9c05a56b564d0ab4aafaf and bibisect is 63a56e5ec52906ba382acdeef4b48f83e5335a88.
 1988b3c2e0dc93b2e3e96d2af99e95c2078fbfa7 is the first *good* commit
Date:   Tue Mar 24 21:08:08 2020 +0100
    source 642cdf2d8341f0b202f01718ccb63ac1b976e18e
Previous source 7dcf08fe6f14951cdf752a3772f25297cc238ce3. Singe commit. 

https://gerrit.libreoffice.org/plugins/gitiles/core/+/642cdf2d8341f0b202f01718ccb63ac1b976e18e%5E!/

commit 642cdf2d8341f0b202f01718ccb63ac1b976e18e	[log]
author	Jan-Marek Glogowski <jan-marek.glogowski@extern.cib.de>	Tue Mar 24 18:59:22 2020 +0100
committer	Jan-Marek Glogowski <glogow@fbihome.de>	Tue Mar 24 21:00:57 2020 +0100
tree ff10f9556c8b17e35b1b964434ecf3c71d6d273e
parent 7dcf08fe6f14951cdf752a3772f25297cc238ce3 [diff]

tdf# bug 131530 keep prepending footnote frame
Comment 11 Timur 2020-05-11 11:17:16 UTC
I experienced another crash few times, when I scrolled immediately on open, without waiting for repagination. 
That's likely different but not reproducible each time.
Comment 12 Timur 2020-05-11 11:21:30 UTC
Linux 7.0+ master: 
real	1m1,047s
user	0m56,237s
sys	0m2,679s

We are now back at the bug report. Looks like there's some slowing down. 
But I don't think perf bibisect is possible. Maybe flamegraph would help.
Comment 13 Telesto 2020-05-11 15:01:41 UTC
(In reply to Timur from comment #11)
> I experienced another crash few times, when I scrolled immediately on open,
> without waiting for repagination. 
> That's likely different but not reproducible each time.

Hmm, have seen that too.. (not for this doc)
Comment 14 Julien Nabet 2020-05-11 16:38:47 UTC
Created attachment 160680 [details]
perf flamegraph

Here's a Flamegraph retrieved on pc Debian x86-64 with master sources updated today.
Comment 15 Timur 2020-05-12 09:23:12 UTC
Xisco, please comment. What can be done with flamegraph, now that Julien was kind to get it?
Comment 16 Telesto 2020-07-07 15:48:35 UTC
16 seconds for me
Version: 7.1.0.0.alpha0+ (x86)
Build ID: 9af38b4504ccda57a0c32eb8bdd03e5a8ca29ddc
CPU threads: 4; OS: Windows 6.3 Build 9600; UI render: Skia/Raster; VCL: win
Locale: nl-NL (nl_NL); UI: en-US
Calc: CL
Comment 17 Timur 2020-07-07 16:33:31 UTC
(In reply to Telesto from comment #16)
> 16 seconds for me
> Version: 7.1.0.0.alpha0+ (x86)
We have different systems so best to compare this with older LO open time on the same machine, like in Comment 8. There is TimeMem for Windows.
Comment 18 Telesto 2020-07-07 16:55:07 UTC
Perhaps more Linux than Windows.. there is annoying idle process spending lots of time layouting the footnotes..
Comment 19 Telesto 2020-07-07 17:58:24 UTC
File opening as such.. not really an issue
Version: 7.0.0.0.beta1+
Build ID: c344de1b9985b6ca10b354e24151d0bdf92dc20e
CPU threads: 2; OS: Linux 5.3; UI render: default; VCL: x11
Locale: en-US (en_US.UTF-8); UI: en-US
Calc: threaded

File is certainly slower compared to Windows, with gen and gtk3 backend. Pages being filled after scrolling through
Comment 20 Roman Kuznetsov 2021-09-22 19:33:59 UTC
18 sec in

Version: 7.3.0.0.alpha0+ (x64) / LibreOffice Community
Build ID: a9cc066a86c6bd3423c5802c5a4eded55a50c754
CPU threads: 4; OS: Windows 6.1 Service Pack 1 Build 7601; UI render: Skia/Raster; VCL: win
Locale: ru-RU (ru_RU); UI: en-US
Calc: threaded

I don't think it can be better for a 820-pages document, may be it's time for closing of this report?
Comment 21 Timur 2021-09-23 14:54:13 UTC
Here is a testing on the same Linux, obsoleting Comment 8 and Comment 12. I guess that 1st time run takes more of LO than document, so 2nd time is more relevant, seconds before 'total'. 
This is how Zsh shows 'time', somewhat diff. from Bash. (Looks better with wider screen).

LO			1st time											2nd time										pages
OO 3.3		19,16s user 1,47s system 62% cpu 33 total		19,16s user 1,47s system 62% cpu 33 total
3.5o 		13,17s user 0,87s system 58% cpu 24 total		12,82s user 0,44s system 94% cpu 14 total		819 pages
3.5m/4.3	76,42s user 0,90s system 95% cpu 1:21 total		
4.1o		22,25s user 1,14s system 92% cpu 25 total		22,19s user 0,69s system 96% cpu 24 total
4.1m		20,91s user 1,14s system 58% cpu 38 total		20,20s user 0,75s system 97% cpu 22 total
4.3m		64,42s user 1,53s system 85% cpu 1:16 total
5.2m		34,44s user 1,32s system 65% cpu 55 total		35,06s user 1,13s system 86% cpu 42 total
5.4m		31,46s user 1,06s system 95% cpu 34 total		27,00s user 0,80s system 96% cpu 29 total
6.1m		32,71s user 1,26s system 69% cpu 49 total														819
6.4m		24,50s user 0,96s system 63% cpu 40 total														1491 
7.0m		24,05s user 1,38s system 60% cpu 42 total		23,53s user 0,80s system 88% cpu 28 total		1491 ...
7.3+		21,97s user 1,34s system 47% cpu 50 total		20,71s user 0,78s system 99% cpu 22 total		1482 > 1084 > 820 

Current 7.3+ time seems comparable to LO 4.1 master time (time in between were worse), but slower than with LO 3.5 from 43all oldest. 43all master that's some 4.3 is very slow.
This ODT has no tracking changes or images, just many 4062 footnotes and some 50 comments. 
I guess it should at least be fast as 3.5 so I don't think this should be closed. 

Another problem is that with 3.5 pages were immediatelly counted as 819, while with 7.3+ it first shows 1482, which soon goes to 1084 and then to 820. 
Probably another issue in 6.2/6.3/6.4 or result of fixing bug 129529.
Comment 22 Julien Nabet 2021-09-23 20:01:26 UTC
Created attachment 175227 [details]
perf flamegraph

Here's a new Flamegraph during opening and a bit of scrolling retrieved on pc Debian x86-64 with master sources updated today (11ddd00117ad9dd4434b5e057d992f1a2eab49a8) + gen rendering + new LO profile.