Bug 118593 - Opening first document pauses for 6-7 s, drops to 2 s by inserting a smart card into reader
Summary: Opening first document pauses for 6-7 s, drops to 2 s by inserting a smart ca...
Status: RESOLVED FIXED
Alias: None
Product: LibreOffice
Classification: Unclassified
Component: LibreOffice (show other bugs)
Version:
(earliest affected)
5.3.0.3 release
Hardware: x86-64 (AMD64) Linux (All)
: medium normal
Assignee: Miklos Vajna
URL:
Whiteboard: target:6.2.0 target:6.1.1
Keywords: bibisected, regression
Depends on:
Blocks:
 
Reported: 2018-07-06 19:13 UTC by sasu.liuhanen
Modified: 2018-09-12 10:28 UTC (History)
3 users (show)

See Also:
Crash report or crash signature:


Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description sasu.liuhanen 2018-07-06 19:13:28 UTC
Description:
Opening any other document (e.g. odt, ods, odp, docx) than plain text is very slow, unless one such document is already open in any LO window. Reader/Calc/Impress window opens instantly, but pauses then for 6-7 seconds before showing the contents of the document. If the document is opened from within Writer, it displays "Loading document..." during the wait. The size of the document doesn't have any perceptible influence on the time.

Purging and reinstalling LO does not help. Neither does removing user profiles or deleting ~/.config/libreoffice. Using safe-mode changes nothing either.

Having one LO window open and opening any document (other than plain text) in it, abolishes the whole wait from subsequent opens and everything works as expected. In summary, LO seems to pause and wait for something while opening the first document and the wait is gone after the first document is opened.

Steps to Reproduce:
1. Open Reader
2. Open any odt, ods, odp or docx document
3. Program window opens immediately
4. The program waits for something for 6-7 seconds
5. The document opens
6. Open any other document
7. The second document opens immediately

OR

1. Open any above-mentioned document from the command line
2. Program window opens immediately
3. The program waits for something for 6-7 seconds
4. The document opens
5. Open any other document
6. The second document opens immediately

(and the same with Calc and Impress)

Actual Results:
6-7 s wait on opening the first documents, next documents open immediately. 

Expected Results:
More or less immediate document open (at least on empty / almost empty documents)


Reproducible: Always


User Profile Reset: Yes


OpenGL enabled: Yes

Additional Info:
Enabling / disabling hardware acceleration doesn't change anything. Resources are not the issue (10 cores, 128GB memory, very fast SSDs).
Comment 1 sasu.liuhanen 2018-07-06 19:59:10 UTC
Looking at strace output during the wait:
- repeated nanosleeps
- reads from smartcard reader

When I put a smart card into the reader, the delay drops down to about two seconds and LO seems to detect the card as indicated by the card reader led blinking. Removing the card reader by unplugging it does not remove the delay, however. With the reader unplugged the delay is back to the initial 6-7 seconds.
Comment 2 Buovjaga 2018-07-15 16:45:40 UTC
As this case involves hardware that many testers do not have, would you like to test with older releases to see, if the behaviour is different? An easy way is to use appimages: https://libreoffice.soluzioniopen.com/index.php/old-versions/

Just set chmod +x on the file and run, no need to install anything.

Note that older ones may not run due to library incompatibilities.

You might try a version from each of the 3.x, 4.x and 5.x lines.
Comment 3 sasu.liuhanen 2018-07-15 19:04:43 UTC
Tried 5.2.7.2 and it works as expected. It takes a little longer to start than the currently installed version (AppImage issue?), but there is no extra delay opening documents and having a card insert into the reader or not has no effect on anything. Furthermore, the card reader does no react to opening documents (led stays on all the time, not blinking, when a card is in the reader) at all. 

