Bug 104312 - Severe lag on drawing canvas in "Draw"
Summary: Severe lag on drawing canvas in "Draw"
Status: RESOLVED FIXED
Alias: None
Product: LibreOffice
Classification: Unclassified
Component: Draw (show other bugs)
Version:
(earliest affected)
5.2.2.2 release
Hardware: All All
: high major
Assignee: Aron Budea
QA Contact:
URL:
Whiteboard: target:5.4.0 target:5.3.4
Keywords: bibisected, haveBacktrace, perf, regression
: 98132 104427 105428 107044 (view as bug list)
Depends on:
Blocks: 105497 Too-Much-File-Access
  Show dependency treegraph
 
Reported: 2016-12-01 05:51 UTC by laeryn
Modified: 2017-07-22 07:39 UTC (History)
12 users (show)

See Also:
Crash report or crash signature:


Attachments
Example (7.59 KB, application/vnd.oasis.opendocument.graphics)
2016-12-01 15:33 UTC, Telesto
Details
Example drawing document (7.81 KB, application/vnd.oasis.opendocument.graphics)
2016-12-01 15:42 UTC, laeryn
Details
LLDB backtrace (4.75 MB, text/plain)
2016-12-01 20:29 UTC, Telesto
Details
BUILDLOG; LLDB Backtrace and SAL_LOG (1.30 MB, application/zip)
2016-12-10 10:27 UTC, Telesto
Details
LLDB UIElementFactoryManager (2.16 MB, text/plain)
2017-02-21 20:39 UTC, Telesto
Details
Callgrind output from 5.4 (6.75 MB, application/x-xz)
2017-04-06 17:56 UTC, Buovjaga
Details

Note You need to log in before you can comment on or make changes to this bug.
Description laeryn 2016-12-01 05:51:24 UTC
When drawing a shape (a square for example) on the drawing canvas, there is quite a bit of lag. The program's lag gets even worse when I try to select things by dragging a square around objects. It takes a few seconds for the selection square to even appear, and then a few more seconds for it to catch up with the position of my mouse.
Comment 1 Alex Thurgood 2016-12-01 11:37:41 UTC
Please provide a sample document and step by step instructions that clearly shows the behaviour you are experiencing.

I can't reproduce this behaviour in a simple test Draw document containing 5 different default shapes with varying colour fills, and then drawing a select rectangle with the mouse over them.

Version: 5.2.3.3
Build ID: d54a8868f08a7b39642414cf2c8ef2f228f780cf
Threads CPU : 8; Version de l'OS :Mac OS X 10.12.1; UI Render : par défaut; 
Locale : fr-FR (fr_FR.UTF-8); Calc: group
Comment 2 Alex Thurgood 2016-12-01 11:38:36 UTC
Also please provide your OSX hardware setup
Comment 3 Telesto 2016-12-01 15:33:19 UTC
Created attachment 129188 [details]
Example
Comment 4 Telesto 2016-12-01 15:34:14 UTC
Confirming with:
Version: 5.4.0.0.alpha0+
Build ID: 2bad9f1cd8da0cd3d8ff33e875eaf10c1fd9d0bf
CPU Threads: 4; OS Version: Mac OS X 10.12.1; UI Render: default; 
TinderBox: MacOSX-x86_64@49-TDF, Branch:master, Time: 2016-11-29_01:04:44
Locale: nl-NL (nl_NL.UTF-8); Calc: group

Steps to reproduce
1. Open attached file
2. Select green square
3. Select blue square
4. Take notice time required before the selection square appears
Comment 5 laeryn 2016-12-01 15:42:12 UTC
Created attachment 129189 [details]
Example drawing document
Comment 6 laeryn 2016-12-01 15:44:05 UTC
Version: 5.2.3.3
Build ID: d54a8868f08a7b39642414cf2c8ef2f228f780cf
CPU Threads: 4; OS Version: Mac OS X 10.12.2; UI Render: GL; 
Locale: en-US (en_US.UTF-8); Calc: group

