Bug 130795 - FILEOPEN: Spreadsheet takes long to open
Summary: FILEOPEN: Spreadsheet takes long to open
Status: RESOLVED FIXED
Alias: None
Product: LibreOffice
Classification: Unclassified
Component: Calc (show other bugs)
Version:
(earliest affected)
6.2.0.3 release
Hardware: All All
: medium normal
Assignee: Not Assigned
URL:
Whiteboard: target:7.3.0
Keywords: bibisected, bisected, perf, regression
Depends on:
Blocks: Regressions-row-height
  Show dependency treegraph
 
Reported: 2020-02-20 08:12 UTC by Elmar
Modified: 2021-11-09 11:48 UTC (History)
6 users (show)

See Also:
Crash report or crash signature:


Attachments
long time to open (879.23 KB, application/vnd.oasis.opendocument.spreadsheet)
2020-02-20 08:17 UTC, Elmar
Details
Flamegraph (160.07 KB, application/x-bzip)
2020-02-20 20:59 UTC, Julien Nabet
Details
perf flamegraph (104.34 KB, application/x-bzip)
2021-09-09 19:12 UTC, Julien Nabet
Details
perf flamegraph (87.64 KB, application/x-bzip)
2021-09-17 11:35 UTC, Julien Nabet
Details

Note You need to log in before you can comment on or make changes to this bug.
Description Elmar 2020-02-20 08:12:57 UTC
Description:
Seems to be related to external links. 

in v6.0 is almost instantaneous - and comes up with a message to ask if links should be updated.

Steps to Reproduce:
1. open a large xlsx
2. 
3. 

Actual Results:
Have to wait for long time
Initially abandoned, then tried with v6

Expected Results:
should not take so long to eb available


Reproducible: Always


User Profile Reset: No



Additional Info:
[Information automatically included from LibreOffice]
Locale: en-GB
Module: SpreadsheetDocument
[Information guessed from browser]
OS: Linux (All)
OS is 64bit: yes
Comment 1 Elmar 2020-02-20 08:17:25 UTC
Created attachment 158022 [details]
long time to open

xlsx saved to ods (original files size 1.9MB) problem same
Comment 2 Xisco Faulí 2020-02-20 09:13:02 UTC
it takes

real	2m22,490s
user	3m12,778s
sys	0m32,862s


in

Version: 7.0.0.0.alpha0+
Build ID: bc994a4b01cf61444452bb377010c7c4cc377698
CPU threads: 4; OS: Linux 4.19; UI render: default; VCL: gtk3; 
Locale: en-US (en_US.UTF-8); UI-Language: en-US
Calc: threaded
Comment 3 Xisco Faulí 2020-02-20 09:22:41 UTC
in

Version: 5.2.0.0.alpha0+
Build ID: 3ca42d8d51174010d5e8a32b96e9b4c0b3730a53
Threads 4; Ver: 4.19; Render: default;

it takes

real	8m36,323s
user	7m32,024s
sys	0m2,208s


so I great improvement has been done
Comment 4 Xisco Faulí 2020-02-20 09:23:23 UTC Comment hidden (obsolete)
Comment 5 Julien Nabet 2020-02-20 09:26:54 UTC Comment hidden (obsolete)
Comment 6 Elmar 2020-02-20 09:32:59 UTC
How come v6.0 is so much faster?
When check edit/links, shows that the setting is "manual" - so should it not check that and ignore the links?
v6.0 also has a progress bar - not shown in v7
(at least one knows that that Calc has not frozen)
Comment 7 Xisco Faulí 2020-02-20 09:41:05 UTC
it takes

real	7m6,001s
user	6m45,494s
sys	0m1,733s


in

Version: 4.3.0.0.alpha1+
Build ID: c15927f20d4727c3b8de68497b6949e72f9e6e9e
Comment 8 Xisco Faulí 2020-02-20 09:43:45 UTC Comment hidden (obsolete)
Comment 9 Xisco Faulí 2020-02-20 09:54:48 UTC
ok, it takes

real	0m58,031s
user	0m41,518s
sys	0m2,249s

in

Version: 6.0.0.0.alpha1+
Build ID: 6eeac3539ea4cac32d126c5e24141f262eb5a4d9
CPU threads: 4; OS: Linux 4.19; UI render: default; VCL: gtk3; 
Locale: en-US (en_US.UTF-8); Calc: group threaded

