Bug 112989 - Time required to export a large document has doubled for Latin (text layout issue)
Summary: Time required to export a large document has doubled for Latin (text layout i...
Status: RESOLVED FIXED
Alias: None
Product: LibreOffice
Classification: Unclassified
Component: LibreOffice (show other bugs)
Version:
(earliest affected)
5.3.0.1 rc
Hardware: All All
: highest major
Assignee: Not Assigned
URL:
Whiteboard: target:6.5.0 target:6.4.0.1
Keywords: bibisected, bisected, haveBacktrace, perf, regression
: 108513 112979 113139 118165 (view as bug list)
Depends on:
Blocks: HarfBuzz-regressions
  Show dependency treegraph
 
Reported: 2017-10-08 09:15 UTC by Telesto
Modified: 2019-12-18 14:55 UTC (History)
4 users (show)

See Also:
Crash report or crash signature:


Attachments
Bibisect log (2.91 KB, text/plain)
2017-10-08 09:16 UTC, Telesto
Details
Example file (361.32 KB, application/vnd.oasis.opendocument.text)
2017-10-08 09:17 UTC, Telesto
Details
Very Sleepy results (725.17 KB, application/x-zip-compressed)
2017-10-30 11:45 UTC, Telesto
Details
Screenshot (59.82 KB, image/png)
2017-11-02 20:55 UTC, Telesto
Details
Screenshot Non-Debug (36.07 KB, image/png)
2017-11-03 08:31 UTC, Telesto
Details
Very Sleepy time profile results (129.94 KB, application/zip)
2017-11-03 08:32 UTC, Telesto
Details
Very sleepy when exporting to PDF in multi-page view (31.93 KB, image/png)
2017-11-03 08:58 UTC, Telesto
Details
SHGetFileInfoW Non-Debug build (28.45 KB, image/png)
2017-11-03 09:00 UTC, Telesto
Details
Example file (637.76 KB, application/vnd.oasis.opendocument.text)
2017-11-15 20:53 UTC, Telesto
Details
Xcode Instruments Screenshots time profiler & code peaks (2.05 MB, application/zip)
2017-11-16 20:46 UTC, Telesto
Details
Example file (21.87 KB, application/vnd.oasis.opendocument.spreadsheet)
2017-11-25 21:46 UTC, Telesto
Details
Perf flamegraph (1.11 MB, image/svg+xml)
2019-04-06 17:44 UTC, Buovjaga
Details
Perf Flame Graph Win (647.54 KB, image/svg+xml)
2019-05-08 14:20 UTC, Telesto
Details

Note You need to log in before you can comment on or make changes to this bug.
Description Telesto 2017-10-08 09:15:50 UTC
Description:
Time required to export a large document has doubled

Steps to Reproduce:
1. Open the attached file
2. Wait until the CPU usage falls back to around 0
3. Export the PDF and take notice of the time required

Actual Results:  
With 5.2.5 it takes around 15-20 seconds

Expected Results:
Since LibO5.3.0.1 around 40 seconds is required


Reproducible: Always

User Profile Reset: No

Additional Info:
Found in
Version: 6.0.0.0.alpha0+
Build ID: c5a93cad149618bbd43632f1660a558c34bdbf7e
CPU threads: 4; OS: Windows 6.3; UI render: default; 
TinderBox: Win-x86@42, Branch:master, Time: 2017-10-07_01:04:25
Locale: nl-NL (nl_NL); Calc: CL

and in LibO5.3.0.1 


User-Agent: Mozilla/5.0 (Windows NT 6.3; WOW64; rv:52.0) Gecko/20100101 Firefox/52.0
Comment 1 Telesto 2017-10-08 09:16:55 UTC
Created attachment 136840 [details]
Bibisect log

author	Khaled Hosny <khaledhosny@eglug.org>	2016-11-02 21:52:06 (GMT)
committer	Khaled Hosny <khaledhosny@eglug.org>	2016-11-03 00:17:06 (GMT)
commit	8f2dd1df1d6cc94ebbc1149de72bc6d6dffa6533 (patch)
tree	db496889434c484a87b13ffcc4650d65e6672129
parent	c8be45889217c555e4bec92af838d0524ceba4e0 (diff)
Revert "Revert "Enable the new text layout engine by default""
This reverts commit 3950166877bf1308f9e449992e20b558342af825.
Comment 2 Telesto 2017-10-08 09:17:14 UTC
Created attachment 136841 [details]
Example file
Comment 3 Xisco Faulí 2017-10-17 09:22:56 UTC
I can't confirm it. In

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

it takes 

real	1m1,378s
user	1m0,772s
sys	0m0,328s

to open and export it.
-> time program/soffice --headless --convert-to pdf /home/xisco/Baixades/Demo\(3\)\ -\ kopie.odt --outdir /home/xisco/Escriptori/

OTOH, 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)