Steps to reproduce (As Telesto mentioned):
1. Open the document
2. Use select cursor to drag a selection box around objects
3. Wait for selection box to show up because it is lagging
4. Wait for selection box to catch up with mouse after it shows up

Also, this happens whether or not I have OpenGL turned on.
Comment 7 Telesto 2016-12-01 20:29:05 UTC
Created attachment 129199 [details]
LLDB backtrace

Backtrace will switching selecting a square. Done with:
Version: 5.4.0.0.alpha0+
Build ID: 2bad9f1cd8da0cd3d8ff33e875eaf10c1fd9d0bf
CPU Threads: 4; OS Version: Mac OS X 10.12.2; UI Render: default; 
TinderBox: MacOSX-x86_64@49-TDF, Branch:master, Time: 2016-11-29_01:04:44
Locale: en-US (en_US.UTF-8); Calc: group
Comment 8 laeryn 2016-12-02 05:42:10 UTC
I noticed there is also the same initial delay for drawing a shape while in Writer
Comment 9 Alex Thurgood 2016-12-02 08:43:06 UTC
With the test file provided by Telesto, and on my Mac-mini (mid-2010), I can confirm also with

Version: 5.2.3.3
Build ID: d54a8868f08a7b39642414cf2c8ef2f228f780cf
Threads CPU : 2; Version de l'OS :Mac OS X 10.12.1; UI Render : par défaut; 
Locale : fr-FR (fr_FR.UTF-8); Calc: group


My previous testing of my own shape addition and selection was carried out on a more recent Macbook Pro, which might explain why I saw no noticeable difference - the shapes were also smaller.

In Telesto's trace there seems to be a lot of expenditure in populating objects of the shape in the sidebar - could it be that this represents a bottleneck and that the selection outline is only drawn once all of the shape's properties have populated the sidebar control ?

No idea who is responsible for this stuff, but confirming
Comment 10 Alex Thurgood 2016-12-02 08:46:10 UTC
Tested the same ODG file against

Version: 4.1.4.2
Build ID: 0a0440ccc0227ad9829de5f46be37cfb6edcf72

on same Mac mini hardware and the selection outline display is instantaneous (or virtually), which would tend to validate my hypothesis that it is the implementation of the sidebar that causes the lag in recent versions.
Comment 11 Alex Thurgood 2016-12-02 08:53:35 UTC
@Thorsten, Armin : thoughts ?
Comment 12 Telesto 2016-12-05 09:05:54 UTC
*** Bug 104326 has been marked as a duplicate of this bug. ***
Comment 13 Alex Thurgood 2016-12-06 08:47:30 UTC
*** Bug 104427 has been marked as a duplicate of this bug. ***
Comment 14 MarjaE 2016-12-06 17:45:14 UTC
If 104427 is the same bug, then this appears by 5.2.2.2 and amost certainly earlier.
Comment 15 Telesto 2016-12-07 19:10:41 UTC
The cause seems to be a SQLite issue. Within the backtrace I noticed different errors concerning SQLite. For example:

libsqlite3.dylib`sqlite3StartTable:
"temporary table name must be unqualified"
"unknown database %T"
"not authorized"
"there is already an index named %s"
"table %T already exists"
"authorizer malfunction"

libsqlite3.dylib`yy_reduce:
"parser stack overflow"
"Expression tree is too large (maximum depth %d)"
; "too many terms in compound SELECT"
"syntax error after column name "%.*s""
"the NOT INDEXED clause is not allowed on UPDATE or DELETE statements within triggers"
"temporary trigger may not have qualified name"
; "too many arguments on function %T"
"syntax error after column name "%.*s""
"qualified table names are not allowed on INSERT, UPDATE, and DELETE statements within triggers"
"the INDEXED BY clause is not allowed on UPDATE or DELETE statements within triggers"
; "parameters are not allowed in views"
; "too many terms in compound SELECT"
"ROLLBACK"
"not authorized"
"variable number must be between ?1 and ?%d"
"corrupt database"
"too many columns on %s"
"index associated with UNIQUE or PRIMARY KEY constraint cannot be dropped"
"Cannot add a column to a view"
"Cannot add a UNIQUE column"
"virtual tables may not be altered"
"near "%T": syntax error"
"authorizer malfunction"
Comment 16 Telesto 2016-12-10 10:27:15 UTC
Created attachment 129451 [details]
BUILDLOG; LLDB Backtrace and SAL_LOG

