Bug 103571 - macOS 100% CPU usage when minimizing screen if multiple documents are opened
Summary: macOS 100% CPU usage when minimizing screen if multiple documents are opened
Status: VERIFIED FIXED
Alias: None
Product: LibreOffice
Classification: Unclassified
Component: LibreOffice (show other bugs)
Version:
(earliest affected)
4.4.0.1 rc
Hardware: All Mac OS X (All)
: high critical
Assignee: Tor Lillqvist
URL:
Whiteboard: target:6.1.0 target:6.0.3
Keywords: perf, regression
: 103126 105068 107578 113467 (view as bug list)
Depends on:
Blocks: MacOS-Performance
  Show dependency treegraph
 
Reported: 2016-10-29 08:25 UTC by Telesto
Modified: 2018-03-05 15:10 UTC (History)
9 users (show)

See Also:
Crash report or crash signature:


Attachments
Xcode Instruments Memory Allocation full list (15.78 KB, text/csv)
2016-10-29 13:58 UTC, Telesto
Details
Assembly Information around the malloc (326.49 KB, application/vnd.oasis.opendocument.text)
2016-10-29 14:02 UTC, Telesto
Details
export SAL_LOG=+INFO,+WARN (4.52 MB, application/zip)
2016-11-03 10:07 UTC, Telesto
Details
LLDB output (759.94 KB, text/plain)
2016-11-08 14:13 UTC, Telesto
Details
LLDB backtrace (2.90 MB, text/plain)
2016-11-08 15:22 UTC, Telesto
Details
LLDB Backtrace Font Issue (2.74 MB, text/plain)
2016-11-11 10:51 UTC, Telesto
Details
LLDB Backtrace, Build Log, Instruments Time Profile (2.86 MB, application/x-compressed)
2017-01-05 09:44 UTC, Telesto
Details
LLDB Backtrace, Build Log (668.26 KB, application/zip)
2017-01-12 11:46 UTC, Telesto
Details
Xcode instruments screenshots and BT (912.50 KB, application/x-zip-compressed)
2017-09-07 09:23 UTC, Telesto
Details

Note You need to log in before you can comment on or make changes to this bug.
Description Telesto 2016-10-29 08:25:29 UTC
Description:
When minimizing one of multiple opened documents LO gets unresponsive for a while, depending on the number of opened documents and system specs. With LibreOffice 4.3.7.2 everything is fine. The problem seems to be introduced between LO 4.3.7.2 and 4.4.0.1 RC and seems to be related to a change Apple has made.  I haven't exactly tested it yet for this one, but I suppose MacOS X Yosemite or up is required (see bug 103248). 

The cause of the problem seems to be the same as bug 103126. The difference is that
- “Automatically hide and show the Dock” isn't enabled
- Sleep isn't required

It seems to be an OSX-specific context-switching

The affected system is a MacBook Air 11" Early 2014 (1,4 Ghz, 4 GB RAM, 128 GB SSD)



Steps to Reproduce:
1. Use a Mac with MacOS Sierra (didn't it with other versions yet but should work) with or without an existing Libreoffice user profile
2. Create plenty blank documents (14 or more; depending on the system specs and the number of opened documents the hang takes longer)
3. Minimize one of the 14 blank documents 

Actual Results:  
The other opened documents will be unresponsive. CPU usage spikes to 100% for particular time. Depending on system specs and the number of opened documents


Expected Results:
LibreOffice stay's responsive


Reproducible: Always

User Profile Reset: YES

Additional Info:


User-Agent: Mozilla/5.0 (Windows NT 6.2; WOW64; rv:45.0) Gecko/20100101 Firefox/45.0
Comment 1 Telesto 2016-10-29 13:58:21 UTC
Created attachment 128344 [details]
Xcode Instruments Memory Allocation full list
Comment 2 Telesto 2016-10-29 14:02:57 UTC
Created attachment 128345 [details]
Assembly Information around the malloc
Comment 3 Telesto 2016-10-30 11:28:49 UTC Comment hidden (obsolete)
Comment 4 Telesto 2016-10-30 13:54:15 UTC
There need to be a saved (default) profile for the bug to occur.
Comment 5 Telesto 2016-11-03 10:07:14 UTC
Created attachment 128463 [details]
export SAL_LOG=+INFO,+WARN

Export SAL_LOG=+INFO,+WARN when minimising on MacOS Sierra 10.12.1 with LO 5.3.0.0.alpha0+
Build ID: a9afa89e953f0f32acf26b143717e7d067cbc75a
CPU Threads: 4; OS Version: Mac OS X 10.12.1; UI Render: default; 
TinderBox: MacOSX-x86_64@49-TDF, Branch:master, Time: 2016-10-13_05:13:57
Locale: nl-NL (nl_NL.UTF-8); Calc: group
Comment 6 Alex Thurgood 2016-11-03 10:12:48 UTC
Confirming.

1) Opened 15 blank documents in LO Writer 5212 OSX 10.12
2) Minimized three of the document windows.
3) LO application becomes unresponsive, even when switching contexts (Space switching) or clicking on other app windows and back to LO app windows.
Comment 7 Telesto 2016-11-03 10:59:31 UTC
The problem isn't specific for a MacOS version. I found it in Mavericks, Yosemite and Sierra (I didn't test El Capitan). The problem is most noticeable since LO 4.4.0.0 and up. Prior, with LO 4.3.7.2, there is just a small hick-up (+/-5 sec) when minimising one or two screens out of 30.
Comment 8 Telesto 2016-11-05 20:26:39 UTC Comment hidden (obsolete)
Comment 9 Michael Meeks 2016-11-07 11:44:30 UTC
Hi Telesto - its great to have your RTF documents with log fragments inside a zip file - but up-loading an ODT or DOCX would be more helpful (and is already compressed / zipped ;-).