so it seems it was pretty slow in the past, improved a lot, and now it has regress a little bit
Comment 10 Xisco Faulí 2020-02-20 10:10:43 UTC
so, the import time got worse after https://cgit.freedesktop.org/libreoffice/core/commit/?id=1e55a47e89a9d9d6cf9cb3993484022aaf2c097b, however, it doesn't mean the problem was introduced by this commit. In previous versions, ie 6.0. the issue can be reproduced if recalculation on File Load for ODF files is set to Always Recalculate in Tools/Options.../LibreOffice Calc/Formula
Comment 11 Xisco Faulí 2020-02-20 10:22:49 UTC Comment hidden (no-value)
Comment 12 Julien Nabet 2020-02-20 20:59:54 UTC
Created attachment 158062 [details]
Flamegraph

Here's a Flamegraph retrieved on pc Debian x86-64 with master sources updated today.
Comment 13 Xisco Faulí 2020-02-20 22:07:12 UTC Comment hidden (obsolete)
Comment 14 Timur 2021-09-01 13:24:18 UTC
Linux 5.2 m:
real	0m31,827s
user	0m18,338s
sys	0m0,799s

Linux 6.0 m:
real	0m39,547s
user	0m21,360s
sys	0m1,238s

Linux 6.2 pre 1e55a47e89a9d9d6cf9cb3993484022aaf2c097b (time spent on loading, calculating):
real	0m40,949s
user	0m22,269s
sys	0m1,295s

Linux 6.2 with 1e55a47e89a9d9d6cf9cb3993484022aaf2c097b:
real	1m46,854s
user	1m28,051s
sys	0m1,488s

Linux 6.3 m:
real	1m20,008s
user	1m49,742s
sys	0m3,880s

Linux 7.0 m - initially reported version:
real	1m38,572s
user	2m7,639s
sys	0m4,439s

Linux 7.3+ master
real	0m56,994s
user	1m27,686s
sys	0m5,903s

Time recorded on 2nd load so it's longer in reality. 
In current master 7.3+ time is better than when reported with 7.0 but it's still worse than before. 

Can be considered a regression so I block to bug 125077. 
Recalculate in Tools/Options.../LibreOffice Calc/Formula is for formula and I don't see it as relevant, all test are without recalculation.
Comment 15 Commit Notification 2021-09-04 17:21:36 UTC
Noel Grandin committed a patch related to this issue.
It has been pushed to "master":

https://git.libreoffice.org/core/commit/41a46a306f40a7296c56bdeea0ba8a6d630aa15c