it takes

real	2m18,425s
user	2m3,976s
sys	0m0,400s

Could you please use 'time' to get accurate numbers?
Comment 4 Telesto 2017-10-17 11:44:18 UTC
LibO6 on Windows
$ time instdir/program/soffice --headless --convert-to pdf "C:\Demo.odt"
convert C:\Demo.odt -> C:\cygwin\home\DEMO\bibisect-win32-6.0\Demo.pdf using filter : writer_pdf_Export

real    1m8,039s
user    0m0,015s
sys     0m0,000s

LibO5.2 on Windows
$ time instdir/program/soffice --headless --convert-to pdf "C:\Demo.odt"
convert C:\Demo.odt -> C:\cygwin\home\DEMO\bibisect-win32-5.2\Demo.pdf using filter : writer_pdf_Export

real    0m29,305s
user    0m0,000s
sys     0m0,000s

It's the same file, I only renamed it.
Comment 5 Telesto 2017-10-29 17:04:28 UTC
*** Bug 113139 has been marked as a duplicate of this bug. ***
Comment 6 Telesto 2017-10-29 17:05:10 UTC
*** Bug 113350 has been marked as a duplicate of this bug. ***
Comment 7 Telesto 2017-10-29 17:06:07 UTC
*** Bug 112979 has been marked as a duplicate of this bug. ***
Comment 8 Khaled Hosny 2017-10-30 09:10:29 UTC
Can someone run this in a profiler and find where the new time is spent? I’m not very familiar with Windows to know how to do that, sorry.
Comment 9 Telesto 2017-10-30 11:45:57 UTC
Created attachment 137368 [details]
Very Sleepy results

