Last Update: 2007 Dec 12

Summary


I developed a rough solution which reduces the time to find similar AttributeProperty objects in a Table from 68 seconds to ~16 seconds on an AMD Duron 1.1GHz box running Windows 2000 SP4. My original time measurements were gathered while running Abiword attached to a debugger. Whoops.

Diffs can be found here: http://www.geocities.com/typopl/bug5291diff.txt

Wed Oct 1 2003 Update

After a few more patches, Abiword is no longer the laggard in import performance with documents containing large tables.

Here's a table that shows the time in seconds for importing the RTF spec using Abiword, along with each set of patches:

Fri Oct 3 2003 Update

A smaller bunch of patches were created which reduce the time for "Building document...".

I've updated the table for the latest results (half the patches from Patch #4 have been committed) and added entries for import times for other text apps.

Wed Oct 8 2003 Update

Robert Wilhelm reworked my UT_StringPtrMap::pick patch to completely remove all use of temp UT_String's.

I had a similar patch on my box. Hats off to him for getting the faster version checked in.

Here's a table that shows the time in seconds for importing the RTF spec: using Abiword, along with each set of patches, plus other text apps:

AppImport doc (secs)Import doc + Build doc (secs)
Abiword 2.0.06892
... + Patch 11633
... + Patches 1-2926
... + Patches 1-3423
... + Patches 1-4415
... + Patches 1-5414
   
Open Office 1.1412
Microsoft Word 200039
Microsoft Wordpad22

Mon Oct 3 2005 Update

With the release of AbiWord 2.4.0, I decided to check the import speed of the latest word processors.

A Toshiba Satellite A70 (3.06GHz Mobile Intel P4) running Windows 2000 SP4 was used for timing.

The Windows Date/Time Control Panel was used for timing and the Mem Usage column of the Windows Task Manager was used for the Memory used data. I minimized and restored the app before timing the RTF spec import.

Things don't look too good for the latest open source word processors.

The latest versions of both OpenOffice and AbiWord are slower than the previous versions.

AbiWord 2.4.0 hangs when loading the RTF spec file. I killed the app after 45 minutes.

Looking at the AbiWord Bugzilla database, one possible bug causing the hang may be Bugzilla Bug 7814 - inconsistent piecetable on RTF import - created 2004-Nov-2.

I added an entry for the time it took AbiWord to load and paginate 98% of the RTF spec before the hang occurs.

AppImport doc (secs)Memory used (MB)
Microsoft WordPad1-27-8
Microsoft Word 2003 - UI responsive317.4
Microsoft Word 2003 - lazy repagination finished1017.4
OpenOffice 1.1.55-629.8
AbiWord 2.2.1017-19101-103
OpenOffice 2.0rc9-1038-42
   
AbiWord 2.4.0Stopped after 2700secs (45min)105
AbiWord 2.4.064secs @ 98% loaded105

Fri Oct 14 2005 Update

Abiword 2.4.1 was released. I downloaded it and found the hang still occurred.

Robert Wilhelm entered a bug and an AbiWord dev was able to checkin a fix for the bug.

See commit: Re: CVS: commit msevior abi/src/text/ptbl/xp pt_PT_Append.cpp.

With this fix, AbiWord doesn't hang anymore. Robert was also able to track down a major cause of slowdown from version 2.2.x.

See Re: load time regression: Re: commit: Change Record UUID's.

AppImport doc (secs)Memory used (MB)
AbiWord 2.4.1 with MSevior's fp_line.cpp checkin6796
AbiWord 2.4.1 with MSevior's fp_line.cpp checkin and UT_UUID::_makeUUID changed to counter3696

Thu Oct 20 2005 Update

I tried out Corel Office 12, namely WordPerfect® 12, to see how fast it could load the RTF 1.5 spec. N.B. The WordPerfect UI looks like it has barely changed since 1995

Final Result: WordPerfect® 12 tries to load the RTF 1.5 spec and then displays a dialog stating "Unknown File Format".

AppImport doc (secs)Memory used (MB)
WordPerfect® 12Fails to load RTF 1.5 specN/A

Thu Jan 26 2006 Update

Abiword 2.4.2 and Corel WordPerfect® Office X3 have been released.

The main slowdown in Abiword has been fixed. WordPerfect® X3 is able to load the RTF 1.5 spec successfully. The UI still looks circa 1995 though.

AppImport doc (secs)Memory used (MB)
WordPerfect® X38-1160-70
Abiword 2.4.230-38105

Wed Dec 12 2007 Update

Abiword 2.4.6 and Abiword 2.5.2 have been released.

No change in Abiword 2.4.x branch. Abiword 2.5.x branch seems to be about 10-15% faster. Memory used in 2.5.2 is 40% less than 2.4.6. System used for timing is the same Toshiba laptop as before.

AppImport doc (secs)Memory used (MB)
Abiword 2.5.228-3070-77
Abiword 2.4.633-34128

Links:

  1. Bugzilla bug entry: Bugzilla Bug 5291 document import too slow
  2. Start of discussion thread: 5291 RTF import slow
  3. Patch 1: Light at the end of the tunnel Was Re: 5291 - A Task Force
  4. Patch 2: PATCH: Next 5291 speedup
  5. Patch 3: Re: PATCH: Next 5291 speedup
  6. Patch 4: More 5291 speedups
  7. Patch 5: Commit: Patch bug5291e

 

Problem


Bug 5291 describes slow document loading with a particular RTF file.

The problem seems to be in the table code for handling Attributes and Properties.

Profiling Abiword loading the document in question gives us:

Module Statistics for abiword.exe
 Time in module:105,683.073 millisecond
 Percent of time in module:100.0%
 Functions in module:11,516
 Hits in module:229,915,486
 Module function coverage:0.1%

