Bug 155212 - Writer is very slow when opening a file that includes embedded fonts (macOS)
Summary: Writer is very slow when opening a file that includes embedded fonts (macOS)
Status: CLOSED FIXED
Alias: None
Product: LibreOffice
Classification: Unclassified
Component: Writer (show other bugs)
Version:
(earliest affected)
7.5.3.2 release
Hardware: x86-64 (AMD64) macOS (All)
: medium normal
Assignee: Patrick (volunteer)
URL:
Whiteboard: target:25.2.0 target:24.8.0.0.beta2 t...
Keywords: bibisected, bisected, perf, regression
: 158915 161459 (view as bug list)
Depends on:
Blocks: File-Opening
  Show dependency treegraph
 
Reported: 2023-05-09 10:33 UTC by Chris Tapp
Modified: 2024-08-23 11:53 UTC (History)
7 users (show)

See Also:
Crash report or crash signature:


Attachments
File without fonts (41.08 KB, application/vnd.oasis.opendocument.text)
2023-05-09 10:35 UTC, Chris Tapp
Details
File with fonts (5.71 MB, application/vnd.oasis.opendocument.text)
2023-05-09 10:35 UTC, Chris Tapp
Details
CPU profile of --convert-to pdf With-Fonts.odt using Xcode's Instruments application (1.79 MB, image/png)
2024-06-07 21:44 UTC, Patrick (volunteer)
Details

Note You need to log in before you can comment on or make changes to this bug.
Description Chris Tapp 2023-05-09 10:33:53 UTC
Description:
I have two documents that use the same fonts (Open Sans, Courier New). One has the fonts embedded, the other does not, but they are otherwise identical (and basically empty).

Opening the document with the embedded fonts on an Intel Mac means that Writer goes unresponsive for several minutes. The document without the embedded fonts opens as expected.

Steps to Reproduce:
1.Open the "With-Fonts.odt" file that is attached to this ticket.
2.Open the "Without-Fonts.odt" file that is attached to this ticket.


Actual Results:
1.The "With-Fonts.odt" file takes ~290s to open - CPU is at 90%.
2.The "Without-Fonts.odt" file takes ~4s to open.


Expected Results:
The "With-Fonts.odt" file should take approximately the same amount of time to open.


Reproducible: Always


User Profile Reset: Yes

Additional Info:
Saving "With-Fonts.odt" also takes significantly longer. It would be reasonable for it to take a bit longer, but the times are ~15s vs 3s.

Version: 7.5.3.2 (X86_64) / LibreOffice Community
Build ID: 9f56dff12ba03b9acd7730a5a481eea045e468f3
CPU threads: 12; OS: Mac OS X 13.3.1; UI render: default; VCL: osx
Locale: en-GB (en_GB.UTF-8); UI: en-US
Calc: threaded
Comment 1 Chris Tapp 2023-05-09 10:35:18 UTC
Created attachment 187164 [details]
File without fonts
Comment 2 Chris Tapp 2023-05-09 10:35:45 UTC
Created attachment 187165 [details]
File with fonts
Comment 3 ⁨خالد حسني⁩ 2023-05-09 15:30:19 UTC
The file with fonts is indeed slower, but it is not that slow. One command line:


$ time /Applications/LibreOffice.app/Contents/MacOS/soffice --convert-to pdf Without-Fonts.odt
        2.93 real         1.85 user         0.62 sys

$ time /Applications/LibreOffice.app/Contents/MacOS/soffice --convert-to pdf With-Fonts.odt
       18.86 real        11.10 user         2.67 sys

So it takes 18 seconds not minutes.
Comment 4 Roman Kuznetsov 2023-05-09 18:21:58 UTC
hm...

Version: 7.6.0.0.alpha0+ (X86_64) / LibreOffice Community
Build ID: 69d0be09ad81935f7da4b6f8d036c3562357d068
CPU threads: 16; OS: Windows 10.0 Build 19045; UI render: Skia/Raster; VCL: win
Locale: ru-RU (ru_RU); UI: ru-RU
Calc: CL threaded