New backtrace. Done with: 
Version: 5.4.0.0.alpha0+
Build ID: a564821eb9e991774195120e6965b2a8b1419dc5
CPU Threads: 4; OS Version: Mac OS X 10.12.2; UI Render: default; 
Locale: en-US (en_US.UTF-8); Calc: group


The trace looks different compared to the first one and partly the same as bug 99784 (compare frame 91 with frame 13)
Comment 17 Telesto 2016-12-10 21:18:47 UTC
Issue is also noticeable with Windows. Fast switching between items and dragging them around feels a bit sluggish, compared to 4.4.6.3. CPU usage is also a bit higher.

Found in
Version: 5.4.0.0.alpha0+
Build ID: 84f2ff67a7e404febf710b1dc7f66d06745c503f
CPU Threads: 4; OS Version: Windows 6.19; UI Render: default; 
TinderBox: Win-x86@42, Branch:master, Time: 2016-12-09_23:20:01
Locale: nl-NL (nl_NL); Calc: CL

and in
Version: 5.3.0.0.alpha1+
Build ID: 43b5ca69aa545cf93eded55258d92d651917815f
CPU Threads: 4; OS Version: Windows 6.2; UI Render: default; Layout Engine: new; 
TinderBox: Win-x86@62-merge-TDF, Branch:MASTER, Time: 2016-11-18_05:27:05
Locale: nl-NL (nl_NL); Calc: CL

Less prone in versie 5.2.2.1 but CPU usage is still a bit higher compared to  4.4.6.3 
Build ID: 3c2231d4aa4c68281f28ad35a100c092cff84f5d
CPU Threads: 4; Versie besturingssysteem:Windows 6.2; UI Render: standaard; 
Locale: nl-NL (nl_NL); Calc: CL
Comment 18 Aron Budea 2017-01-24 02:10:07 UTC Comment hidden (bibisection)
Comment 19 Aron Budea 2017-01-24 02:26:25 UTC
Bibisect first pointed to this commit:
https://cgit.freedesktop.org/libreoffice/core/commit/?id=64a708cba9b954afe3331f63c58218eb53b3d0ce
author		Caolán McNamara <caolanm@redhat.com>	2016-11-05 20:28:27 (GMT)
committer	Caolán McNamara <caolanm@redhat.com>	2016-11-07 21:04:50 (GMT)

"Revert "Reverts a commit series that cripple windows ci." "

Which pointed to this commit:
https://cgit.freedesktop.org/libreoffice/core/commit/?id=db380aab1063e8a5e40111c40ee9f7921aa82601
author		Norbert Thiebaud <nthiebaud@gmail.com>	2016-11-05 18:28:17 (GMT)
committer	Norbert Thiebaud <nthiebaud@gmail.com>	2016-11-05 18:42:40 (GMT)

"Reverts a commit series that cripple windows ci."

Then I did a second bibisect on the preceding commits, which, to no surprise pointed to the this range:
https://cgit.freedesktop.org/libreoffice/core/log/?qt=range&q=43bc3031483d172eccd72c3804e2d4fc2ef37de4..f9a2c1c12ecad833c63b894c89d6008907477eb5

...which is the same series of commits. Since the author is Caolán, adding Cc: to Caolán McNamara, please take a look.
If these commits build on Linux, and a bisect would be helpful, I can do that, just let me know.

Btw, I used attachment 129188 [details] provided by Telesto in comment 3.

