Bug 104582 - Recurring opening, read, and closing of every config directory when an animated GIF is refreshing canvas
Summary: Recurring opening, read, and closing of every config directory when an animat...
Status: RESOLVED WORKSFORME
Alias: None
Product: LibreOffice
Classification: Unclassified
Component: graphics stack (show other bugs)
Version:
(earliest affected)
5.0.2.2 release
Hardware: All Windows (All)
: high normal
Assignee: Not Assigned
URL:
Whiteboard:
Keywords: bibisected, bisected, perf, regression
: 104584 (view as bug list)
Depends on:
Blocks: Writer-Images Too-Much-File-Access
  Show dependency tree / graph
 
Reported: 2016-12-11 15:33 UTC by Telesto
Modified: 2017-10-23 18:22 UTC (History)
4 users (show)

See Also:
Crash report or crash signature:

Attachments
Additional example (453.91 KB, application/vnd.oasis.opendocument.text)
2016-12-14 10:33 UTC, Telesto 		Details
Process Monitor Output LO5400 (2.98 MB, application/vnd.oasis.opendocument.spreadsheet)
2016-12-14 14:41 UTC, Telesto 		Details
SAL_LOG=+TIMESTAMP+INFO,+WARN (43.09 KB, application/vnd.oasis.opendocument.spreadsheet)
2016-12-15 14:09 UTC, Telesto 		Details
Instrument screenshots (1003.10 KB, application/pdf)
2017-09-06 08:57 UTC, Telesto 		Details
View All Add an attachment (proposed patch, testcase, etc.)

Note You need to log in before you can comment on or make changes to this bug.
Description Telesto 2016-12-11 15:33:56 UTC 
Description:
The gif animation takes a steady disk i/o around 530 kb/s. With LibO 5.0.0.5 the disk I/O is around 0 kb/s




 

Steps to Reproduce:
1.Download http://forums.x-plane.org/uploads/monthly_2016_07/GPS24golden.gif.5d39c488452fdbfe7ac47db70df3cbc8.gif
2.Open Writer
3.Add gif to writer document
2.Take notice of disk I/O soffice.bin (with Process Explorer for example)

Actual Results:  
Relatively high disk and CPU usage

Expected Results:
Nearly no disk usage


Reproducible: Always

User Profile Reset: No

Additional Info:
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

but not in
Version: 5.0.0.5
Build ID: 1b1a90865e348b492231e1c451437d7a15bb262b
Locale: en-US (nl_NL)


User-Agent: Mozilla/5.0 (Windows NT 6.2; WOW64; rv:45.0) Gecko/20100101 Firefox/45.0
Comment 1 Telesto 2016-12-14 10:33:46 UTC 
Created attachment 129622 [details]
Additional example
Comment 2 Telesto 2016-12-14 14:41:44 UTC 
Created attachment 129635 [details]
Process Monitor Output LO5400

Quite a large file for just 45 seconds or so.. same pattern over and over:

15:34:09.3257989	soffice.bin	1276	CreateFile	C:\Program Files (x86)	SUCCESS	Desired Access: Read Data/List Directory, Synchronize, Disposition: Open, Options: Directory, Synchronous IO Non-Alert, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened
15:34:09.3258149	soffice.bin	1276	QueryDirectory	C:\Program Files (x86)\LibreOfficeDev 5	SUCCESS	Filter: LibreOfficeDev 5, 1: LibreOfficeDev 5
15:34:09.3258279	soffice.bin	1276	CloseFile	C:\Program Files (x86)	SUCCESS	
15:34:09.3258788	soffice.bin	1276	CreateFile	C:\Program Files (x86)\LibreOfficeDev 5	SUCCESS	Desired Access: Read Data/List Directory, Synchronize, Disposition: Open, Options: Directory, Synchronous IO Non-Alert, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened
15:34:09.3259038	soffice.bin	1276	QueryDirectory	C:\Program Files (x86)\LibreOfficeDev 5\share	SUCCESS	Filter: share, 1: share
15:34:09.3259146	soffice.bin	1276	CloseFile	C:\Program Files (x86)\LibreOfficeDev 5	SUCCESS	
15:34:09.3259562	soffice.bin	1276	CreateFile	C:\Program Files (x86)\LibreOfficeDev 5\share	SUCCESS	Desired Access: Read Data/List Directory, Synchronize, Disposition: Open, Options: Directory, Synchronous IO Non-Alert, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened
15:34:09.3259718	soffice.bin	1276	QueryDirectory	C:\Program Files (x86)\LibreOfficeDev 5\share\config	SUCCESS	Filter: config, 1: config
15:34:09.3259833	soffice.bin	1276	CloseFile	C:\Program Files (x86)\LibreOfficeDev 5\share	SUCCESS	
15:34:09.3260333	soffice.bin	1276	CreateFile	C:\Program Files (x86)\LibreOfficeDev 5\share\config	SUCCESS	Desired Access: Read Data/List Directory, Synchronize, Disposition: Open, Options: Directory, Synchronous IO Non-Alert, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened
15:34:09.3260498	soffice.bin	1276	QueryDirectory	C:\Program Files (x86)\LibreOfficeDev 5\share\config\images_oxygen.zip	SUCCESS	Filter: images_oxygen.zip, 1: images_oxygen.zip
15:34:09.3260622	soffice.bin	1276	CloseFile	C:\Program Files (x86)\LibreOfficeDev 5\share\config	SUCCESS	
15:34:09.3261176	soffice.bin	1276	CreateFile	C:\Program Files (x86)\LibreOfficeDev 5\share\config	SUCCESS	Desired Access: Read Data/List Directory, Synchronize, Disposition: Open, Options: Directory, Synchronous IO Non-Alert, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened
15:34:09.3261345	soffice.bin	1276	QueryDirectory	C:\Program Files (x86)\LibreOfficeDev 5\share\config\images_oxygen.zip	SUCCESS	Filter: images_oxygen.zip, 1: images_oxygen.zip
15:34:09.3261468	soffice.bin	1276	CloseFile	C:\Program Files (x86)\LibreOfficeDev 5\share\config	SUCCESS
Comment 3 V Stuart Foote 2016-12-14 22:26:25 UTC 
Confirming on Windows 8.1 Ent 64-bit en-US with
Version: 5.3.0.0.beta2 (x64)
Build ID: a7e30712ad6d8bc9286007b37aa581983e0caba3
CPU Threads: 8; OS Version: Windows 6.29; UI Render: default; Layout Engine: new; 
Locale: en-US (en_US); Calc: CL

or recent master
Version: 5.4.0.0.alpha0+
Build ID: a238c829b209d0708714aa753fb686525411825f
CPU Threads: 8; OS Version: Windows 6.29; UI Render: default; 
TinderBox: Win-x86@39, Branch:master, Time: 2016-12-08_10:37:27
Locale: en-US (en_US); Calc: CL

For some reason, when the animated GIF is refreshing canvas in Writer there is a recurring opening, read, and closing of every directory and zip'd archive in the share\config directory.

The same animated GIF inserted to Impress canvas does not exhibit repetitive share\config directory access and Disk I/O for LibreOffice PID is negligible.
Comment 4 Telesto 2016-12-15 12:57:09 UTC 
Also found in:
Version: 5.0.2.2
Build ID: 37b43f919e4de5eeaca9b9755ed688758a8251fe
Locale: en-US (nl_NL)
Comment 5 Telesto 2016-12-15 13:34:01 UTC 
*** Bug 104584 has been marked as a duplicate of this bug. ***
Comment 6 Telesto 2016-12-15 13:45:29 UTC 
Adding "needsDevAdvice" because it seems related to bug 104589.
Comment 7 Telesto 2016-12-15 14:09:30 UTC 
Created attachment 129670 [details]
SAL_LOG=+TIMESTAMP+INFO,+WARN

SALLOG of laucning and opening/running 'Additional example'
Version: 5.4.0.0.alpha0+
Build ID: d538d3d84172a74dfe97d59a6d3daf9a45459cab
CPU Threads: 4; OS Version: Windows 6.19; UI Render: default; 
TinderBox: Win-x86@39, Branch:master, Time: 2016-12-14_00:28:59
Locale: nl-NL (nl_NL); Calc: CL
Comment 8 Telesto 2017-01-29 09:04:14 UTC 
Aron, could you take a look at this one. 

Found in:
Version: 5.4.0.0.alpha0+
Build ID: b41186a2fc49e440890b8c86e5367352ffaf9cd6
CPU Threads: 4; OS Version: Windows 6.19; UI Render: default; 
TinderBox: Win-x86@42, Branch:master, Time: 2017-01-26_01:50:40
Locale: nl-NL (nl_NL); Calc: CL