Func Time (ms)%Func+Child Time (ms)%Hit CountFunction
54,307.06251.454,307.06251.442,491,930_UT_XML_stricmp
26,297.88224.9103,609.22598.017,377,706PP_AttrProp::isExactMatch
8,060.9757.68,060.9757.642,496,802UT_String::c_str
6,067.9665.76,067.9665.742,496,802UT_StringPtrMap::_key
5,294.0705.05,294.0705.031,642,386UT_StringPtrMap::_next
3,581.2703.43,581.2703.410,890,438UT_StringPtrMap::_first
2,073.8472.0105,683.073100.027,492pp_TableAttrProp::findMatch
0.0000.00.0000.042,491,930_UT_stricmp

From just 27,492 calls to pp_TableAttrProp::findMatch results in 42,491,930 calls to UT_XML_stricmp and others.

UT_XML_stricmp and PP_AttrProp::isExactMatch seem to be the main culprits.

 

Setup


Windows 2000 SP4. MS VC6 with SP5.

Abiword source code from abiword-2.0.0.tar.gz

 

Code Investigation


I intermix map and hash in the following description.

In pp_TableAttrProp::findMatch, there's a for-loop iterating over every PP_AttrProp in a vector.

In PP_AttrProp, attributes and properties are stored in separate hashes along with their associated values. These are all strings.

In PP_AttrProp::isExactMatch, there's a test to see that the checksums of the two PP_AttrProp are equal before proceeding, followed by several other inexpensive checks before actually comparing each Attribute and Property for equality.

PP_AttrProp::isExactMatch goes thru the attribute and property hashes using a cursor. Looking at the code for UT_StringPtrMap shows that the cursor iterates over the array for the hash, skipping over empty and deleted slots.

N.B. the comparisons in PP_AttrProp::isExactMatch use a case-insensitive string comparison.

In PP_AttrProp::_computeCheckSum, the checksum is computed only if there are both attributes and properties, otherwise the checksum is 0.

The checksum consists of the sum of the lengths of each attribute and property and their associated values.

Possible Flaw

________________________________________________________________________________

PP_AttrProp::isExactMatch goes thru the Attribute and Property maps.

It assumes that if the order of items in a map is the same, and the items in the map are equal (using a case-insensitive comparison), then the PP_AttrProps are equal.

But the hash function used to put a PP_AttrProp in the map doesn't handle items in a case-insensitive manner.

Therefore two items with the same text but different case may get placed in different areas of the map. So the order that the cursor returns items may be different based on Attributes/Properties that differ only in case.

However Attributes are converted to lowercase before they're added to the map.

So Properties are the possible problem area, espcially if there are lots of properties in the map.

Proposed Solution


Here's the result of profiling the new version of Abiword loading the RTF doc:

Module Statistics for abiword.exe
 Time in module:944.385 millisecond
 Percent of time in module:100.0%
 Functions in module:11,528
 Hits in module:2,420,280
 Module function coverage:0.1%

Func Time (ms)%Func+Child Time (ms)%Hit CountFunction
325.83634.5325.83634.5270,068_UT_XML_stricmp
175.14118.5710.23175.252,284PP_AttrProp::isExactMatch
84.1548.984.1548.9365,240PP_AttrProp::getCheckSum
74.8317.9138.30814.6256,856compareAPBinary
66.1187.066.1187.0342,016UT_String::c_str
49.5815.349.5815.3271,112UT_StringPtrMap::_next
46.5664.946.5664.9342,016UT_StringPtrMap::_key
37.7264.0176.03418.627,492UT_Vector::binarysearch
35.2003.7944.385100.027,492pp_TableAttrProp::findMatch
24.0102.524.0102.571,948_UT_XML_strcmp
22.9792.422.9792.4106,856UT_StringPtrMap::_first
2.2430.22.2430.216,832PP_AttrProp::getIndex
0.0000.00.0000.0270,068_UT_stricmp

 

Just to make sure the checksum calculations are not too expensive, I profiled the old and new Abiwords AP checksum code while loading the RTF doc.

It looks like the new checksum calculation is possibly 20x more epxensive.

But it saves more time in pp_TableAttrProp::findMatch.

Module Statistics for OLD abiword.exe
 Time in module:25.680 millisecond
 Percent of time in module:100.0%
 Functions in module:11,526
 Hits in module:97,561
 Module function coverage:0.1%

Func Time (ms)%Func+Child Time (ms)%Hit CountFunction
14.01254.625.680100.022,178PP_AttrProp::_computeCheckSum
4.82618.84.82618.828,922_UT_XML_strlen
2.55910.02.55910.014,461UT_StringPtrMap::_next
1.8717.31.8717.314,461UT_String::c_str
1.8577.21.8577.214,461UT_StringPtrMap::_key
0.5562.20.5562.23,078UT_StringPtrMap::_first

 

Module Statistics for NEW abiword.exe
 Time in module:470.589 millisecond
 Percent of time in module:100.0%
 Functions in module:11,522
 Hits in module:1,340,335
 Module function coverage:0.1%

Func Time (ms)%Func+Child Time (ms)%Hit CountFunction
156.62333.3470.589100.022,178PP_AttrProp::_computeCheckSum
151.20132.1151.20132.1284,783_UT_lowerString
47.93810.247.93810.2289,956_UT_XML_strlen
47.30510.147.30510.1284,783_UT_XML_strncpy
25.3575.425.3575.4144,978UT_StringPtrMap::_next
19.5024.119.5024.1144,978UT_String::c_str
18.8604.018.8604.0144,978UT_StringPtrMap::_key
3.8020.83.8021.223,701UT_StringPtrMap::_first

 

1