Performance/OOo31 LibrariesOnStartup
Contents
Libraries loaded on OpenOffice.org 3.1 startup (Windows)
The startup performance of OpenOffice.org is not as good as many people expect. This has several reasons which more or less are based on the long development history. Due to discussion with many people it should be clear that we process too much code during the startup process.I think it's the best way to make the startup much faster if we completely understand what libraries are loaded and why they are used.
My first analysis results strengthen our thesis that too much code (libraries) is involved in the startup process. The following numbers have been retrieved from the build DEV300m40 under Windows. The Microsoft VisualStudio Debugger shows exactly when a library is loaded into the address space of a debugged process. Therefore it's valuable tool to retrieve information about the libraries which are loaded during startup.
Some statistically information about all the libraries we provide in OpenOffice.org.
| Data/Folder | Program | Basis | URE | Sum |
|---|---|---|---|---|
| Number | 4 | 293 | 50 | 347 |
| Size (Bytes) | 2.750.464 | 161.765.640 | 6.677.152 | 171.193.256 |
I use certain measurement points to see what libraries have been loaded by OpenOffice.org:
| Measurement point | Total number of libraries loaded (OOo libs) | Percentage of all OpenOffice.org libraries. | Percentage of all OpenOffice.org libraries (size) |
|---|---|---|---|
| Desktop ctor (Application object created on the stack) | 57 (33) | 9,50 % | 26,14 % |
| Desktop::Init (First initializations, e.g. UNO service manager) | 59 (34) | 9,80 % | 26,18 % |
| Desktop::Main () just entered | 70 (34) | 13,00 % | 27,59 % |
| Desktop::Main (before we enter the main message loop)/StartCenter ready | 98 (70) | 20,20 % | 34,16 % |
| Empty Writer document | 129 (93) | 26,80 % | 46,37 % |
Table with the loading order of libraries of OpenOffice.org under Windows
The following table shows when&what libraries are loaded during the OpenOffice.org 3.1 startup.
| Order of Loading | Library/Executable | Size |
|---|---|---|
| 001 | soffice.bin | 7.418.368 |
| 002 | sal3.dll | 1.732.608 |
| 003 | uwinapi.dll | 86.016 |
| 004 | sofficeapi.dll | 326.144 |
| 005 | comphelp4MSC.dll | 948.224 |
| 006 | cppuhelper3MSC.dll | 431.104 |
| 007 | salhelper3MSC.dll | 13.824 |
| 008 | cppu3.dll | 143.360 |
| 009 | stlport_vc7145.dll | 597.504 |
| 010 | ucbhelper4MSC.dll | 356.864 |
| 011 | vos3MSC.dll | 94.208 |
| 012 | i18nisolang1MSC.dll | 24.576 |
| 013 | sfxmi.dll | 3.110.912 |
| 014 | fwemi.dll | 849.408 |
| 015 | fwimi.dll | 299.008 |
| 016 | utlmi.dll | 465.920 |
| 017 | tlmi.dll | 509.952 |
| 018 | basegfxmi.dll | 572.928 |
| 019 | vclmi.dll | 3.074.048 |
| 020 | sotmi.dll | 257.024 |
| 021 | i18nutilMSC.dll | 67.072 |
| 022 | icuuc40.dll | 949.760 |
| 023 | icudt40.dll | 13.912.064 |
| 024 | svlmi.dll | 724.992 |
| 025 | svtmi.dll | 2.884.608 |
| 026 | tkmi.dll | 1.870.336 |
| 027 | jvmfwk3.dll | 89.088 |
| 028 | libxml2.dll | 970.752 |
| 029 | sbmi.dll | 1.310.208 |
| 030 | xcrmi.dll | 529.920 |
| 031 | saxmi.dll | 80.384 |
| 032 | jmi_g.dll | 32.768 |
| 033 | jvmaccess3MSC.dll | 25.600 |
| Desktop ctor | 44.759.552 | |
| 034 | msci_uno.dll | 52.224 |
| Desktop::Init() just entered the method | 44.811.776 | |
| 035 | bootstrap.dll | 453.632 |
| 036 | reg3.dll | 99.328 |
| 037 | store3.dll | 78.336 |
| 038 | unsafe_uno_uno.dll | 12.800 |
| 039 | purpenvhelper3MSC.dll | 18.432 |
| 040 | configmgr2.uno.dll | 1.432.064 |
| 041 | stocservices.uno.dll | 92.672 |
| 042 | sysmgr1.dll | 37.888 |
| 043 | sax.uno.dll | 135.680 |
| 044 | localebe1.uno.dll | 30.208 |
| 045 | behelper.uno.dll | 31.232 |
| Desktop::Main() just entered the method | 47.234.048 | |
| 046 | splmi.dll | 148.992 |
| 047 | ucb1.dll | 197.632 |
| 048 | fwlmi.dll | 106.496 |
| 049 | ucpfile1.dll | 245.248 |
| 050 | fwkmi.dll | 1.879.552 |
| 051 | dnd.dll | 115.200 |
| 052 | fileacc.dll | 52.224 |
| 053 | package2.dll | 248.320 |
| 054 | fsstorage.uno.dll | 94.208 |
| 055 | i18npool.dll | 1.235.456 |
| 056 | icuin40.dll | 1.052.160 |
| 057 | updchk.uno.dll | 166.912 |
| 058 | libcurl.dll | 121.344 |
| 059 | deploymentmi.uno.dll | 266.240 |
| 060 | deploymentmiscmi.dll | 100.864 |
| 061 | libdb42.dll | 541.184 |
| 062 | helplinkermi.dll | 134.144 |
| 063 | libxslt.dll | 166.400 |
| 064 | updatefeed.uno.dll | 77.824 |
| 065 | unoxmlmi.dll | 280.064 |
| 066 | ucpexpand1.uno.dll | 24.576 |
| 067 | updchkmi.dll | 48.640 |
| 068 | resmi.dll | 65.024 |
| 069 | lngmi.dll | 982.016 |
| 070 | xomi.dll | 2.898.432 |
| Desktop::Main() just before entering the message loop | 58.483.200 | |
| 071 | oleautobridge.uno.dll | 280.576 |
| 072 | emsermi.dll | 148.992 |
| 073 | uuimi.dll | 198.144 |
| 074 | filterconfig1.dll | 188.416 |
| 075 | swmi.dll | 7.332.352 |
| 076 | svxmi.dll | 9.172.992 |
| 077 | avmediami.dll | 56.832 |
| 078 | gomi.dll | 295.936 |
| 079 | drawinglayermi.dll | 802.304 |
| 080 | canvastoolsmi.dll | 498.176 |
| 081 | aggmi.dll | 129.024 |
| 082 | cppcanvasmi.dll | 285.184 |
| 083 | localedata_euro.dll | 642.048 |
| 084 | localedata_en.dll | 104.448 |
| 085 | xstor.dll | 239.616 |
| 086 | reflection.uno.dll | 99.840 |
| 087 | guesslangmi.dll | 36.864 |
| 088 | libtextcat.dll | 14.848 |
| 089 | introspection.uno.dll | 98.816 |
| 090 | sysdtrans.dll | 107.008 |
| 091 | ftrans1.dll | 50.688 |
| 092 | mcnttype.dll | 33.792 |
| 093 | ldapbe2.uno.dll | 83.968 |
| Empty Writer document up and running | 79.384.014 |
Just to get an idea what the first measurement point "Desktop ctor" means. The following code snippet can be found in the desktop project
extern "C" int soffice_main() { tools::extendApplicationEnvironment(); RTL_LOGFILE_PRODUCT_TRACE( "PERFORMANCE - enter Main()" ); desktop::Desktop aDesktop; // FIRST MEASUREMENT POINT // This string is used during initialization of the Gtk+ VCL module aDesktop.SetAppName( rtl::OUString(RTL_CONSTASCII_USTRINGPARAM("soffice")) ); SVMain(); return 0; }
It's obvious to see that several libraries are loaded/used that nobody would think of. Especially sbmi.dll (Basic), sfx2mi.dll (old framework), sotmi.dll are loaded before any initialization is done, even VCL is not inialized yet. There are several other libraries where one can ask why they are used that early in the startup process. This simple analysis already raised many questions that need to be answered.
Table with the loading order of libraries of svdem.exe under Windows
In contrast to the OpenOffice.org executable the following table provides the libraries used by the svdem.exe which is a minimal VCL based application (built in the VCL project).
| Order of Loading | Library/Executable | Size |
|---|---|---|
| 001 | svdem.exe | 15360 |
| 002 | cppuhelper3MSC.dll | 431.104 |
| 003 | sal3.dll | 1.732.608 |
| 004 | uwinapi.dll | 86.016 |
| 005 | salhelper3MSC.dll | 13.824 |
| 006 | cppu3.dll | 143.360 |
| 007 | stlport_vc7145.dll | 597.504 |
| 008 | tlmi.dll | 509.952 |
| 009 | vos3MSC.dll | 94.208 |
| 010 | basegfxmi.dll | 572.928 |
| 011 | iso18nisolangMSC.dll | 24.576 |
| 012 | comphelp4MSC.dll | 948.224 |
| 013 | ucbhelper4MSC.dll | 356.864 |
| 014 | vclmi.dll | 3.074.048 |
| 015 | sotmi.dll | 257.024 |
| 016 | utlmi.dll | 465.920 |
| 017 | i18nutilMSC.dll | 67072 |
| 018 | icuuc40.dll | 949760 |
| 019 | icudt40.dll | 13912064 |
| SAL_IMPLEMENT_MAIN() entered | 24.252.416 | |
| 020 | bootstrap.dll | 453.632 |
| 021 | reg3.dll | 99.328 |
| 022 | store3.dll | 78.336 |
| 023 | msci_uno.dll | 52.224 |
| 024 | unsafe_uno_uno.dll | 12.800 |
| 025 | purpenvhelper3MSC.dll | 18.432 |
| 026 | tkmi.dll | 1.870.336 |
| Application usable | 26.837.504 |
The following code snippet from svdem.cxx (inside in VCL/workben) shows where the first measurement point is located.
SAL_IMPLEMENT_MAIN()
{
tools::extendApplicationEnvironment(); // <- First measurement point
Reference< XMultiServiceFactory > xMS;
xMS = cppu::createRegistryServiceFactory( rtl::OUString( RTL_CONSTASCII_USTRINGPARAM( "applicat.rdb" ) ), sal_True );
InitVCL( xMS );
::Main();
DeInitVCL();
return 0;
}Even the svdem.exe needs to load many OpenOffice.org libraries. This result supports people who report that also svdem.exe has a bad cold startup time. There is one library (icudt40.dll) which has a size that makes up about 50% of the sum of all libraries.
| Measurement point | Total number of libraries loaded (OOo libs) | Percentage of all OpenOffice.org libraries. | Percentage of all OpenOffice.org libraries (size) |
|---|---|---|---|
| SAL_IMPLEMENT_MAIN() entered | 44 (19) | 5,47 % | 14,16% |
| svdem.exe up and running | 60 (26) | 7,95 % | 15,68 % |
File I/O during OpenOffice.org startup
It was reported that OpenOffice.org has a high amount of file access during startup. This part wants to analyze what file I/O is done by OpenOffice.org. Under Windows one can use the Microsoft tools from www.sysinternals.com which provide FileMon and DiskMon. Especially FileMon gives you valuable insight into the startup process of OpenOffice.org.
Costs of library loading
This chapter tries to figure out what costs are involved in library loading under Windows. As described in the previous chapters OpenOffice.org uses a big number of libraries during startup. Currently it's not really known what does this cost, especially in the cold startup scenario where no libraries could be loaded from the cache.
This snippet below has been directly copied from the output of FileMon and shows how the sal3.dll library is opened in OpenOffice.org during startup. This OpenOffice.org startup was done after a reboot of the machine where one can expect that no application libraries are found in the system cache. The overall startup time was ~15-20 seconds.
Time hh:mm:ss:ms Executable:PID Function File Result Options ------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- 17:36:57.453 soffice.exe:3864 OPEN C:\home\cd100003\INSTALL\DEV300M40\OPENOFFICE.ORG 3\URE\BIN\SAL3.DLL REPARSE Options: Open Access: Read-Attributes 17:36:57.453 soffice.exe:3864 OPEN C:\home\cd100003\install\dev300m40\OpenOffice.org 3\program\ REPARSE Options: Open Directory Access: 00100080 17:36:57.453 soffice.exe:3864 OPEN D:\\INSTALL\DEV300M40\OPENOFFICE.ORG 3\PROGRAM SUCCESS Options: Open Directory Access: 00100080 17:36:57.453 soffice.exe:3864 DIRECTORY D:\\INSTALL\DEV300M40\OPENOFFICE.ORG 3\PROGRAM SUCCESS FileDirectoryInformation: soffice.exe 17:36:57.453 soffice.exe:3864 QUERY INFORMATION D:\\INSTALL\DEV300M40\OPENOFFICE.ORG 3\URE\BIN\SAL3.DLL SUCCESS Attributes: A 17:36:57.453 soffice.exe:3864 OPEN C:\home\cd100003\install\dev300m40\OpenOffice.org 3\URE\bin\sal3.dll REPARSE Options: Open Access: 00100021 17:36:57.453 soffice.exe:3864 OPEN C:\home\cd100003\install\dev300m40\OpenOffice.org 3\program\ REPARSE Options: Open Directory Access: 00100080 17:36:57.453 soffice.exe:3864 OPEN D:\\INSTALL\DEV300M40\OPENOFFICE.ORG 3\PROGRAM SUCCESS Options: Open Directory Access: 00100080 17:36:57.453 soffice.exe:3864 DIRECTORY D:\\INSTALL\DEV300M40\OPENOFFICE.ORG 3\PROGRAM SUCCESS FileDirectoryInformation: soffice.exe 17:36:57.453 soffice.exe:3864 OPEN D:\\INSTALL\DEV300M40\OPENOFFICE.ORG 3\URE\BIN\SAL3.DLL SUCCESS Options: Open Access: 00100021 17:36:57.453 soffice.exe:3864 READ D: SUCCESS Offset: 0 Length: 4096 17:36:57.468 soffice.exe:3864 READ D: SUCCESS Offset: 1728512 Length: 4096 17:36:57.468 soffice.exe:3864 READ D: SUCCESS Offset: 1716224 Length: 4096 17:36:57.468 soffice.exe:3864 READ D: SUCCESS Offset: 1724416 Length: 4096 17:36:57.468 soffice.exe:3864 READ D: SUCCESS Offset: 1703936 Length: 4096 17:36:57.484 soffice.exe:3864 READ D: SUCCESS Offset: 1720320 Length: 4096 17:36:57.484 soffice.exe:3864 READ D: SUCCESS Offset: 1708032 Length: 4096 17:36:57.484 soffice.exe:3864 READ D: SUCCESS Offset: 1679360 Length: 4096 17:36:57.515 soffice.exe:3864 READ D: SUCCESS Offset: 1683456 Length: 4096 17:36:57.515 soffice.exe:3864 READ D: SUCCESS Offset: 1712128 Length: 4096 17:36:57.515 soffice.exe:3864 READ D: SUCCESS Offset: 1691648 Length: 4096 17:36:57.515 soffice.exe:3864 READ D: SUCCESS Offset: 1671168 Length: 4096 17:36:57.515 soffice.exe:3864 READ D: SUCCESS Offset: 1675264 Length: 4096 17:36:57.515 soffice.exe:3864 QUERY INFORMATION D:\\INSTALL\DEV300M40\OPENOFFICE.ORG 3\URE\BIN\SAL3.DLL SUCCESS Length: 1732608 17:36:57.515 soffice.exe:3864 CLOSE D:\\INSTALL\DEV300M40\OPENOFFICE.ORG 3\URE\BIN\SAL3.DLL SUCCESS 17:36:57.515 soffice.exe:3864 READ D:\\INSTALL\DEV300M40\OPENOFFICE.ORG 3\URE\BIN\SAL3.DLL SUCCESS Offset: 1671168 Length: 16384 17:36:57.531 soffice.exe:3864 READ D:\\INSTALL\DEV300M40\OPENOFFICE.ORG 3\URE\BIN\SAL3.DLL SUCCESS Offset: 1711104 Length: 1536 17:36:57.531 soffice.exe:3864 OPEN C:\home\cd100003\install\dev300m40\OpenOffice.org 3\URE\bin\sal3.dll.2.Config REPARSE Options: Open Access: 001200A9 17:36:57.531 soffice.exe:3864 OPEN C:\home\cd100003\install\dev300m40\OpenOffice.org 3\program\ REPARSE Options: Open Directory Access: 00100080 17:36:57.531 soffice.exe:3864 OPEN D:\\INSTALL\DEV300M40\OPENOFFICE.ORG 3\PROGRAM SUCCESS Options: Open Directory Access: 00100080 17:36:57.531 soffice.exe:3864 DIRECTORY D:\\INSTALL\DEV300M40\OPENOFFICE.ORG 3\PROGRAM SUCCESS FileDirectoryInformation: soffice.exe 17:36:57.531 soffice.exe:3864 OPEN D:\\INSTALL\DEV300M40\OPENOFFICE.ORG 3\URE\BIN\SAL3.DLL.2.CONFIG NOT FOUND Options: Open Access: 001200A9 17:36:57.531 soffice.exe:3864 READ D:\\INSTALL\DEV300M40\OPENOFFICE.ORG 3\URE\BIN\SAL3.DLL SUCCESS Offset: 172032 Length: 16384
The timer resolution is typically 15ms for Windows systems. So the numbers have a certain amount of error. The output from FileMon shows us that libraries are not read in one portion into the address space of a process. There are three different access phases one can see here and which can be found by any other library.
- The first page (4096 bytes) of the libray is loaded.
- Different parts of the library are loaded which always have the same size (4096 bytes) which also the normal page size of x86 based CPUs.
- At the end data is read with different sizes (e.g. sal3 with 16.384, 1536 and 16.384 bytes)
It's interesting to see that loading the initial part of sal3 needs ~80ms. It should be clear that more parts of the libraries are loaded into memory whenever more code/data is needed. Therefore it should be clear that the numbers are more the lower bound for library loading. ~80 ms sounds not very much but if we look at the number of libraries we load at startup this can grow to huge times! The following table tries to show what time is initially spent for all libraries that are loaded during startup. It will help us to see what impact library loading has on cold startup time. If you look at the times you will clearly see that it's not always related to the library size, there must be other parameters which influence it. May be it depends on the number of exports or statics. This must be clarified to know what can we do to improve here.
- See Performance/Startup#ELF_Dynamic_Objects; Sb 15:14, 11 February 2009 (UTC).
| Order of Loading | Library/Executable | Size | Time (ms) to init/load (FileMon) |
|---|---|---|---|
| 001 | soffice.bin | 7.418.368 | ?? |
| 002 | sal3.dll | 1.732.608 | 78 |
| 003 | uwinapi.dll | 86.016 | 47 |
| 004 | sofficeapi.dll | 326.144 | 94 |
| 005 | comphelp4MSC.dll | 948.224 | 78 |
| 006 | cppuhelper3MSC.dll | 431.104 | 47 |
| 007 | salhelper3MSC.dll | 13.824 | 16 |
| 008 | cppu3.dll | 143.360 | 15 |
| 009 | stlport_vc7145.dll | 597.504 | 15 |
| 010 | ucbhelper4MSC.dll | 356.864 | 63 |
| 011 | vos3MSC.dll | 94.208 | 31 |
| 012 | i18nisolang1MSC.dll | 24.576 | 16 |
| 013 | sfxmi.dll | 3.110.912 | 125 |
| 014 | fwemi.dll | 849.408 | 63 |
| 015 | fwimi.dll | 299.008 | 47 |
| 016 | utlmi.dll | 465.920 | 47 |
| 017 | tlmi.dll | 509.952 | 63 |
| 018 | basegfxmi.dll | 572.928 | 141 |
| 019 | vclmi.dll | 3.074.048 | 182 |
| 020 | sotmi.dll | 257.024 | 62 |
| 021 | i18nutilMSC.dll | 67.072 | 31 |
| 022 | icuuc40.dll | 949.760 | 63 |
| 023 | icudt40.dll | 13.912.064 | 125 |
| 024 | svlmi.dll | 724.992 | 78 |
| 025 | svtmi.dll | 2.884.608 | 93 |
| 026 | tkmi.dll | 1.870.336 | 109 |
| 027 | jvmfwk3.dll | 89.088 | 15 |
| 028 | libxml2.dll | 970.752 | 63 |
| 029 | sbmi.dll | 1.310.208 | 78 |
| 030 | xcrmi.dll | 529.920 | 79 |
| 031 | saxmi.dll | 80.384 | 16 |
| 032 | jmi_g.dll | 32.768 | 0 |
| 033 | jvmaccess3MSC.dll | 25.600 | 16 |
| Desktop ctor | 44.759.552 | ~1996 ms | |
| 034 | msci_uno.dll | 52.224 | |
| Desktop::Init() just entered the method | 44.811.776 | ||
| 035 | bootstrap.dll | 453.632 | |
| 036 | reg3.dll | 99.328 | |
| 037 | store3.dll | 78.336 | |
| 038 | unsafe_uno_uno.dll | 12.800 | |
| 039 | purpenvhelper3MSC.dll | 18.432 | |
| 040 | configmgr2.uno.dll | 1.432.064 | |
| 041 | stocservices.uno.dll | 92.672 | |
| 042 | sysmgr1.dll | 37.888 | |
| 043 | sax.uno.dll | 135.680 | |
| 044 | localebe1.uno.dll | 30.208 | |
| 045 | behelper.uno.dll | 31.232 | |
| Desktop::Main() just entered the method | 47.234.048 | ||
| 046 | splmi.dll | 148.992 | |
| 047 | ucb1.dll | 197.632 | |
| 048 | fwlmi.dll | 106.496 | |
| 049 | ucpfile1.dll | 245.248 | |
| 050 | fwkmi.dll | 1.879.552 | |
| 051 | dnd.dll | 115.200 | |
| 052 | fileacc.dll | 52.224 | |
| 053 | package2.dll | 248.320 | |
| 054 | fsstorage.uno.dll | 94.208 | |
| 055 | i18npool.dll | 1.235.456 | |
| 056 | icuin40.dll | 1.052.160 | |
| 057 | updchk.uno.dll | 166.912 | |
| 058 | libcurl.dll | 121.344 | |
| 059 | deploymentmi.uno.dll | 266.240 | |
| 060 | deploymentmiscmi.dll | 100.864 | |
| 061 | libdb42.dll | 541.184 | |
| 062 | helplinkermi.dll | 134.144 | |
| 063 | libxslt.dll | 166.400 | |
| 064 | updatefeed.uno.dll | 77.824 | |
| 065 | unoxmlmi.dll | 280.064 | |
| 066 | ucpexpand1.uno.dll | 24.576 | |
| 067 | updchkmi.dll | 48.640 | |
| 068 | resmi.dll | 65.024 | |
| 069 | lngmi.dll | 982.016 | |
| 070 | xomi.dll | 2.898.432 | |
| Desktop::Main() just before entering the message loop | 58.483.200 | ||
| 071 | oleautobridge.uno.dll | 280.576 | |
| 072 | emsermi.dll | 148.992 | |
| 073 | uuimi.dll | 198.144 | |
| 074 | filterconfig1.dll | 188.416 | |
| 075 | swmi.dll | 7.332.352 | |
| 076 | svxmi.dll | 9.172.992 | |
| 077 | avmediami.dll | 56.832 | |
| 078 | gomi.dll | 295.936 | |
| 079 | drawinglayermi.dll | 802.304 | |
| 080 | canvastoolsmi.dll | 498.176 | |
| 081 | aggmi.dll | 129.024 | |
| 082 | cppcanvasmi.dll | 285.184 | |
| 083 | localedata_euro.dll | 642.048 | |
| 084 | localedata_en.dll | 104.448 | |
| 085 | xstor.dll | 239.616 | |
| 086 | reflection.uno.dll | 99.840 | |
| 087 | guesslangmi.dll | 36.864 | |
| 088 | libtextcat.dll | 14.848 | |
| 089 | introspection.uno.dll | 98.816 | |
| 090 | sysdtrans.dll | 107.008 | |
| 091 | ftrans1.dll | 50.688 | |
| 092 | mcnttype.dll | 33.792 | |
| 093 | ldapbe2.uno.dll | 83.968 | |
| Empty Writer document up and running | 79.384.014 |