Tried 4.4.7.2 as well, but it won't start. It does show the "LibreOffice / The Document Foundation" splash for a little while, but then dies away. Doesn't give any informative error messages.
Comment 4 Buovjaga 2018-07-16 06:21:07 UTC
Ok, that is interesting. Could you also try an appimage of 6.1 and/or a daily build to confirm that the problem still exists?
Comment 5 sasu.liuhanen 2018-07-16 17:58:05 UTC
Tried appimages of 6.1.0.1 and 6.2.0.0.alpha0+ (2018-07-15) and the wait issue exists on both of those versions. Their behavior seems identical to 6.0.3.2.
Comment 6 Buovjaga 2018-07-16 19:35:13 UTC
(In reply to sasu.liuhanen from comment #5)
> Tried appimages of 6.1.0.1 and 6.2.0.0.alpha0+ (2018-07-15) and the wait
> issue exists on both of those versions. Their behavior seems identical to
> 6.0.3.2.

Ok, so far we know it is something that appeared between 5.2 and 6.0.

What Linux distro are you using? If your distro is a mainstream one, it is possible to git bisect the appearance of the problem.

Setting up the binary bisect repos and going through the whole process is somewhat tedious with various quirks (most of which are documented in the wiki). I assume you live in Finland like me, so I guess I could give you support over the phone to make things less painful :) Feel free to email me about it, if you like.

The binary bisecting guides:
https://wiki.documentfoundation.org/QA/Bibisect
https://wiki.documentfoundation.org/QA/Bibisect/Linux
Comment 7 sasu.liuhanen 2018-07-16 20:42:03 UTC
Ubuntu 18.04. 

It will take at least a few days, maybe more, before I'll be able to try bisecting. But I'll be happy to try to locate the source of this issue.

And thanks for the support offer!
Comment 8 Buovjaga 2018-07-17 09:06:44 UTC
Ok, I think you could narrow it down first with a couple of appimages (the bibisect repos take up gigabytes of space). To be sure that the issue is not something backported to a 6.0.x minor release, you could try with an appimage of 6.0.0. Then, 5.4.0 and 5.3.0. After this testing, you would have an idea of which bibisect repo to try.
Comment 9 sasu.liuhanen 2018-07-21 19:05:13 UTC
Haven't had time for a bibisect attempt yet, but narrowed down the emergence of the issue between versions 5.2.7.2 (works as expected) and 5.3.0.3 (has the issue).
Comment 10 sasu.liuhanen 2018-07-21 20:28:46 UTC
Bisect results:
 10dfe6677566917cb0c8a77db367fad9281985d2 is the first bad commit
commit 10dfe6677566917cb0c8a77db367fad9281985d2
Author: Jenkins Build User <tdf@pollux.tdf>
Date:   Tue Nov 8 17:48:52 2016 +0100

    source a69873d212c903ea8a1f0d5ca40ae3f08b83a871
    
    source a69873d212c903ea8a1f0d5ca40ae3f08b83a871

:040000 040000 629d6abcde165513ecfc71ddd98261f6f9de9037 aabc203987c5f724dcdf226c2b1840b789499ecc M	instdir