dynamic_cast -> static_cast (tdf#130795)

It will be available in 7.3.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 16 Timur 2021-09-08 09:49:38 UTC
Linux 7.3+, same system:

Pre fix 1st time: 
real	0m36,454s
user	0m58,049s
sys	0m3,584s
Pre fix 2st time: 
real	0m33,827s
user	0m52,990s
sys	0m2,951s

Post-fix 41a46a306f40a7296c56bdeea0ba8a6d630aa15c 1st time: 
real	0m35,072s
user	0m55,159s
sys	0m3,097s
Post-fix 2st time: 
real	0m29,631s
user	0m45,245s
sys	0m2,412s

So fix improved this slightly. 
On fileopen we see "Adapt row height" so it indicates where time is spent. 

73+ 1st time:
real	0m35,328s
user	0m55,636s
sys	0m3,704s
2nd time:
real	0m35,395s
user	0m56,583s
sys	0m2,735s

Those timings are not exact.
Real time of 30-35 sec could be considered as good as it ever was (but not as it should be). 
User time of 45-55 sec is longer than 20 sec in 6.2. User+Sys should be CPU time, so indicating worse perf. Here on a multicore system, the user and sys time exceed the real time.
Comment 17 Noel Grandin 2021-09-08 09:54:07 UTC
(In reply to Timur from comment #16)
> On fileopen we see "Adapt row height" so it indicates where time is spent. 

Not in this case, profiler says time is now all over the place.

https://gerrit.libreoffice.org/c/core/+/121717

will improve it considerably when it lands
Comment 18 Commit Notification 2021-09-09 07:07:37 UTC
Noel Grandin committed a patch related to this issue.
It has been pushed to "master":

https://git.libreoffice.org/core/commit/3749d9af3745c0eaff7239e379578e4e2af89e9d

tdf#130795 use concurrent hashmap in SharedStringPool

It will be available in 7.3.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 19 Julien Nabet 2021-09-09 19:12:06 UTC
Created attachment 174931 [details]
perf flamegraph

Here's the Flamegraph retrieved on pc Debian x86-64 with master sources updated today (8104d771b10a5c8b15eae4b67aa112ae2ef77b5b).

I just put the trace for info. If something can be optimized, great, if not, not a pb since it's quite quick to open.
Comment 20 Xisco Faulí 2021-09-10 09:55:56 UTC
it takes

real	0m17,823s
user	0m26,524s
sys	0m1,320s

with the commit from comment 18, while it takes

real	0m28,101s
user	0m38,720s
sys	0m7,812s

without it. Nice improvement
Comment 21 Luboš Luňák 2021-09-11 06:51:04 UTC
The real problem here is not that SharedStringPool would be slow, but that ScTable::ValidQuery()/QueryEvaluator calls it at all. If you look at how it's used, those strings are interned only to do a "fast" case-insensitive comparison _once_, but interning a string apparently takes way longer than a normal comparison would. The concurrent hashmap change is band-aid (at least in this case), the real fix should be removing the SharedStringPool usage from QueryEvaluator. Bug #144249 has a similar problem.
Comment 22 Luboš Luňák 2021-09-11 06:55:14 UTC
(The relevant commit for bug #144249 being https://git.libreoffice.org/core/commit/d0316985db22efd6708dffa173eaabb430f6b9a8, I did not CC the bugreport on that one. And I don't know if I'll have the time to do the suggested change and test it, so feel free to.)
Comment 23 Julien Nabet 2021-09-11 07:15:13 UTC
(In reply to Luboš Luňák from comment #21)
> The real problem here is not that SharedStringPool would be slow, but that
> ScTable::ValidQuery()/QueryEvaluator calls it at all. If you look at how
> it's used, those strings are interned only to do a "fast" case-insensitive
> comparison _once_, but interning a string apparently takes way longer than a
> normal comparison would. The concurrent hashmap change is band-aid (at least
> in this case), the real fix should be removing the SharedStringPool usage
> from QueryEvaluator. Bug #144249 has a similar problem.

So we could also remove the brand new lib dependency on cuckoo (unless it could be used for something else?)

About SharedStringPool, I took a look at git history.
git log --follow -S 'svl::SharedStringPool' sc/source/core/data/table3.cxx
commit 2f39c27be2bd66f149e0a4efdd7fa37daee43fb1
Author: Kohei Yoshida <kohei.yoshida@collabora.com>
Date:   Wed Oct 9 10:50:23 2013 -0400

    Use shared string's fast equality check for ValidQuery().
    
    Change-Id: Ib84087a10cc10a7533e64c4e8998354b52017df7

commit a11e224e07a4fda0de64a9a0a181f6034e08d2e5
Author: Kohei Yoshida <kohei.yoshida@collabora.com>
Date:   Tue Oct 8 21:46:56 2013 -0400

    Store svl::SharedString in query entry items, and adjust all call sites.
    
    Change-Id: Ifd3bbb84c7abbe983a017a169c7e05914ef33450

Kohei was in the trio Calc experts (Eike, Kohei, Markus), so I suppose he had done some perf tests but perhaps with all code change after all these years, those are no more relevant?

Eike: any thoughts here?
Comment 24 Luboš Luňák 2021-09-13 09:16:19 UTC
> So we could also remove the brand new lib dependency on cuckoo (unless it
> could be used for something else?)

I think so.
 
> Kohei was in the trio Calc experts (Eike, Kohei, Markus), so I suppose he
> had done some perf tests but perhaps with all code change after all these
> years, those are no more relevant?

Using SharedString is worth it if the object is used multiple times to offset the creation cost. The problem here is that the object is used just once.
Comment 25 Noel Grandin 2021-09-13 11:42:27 UTC
(In reply to Luboš Luňák from comment #21)
> The real problem here is not that SharedStringPool would be slow, but that
> ScTable::ValidQuery()/QueryEvaluator calls it at all. If you look at how


The primary call-site in this bug is
   QueryEvaluator:: compareByStringComparator
which is this code:
   https://opengrok.libreoffice.org/xref/core/sc/source/core/data/table3.cxx?r=0a9b68c9#2687

If I switch that to
    // fallback
    const CharClass& rCharClass = *ScGlobal::getCharClassPtr();
    rtl_uString* pTmpRHS = const_cast<rtl_uString*>(rItem.maString.getDataIgnoreCase());
    bOk = rCharClass.uppercase(*pValueSource2) == OUString::unacquired(&pTmpRHS);

This document takes twice as long to load.

Possibly you had something else in mind?
Comment 26 Luboš Luňák 2021-09-13 13:41:51 UTC
No, that's the code I had in mind, I assumed that intern() would be slower than using the string directly, as was the case with bug #144249.
Comment 27 Luboš Luňák 2021-09-15 09:23:46 UTC
That said, looking at the profiling of the comment #25 code, the majority of time spent there is not spent actually uppercasing the string, it's spent in lock contention and the i18n classes repeatedly updating their internal state. Without that, it seems the performance would be about the same. So the reason why the SharedStringPool version is faster is because our i18n code is dumb (at least as far as performance goes) and usage of libcuckoo removes these problems from SharedStringPool, not because using SharedStringPool be inherently faster here.

But I don't think I'll have the time to try to redesign the i18n code or look into why ValidQuery() gets called so often.
Comment 28 Noel Grandin 2021-09-17 09:35:43 UTC
After doing several rounds of optimisation to the uppercase machinery, I can get it to be __almost__ as fast as using the SharedStringPool :-)

Possibly there is some stuff that could be done with the tables in i18nutil/ but I don't feel like touching that
Comment 29 Julien Nabet 2021-09-17 11:35:04 UTC
Created attachment 175094 [details]
perf flamegraph

Thank you Noel for the patches!

For those interested, here's a brand new Flamegraph retrieved on pc Debian x86-64 with master sources updated today (d0940e0cca552f65ea4e85d9895682afab230c87) + enable-symbols (not enable-dbgutil) + brand new LO profile + gen rendering.
Comment 30 Luboš Luňák 2021-11-08 19:47:41 UTC
Changes for bug #139444 now avoid use of SharedStringPool::intern() here altogether, and it's reasonably fast.

I don't know if we still need libcuckoo after this, keeping this open in case Noel wants to examine that.
Comment 31 Xisco Faulí 2021-11-09 10:31:56 UTC
(In reply to Luboš Luňák from comment #30)
> Changes for bug #139444 now avoid use of SharedStringPool::intern() here
> altogether, and it's reasonably fast.
> 
> I don't know if we still need libcuckoo after this, keeping this open in
> case Noel wants to examine that.

Hi Lubos,
I gave a try at it and these are my findings:

1. Import time WITH Noel's patch and WITHOUT Lubos' patches:

real	0m20,625s
user	0m26,714s
sys	0m1,415s

2. Import time WITHOUT Noel's patch and WITHOUT Lubos' patches:

real	0m27,653s
user	0m32,110s
sys	0m8,507s

3. Import time WITHOUT Noel's patch and WITH Lubos' patches:

real	0m12,181s
user	0m15,275s
sys	0m0,774s

4. Import time WITH Noel's patch and WITH Lubos' patches:

real	0m11,795s
user	0m14,853s
sys	0m0,861s
Comment 32 Elmar 2021-11-09 10:55:33 UTC
It now takes a second or two
Comment 33 Xisco Faulí 2021-11-09 11:48:30 UTC
(In reply to Elmar from comment #32)
> It now takes a second or two

Let's close it as RESOLVED FIXED instead. Another comparison:

in

Version: 7.2.3.0.0+ / LibreOffice Community
Build ID: f5e4dbfccdbc0d810cf82c52f14801dddf95631a
CPU threads: 4; OS: Linux 5.10; UI render: default; VCL: gtk3
Locale: en-US (en_US.UTF-8); UI: en-US
Calc: threaded

it takes

real	0m24,275s
user	0m32,842s
sys	0m8,268s

while in

Version: 7.3.0.0.alpha1+ / LibreOffice Community
Build ID: a14b783bbe8eda32b4b79530d85ffc48b6ed0305
CPU threads: 4; OS: Linux 5.10; UI render: default; VCL: gtk3
Locale: en-US (en_US.UTF-8); UI: en-US
Calc: threaded

it takes

real	0m12,091s
user	0m15,518s
sys	0m0,813s