(In reply to Khaled Hosny from comment #8)
> Can someone run this in a profiler and find where the new time is spent? I’m
> not very familiar with Windows to know how to do that, sorry.

I created a time profile with very sleepy (http://www.codersnotes.com/sleepy/).
http://github.com/CyberShadow/verysleepy/releases/download/v0.90/verysleepy-cs-0.90.exe

Not sure how reliable it is, but it might work. 

I did three runs (x86). Two with LibO 5.3.7.2 (old and new layout) and one with a LibO6 debug build from 22 oct with symbols.
Comment 10 Telesto 2017-11-02 20:55:10 UTC
Created attachment 137481 [details]
Screenshot

Most time is spend in ScriptRun:

u_getNumericValue_59	icuuc59	[unknown]	0	0x5c1f6ad7
uscript_getScript_59	icuuc59	[unknown]	0	0x5c1f8d96
vcl::ScriptRun::next	vcllo	c:\cygwin\home\tinderbox\master\vcl\source\gdi\scrptrun.cxx	162	0x5c77e8dd
vcl::TextLayoutCache::TextLayoutCache	vcllo	c:\cygwin\home\tinderbox\master\vcl\source\gdi\commonsallayout.cxx	290	0x5c782423
CommonSalLayout::LayoutText	vcllo	c:\cygwin\home\tinderbox\master\vcl\source\gdi\commonsallayout.cxx	454	0x5c783d28
Comment 11 Khaled Hosny 2017-11-03 00:09:35 UTC
(In reply to Telesto from comment #10)
> Created attachment 137481 [details]
> Screenshot
> 
> Most time is spend in ScriptRun:
> 
> u_getNumericValue_59	icuuc59	[unknown]	0	0x5c1f6ad7
> uscript_getScript_59	icuuc59	[unknown]	0	0x5c1f8d96
> vcl::ScriptRun::next	vcllo
> c:\cygwin\home\tinderbox\master\vcl\source\gdi\scrptrun.cxx	162	0x5c77e8dd
> vcl::TextLayoutCache::TextLayoutCache	vcllo
> c:\cygwin\home\tinderbox\master\vcl\source\gdi\commonsallayout.cxx	290
> 0x5c782423
> CommonSalLayout::LayoutText	vcllo
> c:\cygwin\home\tinderbox\master\vcl\source\gdi\commonsallayout.cxx	454
> 0x5c783d28

Debug builds are unreliable for performance profiling, you need to do this with a non-debug build.
Comment 12 Telesto 2017-11-03 08:31:42 UTC
Created attachment 137491 [details]
Screenshot Non-Debug

Version: 6.0.0.0.alpha1+
Build ID: 13c5dd1d98a480cb01ca8f24242c80e326e4ade8
CPU threads: 4; OS: Windows 6.3; UI render: default; 
TinderBox: Win-x86@42, Branch:master, Time: 2017-10-30_23:52:07
Locale: nl-NL (nl_NL); Calc: CL
Comment 13 Telesto 2017-11-03 08:32:46 UTC
Created attachment 137492 [details]
Very Sleepy time profile results
Comment 14 Telesto 2017-11-03 08:58:32 UTC
Created attachment 137493 [details]
Very sleepy when exporting to PDF in multi-page view

I probably found a second issue.
1. Exporting to PDF is single page view (or using command line) is slow
2. Doing that in multi-page view makes thing even slower (something about freeing SwAnchoredDrawObject::IsValidPos) [Not sure if I should report this here, though]
Comment 15 Telesto 2017-11-03 09:00:59 UTC
Created attachment 137494 [details]
SHGetFileInfoW Non-Debug build
Comment 16 Telesto 2017-11-15 19:40:41 UTC
Only for the record. Another example.
1. Open attachment bug 123999
2. Hold page down key and take notice of the time to scroll down with page down (a similar increase as with the export time). LibO5.3 with the old layout engine noticeably faster. 
Setting to win only
Comment 17 Khaled Hosny 2017-11-15 20:30:11 UTC
(In reply to Telesto from comment #16)
> Only for the record. Another example.
> 1. Open attachment bug 123999
> 2. Hold page down key and take notice of the time to scroll down with page
> down (a similar increase as with the export time). LibO5.3 with the old
> layout engine noticeably faster. 
> Setting to win only

The old layout engine on Windows (for Latin text) was a very simplistic and didn’t do much. It would be interesting to compare with non-Latin text (e.g. Arabic) to have a more meaningful comparison.
Comment 18 Telesto 2017-11-15 20:53:01 UTC
Created attachment 137792 [details]
Example file

> The old layout engine on Windows (for Latin text) was a very simplistic and
> didn’t do much. It would be interesting to compare with non-Latin text (e.g.
> Arabic) to have a more meaningful comparison.

Scrolling speed with Harbuzz is a little slower
Comment 19 Telesto 2017-11-16 08:06:35 UTC
Similar result with MacOS

Version: 6.0.0.0.alpha1
Build ID: c1d1f859b268f650143d48f294999cda0fa57350
CPU threads: 4; OS: Mac OS X 10.12.6; UI render: default; 
Locale: nl-NL (nl_NL.UTF-8); Calc: group

MacBook-Air-van:~ demo$ time /Applications/LibreOfficeDev.app/Contents/MacOS/soffice --headless --convert-to pdf /Users/demo/Downloads/Demo\(3\)\ -\ kopie.odt --outdir /Users/demo/Documents/
convert /Users/demo/Downloads/Demo(3) - kopie.odt -> /Users/demo/Documents//Demo(3) - kopie.pdf using filter : writer_pdf_Export
Overwriting: /Users/demo/Documents//Demo(3) - kopie.pdf

real	2m1.820s
user	1m59.029s
sys	0m2.147s

-----------------

Version: 5.3.7.2
Build ID: 6b8ed514a9f8b44d37a1b96673cbbdd077e24059
CPU Threads: 4; OS Version: Mac OS X 10.12.6; UI Render: default; Layout Engine: old; 
Locale: nl-NL (nl_NL.UTF-8); Calc: group

without Harfbuzz

MacBook-Air-van:~ demo$ time /Applications/LibreOffice.app/Contents/MacOS/soffice --headless --convert-to pdf /Users/demo/Downloads/Demo\(3\)\ -\ kopie.odt --outdir /Users/demo/Documents/
convert /Users/demo/Downloads/Demo(3) - kopie.odt -> /Users/demo/Documents//Demo(3) - kopie.pdf using filter : writer_pdf_Export
Overwriting: /Users/demo/Documents//Demo(3) - kopie.pdf

real	1m12.281s
user	1m9.470s
sys	0m1.874s

with harfbuzz
MacBook-Air-van:~ demo$ time /Applications/LibreOffice.app/Contents/MacOS/soffice --headless --convert-to pdf /Users/demo/Downloads/Demo\(3\)\ -\ kopie.odt --outdir /Users/demo/Documents/
convert /Users/demo/Downloads/Demo(3) - kopie.odt -> /Users/demo/Documents//Demo(3) - kopie.pdf using filter : writer_pdf_Export
Overwriting: /Users/demo/Documents//Demo(3) - kopie.pdf

real	1m52.251s
user	1m48.966s
sys	0m2.180s
Comment 20 Telesto 2017-11-16 20:46:21 UTC
Created attachment 137818 [details]
Xcode Instruments Screenshots time profiler & code peaks
Comment 21 Buovjaga 2017-11-22 11:23:58 UTC
*** Bug 108513 has been marked as a duplicate of this bug. ***
Comment 22 Buovjaga 2017-11-22 11:24:33 UTC
NEW per dupes.
Comment 23 Telesto 2017-11-25 21:46:13 UTC
Created attachment 137988 [details]
Example file

A fast way to reproduce:
1. Open the attached file
2. Hold scroll down & monitor CPU usage; CPU will be 25% with the new Text Layout engine and 12% with the old one. Scrolling speed is fine, though

Repro on Windows, but not on Linux
Comment 24 Khaled Hosny 2017-11-26 12:34:15 UTC
Any meaningful comparison should use Arabic, Indic or other complex scripts. The old layout engines had a shortcut for Latin and similar scripts that did very simplistic and fast layout, the new engine does not have such shortcuts in principle.

This is not to say our text layout is sub-optimal, it is very sub-optimal actually, but that is not a regression. It has always been sub-optimal, we were just lying by handling Latin in a special way.
Comment 25 Telesto 2017-11-27 11:02:50 UTC
(In reply to Khaled Hosny from comment #24)
> Any meaningful comparison should use Arabic, Indic or other complex scripts.
> The old layout engines had a shortcut for Latin and similar scripts that did
> very simplistic and fast layout, the new engine does not have such shortcuts
> in principle.

I compared it again, with some Arabic text. Slow with the old engine, bit faster but still slow with the new engine. 

> This is not to say our text layout is sub-optimal, it is very sub-optimal
> actually, but that is not a regression. It has always been sub-optimal, we
> were just lying by handling Latin in a special way.

It depends how you interpret a regression. There are multiple sub-types:
a. Regression due a change in the operation system (the code has not changed, isn't working anymore as expected) 
b. A regression between versions of LibreOffice (the behavior changed to the worse, sec)
c. Technical approach. A unexpected /unintended performance loss.

A/B feel like regressions in the users point of view, but maybe not in the technical sense of a dev. So it's depending how the keywords are meant (not clear to me)

Anyway, losing the Latin shortcuts is quite noticeable in quite a lot area's. (I keep finding new variant). For example large copy/paste actions

I would add it to the tender suggestions. It's quite a core feature. Or an attempt to find a sponsor for this one :-).
Comment 26 Khaled Hosny 2017-11-27 15:20:59 UTC
(In reply to Telesto from comment #25)
> I would add it to the tender suggestions. It's quite a core feature.

Please do.

> Or an attempt to find a sponsor for this one :-).

Good luck with that. I've been told (and experienced) no one cares about text layout, no one with deep enough pockets to finance such work.
Comment 27 Telesto 2018-02-19 09:19:20 UTC
Only for the record (before I forget), an additional way to repro
1. Open the attached file 136841
2. Wait until the CPU usage falls back to around 0
3. At a page header

Still hoping for tender is this area ;-)
Comment 28 Telesto 2018-03-14 11:32:25 UTC
A more real life example: attachment 140185 [details]
Comment 29 Timur 2018-06-14 12:20:15 UTC
*** Bug 116399 has been marked as a duplicate of this bug. ***
Comment 30 Telesto 2018-07-02 14:10:35 UTC
*** Bug 118165 has been marked as a duplicate of this bug. ***
Comment 32 Telesto 2018-10-27 13:09:42 UTC
Repro with
Version: 6.2.0.0.alpha1+
Build ID: 96cf06c947838120e37f3fbb4d0543dd882cb20c
CPU threads: 4; OS: Windows 6.3; UI render: default; VCL: win; 
TinderBox: Win-x86@42, Branch:master, Time: 2018-10-25_22:57:51
Locale: nl-NL (nl_NL); Calc: CL
Comment 33 Telesto 2018-10-27 13:20:41 UTC
@Miklos
Not sure if you're interested, but this might be related to "Text layout performance". See comment 24
Comment 34 Buovjaga 2019-04-06 17:44:29 UTC
Created attachment 150572 [details]
Perf flamegraph

Arch Linux 64-bit
Version: 6.3.0.0.alpha0+
Build ID: 558956dc811a1f0f07411e348f7081a467bbc3b5
CPU threads: 8; OS: Linux 5.0; UI render: default; VCL: gtk3; 
Locale: fi-FI (fi_FI.UTF-8); UI-Language: en-US
Calc: threaded
Built on 4 April 2019
Comment 35 Telesto 2019-05-08 14:20:58 UTC
Created attachment 151246 [details]
Perf Flame Graph Win

Version: 6.3.0.0.alpha0+
Build ID: 128145e227ef91fb2f23893e73d38ae72cf074e5
CPU threads: 2; OS: Windows 6.3; UI render: default; VCL: win; 
Locale: nl-NL (nl_NL); UI-Language: en-US
Calc: threaded

symbol-only build
Comment 36 Xisco Faulí 2019-11-29 12:50:18 UTC
Changing priority to 'high' since the number of duplicates is 5 or higher
Comment 37 Xisco Faulí 2019-12-02 13:40:25 UTC
Changing priority to 'highest' since this a regression and the number of duplicates is higher than 5 or the number of people in CC higher than 20
Comment 38 Xisco Faulí 2019-12-05 10:59:42 UTC
it takes

real	5m10,981s
user	4m53,429s
sys	0m2,727s


in

Version: 6.5.0.0.alpha0+
Build ID: 304368c7be2c9e408cc3884183e39d90a4b15da7
CPU threads: 4; OS: Linux 4.15; UI render: default; VCL: gtk3; 
Locale: ca-ES (ca_ES.UTF-8); UI-Language: en-US
Calc: threaded
Comment 39 Xisco Faulí 2019-12-05 11:01:00 UTC
@Noel, I thought you could be interested in this issue...
Comment 40 Noel Grandin 2019-12-17 12:27:09 UTC
I have a small fix for this issue, but the bulk of the regression is simply due to the fact that we are doing more work these days because we cater properly for more languages.
Comment 41 Commit Notification 2019-12-17 12:51:59 UTC
Noel Grandin committed a patch related to this issue.
It has been pushed to "master":

https://git.libreoffice.org/core/commit/11c0effe3def917ec2002a30dbbcca1c5758ffa9

tdf#112989 reduce export to PDF time

It will be available in 6.5.0.

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

Affected users are encouraged to test the fix and report feedback.
Comment 42 Xisco Faulí 2019-12-17 14:28:42 UTC
using attachment 136841 [details], export time goes from

real	4m22,797s
user	4m16,022s
sys	0m2,515s

before Noel's commit to

real	4m1,308s
user	3m57,773s
sys	0m2,485s

after Noel's commit
Comment 43 Commit Notification 2019-12-17 22:53:36 UTC
Noel Grandin committed a patch related to this issue.
It has been pushed to "libreoffice-6-4":

https://git.libreoffice.org/core/commit/580f2b93a9c754743341e5e2f40084bceb8a1680

tdf#112989 reduce export to PDF time

It will be available in 6.4.0.1.

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

Affected users are encouraged to test the fix and report feedback.
Comment 44 Xisco Faulí 2019-12-18 13:59:30 UTC
took measurements again:

real	3m38,023s
user	3m35,903s
sys	0m1,863s

in

Version: 6.5.0.0.alpha0+
Build ID: fb1eac64df88baae9f211d052793773686c0e180
CPU threads: 4; OS: Linux 4.15; UI render: default; VCL: gtk3; 
Locale: ca-ES (ca_ES.UTF-8); UI-Language: en-US
Calc: threaded

-------------------------

real	4m7,506s
user	4m4,868s
sys	0m2,327s

in

Version: 6.2.0.0.alpha1+
Build ID: a20a2d7e0d28658f2d9089da076961a599833a28
CPU threads: 4; OS: Linux 4.15; UI render: default; VCL: gtk3; 
Locale: ca-ES (ca_ES.UTF-8); UI-Language: en-US
Calc: threaded

-------------------------

real	4m27,078s
user	4m23,393s
sys	0m2,911s

in

Version: 5.4.0.0.alpha1+
Build ID: 9feb7f7039a3b59974cbf266922177e961a52dd1
CPU threads: 4; OS: Linux 4.15; UI render: default; VCL: gtk3; 
Locale: ca-ES (ca_ES.UTF-8); Calc: group

-------------------------

real	8m18,685s
user	8m14,931s
sys	0m2,220s

in

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

-------------------------

real	10m22,674s
user	10m16,218s
sys	0m2,475s

in

Version: 4.3.0.0.alpha1+
Build ID: c15927f20d4727c3b8de68497b6949e72f9e6e9e
Comment 45 Buovjaga 2019-12-18 14:34:00 UTC
Thanks for the improvement, Noel!

I'm going to go ahead and close this as fixed. If someone is able to articulate precisely what else could be done code-wise, please open a new report. It is clear at this point that we need a report with a proposed strategy - pure observation is not enough.
Comment 46 Xisco Faulí 2019-12-18 14:35:11 UTC
I'm sorry but this issue is just a mess.
First, it was confirmed in comment 22 per duplicates but all the duplicates are from the same person.
Second, This issue is about exporting to PDF, comment 16, comment 23 and some duplicates are not about exporting PDF but other steps. What is their relation ?
Finally, as I mentioned in comment and comment 44, it's faster in master than before 8f2dd1df1d6cc94ebbc1149de72bc6d6dffa6533. Besides, Noel pushed a patch improving it.
Closing this issue as RESOLVED FIXED. I'll create a follow-up bug for the time it takes to export to PDF in master, in case it can be improved.
@Telesto, please recheck the duplicates ones in master, if you still reproduce them, change their status to UNCONFIRMED and wait for someone to confirm it. Thanks in advance.

@Noel, thanks for taking a look at this issue and improving it
Comment 47 Xisco Faulí 2019-12-18 14:55:20 UTC
(In reply to Xisco Faulí from comment #46)
> Closing this issue as RESOLVED FIXED. I'll create a follow-up bug for the
> time it takes to export to PDF in master, in case it can be improved.

Reusing bug 116400 for that