opens the File with fonts instantly

here is AMD Ryzen 5700U and Windows 10 on SSD

macOS only problem?
Comment 5 Chris Tapp 2023-05-10 09:39:41 UTC
(In reply to خالد حسني from comment #3)
> The file with fonts is indeed slower, but it is not that slow. One command
> line:
> 
> 
> $ time /Applications/LibreOffice.app/Contents/MacOS/soffice --convert-to pdf
> Without-Fonts.odt
>         2.93 real         1.85 user         0.62 sys
> 
> $ time /Applications/LibreOffice.app/Contents/MacOS/soffice --convert-to pdf
> With-Fonts.odt
>        18.86 real        11.10 user         2.67 sys
> 
> So it takes 18 seconds not minutes.

What system do you have? Running those commands here I get:

% time /Applications/LibreOffice.app/Contents/MacOS/soffice --convert-to pdf Without-Fonts.odt
   0.49s user 0.10s system 50% cpu 1.187 total

% time /Applications/LibreOffice.app/Contents/MacOS/soffice --convert-to pdf With-Fonts.odt
   0.55s user 0.32s system 0% cpu 20:32.21 total

Which shows embedded fonts is much slower - in fact, it is quicker to load the document and then export that it is to export from the command line.
Comment 6 Chris Tapp 2023-05-10 13:24:51 UTC
(In reply to Chris Tapp from comment #5)
> (In reply to خالد حسني from comment #3)
> > The file with fonts is indeed slower, but it is not that slow. One command
> > line:
> > 
> > 
> > $ time /Applications/LibreOffice.app/Contents/MacOS/soffice --convert-to pdf
> > Without-Fonts.odt
> >         2.93 real         1.85 user         0.62 sys
> > 
> > $ time /Applications/LibreOffice.app/Contents/MacOS/soffice --convert-to pdf
> > With-Fonts.odt
> >        18.86 real        11.10 user         2.67 sys
> > 
> > So it takes 18 seconds not minutes.
> 
> What system do you have? Running those commands here I get:
> 
> % time /Applications/LibreOffice.app/Contents/MacOS/soffice --convert-to pdf
> Without-Fonts.odt
>    0.49s user 0.10s system 50% cpu 1.187 total
> 
> % time /Applications/LibreOffice.app/Contents/MacOS/soffice --convert-to pdf
> With-Fonts.odt
>    0.55s user 0.32s system 0% cpu 20:32.21 total
> 
> Which shows embedded fonts is much slower - in fact, it is quicker to load
> the document and then export that it is to export from the command line.

Meant to add:

Which is strange, as it shows a much longer total time, but similar system and user times.
Comment 7 Chris Tapp 2023-05-10 13:46:55 UTC
I'm closing this as I'm now seeing a "reasonable" speed difference after restarting the system - it appears to be something within the OS, which is consistent with timings reported for the command line runs.

Thanks for the comments.
Comment 8 ⁨خالد حسني⁩ 2023-05-10 14:50:48 UTC
(In reply to Roman Kuznetsov from comment #4)
> macOS only problem?

Yes, it seems that we reload the system font list after loading each font from the document and this seems to be a bit slow on macOS.
Comment 9 Chris Tapp 2023-05-11 07:31:08 UTC
I've decided to reopen this as the problem reappeared shortly after the reboot, so it is not clear to me if the issue is with the system or writer.
Comment 10 Roman Kuznetsov 2023-05-11 07:34:02 UTC
Let's set it to NEW by Khaled's confirming
Comment 11 Chris Tapp 2023-05-11 11:04:17 UTC
More testing:

If LibreOffice is open, but there are no open documents:

% time /Applications/LibreOffice.app/Contents/MacOS/soffice --convert-to pdf With-Fonts.odt
   0.49s user 0.10s system 4% cpu 12.369 total

If LibreOffice is open and displaying Without-Fonts.odt:

% time /Applications/LibreOffice.app/Contents/MacOS/soffice --convert-to pdf With-Fonts.odt
   0.49s user 0.10s system 0% cpu 2:45.82 total

So, user and system time are the same, but there is a large increase in the total processing time.

If there are 6 documents open, then the total time increases even more (other timings the same):

% time /Applications/LibreOffice.app/Contents/MacOS/soffice --convert-to pdf With-Fonts.odt
   0.50s user 0.11s system 0% cpu 18:16.57 total

To me, this looks like there may be a lock related issue somewhere?
Comment 12 Telesto 2024-06-07 17:58:23 UTC
*** Bug 161459 has been marked as a duplicate of this bug. ***
Comment 13 Telesto 2024-06-07 17:59:25 UTC
*** Bug 158915 has been marked as a duplicate of this bug. ***
Comment 14 Dennis Roczek 2024-06-07 18:25:03 UTC
(In reply to ⁨خالد حسني⁩ from comment #3)
> The file with fonts is indeed slower, but it is not that slow. One command
> line:
> 
> 
> $ time /Applications/LibreOffice.app/Contents/MacOS/soffice --convert-to pdf
> Without-Fonts.odt
>         2.93 real         1.85 user         0.62 sys
> 
> $ time /Applications/LibreOffice.app/Contents/MacOS/soffice --convert-to pdf
> With-Fonts.odt
>        18.86 real        11.10 user         2.67 sys
> 
> So it takes 18 seconds not minutes.

Depend on hardware. Macos macbook 2014 is loading as hell long. Win 10 surface go (!) instantly (In reply to Roman Kuznetsov from comment #4)
> hm...
> 
> Version: 7.6.0.0.alpha0+ (X86_64) / LibreOffice Community
> Build ID: 69d0be09ad81935f7da4b6f8d036c3562357d068
> CPU threads: 16; OS: Windows 10.0 Build 19045; UI render: Skia/Raster; VCL:
> win
> Locale: ru-RU (ru_RU); UI: ru-RU
> Calc: CL threaded
> 
> opens the File with fonts instantly
> 
> here is AMD Ryzen 5700U and Windows 10 on SSD
> 
> macOS only problem?
Yes. Tested also ubuntu, see dp in #161459
Comment 15 Dennis Roczek 2024-06-07 18:25:28 UTC
@chris is this a regression
Comment 16 Patrick (volunteer) 2024-06-07 21:44:54 UTC
Created attachment 194600 [details]
CPU profile of --convert-to pdf With-Fonts.odt using Xcode's Instruments application

Note: on macOS, Instruments can only attach to non-release builds such as a nightly master build or a local build.
Comment 17 Stéphane Guillou (stragu) 2024-06-07 22:10:54 UTC
(In reply to Dennis Roczek from comment #15)
> @chris is this a regression
As per duplicate bug 158915, yes. Not present in 7.3.3.
Comment 18 Telesto 2024-06-07 23:29:39 UTC
FWIW: there was a similar issue on Windows in the past covered by bug 69060, got fixed in 6.3.0. Maybe unrelated though.. the regression here being introduced later on.
Comment 19 Patrick (volunteer) 2024-06-08 14:26:01 UTC
Since this bug only occurs on macOS, I used the debug patch at the end of this comment to see how much time is being spent loading macOS fonts. In my tests, "--convert-to pdf With-Fonts.odt" takes at least 20 seconds on my M1 MacBook Pro.

With the debug patch, the GetCoretextFontList() function gets called 2 times (cumulative time for that is +/- 0.5 seconds) to launch LibreOffice and display the Start Center. Then, when I run "--convert-to pdf With-Fonts.odt", the GetCoretextFontList() function gets called 89 more times and cumulative time in this function jumps to +/- 19 seconds.

I count only 19 fonts in the With-Fonts.odt file so my first guess is that LibreOffice's macOS code is unnecessarily reloading all the system fonts. Not sure where this is happening yet but I will continue to read through the code and see if I can come up with any idea how to reduce the number of system font reloads.

Note: below is the debug patch that I used:

diff --git a/vcl/quartz/SystemFontList.cxx b/vcl/quartz/SystemFontList.cxx
index 3ca09bfcf21e..c2a9cf97b1c5 100644
--- a/vcl/quartz/SystemFontList.cxx
+++ b/vcl/quartz/SystemFontList.cxx
@@ -282,12 +282,21 @@ bool SystemFontList::Init()
 
 std::unique_ptr<SystemFontList> GetCoretextFontList()
 {
+static unsigned long nCount = 0;
+static long long aTotal;
+auto aStart = std::chrono::high_resolution_clock::now();
+nCount++;
     std::unique_ptr<SystemFontList> pList(new SystemFontList());
     if( !pList->Init() )
     {
-        return nullptr;
+        // return nullptr;
+        pList.reset();
     }
 
+auto aEnd = std::chrono::high_resolution_clock::now();
+auto aDeltaTime = aEnd - aStart;
+aTotal += std::chrono::duration_cast<std::chrono::milliseconds>(aDeltaTime).count();
+fprintf(stderr, "Total elapsed milliseconds: %lu %lli\n", nCount, aTotal);
     return pList;
 }
Comment 20 Patrick (volunteer) 2024-06-08 17:31:20 UTC
(In reply to Patrick Luby (volunteer) from comment #19)
> With the debug patch, the GetCoretextFontList() function gets called 2 times
> (cumulative time for that is +/- 0.5 seconds) to launch LibreOffice and
> display the Start Center. Then, when I run "--convert-to pdf
> With-Fonts.odt", the GetCoretextFontList() function gets called 89 more
> times and cumulative time in this function jumps to +/- 19 seconds.

Another data point: I launched LibreOffice with my debug patch, opened 10 empty Writer documents, and ran "--convert-to pdf With-Fonts.odt". The GetCoretextFontList() function was called nearly 3000 times and the run took around 11 minutes to complete.

I also saw memory usage climb steadily to a few hundred megabytes during the above run so my guess is that LibreOffice's macOS code is creating a separate system font list for each window and each of its internal tree of child subwindows (e.g. buttons, comboboxes, status bar, etc.).

I don't see any calls to the GetCoretextFontList() function when opening new documents or exsiting documents that do not contain fonts. So the creation of excessive copies of the system font list is triggered when LibreOffice tries to update the system font list after loading the .odt's embedded fonts.
Comment 21 Telesto 2024-06-09 00:03:34 UTC
(In reply to Patrick Luby (volunteer) from comment #20)
Your observation is matching the one in bug 114697; technical analysis by Mike Kaganski); duplicate of bug 69060, IMHO

Commit message for bug 69060 https://git.libreoffice.org/core/+/98d71c4e0847797a4ba9229a8e6d832a8a3d5e0f%5E%21

This accumulates all calls to OutputDevice::ImplRefreshAllFontData
while loading document's model, to avoid multiple updates for each
imported font. After loading, OutputDevice::ImplRefreshAllFontData
is executed once.
Comment 22 Dennis Roczek 2024-06-10 18:50:18 UTC
So maybe it help, but I did a bibisect and found the problematic commit:

tdf#72456: Don’t cache macOS font list - https://git.libreoffice.org/core/commit/3b6e9582ce43242a2304047561116bb26808408b

More or less, the commit is by design.
Comment 23 Patrick (volunteer) 2024-06-10 19:24:13 UTC
(In reply to Dennis Roczek from comment #22)
> So maybe it help, but I did a bibisect and found the problematic commit:
> 
> tdf#72456: Don’t cache macOS font list -
> https://git.libreoffice.org/core/commit/
> 3b6e9582ce43242a2304047561116bb26808408b
> 
> More or less, the commit is by design.

Thank you for bibisecting this. So I think I have enough data now to attempt a fix. I will try to reenable caching of the font list, but only during the brief time that font updates are locked (see commit https://git.libreoffice.org/core/+/98d71c4e0847797a4ba9229a8e6d832a8a3d5e0f%5E%21). Hopefully, this won't break Khaled's fix for tdf#72456.
Comment 24 Commit Notification 2024-06-12 21:02:50 UTC
Patrick Luby committed a patch related to this issue.
It has been pushed to "master":

https://git.libreoffice.org/core/commit/195ed184dd1552816bdebfe9c54fb6408bf91cc1

tdf155212 clear the cached system font list after loading a font

It will be available in 25.2.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 25 Patrick (volunteer) 2024-06-12 21:14:28 UTC
I have committed a fix this bug. If anyone can test my fix, it would be much appreciated.

I added back the system font list cache but, to avoid tdf#72456, I force the cache to be cleared immediately after LibreOffice loads any fonts on macOS. So, when a document with embedded fonts is finished loading and LibreOffice calls for each window and subwindow to refresh its system font list, the first window finds the cache empty and reloads the latest system fonts. Then, all of the remaining windows and subwindows use the system font list cached by the first window.

Anyway, the fix should be in tomorrow's (13 June 2024) nightly master builds:

https://dev-builds.libreoffice.org/daily/master/current.html

Note for macOS testers: the nightly master builds install in /Applications/LibreOfficeDev.app. These builds are not codesigned like regular LibreOffice releases so you will need to execute the following Terminal command after installation but before you launch /Applications/LibreOfficeDev:

xattr -d com.apple.quarantine /Applications/LibreOfficeDev.app
Comment 26 Patrick (volunteer) 2024-06-12 21:26:58 UTC
I forgot to mention the times that I now see when I launch my local debug build (which is likely slower than the nightly or release builds), opened 1 or more empty Writer documents, and then the following command:

time ./instdir/LibreOfficeDev.app/Contents/MacOS/soffice --convert-to pdf ~/Downloads/With-Fonts.odt

Here is the results:

1. With 1 Writer document open:
   ./instdir/LibreOfficeDev.app/Contents/MacOS/soffice --convert-to pdf   0.95s user 0.04s system 43% cpu 2.262 total

2. With 10 Writer documents open:
   ./instdir/LibreOfficeDev.app/Contents/MacOS/soffice --convert-to pdf   0.95s user 0.04s system 21% cpu 4.579 total

Before my fix, case 1 took 20 - 30 seconds and case 2 would take at least 10 minutes.
Comment 27 Commit Notification 2024-06-13 13:41:29 UTC
Patrick Luby committed a patch related to this issue.
It has been pushed to "libreoffice-24-8":

https://git.libreoffice.org/core/commit/c270131be7a8ecc9599dc0f0fe6ea24c650f32ed

tdf#155212 clear the cached system font list after loading a font

It will be available in 24.8.0.0.beta2.

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 28 Commit Notification 2024-06-14 23:09:17 UTC
Patrick Luby committed a patch related to this issue.
It has been pushed to "libreoffice-24-2":

https://git.libreoffice.org/core/commit/3fdb05a2c0a407d96b40fb8424b2f1ed8298f127

tdf#155212 clear the cached system font list after loading a font

It will be available in 24.2.5.

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 29 Dennis Roczek 2024-06-19 14:02:16 UTC
(In reply to Patrick Luby (volunteer) from comment #25)
> I have committed a fix this bug. If anyone can test my fix, it would be much
> appreciated.

Wow! Much, much faster! Love it!

Thanks for your work!
Comment 30 Chris Tapp 2024-08-23 11:53:44 UTC
Thanks - just tried this with 24.8.0.3 and performance is great!