Your log seems to be very long on churning debug around langtag and rendering - you can expect a dbgutil build to work rather more hard.

I don't believe the race mentioned in svapp.cxx has anything to do with this FWIW. Of course - hard to do anything without a Mac.

Prolly a better way to find what is going on - is to break in the debugger and step through what is happening in this long delay. The trace suggests we are doing something silly with fonts - almost certainly re-populating / rendering the font pop-downs (perhaps in each window) for a rather large set of fonts.

Would be great to have an xcode trace (with debugging symbols - ie. unless you see CXX files and line numbers in the trace it has not got debugging symbols) - during the slowness.
Comment 10 Telesto 2016-11-08 14:13:36 UTC
Created attachment 128570 [details]
LLDB output

I don't really know my way around in LLDB (novice), and the start of the backtrace is somewhat random but seems to contain some relevant information.
Comment 11 Telesto 2016-11-08 15:22:15 UTC
Created attachment 128576 [details]
LLDB backtrace

This LLDB backtrace seems the contain the problem.
Comment 12 Michael Meeks 2016-11-08 15:46:10 UTC
Ah - so the top of the trace shows that it is taking time in dumping debugging information to a stream (the SAL_LOG stuff) - which is done whether or not we actually end up logging that.

Might be good to continue  and break things a few times through the delay - to see what is going on and consuming the time =)
Comment 13 Michael Meeks 2016-11-08 15:57:10 UTC
Interesting trace - quite possibly we get 'screenParametersChanged' called when windows are minimized / maximised etc.

If OSX is broadcasting that to every app window when we minimize one of them, and then we go on to re-draw the entire window; and then we broadcast this:

    CallCallback( SalEvent::DisplayChanged, nullptr );

to every window as well - we end up with an N^2 re-render of each window =) which seems a little OTT.

Quite possibly:

void AquaSalFrame::screenParametersChanged()
{
    UpdateFrameGeometry();

    if( mpGraphics )
        mpGraphics->updateResolution();
    CallCallback( SalEvent::DisplayChanged, nullptr );
}

should check to see whether the frame geometry actually changed and only emit the event if that is the case.

Having said that 'DisplayChanged' - is really an event that should only get emitted when the physical display and/or monitor size changes - like plugging in a remote display etc.

Have we emitted that in error much more frequently than we should:

osx/salinst.cxx-    [[NSNotificationCenter defaultCenter] addObserver: NSApp
osx/salinst.cxx:                                          selector: @selector(screenParametersChanged:)
osx/salinst.cxx-                                          name: NSApplicationDidChangeScreenParametersNotification
osx/salinst.cxx-                                          object: nil ];

I imagine we don't need to do:

osx/vclnsapp.mm:-(void)screenParametersChanged: (NSNotification*) pNotification
osx/vclnsapp.mm-{
osx/vclnsapp.mm-    (void)pNotification;
osx/vclnsapp.mm-    SolarMutexGuard aGuard;
osx/vclnsapp.mm-
osx/vclnsapp.mm-    SalData* pSalData = GetSalData();
osx/vclnsapp.mm-    std::list< AquaSalFrame* >::iterator it;
osx/vclnsapp.mm-    for( it = pSalData->maFrames.begin(); it != pSalData->maFrames.end(); ++it )
osx/vclnsapp.mm-    {
osx/vclnsapp.mm:        (*it)->screenParametersChanged();
osx/vclnsapp.mm-    }

For every frame - if we are also then going to re-broadcast this to every frame higher up the stack.

Of course. Just based on some quick code-reading, I have no Mac to hack or test this on.
Comment 14 Telesto 2016-11-08 16:30:37 UTC Comment hidden (obsolete)
Comment 15 Alex Thurgood 2016-11-08 17:21:35 UTC
(In reply to Telesto from comment #14)
> In can't help either. By the way I noticed a deprecation:
> 

>    626 	SAL_WNODEPRECATED_DECLARATIONS_PUSH
>    627 	    // 'NSAnyEventMask' is deprecated: first deprecated in macOS
> 10.12


I see this too, but I thought it was unrelated and was in two minds about opening a bug report for it. As the console message that is thrown when this happen talks about "in future versions this will throw an exception", I did wonder whether we weren't setting ourselves up for a future SIGABRT with this.

@Telesto : perhaps you could open a separate bug report for this ?
Comment 16 Telesto 2016-11-11 10:51:07 UTC Comment hidden (obsolete)
Comment 17 Telesto 2016-11-19 15:56:50 UTC Comment hidden (obsolete)
Comment 18 Alex Thurgood 2017-01-03 18:09:49 UTC
*** Bug 105068 has been marked as a duplicate of this bug. ***
Comment 19 Telesto 2017-01-05 09:44:29 UTC Comment hidden (obsolete)
Comment 20 Telesto 2017-01-10 10:54:25 UTC Comment hidden (obsolete)
Comment 21 Telesto 2017-01-12 11:46:26 UTC
Created attachment 130356 [details]
LLDB Backtrace, Build Log

New backtrace
Version: 5.4.0.0.alpha0+
Build ID: 88f561204d7cee25633df8117cc8d7e1ebd8e9ad
CPU Threads: 4; OS Version: Mac OS X 10.12.2; UI Render: default; 
Locale: en-US (en_US.UTF-8); Calc: group
Comment 22 Michael Meeks 2017-01-12 11:58:07 UTC
Hey there - the good news is, I finally have an old 2nd hand Mac; but of course, still -very- limited time - so, when I get a build hopefully can reproduce & look into some of these issues.
Comment 23 Telesto 2017-01-12 13:20:32 UTC Comment hidden (obsolete)
Comment 24 Alex Thurgood 2017-05-03 13:49:34 UTC
*** Bug 107578 has been marked as a duplicate of this bug. ***
Comment 25 Telesto 2017-09-07 09:23:00 UTC
Created attachment 136089 [details]
Xcode instruments screenshots and BT

As requested in comment 9 a Xcode trace and some screenshots
Comment 26 Julien Nabet 2017-09-07 09:29:02 UTC
Michael:
the pb seems to be in this part:
  7 libswlo.dylib SwEditWin::DataChanged(DataChangedEvent const&) /Users/demo/lode/dev/core/sw/source/uibase/docvw/edtwin3.cxx:166
  8 libvcllo.dylib vcl::Window::CompatDataChanged(DataChangedEvent const&) /Users/demo/lode/dev/core/vcl/source/window/window.cxx:3709
  9 libvcllo.dylib vcl::Window::NotifyAllChildren(DataChangedEvent&) /Users/demo/lode/dev/core/vcl/source/window/event.cxx:43
  10 libvcllo.dylib vcl::Window::NotifyAllChildren(DataChangedEvent&) /Users/demo/lode/dev/core/vcl/source/window/event.cxx:48

If I interpret this correctly, there's a recursive loop here:
41  void Window::NotifyAllChildren( DataChangedEvent& rDCEvt )
42  {
43      CompatDataChanged( rDCEvt );
44 
45      vcl::Window* pChild = mpWindowImpl->mpFirstChild;
46      while ( pChild )
47      {
48          pChild->NotifyAllChildren( rDCEvt ); <--------- recursive loop
49          pChild = pChild->mpWindowImpl->mpNext;
50      }
51  }

because of this CompatDataChanged is called many times, so fonts are reloaded many times.

I thought about adding a "level" argument to NotifyAllChildren so we could distinguish initial call of NotifyAllChildren with the recursive one.
CompatDataChanged should be called only by initial calls.

It would give:

if nLevel
    CompatDataChanged( rDCEvt );
41  void Window::NotifyAllChildren( DataChangedEvent& rDCEvt, int nLevel /* by default value = 0 */  )
42  {
43      if (nLevel) 
44          CompatDataChanged( rDCEvt );
45      vcl::Window* pChild = mpWindowImpl->mpFirstChild;
46      while ( pChild )
47      {
48          pChild->NotifyAllChildren( rDCEvt, nLevel+1 );
49          pChild = pChild->mpWindowImpl->mpNext;
50      }
51  }
what do you think?
Comment 27 Julien Nabet 2017-09-07 10:00:46 UTC
Argh, my suggestion is wrong since recursive loop would be useless.
I thought we may transmit nLevel to CompatDataChanged and so towards all the DataChanged methods or adding a Datachanged method with 2 arguments for some cases?
Comment 28 Telesto 2017-10-02 10:00:22 UTC
(In reply to Julien Nabet from comment #27)
> Argh, my suggestion is wrong since recursive loop would be useless.
> I thought we may transmit nLevel to CompatDataChanged and so towards all the
> DataChanged methods or adding a Datachanged method with 2 arguments for some
> cases?

I most likely found the culprit. Things are back to normal after reverting: https://cgit.freedesktop.org/libreoffice/core/commit/?id=0497864bd4f603605997938d504ef9598623e713
Comment 29 Julien Nabet 2017-10-02 10:10:58 UTC
(In reply to Telesto from comment #28)
> (In reply to Julien Nabet from comment #27)
>...
> I most likely found the culprit. Things are back to normal after reverting:
> https://cgit.freedesktop.org/libreoffice/core/commit/
> ?id=0497864bd4f603605997938d504ef9598623e713

Good catch!

David: Thought you might be interested in this one. In comment 26, I found a recursive loop which call the indicated function. Any idea how to fix this?
Comment 30 Alex Thurgood 2017-11-10 08:06:50 UTC
*** Bug 113467 has been marked as a duplicate of this bug. ***
Comment 31 Alex Thurgood 2017-11-10 08:11:46 UTC
@David : any thoughts on whether we can revert the commit in question or whether it can be changed somehow to avoid the huge penalty it causes on MacOS ?
Comment 32 Telesto 2017-11-18 20:59:15 UTC
For what it's worth:
The problem seems to starts with screenParametersChanged which leads to a DisplayChanged event which leads to a DataChangedEventType::DISPLAY event ending up refreshing all fonts (or something like that)

The screenParametersChanged 'broadcast' will happen even when I remove the screenParametersChanged stuff here
https://opengrok.libreoffice.org/xref/core/vcl/osx/salinst.cxx#166
because of https://opengrok.libreoffice.org/xref/core/vcl/osx/salframeview.mm#304

ScreenParametersChanged 'broadcast' will also happen when I comment out https://opengrok.libreoffice.org/xref/core/vcl/osx/salframeview.mm#304
and letting salinst.cxx#166 intact.
Comment 33 Telesto 2018-01-21 17:57:57 UTC Comment hidden (obsolete)
Comment 34 Tor Lillqvist 2018-01-23 23:00:56 UTC
I can't seem to reproduce this, with a debugging build of current master on High Sierra, on an iMac, with 20 empty Writer documents. Has the bug gone away in master, or does it not happen in High Sierra, or is my machine so powerful that I don't see it? Or what am I missing?

(I don't really think the last, this machine is not *that* much more powerful than a 2014 MacBook Air, I should see some short amount of unresponsiveness if the problem was there, I think. And anyway, this is a debugging (not optimised) build, so performance problems should be more obvious than with a production build.)
Comment 35 Telesto 2018-01-24 08:26:12 UTC
I still reproduce this, using the steps in comment 6
1) Opened 15 blank documents
2) Minimized three of the document windows.


Another way
1. Open System Preferences from the Apple menu and choose “Dock”
2. Check the box for “Automatically hide and show the Dock” by clicking the checkbox next to it
3. Start Libreoffice Writer
4. Create 12-20 blank documents
5. Put your computer to sleep (by choosing Sleep from the Apple menu)
6. Wake Mac again
7. Create a new document (CMD + N)
Comment 36 Alex Thurgood 2018-01-24 16:15:08 UTC
No repro for me either now with

Version: 6.1.0.0.alpha0+
Build ID: 44e9bbc29cc37d2bac089b8f051478f62f7d5d31
CPU threads: 4; OS: Mac OS X 10.13.2; UI render: default; 
Locale: fr-FR (fr_FR.UTF-8); Calc: group threaded

Debug enabled build
Comment 37 Alex Thurgood 2018-01-24 16:16:53 UTC
I tested on Macmini 2014, 2,6 GHz Intel Core i5, 8 Go 1600 MHz DDR3, Intel Iris 1536 Mo.
Comment 38 Telesto 2018-01-24 17:28:49 UTC
Odd, I still repro it with
Version: 6.1.0.0.alpha0+
Build ID: 6fc9d4a482ab50a1bf8fefb1dae2a6ded3c7e3dd
CPU threads: 4; OS: Mac OS X 10.13.3; UI render: default; 
TinderBox: MacOSX-x86_64@49-TDF, Branch:master, Time: 2018-01-24_04:46:24
Locale: nl-NL (nl_US.UTF-8); Calc: group threaded

with a regular daily build and with my own symbol only build..

*No special settings or applications or fonts
*No external monitor attached
*Java disabled
Comment 39 Telesto 2018-01-24 19:56:56 UTC
Argh.. I probably found the cause. The dock size slider in System Preferences -> Dock is set halfway by default. However, the slider range is totally wrong. The dock size only changes between 0-40%. Setting the slider to 50% will cause a mismatch, triggering NSApplication notifications...
Comment 40 Telesto 2018-01-25 08:39:50 UTC
*** Bug 103126 has been marked as a duplicate of this bug. ***
Comment 41 Alex Thurgood 2018-01-25 10:27:56 UTC
(In reply to Telesto from comment #39)
> Argh.. I probably found the cause. The dock size slider in System
> Preferences -> Dock is set halfway by default. However, the slider range is
> totally wrong. The dock size only changes between 0-40%. Setting the slider
> to 50% will cause a mismatch, triggering NSApplication notifications...


Yep. Confirming with

Version: 6.1.0.0.alpha0+
Build ID: 44e9bbc29cc37d2bac089b8f051478f62f7d5d31
CPU threads: 4; OS: Mac OS X 10.13.2; UI render: default; 
Locale: fr-FR (fr_FR.UTF-8); Calc: group threaded

I've managed to freeze LO completely just by opening up 20 new Writer documents and then reducing one window, after setting the Dock to 50% with the slider. I didn't need to send LO to sleep.
Comment 42 Tor Lillqvist 2018-01-25 20:25:01 UTC
I don't see any percentage scale in the System Preferences > Dock > Size slider. When you talk about 50% or 40%, is that just an eyeballed estimation? After touching it, how do I get it back to the default? (Not that it matters much to me how big it is, I practically never use the Dock for anything, and of course I have it to auto-hide.)
Comment 43 Martin Srebotnjak 2018-01-25 21:57:44 UTC Comment hidden (obsolete)
Comment 44 Telesto 2018-01-25 22:18:43 UTC
(In reply to Tor Lillqvist from comment #42)
> I don't see any percentage scale in the System Preferences > Dock > Size
> slider. When you talk about 50% or 40%, is that just an eyeballed
> estimation? After touching it, how do I get it back to the default? (Not
> that it matters much to me how big it is, I practically never use the Dock
> for anything, and of course I have it to auto-hide.)

Sorry, that's my eyeball estimation :-). Everything is working fine as long as the dock responds to the Dock Size slider. The issue starts when the Dock stops growing, while the slider is suggestion room for a larger one. It's probably set to the middle by default (and that's already to much for my 11" screen)

My experience with Macs is very limited. So it might not be reproducible on no-retina Macs and/or Macs with a smaller screen dimension.

Btw, no clue how the set it back to the default setting. Except for a new user profile, or guessing the middle of the slider.
Comment 45 Telesto 2018-01-30 12:54:30 UTC
(In reply to Telesto from comment #44)
> Sorry, that's my eyeball estimation :-). Everything is working fine as long
> as the dock responds to the Dock Size slider. The issue starts when the Dock
> stops growing, while the slider is suggestion room for a larger one. It's
> probably set to the middle by default (and that's already to much for my 11"
> screen)

Dammit, this still isn't the whole story. The issue (also) arises with to many windows minimised to the dock. At the point where the icons are shrinking.. :( 

1) Opened 15 blank documents
2) Minimise them all to the dock
2) Restore a minimised Writer document.
Comment 46 Martin Srebotnjak 2018-02-08 10:37:55 UTC
Upping the importance to raise visibility of this bug.

Thanks to all who try to fix this one, it is really a painful one!
Comment 47 Michael Meeks 2018-02-23 10:00:32 UTC
One thing that is ~obviously wrong is this:


    frame #38: 0x00000001150cbd8a libvcllo.dylib`SalTimer::CallCallback(this=0x000060000001b630, idle=true) + 58 at saltimer.hxx:55
...
libvcllo.dylib`AquaSalInstance::AnyInput(this=0x00006080000b9aa0, nType=KEYBOARD) + 603 at salinst.cxx:786
    frame #52: 0x0000000114f58ef6 libvcllo.dylib`Application::AnyInput(nType=KEYBOARD) + 38 at svapp.cxx:631

The windows impl of AnyInput doesn't look like it processes timers or events - it is a real 'Peek' method - not expected to re-enter in a weird way:

vcl/win/app/salinst.cxx (WinSalInstance::AnyInput)

packed with this sort of thing:

        if ( PeekMessageW( &aMsg, nullptr, 0, 0, PM_NOREMOVE | PM_NOYIELD ) )

vs.

vcl/osx/salinst.cxx (AquaSalInstance::AnyInput)

which does:

    NSEvent* pEvent = [NSApp nextEventMatchingMask: nEventMask untilDate: nil
                            inMode: NSDefaultRunLoopMode dequeue: NO];

Which looks like a go-wild "run the loop" crazy thing ;-) which may be a wider systemic problem highlighted here (?)

Are we adding timers to the wrong mode for that loop ? or do we need a custom mode so we can exclude ~everything from running and just peek ? or perhaps a different method call ?
Comment 48 Tor Lillqvist 2018-02-23 10:47:08 UTC
In fact, the documentation for the Win32 PeekMessage() https://msdn.microsoft.com/en-us/library/windows/desktop/ms644943(v=vs.85).aspx does describe that it is not as trivial as one might hope. "During this call, the system delivers pending, nonqueued messages, that is, messages sent to windows owned by the calling thread using the SendMessage, SendMessageCallback, SendMessageTimeout, or SendNotifyMessage function. Then the first queued message that matches the specified filter is retrieved. The system may also process internal events."

And about SendMessage(), "The SendMessage function calls the window procedure for the specified window and does not return until the window procedure has processed the message".
Comment 49 Tor Lillqvist 2018-02-23 11:10:13 UTC
Ah yes, now I think I can reproduce it.
Comment 50 Michael Meeks 2018-02-23 11:11:10 UTC
Hokay - so, lets compare it with the gtk3 backend which we know works; that pulls events from the gdk event queue - and stuffs them back without processing any =)

It also first calls gdk_events_pending() - which does the underlying socket I/O to the X server (when using X) - via 'XPending()' -> XEventsQueued with QueuedAfterFlush - but I don't see any event processing; particularly of the glib mainloop which handles timeouts =)

Hence the "I don't expect that" really =)
Comment 51 Tor Lillqvist 2018-02-23 11:22:40 UTC
I wonder if a good fix would be to modify AquaSalFrame::screenParametersChanged() so that if nothing actually has changed (but we got the NSApplicationDidChangeScreenParametersNotification notification because of something unessential like the Dock size changing), then don't call CallCallback(SalEvent::DisplayChanged, nullptr).
Comment 52 Tor Lillqvist 2018-02-23 11:24:13 UTC
Here is a sample stack trace from Xcode while it is doing something for very long... Horror, horror.

#0	0x000000010a9ca9b2 in CommonSalLayout::CommonSalLayout(CoreTextStyle const&) at /Users/tml/lo/osx/vcl/source/gdi/CommonSalLayout.cxx:243
#1	0x000000010a9caedd in CommonSalLayout::CommonSalLayout(CoreTextStyle const&) at /Users/tml/lo/osx/vcl/source/gdi/CommonSalLayout.cxx:243
#2	0x000000010abeafa0 in AquaSalGraphics::GetTextLayout(ImplLayoutArgs&, int) at /Users/tml/lo/osx/vcl/quartz/salgdi.cxx:518
#3	0x000000010a632f3b in OutputDevice::ImplLayout(rtl::OUString const&, int, int, Point const&, long, long const*, SalLayoutFlags, vcl::TextLayoutCache const*) const at /Users/tml/lo/osx/vcl/source/outdev/text.cxx:1335
#4	0x000000010a634cb6 in OutputDevice::GetTextArray(rtl::OUString const&, long*, int, int, vcl::TextLayoutCache const*, SalLayout const*) const at /Users/tml/lo/osx/vcl/source/outdev/text.cxx:992
#5	0x000000010a634a76 in OutputDevice::GetTextWidth(rtl::OUString const&, int, int, vcl::TextLayoutCache const*, SalLayout const*) const at /Users/tml/lo/osx/vcl/source/outdev/text.cxx:912
#6	0x000000010a521f7b in ImplListBoxWindow::ImplUpdateEntryMetrics(ImplEntryType&) at /Users/tml/lo/osx/vcl/source/control/imp_listbox.cxx:640
#7	0x000000010a5211d6 in ImplListBoxWindow::ImplCalcMetrics() at /Users/tml/lo/osx/vcl/source/control/imp_listbox.cxx:556
#8	0x000000010a522685 in ImplListBoxWindow::SetUserItemSize(Size const&) at /Users/tml/lo/osx/vcl/source/control/imp_listbox.cxx:590
#9	0x000000010a4be236 in ComboBox::SetUserItemSize(Size const&) at /Users/tml/lo/osx/vcl/source/control/combobox.cxx:1256
#10	0x0000000109072f68 in FontNameBox::ImplCalcUserItemSize() at /Users/tml/lo/osx/svtools/source/control/ctrlbox.cxx:826
#11	0x0000000109071ed1 in FontNameBox::Fill(FontList const*) at /Users/tml/lo/osx/svtools/source/control/ctrlbox.cxx:800
#12	0x0000000107c01ac7 in SvxFontNameBox_Impl::Fill(FontList const*) at /Users/tml/lo/osx/svx/source/tbxctrls/tbcontrl.cxx:227
#13	0x0000000107bdee68 in lcl_GetDocFontList(FontList const**, SvxFontNameBox_Impl*) at /Users/tml/lo/osx/svx/source/tbxctrls/tbcontrl.cxx:958
#14	0x0000000107bdf89e in SvxFontNameBox_Impl::DataChanged(DataChangedEvent const&) at /Users/tml/lo/osx/svx/source/tbxctrls/tbcontrl.cxx:1120
#15	0x00000001820d72b0 in framework::ToolBarManager::DataChanged(DataChangedEvent const*) at /Users/tml/lo/osx/framework/source/uielement/toolbarmanager.cxx:1823
#16	0x00000001820c0448 in framework::ToolBarManager::LinkStubDataChanged(void*, DataChangedEvent const*) at /Users/tml/lo/osx/framework/source/uielement/toolbarmanager.cxx:1807
#17	0x000000010a41cca8 in Link<DataChangedEvent const*, void>::Call(DataChangedEvent const*) const at /Users/tml/lo/osx/include/tools/link.hxx:84
#18	0x000000010a41cc40 in ToolBox::DataChanged(DataChangedEvent const&) at /Users/tml/lo/osx/vcl/source/window/toolbox.cxx:4081
#19	0x000000010a460322 in vcl::Window::CompatDataChanged(DataChangedEvent const&) at /Users/tml/lo/osx/vcl/source/window/window.cxx:3801
#20	0x000000010a2df29f in vcl::Window::NotifyAllChildren(DataChangedEvent&) at /Users/tml/lo/osx/vcl/source/window/event.cxx:43
#21	0x000000010a2df2ec in vcl::Window::NotifyAllChildren(DataChangedEvent&) at /Users/tml/lo/osx/vcl/source/window/event.cxx:48
#22	0x000000010a2df2ec in vcl::Window::NotifyAllChildren(DataChangedEvent&) at /Users/tml/lo/osx/vcl/source/window/event.cxx:48
#23	0x000000010a2df2ec in vcl::Window::NotifyAllChildren(DataChangedEvent&) at /Users/tml/lo/osx/vcl/source/window/event.cxx:48
#24	0x000000010aa94443 in Application::NotifyAllWindows(DataChangedEvent&) at /Users/tml/lo/osx/vcl/source/app/svapp.cxx:762
#25	0x000000010a47cede in ImplHandleSalSettings(SalEvent) at /Users/tml/lo/osx/vcl/source/window/winproc.cxx:2128
#26	0x000000010a479be8 in ImplWindowFrameProc(vcl::Window*, SalEvent, void const*) at /Users/tml/lo/osx/vcl/source/window/winproc.cxx:2474
#27	0x000000010abfab55 in SalFrame::CallCallback(SalEvent, void const*) const at /Users/tml/lo/osx/vcl/inc/salframe.hxx:279
#28	0x000000010ac86c2f in AquaSalFrame::screenParametersChanged() at /Users/tml/lo/osx/vcl/osx/salframe.cxx:271
#29	0x000000010ad5b42d in ::-[VCL_NSApplication screenParametersChanged:](NSNotification *) at /Users/tml/lo/osx/vcl/osx/vclnsapp.mm:367
Comment 53 Michael Meeks 2018-02-23 11:51:45 UTC
Nice trace - so; I imagine that DisplayChanged is presumably the right thing to emit only when something changed - eg. the space available for the app (does that happen when the dock re-sizes ?

Also - I'm suspicious of:

svx/source/tbxctrls/tbcontrl.cxx-    else if ( ( rDCEvt.GetType() == DataChangedEventType::FONTS ) ||
svx/source/tbxctrls/tbcontrl.cxx:              ( rDCEvt.GetType() == DataChangedEventType::DISPLAY ) )

I guess this is perhaps to handle things like font-hint changes on Linux (perhaps) - and I imagine that this particular font combo box is -very- expensive to setup & re-render.

Might be nice to just use FONTS for that - and try to detect if any display settings affect font rendering - and emit a FONTS changed if they do (?) =)

The:
            // HACK: Comparing is incomplete

comment in lcl_GetDocFontList looks particularly interesting to investigate I guess =) if we can avoid re-building it I imagine life is far better.
Comment 54 Tor Lillqvist 2018-02-23 14:39:39 UTC
Suggested fix at https://gerrit.libreoffice.org/50249
Comment 55 Tor Lillqvist 2018-02-23 14:43:41 UTC
FYI, here is some timing debugging output from when just one Writer document was open and I changed the Dock size:

> debug:90663:6971042: -[SalFrameWindow windowDidChangeScreen]
> debug:90663:6971042: -[SalFrameWindow windowDidChangeScreen] took 0.000006 s
> debug:90663:6971042: -[SalFrameWindow windowDidChangeScreen]
> debug:90663:6971042:   AquaSalFrame::screenParametersChanged: CallCallback took 0.027414 s
> debug:90663:6971042: -[SalFrameWindow windowDidChangeScreen] took 0.027461 s
> debug:90663:6971042: -[SalFrameWindow windowDidChangeScreen]
> debug:90663:6971042:   AquaSalFrame::screenParametersChanged: CallCallback took 0.023375 s
> debug:90663:6971042: -[SalFrameWindow windowDidChangeScreen] took 0.023460 s
> debug:90663:6971042: -[SalFrameWindow windowDidChangeScreen]
> debug:90663:6971042:   AquaSalFrame::screenParametersChanged: CallCallback took 0.023808 s
> debug:90663:6971042: -[SalFrameWindow windowDidChangeScreen] took 0.023851 s
> debug:90663:6971042: -[SalFrameWindow windowDidChangeScreen]
> debug:90663:6971042:   AquaSalFrame::screenParametersChanged: CallCallback took 0.021801 s
> debug:90663:6971042: -[SalFrameWindow windowDidChangeScreen] took 0.021874 s
> debug:90663:6971042: -[SalFrameWindow windowDidChangeScreen]
> debug:90663:6971042:   AquaSalFrame::screenParametersChanged: CallCallback took 0.008783 s
> debug:90663:6971042: -[SalFrameWindow windowDidChangeScreen] took 0.008825 s
> debug:90663:6971042: -[SalFrameWindow windowDidChangeScreen]
> debug:90663:6971042:   AquaSalFrame::screenParametersChanged: CallCallback took 0.010233 s
> debug:90663:6971042: -[SalFrameWindow windowDidChangeScreen] took 0.010275 s
> debug:90663:6971042: -[VCL_NSApplication screenParametersChanged]
> debug:90663:6971042:   AquaSalFrame::screenParametersChanged: CallCallback took 0.022160 s
> debug:90663:6971042:   AquaSalFrame::screenParametersChanged: CallCallback took 0.010850 s
> debug:90663:6971042:   AquaSalFrame::screenParametersChanged: CallCallback took 0.023778 s
> debug:90663:6971042:   AquaSalFrame::screenParametersChanged: CallCallback took 0.021911 s
> debug:90663:6971042:   AquaSalFrame::screenParametersChanged: CallCallback took 0.024892 s
> debug:90663:6971042:   AquaSalFrame::screenParametersChanged: CallCallback took 0.021507 s
> debug:90663:6971042: -[VCL_NSApplication screenParametersChanged] took 0.125439 s

and here with three documents open:

> debug:90663:6971042: -[SalFrameWindow windowDidChangeScreen]
> debug:90663:6971042: -[SalFrameWindow windowDidChangeScreen] took 0.000007 s
> debug:90663:6971042: -[SalFrameWindow windowDidChangeScreen]
> debug:90663:6971042:   AquaSalFrame::screenParametersChanged: CallCallback took 0.074095 s
> debug:90663:6971042: -[SalFrameWindow windowDidChangeScreen] took 0.074144 s
> debug:90663:6971042: -[SalFrameWindow windowDidChangeScreen]
> debug:90663:6971042:   AquaSalFrame::screenParametersChanged: CallCallback took 0.069474 s
> debug:90663:6971042: -[SalFrameWindow windowDidChangeScreen] took 0.069551 s
> debug:90663:6971042: -[SalFrameWindow windowDidChangeScreen]
> debug:90663:6971042:   AquaSalFrame::screenParametersChanged: CallCallback took 0.068246 s
> debug:90663:6971042: -[SalFrameWindow windowDidChangeScreen] took 0.068291 s
> debug:90663:6971042: -[SalFrameWindow windowDidChangeScreen]
> debug:90663:6971042:   AquaSalFrame::screenParametersChanged: CallCallback took 0.066944 s
> debug:90663:6971042: -[SalFrameWindow windowDidChangeScreen] took 0.066994 s
> debug:90663:6971042: -[SalFrameWindow windowDidChangeScreen]
> debug:90663:6971042:   AquaSalFrame::screenParametersChanged: CallCallback took 0.024242 s
> debug:90663:6971042: -[SalFrameWindow windowDidChangeScreen] took 0.024287 s
> debug:90663:6971042: -[SalFrameWindow windowDidChangeScreen]
> debug:90663:6971042:   AquaSalFrame::screenParametersChanged: CallCallback took 0.067261 s
> debug:90663:6971042: -[SalFrameWindow windowDidChangeScreen] took 0.067301 s
> debug:90663:6971042: -[SalFrameWindow windowDidChangeScreen]
> debug:90663:6971042:   AquaSalFrame::screenParametersChanged: CallCallback took 0.066743 s
> debug:90663:6971042: -[SalFrameWindow windowDidChangeScreen] took 0.066820 s
> debug:90663:6971042: -[SalFrameWindow windowDidChangeScreen]
> debug:90663:6971042:   AquaSalFrame::screenParametersChanged: CallCallback took 0.023351 s
> debug:90663:6971042: -[SalFrameWindow windowDidChangeScreen] took 0.023382 s
> debug:90663:6971042: -[SalFrameWindow windowDidChangeScreen]
> debug:90663:6971042:   AquaSalFrame::screenParametersChanged: CallCallback took 0.025091 s
> debug:90663:6971042: -[SalFrameWindow windowDidChangeScreen] took 0.025230 s
> debug:90663:6971042: -[SalFrameWindow windowDidChangeScreen]
> debug:90663:6971042:   AquaSalFrame::screenParametersChanged: CallCallback took 0.026617 s
> debug:90663:6971042: -[SalFrameWindow windowDidChangeScreen] took 0.026713 s
> debug:90663:6971042: -[SalFrameWindow windowDidChangeScreen]
> debug:90663:6971042:   AquaSalFrame::screenParametersChanged: CallCallback took 0.067003 s
> debug:90663:6971042: -[SalFrameWindow windowDidChangeScreen] took 0.067048 s
> debug:90663:6971042: -[SalFrameWindow windowDidChangeScreen]
> debug:90663:6971042:   AquaSalFrame::screenParametersChanged: CallCallback took 0.067794 s
> debug:90663:6971042: -[SalFrameWindow windowDidChangeScreen] took 0.067872 s
> debug:90663:6971042: -[SalFrameWindow windowDidChangeScreen]
> debug:90663:6971042:   AquaSalFrame::screenParametersChanged: CallCallback took 0.068892 s
> debug:90663:6971042: -[SalFrameWindow windowDidChangeScreen] took 0.068934 s
> debug:90663:6971042: -[SalFrameWindow windowDidChangeScreen]
> debug:90663:6971042:   AquaSalFrame::screenParametersChanged: CallCallback took 0.069128 s
> debug:90663:6971042: -[SalFrameWindow windowDidChangeScreen] took 0.069176 s
> debug:90663:6971042: -[SalFrameWindow windowDidChangeScreen]
> debug:90663:6971042:   AquaSalFrame::screenParametersChanged: CallCallback took 0.068469 s
> debug:90663:6971042: -[SalFrameWindow windowDidChangeScreen] took 0.068525 s
> debug:90663:6971042: -[SalFrameWindow windowDidChangeScreen]
> debug:90663:6971042:   AquaSalFrame::screenParametersChanged: CallCallback took 0.024791 s
> debug:90663:6971042: -[SalFrameWindow windowDidChangeScreen] took 0.024842 s
> debug:90663:6971042: -[VCL_NSApplication screenParametersChanged]
> debug:90663:6971042:   AquaSalFrame::screenParametersChanged: CallCallback took 0.068519 s
> debug:90663:6971042:   AquaSalFrame::screenParametersChanged: CallCallback took 0.068946 s
> debug:90663:6971042:   AquaSalFrame::screenParametersChanged: CallCallback took 0.068762 s
> debug:90663:6971042:   AquaSalFrame::screenParametersChanged: CallCallback took 0.067797 s
> debug:90663:6971042:   AquaSalFrame::screenParametersChanged: CallCallback took 0.066688 s
> debug:90663:6971042:   AquaSalFrame::screenParametersChanged: CallCallback took 0.067541 s
> debug:90663:6971042:   AquaSalFrame::screenParametersChanged: CallCallback took 0.067825 s
> debug:90663:6971042:   AquaSalFrame::screenParametersChanged: CallCallback took 0.024071 s
> debug:90663:6971042:   AquaSalFrame::screenParametersChanged: CallCallback took 0.069154 s
> debug:90663:6971042:   AquaSalFrame::screenParametersChanged: CallCallback took 0.068377 s
> debug:90663:6971042:   AquaSalFrame::screenParametersChanged: CallCallback took 0.068981 s
> debug:90663:6971042:   AquaSalFrame::screenParametersChanged: CallCallback took 0.025192 s
> debug:90663:6971042:   AquaSalFrame::screenParametersChanged: CallCallback took 0.068966 s
> debug:90663:6971042:   AquaSalFrame::screenParametersChanged: CallCallback took 0.068955 s
> debug:90663:6971042:   AquaSalFrame::screenParametersChanged: CallCallback took 0.069286 s
> debug:90663:6971042:   AquaSalFrame::screenParametersChanged: CallCallback took 0.068227 s
> debug:90663:6971042: -[VCL_NSApplication screenParametersChanged] took 1.008116 s
Comment 56 Commit Notification 2018-02-23 19:52:29 UTC
Tor Lillqvist committed a patch related to this issue.
It has been pushed to "master":

http://cgit.freedesktop.org/libreoffice/core/commit/?id=715b7b6f346fdd9c856db268dcd66334b58c273c

tdf#103571: Avoid spurious heavy SalEvent::DisplayChanged callbacks

It will be available in 6.1.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 57 Michael Meeks 2018-02-24 09:46:50 UTC
Patch looks good - although some comments in the gerrit back-port =)

