Bug Hunting Session
Bug 120837 - File saving at least 5 times slower
Summary: File saving at least 5 times slower
Status: VERIFIED FIXED
Alias: None
Product: LibreOffice
Classification: Unclassified
Component: Writer (show other bugs)
Version:
(earliest affected)
6.1.0.0.alpha1+
Hardware: All All
: medium normal
Assignee: Not Assigned
URL:
Whiteboard: target:6.3.0
Keywords: bibisected, bisected, haveBacktrace, perf, regression
Depends on:
Blocks: imageHandling-regressions
  Show dependency treegraph
 
Reported: 2018-10-23 14:26 UTC by Telesto
Modified: 2019-06-13 17:33 UTC (History)
5 users (show)

See Also:
Crash report or crash signature:


Attachments
Example file (518.67 KB, application/vnd.oasis.opendocument.text)
2018-10-23 14:27 UTC, Telesto
Details
bibisect in linux-64-6.1, tail of terminal output (2.98 KB, text/plain)
2018-11-16 21:33 UTC, Terrence Enger
Details
files from callgrind (3.87 MB, application/zip)
2018-12-06 19:13 UTC, Terrence Enger
Details
Perf flamegraph (1.05 MB, image/svg+xml)
2019-04-19 10:58 UTC, Buovjaga
Details

Note You need to log in before you can comment on or make changes to this bug.
Description Telesto 2018-10-23 14:26:54 UTC
Description:
Saving slower file-saving

Steps to Reproduce:
1. Open attached file
2. Press Save or Save As

Actual Results:
18 seconds 

Expected Results:
2 seconds


Reproducible: Always


User Profile Reset: No



Additional Info:
Found in
Version: 6.2.0.0.alpha0+
Build ID: 3846561f79cf9065abd9ca83c9fbfbe7e52e28e2
CPU threads: 4; OS: Windows 6.3; UI render: default; VCL: win; 
TinderBox: Win-x86@42, Branch:master, Time: 2018-10-20_23:33:00
Locale: nl-NL (nl_NL); Calc: CL

but not in
Version: 6.1.0.0.alpha0+
Build ID: c26f644db80e10f755911d277aac0e1d42731d29
CPU threads: 4; OS: Windows 6.3; UI render: default; 
Locale: nl-NL (nl_NL); Calc: CL
Comment 1 Telesto 2018-10-23 14:27:08 UTC
Created attachment 145935 [details]
Example file
Comment 2 Telesto 2018-10-23 14:30:33 UTC
Issue also occurring when saving when exporting to PDF: Point::toPair
Comment 3 Xisco Faulí 2018-10-23 15:12:06 UTC
So it seems the export time has increased over the time.
In

Version: 6.2.0.0.alpha1+
Build ID: cd6dd8c6f3562cbccbc971b916c6a8933840ffeb
CPU threads: 4; OS: Linux 4.15; UI render: default; VCL: gtk3; 
Locale: ca-ES (ca_ES.UTF-8); Calc: threaded

and

Version: 6.1.0.0.alpha1+
Build ID: 3a801799536e6870f2fb111b1cc00b9575a35a39
CPU threads: 4; OS: Linux 4.15; UI render: default; VCL: gtk3; 
Locale: ca-ES (ca_ES.UTF-8); Calc: group

real	0m32.163s
user	0m29.607s
sys	0m1.467s

in

Version: 6.0.0.0.alpha1+
Build ID: 6eeac3539ea4cac32d126c5e24141f262eb5a4d9
CPU threads: 4; OS: Linux 4.15; UI render: default; VCL: gtk3; 
Locale: ca-ES (ca_ES.UTF-8); Calc: group threaded

real	0m11.287s
user	0m7.251s
sys	0m1.286s

and

Version: 5.4.0.0.alpha1+
Build ID: 9feb7f7039a3b59974cbf266922177e961a52dd1
CPU threads: 4; OS: Linux 4.15; UI render: default; VCL: gtk3; 
Locale: ca-ES (ca_ES.UTF-8); Calc: group

real	0m4.477s
user	0m3.426s
sys	0m0.584s
Comment 4 Terrence Enger 2018-11-16 21:33:20 UTC
Created attachment 146699 [details]
bibisect in linux-64-6.1, tail of terminal output

Working on debian-buster in the bibisect-linux-64-6.1 repository, I
see that the bug came into LibreOffice:

          commit    s-h       date        time
          --------  --------  ----------  -----
    good  10fffef2  a61747c2  2018-02-01  10:53:26
    bad   dcc8ce9e  e02efb62  2018-02-01  10:54:22

and

    commit e02efb621fe672aa52e56caa916cf5c3fd0a9cb8
    Author: Tomaž Vajngerl <tomaz.vajngerl@collabora.co.uk>
    Date:   Thu Feb 1 15:28:53 2018 +0900

        Change bitmap table to store XBitmap instead of GraphicObject URL
    
        As we want to get rid of GraphicObject URLs for the more robust
        image life-cycle handling, it was necessary to change the way
        bitmap table stores and handles images, so that they always
        store a Graphic object (wrapped in UNO object that provides the
        XGraphic and XBitmap interface).
    
        In addition this changes loading and saving from ODF (xmloff) and
        OOXML (oox) filters so they don't depend on GraphicObject URL
        anymore, but load or save directly to / from  XGraphic or XBitmap.
    
        Change-Id: I2b88e10056e7d6c920249d59188f86b1a5a32d21
        Reviewed-on: https://gerrit.libreoffice.org/49074
        Tested-by: Jenkins <ci@libreoffice.org>
        Reviewed-by: Tomaž Vajngerl <quikee@gmail.com>