There is another, small performance drop between 5.0.0.5 and 5.1.0.3 from instant switching to almost instant switching (with same ODG file), please open a separate bug report on that.
Comment 20 Caolán McNamara 2017-01-27 09:04:55 UTC
does (in daily master post 9954a91eb841225950ef28a24be5a38abdcb42a9) this now https://cgit.freedesktop.org/libreoffice/core/commit/?id=9954a91eb841225950ef28a24be5a38abdcb42a9 make a difference ?
Comment 21 Aron Budea 2017-01-31 02:41:31 UTC
I'm afraid not. However, I've got some profiling results (not easy to share in a meaningful way, Very Sleepy is a very simple tool), and it seems the sidebar UI elements are recreated again and again:

`anonymous namespace'::UIElementFactoryManager::createUIElement
  `anonymous namespace'::PanelFactory::createUIElement
    svx::sidebar::AreaPropertyPanel::Create
    svx::sidebar::TextPropertyPanel::Create
    svx::sidebar::ShadowPropertyPanel::Create
    svx::sidebar::ParaPropertyPanel::Create
    svx::sidebar::LinePropertyPanel::Create
    svx::sidebar::PosSizePropertyPanel::Create

This whole thing took up roughly 80% of time during the profiling run.
Comment 22 Michael Meeks 2017-01-31 09:24:33 UTC
Hi Aron - awesome work - next step would be to whack a breakpoint into:

`anonymous namespace'::UIElementFactoryManager::createUIElement

while it is running, and work out what stack-trace is triggering that. It would be great to see why it is triggered multiple times etc. =) [ assuming that it is of course ]
Comment 23 Telesto 2017-02-21 20:39:13 UTC
Created attachment 131398 [details]
LLDB UIElementFactoryManager

Version: 5.4.0.0.alpha0+
Build ID: 273823de644f2086377795d3afb51a39d30bfeaa
CPU Threads: 4; OS Version: Mac OS X 10.12.4; UI Render: default; 
Locale: en-US (en_US.UTF-8); Calc: group
Comment 24 Dominic Davies 2017-02-28 08:57:47 UTC
Perhaps this would be obvious at this point but disabling the Sidebar from the View menu results in significantly reduced lag using the above example documents.

Also worth noting is that disabling the Status Bar from the View menu results in further performance gains. Perhaps a related issue?
Comment 25 Caolán McNamara 2017-02-28 09:55:37 UTC
I don't think there's any super mystery here, the sidebar is just tearing down and recreating oodles of widgets on every context change. Some of the widgets are higher cost than others, so f.e. the color one might be quite heavy weight so it could be that reworking the palette loading would make it faster. Or not throwing away the widgets, just hiding them to avoid recreating them later is the way to go.
Comment 26 Dominic Davies 2017-02-28 14:33:29 UTC
Surely the correct way to handle this is to avoid making the entire interface freeze whilst the widgets are processed. Can't this be handled asynchronously? i.e. the object is selected in the canvas and the user continue work whilst the widgets are processed and added to the Sidebar.
Comment 27 Michael Meeks 2017-02-28 15:49:38 UTC
> Surely the correct way to handle this is to avoid making the entire interface
> freeze whilst the widgets are processed. Can't this be handled asynchronously?

I assume it is handled asynchronously - however, it is possible that that happens with too high a priority; and/or that we may need to improve prioritization of tasks to ensure that even if we hit 'idle' (ie. all tasks done) - that we don't allow a low priority task that last-time took <N> milliseconds to consume more than a certain budgeted time each second or so - to somehow push these guys off so they don't block event processing =)

But of course - I could be wrong, and it could be handled synchronously; and - as Caolan says, prolly the easiest fix is profiling to find out why it is quite so slow. That's easy to do with a -non- dbgutil build, that has debugging symbols and callgrind/cachegrind =)
Comment 28 Aron Budea 2017-03-31 22:34:10 UTC
*** Bug 106588 has been marked as a duplicate of this bug. ***
Comment 29 Buovjaga 2017-04-06 17:56:40 UTC
Created attachment 132380 [details]
Callgrind output from 5.4

I did the selection dance while callgrinding on Linux. I hope it helps.

Arch Linux 64-bit, KDE Plasma 5
Version: 5.4.0.0.alpha0+
Build ID: 541b377a94fb1247dbf4c39b5bcf55deb8e5ef60
CPU threads: 8; OS: Linux 4.10; UI render: default; VCL: kde4; 
Locale: fi-FI (fi_FI.UTF-8); Calc: group
Built on March 31st 2016
Comment 30 Buovjaga 2017-04-17 17:09:15 UTC
*** Bug 107044 has been marked as a duplicate of this bug. ***
Comment 31 Aron Budea 2017-05-07 03:16:21 UTC
*** Bug 105428 has been marked as a duplicate of this bug. ***
Comment 32 Commit Notification 2017-05-08 12:53:54 UTC
Aron Budea committed a patch related to this issue.
It has been pushed to "master":

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

tdf#104312, tdf#105428: use static vars in ReplaceStringHookProc

It will be available in 5.4.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 33 Aron Budea 2017-05-09 03:15:40 UTC
I worked with Telesto's attachment 129188 [details] in Windows, and posted a fix based on that. I'm not convinced this is the root of all the similar OSX issues, but we'll see. (Linux seemed to be unaffected)

The majority of the lag was caused by reading the build id from a config file when doing a string id conversion, for each palette color. (or something like that)

Please test again using a fresh daily build.
Comment 34 Commit Notification 2017-05-10 04:18:42 UTC
Aron Budea committed a patch related to this issue.
It has been pushed to "master":

http://cgit.freedesktop.org/libreoffice/core/commit/?id=910ead9c8344f32ba3d280a777306490aed5dac2

tdf#104312: add missing #include

It will be available in 5.4.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 35 tomaskeb 2017-05-10 10:45:16 UTC
*** Bug 98132 has been marked as a duplicate of this bug. ***
Comment 36 Commit Notification 2017-05-16 09:43:30 UTC
Aron Budea committed a patch related to this issue.
It has been pushed to "libreoffice-5-3":

http://cgit.freedesktop.org/libreoffice/core/commit/?id=aafb6a75c7461362aceddeadfbf0db0848af866c&h=libreoffice-5-3

tdf#104312, tdf#105428: use static vars in ReplaceStringHookProc

It will be available in 5.3.4.

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 37 Alex Thurgood 2017-07-21 15:26:13 UTC
(In reply to Commit Notification from comment #36)
> Aron Budea committed a patch related to this issue.
> It has been pushed to "libreoffice-5-3":
> 
> http://cgit.freedesktop.org/libreoffice/core/commit/
> ?id=aafb6a75c7461362aceddeadfbf0db0848af866c&h=libreoffice-5-3
> 
> tdf#104312, tdf#105428: use static vars in ReplaceStringHookProc
> 
> It will be available in 5.3.4.
> 
> 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.


This still doesn't appear to be fixed on OSX with LO5432, where there is still a noticeable lag between selection of an object and display of the object handles.

In comparison, LO41 is lightning fast, with instantaneous display of the selection handlers.

Tested on MacBookPro end-2013 Core i7 with 16Mb 1600 MHz DDR3 RAM ==> Re-opening
Comment 38 Telesto 2017-07-21 16:50:49 UTC
(In reply to Alex Thurgood from comment #37)
There is still a open bug (bug 105500) for a lag introduced between 5.0.0.5 and 5.1.0.3. This report is only about the - fixed - regression introduced with the 5.3.0.0 branch.

So the lag is probably caused by bug 105500 intensified by the poor MacOS performance which has something to do with the main-loop / idle handler re-work. See attachment 132593 [details], bug 106154.
Comment 39 Caolán McNamara 2017-07-21 19:28:34 UTC
so if this is a different problem with the same outcome can this be put back to fixed and open a new one ? otherwise its just like claiming the doctor didn't fix the patients broken leg the last time when he drove into a tree again
Comment 40 Buovjaga 2017-07-22 07:39:11 UTC
(In reply to Caolán McNamara from comment #39)
> so if this is a different problem with the same outcome can this be put back
> to fixed and open a new one ? otherwise its just like claiming the doctor
> didn't fix the patients broken leg the last time when he drove into a tree
> again

I believe so.