and in
Version: 5.0.2.2
Build ID: 37b43f919e4de5eeaca9b9755ed688758a8251fe
Locale: en-US (nl_NL)

but not in:
Version: 5.0.0.5
Build ID: 1b1a90865e348b492231e1c451437d7a15bb262b
Locale: en-US (nl_NL)
Comment 9 Aron Budea 2017-01-31 00:44:34 UTC Comment hidden (bibisection)
Comment 10 Aron Budea 2017-01-31 00:58:21 UTC 
So the change is from Miklos Vajna, but the issue is coming from PaintBufferGuard that he started using in this commit. See partial stack trace below. Note ImplAnimView::draw(...) in the middle of it, and the calls deeper that seem to be responsible for reading directories.

https://cgit.freedesktop.org/libreoffice/core/commit/?id=cd064472ce4ff9d1dd6720c32fde22f36eb232f4
"author	Miklos Vajna <vmiklos@collabora.co.uk>	2015-08-10 14:44:03 (GMT)
committer	Miklos Vajna <vmiklos@collabora.co.uk>	2015-08-10 16:23:59 (GMT)
commit cd064472ce4ff9d1dd6720c32fde22f36eb232f4 (patch)

tdf#93325 ImplAnimView rendercontext: stop painting animgifs directly"

Trace:

vcllo.dll!vcl::IconThemeScanner::ReadIconThemesFromPath(const rtl::OUString & dir) Line 104	C++
vcllo.dll!vcl::IconThemeScanner::ScanDirectoryForIconThemes(const rtl::OUString & path) Line 74	C++
vcllo.dll!vcl::IconThemeScanner::Create(const rtl::OUString & path) Line 162	C++
vcllo.dll!ImplStyleData::ImplStyleData() Line 532	C++
vcllo.dll!std::_Ref_count_obj<ImplStyleData>::_Ref_count_obj<ImplStyleData><>() Line 932	C++
vcllo.dll!std::make_shared<ImplStyleData>() Line 1003	C++
vcllo.dll!StyleSettings::StyleSettings() Line 772	C++
vcllo.dll!ImplAllSettingsData::ImplAllSettingsData() Line 2658	C++
vcllo.dll!std::_Ref_count_obj<ImplAllSettingsData>::_Ref_count_obj<ImplAllSettingsData><>() Line 932	C++
vcllo.dll!std::make_shared<ImplAllSettingsData>() Line 1003	C++
vcllo.dll!AllSettings::AllSettings() Line 2697	C++
vcllo.dll!PaintBufferGuard::PaintBufferGuard(ImplFrameData * pFrameData, vcl::Window * pWindow) Line 47	C++
vcllo.dll!ImplAnimView::draw(unsigned long nPos, VirtualDevice * pVDev) Line 197	C++
vcllo.dll!Animation::ImplTimeoutHdl(Timer * __formal) Line 442	C++
vcllo.dll!Animation::LinkStubImplTimeoutHdl(void * instance, Timer * data) Line 343	C++
vcllo.dll!Link<Timer *,void>::Call(Timer * data) Line 84	C++
vcllo.dll!Timer::Invoke() Line 90	C++
vcllo.dll!ImplSchedulerData::Invoke() Line 48	C++
vcllo.dll!Scheduler::ProcessTaskScheduling(bool bIdle) Line 161	C++
vcllo.dll!Scheduler::CallbackTaskScheduling(bool bIdle) Line 123	C++
vcllo.dll!SalTimer::CallCallback(bool idle) Line 55	C++
vcllo.dll!EmitTimerCallback() Line 174	C++
<snip>
Comment 11 Telesto 2017-06-20 19:28:50 UTC Comment hidden (obsolete)
Comment 12 Telesto 2017-09-06 08:57:34 UTC 
Created attachment 136059 [details]
Instrument screenshots

Based on the stack in comment 10 a small sneak peak into the source code how often specific parts are called related to ImplAnimView::draw and PaintBufferGuard.

I can't make much of it, but hopefully someone else can.
Comment 13 Telesto 2017-10-23 18:22:44 UTC 
No repro with:
Version: 6.0.0.0.alpha1+
Build ID: b17294826830e278d060c876cf4f94a9b4ec16cc
CPU threads: 4; OS: Windows 6.3; UI render: default; 
TinderBox: Win-x86@42, Branch:master, Time: 2017-10-23_06:32:42
Locale: nl-NL (nl_NL); Calc: CL