Within the bibisect process, the CPU time for Save-As in "good"
versions was from 2.37 to 2.52 seconds and in the versions I deemed
"bad" from 13.35 to 13.80 seconds.

I have not found the earlier slowdown that Xisco reported in comment
3, so I am leaving keyword bibisectRequest.
Comment 5 Michael Meeks 2018-12-05 16:56:56 UTC
Would be great to have a callgrind profile of a build with symbols but without dbgutil here if possible; should make it much easier to fix. Thanks !
Comment 6 Terrence Enger 2018-12-06 19:13:35 UTC
Created attachment 147333 [details]
files from callgrind

Included files are:

    callgrind.out.{20223,20224}
        from commands:
            source instdir/program/ooenv
            valgrind --tool=callgrind \
                instdir/program/soffice.bin \
                ~/lo_hacking/notes/bug_12xxxx/bug_120837/Untitled\ 6.odt

    callgrind_annotate.{20223,20224}
        from commands:
            callgrind_annotate --inclusive=yes callgrind.out.20223 \
                > callgrind_annotate.20223
            callgrind_annotate --inclusive=yes callgrind.out.20224 \
                > callgrind_annotate.20224

    callgind_annotate_tree.{20223,20224}
        from commands
            callgrind_annotate --inclusive=yes \
                --tree=both callgrind.out.20223 \
                > callgrind_annotate_tree.20223
            callgrind_annotate --inclusive=yes \
                --tree=both callgrind.out.20224 \
                > callgrind_annotate_tree.20224

I collected these results from commit b7f1b4c0 (2018-12-05 22:23:49)
configured:

    CC=ccache /usr/bin/gcc
    CXX=ccache /usr/bin/g++
    CCFLAGS=-Wshadow
    --with-jdk-home=/usr/lib/jvm/default-java
    --enable-split-debug
    --enable-gdb-index
    --enable-ld=gold
    --enable-option-checking=fatal
    #--enable-dbgutil
    #--enable-debug
    --without-system-postgresql
    --without-myspell-dicts
    --with-extra-buildid
    --without-doxygen
    --with-external-tar=/home/terry/lo_hacking/git/src
    --without-package-format

built and running on debian-buster.

Outside of valgrind, this build used 18.276 CPU seconds to load and
save_as the test file.

In accord with comment 4, I am removing keyword bibisectRequest and
adding bibisected and bisedted.

HTH,
Terry.
Comment 7 Telesto 2019-04-13 17:29:33 UTC
Adding CC to: Tomaž Vajngerl 
>     commit e02efb621fe672aa52e56caa916cf5c3fd0a9cb8
>     Author: Tomaž Vajngerl <tomaz.vajngerl@collabora.co.uk>
>     Date:   Thu Feb 1 15:28:53 2018 +0900
> 
>         Change bitmap table to store XBitmap instead of GraphicObject URL
>     
>         As we want to get rid of GraphicObject URLs for the more robust
>         image life-cycle handling, it was necessary to change the way
>         bitmap table stores and handles images, so that they always
>         store a Graphic object (wrapped in UNO object that provides the
>         XGraphic and XBitmap interface).
>     
>         In addition this changes loading and saving from ODF (xmloff) and
>         OOXML (oox) filters so they don't depend on GraphicObject URL
>         anymore, but load or save directly to / from  XGraphic or XBitmap.
>     
>         Change-Id: I2b88e10056e7d6c920249d59188f86b1a5a32d21
>         Reviewed-on: https://gerrit.libreoffice.org/49074
>         Tested-by: Jenkins <ci@libreoffice.org>
>         Reviewed-by: Tomaž Vajngerl <quikee@gmail.com>
Comment 8 Buovjaga 2019-04-19 10:58:27 UTC
Created attachment 150879 [details]
Perf flamegraph

Graph plateaus are similar to bug 113042 (compression)

Arch Linux 64-bit
Version: 6.3.0.0.alpha0+
Build ID: 1fee3f1da6291bfbcd75455512726215d41b3e83
CPU threads: 8; OS: Linux 5.0; UI render: default; VCL: gtk3; 
Locale: fi-FI (fi_FI.UTF-8); UI-Language: en-US
Calc: threaded
Built on 18 April 2019
Comment 9 Commit Notification 2019-05-22 07:49:31 UTC
Noel Grandin committed a patch related to this issue.
It has been pushed to "master":

https://git.libreoffice.org/core/+/319c57d2af5d26d3910db4b02dca145d8881af44%5E%21

tdf#120837 File saving at least 5 times slower

It will be available in 6.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 10 Xisco Faulí 2019-05-22 11:12:18 UTC
in

Version: 6.3.0.0.alpha1+
Build ID: e7fb44b8c86b4dce1d4c6f15752cc3bf62b14888
CPU threads: 4; OS: Linux 4.15; UI render: default; VCL: gtk3; 
Locale: ca-ES (ca_ES.UTF-8); UI-Language: en-US
Calc: threaded

it takes

real	0m15,577s
user	0m14,067s
sys	0m0,674s

while in

Version: 6.2.5.0.0+
Build ID: 6c3ceaf3e4d59c658d0f9e4e1b22204be25f74e2
CPU threads: 4; OS: Linux 4.15; UI render: default; VCL: gtk3; 
Locale: ca-ES (ca_ES.UTF-8); UI-Language: en-US
Calc: threaded

it takes

real	0m3,085s
user	0m2,390s
sys	0m0,286s
Comment 11 Xisco Faulí 2019-05-22 11:12:43 UTC
@Noel, thanks for fixing this issue!!