I'd really like us to fix the cross-platform issue that this shows up though:

svx/source/tbxctrls/tbcontrl.cxx 's:
            // HACK: Comparing is incomplete

Code seems bad to me - spending all this time doing ~nothing when we plug a remote display in (and on every platform) also seems like a really poor use of time =)

I'd like to investigate why this FontList comparison says the font list has changed when this event occurs - triggering the expensive re-build of the font-list - when it has not =)

Perhaps more interestingly - if that work is done at startup - before we create a new top-level frame ;-) [ as it may well be ] can we do something to speed up new window creation here by eg. deferring that work: just dirtying the combo-box, or having a single item in it which is the current font, and populating it only on first-click ? =) or somesuch clever.

Would be good to get a faster experience on all platforms from this if possible =)

Would also be good to test changing the LCD font rendering settings [ if indeed such settings exist ;-] on Linux which -should- cause the UI to completely refresh - including these fonts: almost certainly it's not an issue because the actual rendering (vs. measuring etc. in that list) should occur at a very low level; but worth a check.

Thanks Tor ! =)
Comment 58 Martin Srebotnjak 2018-02-24 12:08:43 UTC
Could this patch make it into 6.0.1? Please?
Comment 59 Martin Srebotnjak 2018-02-24 12:09:12 UTC
Sorry, meant 6.0.2 (6.0.2.1 was already built two days ago).
Comment 60 Tor Lillqvist 2018-02-26 11:06:49 UTC
Would be great if you who have been able to reproduce the problem (using any approach) could check whether it is fixed now in master. At least the way I could reproduce this is definitely fixed.
Comment 61 Commit Notification 2018-02-26 12:06:39 UTC
Tor Lillqvist committed a patch related to this issue.
It has been pushed to "libreoffice-6-0":

http://cgit.freedesktop.org/libreoffice/core/commit/?id=f99b91ab0a67ce23f1c11bdb67370c0773813d15&h=libreoffice-6-0

tdf#103571: Avoid spurious heavy SalEvent::DisplayChanged callbacks

It will be available in 6.0.2.

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 62 Martin Srebotnjak 2018-02-26 13:53:18 UTC
Great, waiting for any new daily or pre-release builds available for macOS, will report back.
Comment 63 Tor Lillqvist 2018-03-05 10:29:46 UTC
Setting to NEEDINFO, awaiting confirmation that problem is fixed.
Comment 64 Alex Thurgood 2018-03-05 13:30:28 UTC
No repro for me anymore with my own master build of 01/03 or 02/03 (not sure)

Version: 6.1.0.0.alpha0+
Build ID: 9122f4598450d8a96e63fb29cc8166a6ae09587a
CPU threads: 4; OS: Mac OS X 10.13.3; UI render: default; 
Locale: fr-FR (fr_FR.UTF-8); Calc: group
Comment 65 Telesto 2018-03-05 15:00:50 UTC
The target should be 6.0.3. It didn't make it into 6.0.2