Bisect log:
# bad: [1bfd8dda84f0dd2c5662b64f382637d75b8bf227] source 6238f71ddbdc766e733b1c808a4fa7d66f7bde87
# good: [33e60eae04c889baf52713a73dc9944015408914] source 5b168b3fa568e48e795234dc5fa454bf24c9805e
git bisect start 'origin/master' 'oldest'
# good: [964789dfd0674f0447da363a8c52114097796fa3] source e473e0e1b9bc354d53908cb0ca84db06c3051fe2
git bisect good 964789dfd0674f0447da363a8c52114097796fa3
# good: [82e6762ef9ce5acd3ee832074a327ac43d94173a] source 6f345e1e6e2d7f6fdbd746dfd0c91843a5ff2d10
git bisect good 82e6762ef9ce5acd3ee832074a327ac43d94173a
# good: [b496470a254d264be0b15764e76d3ae0cff325da] source 1bbf7f653b6b159afb0bf2c34dd463f58333852c
git bisect good b496470a254d264be0b15764e76d3ae0cff325da
# bad: [85b3496336990ff6a25b39bcb67a0564136455dc] source 2fdbe655bb63dd40fda9b684c5715f21fd5ab639
git bisect bad 85b3496336990ff6a25b39bcb67a0564136455dc
# bad: [2d5c8caa3097fd3bdef457bc3fc58e10df57bf22] source d115a235bf3ff5366d992d01fb418a3eacb9d125
git bisect bad 2d5c8caa3097fd3bdef457bc3fc58e10df57bf22
# good: [9b38dac0365bc16742982f4e682ac08f63bba65a] source 703d00e335bf0d38b3019ec2ba095b27a5fdba2d
git bisect good 9b38dac0365bc16742982f4e682ac08f63bba65a
# good: [8701a36236355ead58796c3ba4227f8cd75b6bcf] source d9c43a1d543774055dd8aa0d8584b36519236238
git bisect good 8701a36236355ead58796c3ba4227f8cd75b6bcf
# good: [9b978929de65707543227e9fb29ac512e9bcf51d] source cc2d27ea1ef4018d0865095853e7d661f8070e1f
git bisect good 9b978929de65707543227e9fb29ac512e9bcf51d
# bad: [f7f28e93298625081db77cd12caab3f310d4f005] source 62401ba3c9df1f7234bd272b3e659a08f546d50c
git bisect bad f7f28e93298625081db77cd12caab3f310d4f005
# good: [d885a85c7fee211e1e858af01f5677dbdd7d5c8a] source 2573f6bba6b3033143b776650f03fd4813669e5b
git bisect good d885a85c7fee211e1e858af01f5677dbdd7d5c8a
# bad: [f44634fb34ad192338ad2c0769783c74cc5b0e0d] source cb34498395a5eb0d33fb019c2ec8534f8854afcd
git bisect bad f44634fb34ad192338ad2c0769783c74cc5b0e0d
# bad: [c5401e16e6eb0cebcedb33dd114d159c1f95425d] source c0da11fb1c1cbc701e64a4b3f1f3c6506ef663d2
git bisect bad c5401e16e6eb0cebcedb33dd114d159c1f95425d
# bad: [10dfe6677566917cb0c8a77db367fad9281985d2] source a69873d212c903ea8a1f0d5ca40ae3f08b83a871
git bisect bad 10dfe6677566917cb0c8a77db367fad9281985d2
# first bad commit: [10dfe6677566917cb0c8a77db367fad9281985d2] source a69873d212c903ea8a1f0d5ca40ae3f08b83a871
Comment 11 Buovjaga 2018-07-22 07:24:28 UTC
Ok, so that points to Miklos's "xmlsecurity: move the sec context from the format helpers to the sign manager"

Adding Cc: to Miklos Vajna
Comment 12 Miklos Vajna 2018-07-25 07:58:01 UTC
Just to be clear, this problem happens even if that first document is not signed, correct?
Comment 13 sasu.liuhanen 2018-07-25 08:06:35 UTC
Yes, it happens with all documents.
Comment 14 Miklos Vajna 2018-07-25 08:11:24 UTC
Okay, then I can confirm a variant of this: libxmlsec is initialized when you open a non-signed document: which is a waste of time. I assume this is the same root cause as your time delay.
Comment 15 Commit Notification 2018-07-31 07:11:11 UTC
Miklos Vajna committed a patch related to this issue.
It has been pushed to "master":

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

tdf#118593 sfx2: no need to call into xmlsecurity without signature streams

It will be available in 6.2.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 16 Commit Notification 2018-08-01 11:10:07 UTC
Miklos Vajna committed a patch related to this issue.
It has been pushed to "libreoffice-6-1":

http://cgit.freedesktop.org/libreoffice/core/commit/?id=5ffc6da9b8270114cc6e1100f79425e70c5a5789&h=libreoffice-6-1

tdf#118593 sfx2: no need to call into xmlsecurity without signature streams

It will be available in 6.1.1.

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 17 sasu.liuhanen 2018-08-02 18:08:13 UTC
6.2.0.0.alpha0+ 2018-07-31 (AppImage) works as expected. Excellent!
Comment 18 Thorsten Behrens (allotropia) 2018-09-12 10:28:32 UTC
*** Bug 119811 has been marked as a duplicate of this bug. ***