Bug 693387 - Regression: performance issues with 8.64 on AIX
Summary: Regression: performance issues with 8.64 on AIX
Status: NOTIFIED FIXED
Alias: None
Product: Ghostscript
Classification: Unclassified
Component: Regression (show other bugs)
Version: 8.64
Hardware: PC All
: P4 normal
Assignee: Marcos H. Woehrmann
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2012-10-16 20:06 UTC by Marcos H. Woehrmann
Modified: 2012-12-27 01:22 UTC (History)
2 users (show)

See Also:
Customer: 460
Word Size: ---


Attachments
timing.png (147.72 KB, image/png)
2012-10-31 22:49 UTC, Marcos H. Woehrmann
Details
timing2.png (160.99 KB, image/png)
2012-11-01 02:03 UTC, Marcos H. Woehrmann
Details
timings.aix.txt (10.93 KB, text/plain)
2012-11-06 17:57 UTC, Marcos H. Woehrmann
Details
timings.linux.txt (29.48 KB, text/plain)
2012-11-06 18:23 UTC, Marcos H. Woehrmann
Details
memory.png (117.11 KB, image/png)
2012-11-08 16:27 UTC, Marcos H. Woehrmann
Details

Note You need to log in before you can comment on or make changes to this bug.
Description Marcos H. Woehrmann 2012-10-16 20:06:12 UTC
The customer reported that there is a significant performance when moving for 8.54 to 8.64 under AIX 5.3:

8.54 20m8.212s 
8.64 214m54.703s 

Here is the command line:

./gs -dNOPAUSE -dBATCH -dSAFER -sDEVICE=tiffg4 -dDEVICEXRESOLUTION=600 -dDEVICEYRESOLUTION=600 -I../lib:../fonts -sOutputFile=P37648.TIFF P37648.PDF
Comment 1 Marcos H. Woehrmann 2012-10-16 20:10:59 UTC
Bisecting shows that the issue began with:

e833acd440c5ff694cec3237eeed45cef69eb02e is the first bad commit
commit e833acd440c5ff694cec3237eeed45cef69eb02e
Author: Alex Cherepanov <alex.cherepanov@artifex.com>
Date:   Mon Feb 12 14:06:50 2007 +0000

    Change the order of allocations because alloc_save_change_alloc() leaves
    alloc_change_t structure it allocates in the state that causes SEGV in GC
    if where member is not initialized. Bug 688833, customer 1130.
Comment 2 Marcos H. Woehrmann 2012-10-16 22:52:46 UTC
gs9.06 processes the file in 51m29.75s
Comment 3 Marcos H. Woehrmann 2012-10-17 00:34:26 UTC
Processing times using -dLastPage=1000:

8.54: 71.911
8.64: 399.863
9.06: 122.863
Comment 4 Ray Johnston 2012-10-17 01:17:20 UTC
For comparable times, please re-run 9.06 with -dUseFastColor since the 8.54
performs a "dumb" color management that is emulated with UseFastColor=true.

Depending on the file, this may not make any difference, but it couldn't
hurt.

The other "improvement" that is in 9.06 is the use of clist based pattern
playback that avoids allocating overly large bitmaps for pattern painting.
Adding -dMaxPatternBitmap=300m may help the performance, even though the
memory usage will be larger. The default MaxPatternBitmap in 9.06 is 8m
(8*1024*1024).

Lastly, some files benefit from -dBufferSpace=32m (the default is 4000000)
Comment 5 Marcos H. Woehrmann 2012-10-31 22:49:25 UTC
Created attachment 9046 [details]
timing.png

This chart compares the runtime (in seconds, along the Y axis) to versions (along the X axis) for both an AIX system (red) and a Linux system (blue) for the first 1000 pages of the customer's test file.   The 8.54 release was ~6730, 8.64 ~9430, and 9.06 ~13450.

The AIX data is more sparse than the Linux data since the AIX run times are longer and access to the virtual loaner is limited.  I'm not able to explain the relative difference in performance that occurs round the 11000 mark
Comment 6 Marcos H. Woehrmann 2012-11-01 01:59:44 UTC
Using Ray's suggestion from comment 4 does not appreciably improve the performance times for the 1000 page test:

9.06: 115.727

Here's the exact command line I used:

time bin/gs -dNOPAUSE -dBATCH -dSAFER -sDEVICE=tiffg4 -dDEVICEXRESOLUTION=600 -dDEVICEYRESOLUTION=600 -I../lib:../fonts -sOutputFile=P37648.TIFF -dMaxPatternBitmap=300000000 -dUseFastColor=true -dBufferSpace=32000000 -dLastPage=1000 ./P37648.PDF
Comment 7 Marcos H. Woehrmann 2012-11-01 02:03:39 UTC
Created attachment 9047 [details]
timing2.png

A version of the timing chart with each data set plotted using an independent scale.
Comment 8 Marcos H. Woehrmann 2012-11-06 17:57:53 UTC
Created attachment 9059 [details]
timings.aix.txt

Text document showing the timings under aix for various commits of Ghostcript.
Comment 9 Marcos H. Woehrmann 2012-11-06 18:18:55 UTC
The P37648.PDF file is too large to attach.  It can be found on casper in ~support/693387.
Comment 10 Marcos H. Woehrmann 2012-11-06 18:23:08 UTC
Created attachment 9062 [details]
timings.linux.txt

The same timings as comment #8 but for Linux.

The command lines used to generate these are the same as comment #6, modifying the -I option appropriately based on the directory structure of the version being tested.

All runs use the default options (i.e. "./autogen.sh ; make").
Comment 11 Marcos H. Woehrmann 2012-11-06 18:47:44 UTC
On IRC someone asked about timing figures for 8.64 with compile_inits=0:

8.54 with compile_inits=0: 21.615
8.64 with compile_inits=0: 127.884
8.64 with compile_inits=1: 97.388
8.64 with compile_inits=1 and  -IResource/font: 119.214 

I've tried compiling 8.54 with compile_inits=1 but I get a seg fault in mkromfs.
Comment 13 Marcos H. Woehrmann 2012-11-07 17:01:06 UTC
I sent the customer the recommendation to leave off the -IResource/Font option and use COMPILE_INITS=1 so that the %rom%Resource fonts would be used instead of the disk based ones and a patch that undid commit 42e8d3f45b0c3c313b2312e477e859b7b65a4973 and they reported these results (all times are for the first 1000 pages):

8.54: 2m45s
stock 8.64: 15m49s
8.64 with %rom%Resource fonts and path: 4m07s

Unfortunately the customer has users who need to add disk based fonts, so we need a set of command line options that will load fonts from %rom%Resource if they are present and disk if not.
Comment 14 Ray Johnston 2012-11-07 23:03:30 UTC
The command line posted via email to Marcos should do exactly what is
requested: "we need a set of command line options that will load fonts from
%rom%Resource if they are present and disk if not."

By putting -I%rom%Resource/Font -Icustomer_fonts    and
  -sGenericResourceDir=%rom%Resource/

then fonts from %rom%Resource/Font should be used first, and only if the
requested font is not found will the "customer_fonts" directory be used.

Note that the fonts on the "customer_fonts" will ONLY be used if there is a
Fontmap file that defines the "alias name" to file_name mapping, or if the
file name EXACTLY (case-sensitive) matches the requested FontName.

I suggest use of strace to see what directories are being enumerated, or what
files are being opened (hopefully AIX has this, but then again, AIX is an "off
brand" unix, so it may not).
Comment 15 Marcos H. Woehrmann 2012-11-08 16:27:51 UTC
Created attachment 9067 [details]
memory.png

Memory usage for various versions of Ghostscript, using the command line from comment #0 (i.e. running all pages).

The interesting commits are (memory usage is in MB):

7693    93dc93589bc3ca25fd2132dfdd1af749209e87c9        216
7694    e833acd440c5ff694cec3237eeed45cef69eb02e        327


7700    26ce3a56440a183a358f8520e66900ce62e356d1        324
7843    95e7059bf4dbc09b82f66146863aabc86ee459fa        344

8024    ee2a8fbeedada82068808b1fa5181d0a62485060        352
8027    ab3e109142b9cec86c993b4bfbabfe32ad3bc3ef        436


8522    be60e0d0d6c1b930cfc6459ef7de63c567de6b7f        396
8526    55871b4d7a853df585a2d89d4d282e3fe153a4f7        500


8953    7a31db6d4142087d29c17e875ef2de1727b9f8b2        529
8955    62b66eb67bda44d5becebc709b565d45bf70c585        402 

Basically memory usage doubled between 8.54 and 8.64 (from 200 megs to 400 megs).
Comment 16 Marcos H. Woehrmann 2012-11-20 18:12:46 UTC
I'm not able to reverse the memory increases noted in comment #15.  Assigning to Henry to re-assign as he sees fit.
Comment 17 Henry Stiles 2012-11-20 19:03:08 UTC
(In reply to comment #15)
> Created an attachment (id=9067) [details]
> memory.png
> 
> Memory usage for various versions of Ghostscript, using the command line from
> comment #0 (i.e. running all pages).
> 
> The interesting commits are (memory usage is in MB):
> 
> 7693    93dc93589bc3ca25fd2132dfdd1af749209e87c9        216
> 7694    e833acd440c5ff694cec3237eeed45cef69eb02e        327
> 

git rev-list --oneline ^93dc93 e833acd
e833acd Change the order of allocations because alloc_save_change_alloc() leaves alloc_change_t structure it allocates in the state that causes SEGV in GC if where member is not initialized. Bug 688833, customer 1130.

That's for Alex to review.

The other significant change is Ray's increasing of the halftone tile cache, I don't see why that should need review, I assume we knowingly increased memory usage for time benefit.  I guess it could be a configuration option.  

I'll pass this on to Alex and ask him to assign it back to me once he reviews e833acd for excessive memory consumption.


> 
> 7700    26ce3a56440a183a358f8520e66900ce62e356d1        324
> 7843    95e7059bf4dbc09b82f66146863aabc86ee459fa        344
> 
> 8024    ee2a8fbeedada82068808b1fa5181d0a62485060        352
> 8027    ab3e109142b9cec86c993b4bfbabfe32ad3bc3ef        436
> 
> 
> 8522    be60e0d0d6c1b930cfc6459ef7de63c567de6b7f        396
> 8526    55871b4d7a853df585a2d89d4d282e3fe153a4f7        500
>to 
> 
> 8953    7a31db6d4142087d29c17e875ef2de1727b9f8b2        529
> 8955    62b66eb67bda44d5becebc709b565d45bf70c585        402 
> 
> Basically memory usage doubled between 8.54 and 8.64 (from 200 megs to 400
> megs).
Comment 18 Marcos H. Woehrmann 2012-12-08 19:20:30 UTC
Ray suggests that backing out 55871b4d7a853df585a2d89d4d282e3fe153a4f7 should reduce the memory usage and be low risk.

Assigning to Marcos to test and email the customer.
Comment 19 Marcos H. Woehrmann 2012-12-27 01:22:01 UTC
(In reply to comment #18)
> Ray suggests that backing out 55871b4d7a853df585a2d89d4d282e3fe153a4f7 should
> reduce the memory usage and be low risk.
> 

Ray suggestion was correct, the memory footprint is reduced by 30% with that commit removed.  I'm sending a patch to the customer and closing this bug since the other commits that increased memory usage are too complicated to safely remove.