JDK-6623164 : severe performance issues with JDK GZIP classes and object serialization
  • Type: Bug
  • Component: core-libs
  • Sub-Component: java.util.jar
  • Affected Version: 6
  • Priority: P4
  • Status: Closed
  • Resolution: Not an Issue
  • OS: windows_xp
  • CPU: x86
  • Submitted: 2007-10-29
  • Updated: 2010-04-04
  • Resolved: 2007-11-08
Related Reports
Relates :  
Relates :  
Description
FULL PRODUCT VERSION :
java version "1.6.0_02"
Java(TM) SE Runtime Environment (build 1.6.0_02-b05)
Java HotSpot(TM) Client VM (build 1.6.0_02-b05, mixed mode, sharing)

ADDITIONAL OS VERSION INFORMATION :
Microsoft Windows XP [Version 5.1.2600]

A DESCRIPTION OF THE PROBLEM :
Both GZIPOutputStream and GZIPInputStream suffer b ad performance when serializing/deserializing certain objects--se below for more details

STEPS TO FOLLOW TO REPRODUCE THE PROBLEM :
Run the code supplied below.

EXPECTED VERSUS ACTUAL BEHAVIOR :
EXPECTED -
[All discussion below refers to the results that I report in the "Actual Result:" section]

The first thing to note is that serialization of the String and the List to a ByteArrayOutputStream both take ~23 ms.

However, if wrap the ByteArrayOutputStream  with a GZIPOutputStream to achieve compression, those serialization times explode to ~58 and ~208 ms for the String and List respectively.

The puzzle with this second case is why the List is ~3.5X slower to serialize than the String.  From the similar raw ByteArrayOutputStream results of ~23 ms, we know that the fundamental serialization performance for both objects is about the same.  So why does using a GZIPOutputStream wrapper cause such a performance drop for the List?

Now lets look at the deserialization results.

Again, when deserializing the String and the List from a raw ByteArrayInputStream both take ~18 ms (which is slightly less than the serialization results, which makes sense).  So both objects seem to have the same deserialization complexity.

Now again, if wrap the ByteArrayInputStream with GZIPInputStream, the performance degrades.

A modest performance degradation is to be expected: decompression takes cpu power.  So maybe the 2X slower results for deserialing the String when use a GZIPInputStream (relative to using a raw ByteArrayInputStream)make sense.  (But 2X does seem a bit high...)

But the performance degrades disastrously for the List: its deserialization is not only 10X worse when use a GZIPInputStream (relative to using a raw ByteArrayInputStream), but its execution time of 293 ms is actually worse than the time it took to serialize that same object in the first place.  In other words, it is taking longer to decompress than to compress!  That is something that should be unheard of for a properly functioning codec.  IT CLEARLY INDICATES THAT SOMETHING IS WRONG WITH SUN'S CODE.

Note the byte[] write/read results: here, when wrap the ByteArrayXXX streams with GZIPXXX streams, get results that make rational sense, such as that readFromBais is X faster than writeToGos.  I was expecting to see similar speedups for the deserialization cases.
ACTUAL -
[below is the output from running the code supplied below on my machine:]

In the results below:
        Baos/Bais <--> ByteArrayOutputStream/ByteArrayInputStream
        Gos/Gis <--> GZIPOutputStream(ByteArrayOutputStream)/GZIPInputStream(ByteArrayInputStream)
        serialize/deserialize <--> ObjectOutputStream/ObjectInputStream wrap the indicated stream

Time execute writeToBaos = 7.510567859375E-4 s; bytesWritten.length = 1048576
Time execute writeToGos = 2.340428462E-2 s; bytesWritten.length = 4408
Time execute serializeStringToBaos = 2.2907570655E-2 s; bytesWritten.length = 1667085
Time execute serializeListToBaos = 2.2490587495E-2 s; bytesWritten.length = 1049789
Time execute serializeStringToGos = 5.813871316E-2 s; bytesWritten.length = 7752
Time execute serializeListToGos = 2.0877016772E-1 s; bytesWritten.length = 12173

Time execute readFromBais = 1.62334528515625E-4
Time execute readFromGis = 8.203528662500001E-3
Time execute deserializeStringFromBais = 1.7993541075E-2
Time execute deserializeListFromBais = 1.9248562315E-2
Time execute deserializeStringFromGis = 3.311483722E-2
Time execute deserializeListFromGis = 2.92674112215E-1


REPRODUCIBILITY :
This bug can be reproduced always.

---------- BEGIN SOURCE ----------
import java.io.*;
import java.util.*;
import java.text.DecimalFormat;
import java.util.zip.*;

//import bb.science.FormatUtil;
//import bb.util.BenchmarkUtil;


/**
* This code benchmarks the effect on performance of using java's GZIP classes.
* <p>
* @author Brent Boyer
*/
public class BenchmarkGzip {
	
	
	private static final DecimalFormat SCIENTIFIC_NOTATION = new DecimalFormat(
		"0.0" +               // insist that at least a decimal digit and the first fractional digit be present
		"##############" +    // after the previous 2 digits, allow an optional number of digits up to the limit of what makes sense for a double
		"E0"                  // insist that the exponent be present and have at least 1 digit
	);
	
	
	public static void main(String[] args) throws Exception {
			// define various stuff to write/serialize:
		byte[] bytesOriginal = new byte[1024 * 1024];
		for (int i = 0; i < bytesOriginal.length; i++) {
			bytesOriginal[i] = (byte) i;
		}
		
		String string = new String(bytesOriginal);
		
		List<Interval> listIntervals = Interval.makeList();
		
			// print explanation:
		System.out.println();
		System.out.println("In the results below:");
		System.out.println("\t" + "Baos/Bais <--> ByteArrayOutputStream/ByteArrayInputStream");
		System.out.println("\t" + "Gos/Gis <--> GZIPOutputStream(ByteArrayOutputStream)/GZIPInputStream(ByteArrayInputStream)");
		System.out.println("\t" + "serialize/deserialize <--> ObjectOutputStream/ObjectInputStream wrap the indicated stream");
		
			// do write/serialize benchmarks:
		System.out.println();
		
		WriteTo writeToBaos = new WriteTo(bytesOriginal, false);
		benchmark(writeToBaos, "writeToBaos");
		
		WriteTo writeToGos = new WriteTo(bytesOriginal, true);
		benchmark(writeToGos, "writeToGos");
		
		SerializeTo serializeStringToBaos = new SerializeTo(string, false);
		benchmark(serializeStringToBaos, "serializeStringToBaos");
		
		SerializeTo serializeListToBaos = new SerializeTo(listIntervals, false);
		benchmark(serializeListToBaos, "serializeListToBaos");
		
		SerializeTo serializeStringToGos = new SerializeTo(string, true);
		benchmark(serializeStringToGos, "serializeStringToGos");
		
		SerializeTo serializeListToGos = new SerializeTo(listIntervals, true);
		benchmark(serializeListToGos, "serializeListToGos");
		
			// do read/deserialize benchmarks:
		System.out.println();
		
		ReadFrom readFromBais = new ReadFrom(writeToBaos);
		benchmark(readFromBais, "readFromBais");
		
		ReadFrom readFromGis = new ReadFrom(writeToGos);
		benchmark(readFromGis, "readFromGis");
		
		DeserializeFrom deserializeStringFromBais = new DeserializeFrom(serializeStringToBaos);
		benchmark(deserializeStringFromBais, "deserializeStringFromBais");
		
		DeserializeFrom deserializeListFromBais = new DeserializeFrom(serializeListToBaos);
		benchmark(deserializeListFromBais, "deserializeListFromBais");
		
		DeserializeFrom deserializeStringFromGis = new DeserializeFrom(serializeStringToGos);
		benchmark(deserializeStringFromGis, "deserializeStringFromGis");
		
		DeserializeFrom deserializeListFromGis = new DeserializeFrom(serializeListToGos);
		benchmark(deserializeListFromGis, "deserializeListFromGis");
	}
	
	
	private static void benchmark(WriteTo writeTo, String label) {
		double execTime = BenchmarkUtil.measure( writeTo );
		//System.out.println("Time execute " + label + " = " + FormatUtil.scaleTimeToPrefix(execTime) + "; bytesWritten.length = " + writeTo.bytesWritten.length);
		System.out.println("Time execute " + label + " = " + SCIENTIFIC_NOTATION.format(execTime) + " s; bytesWritten.length = " + writeTo.bytesWritten.length);
	}
	
	
	private static void benchmark(ReadFrom readFrom, String label) {
		double execTime = BenchmarkUtil.measure( readFrom );
		//System.out.println("Time execute " + label + " = " + FormatUtil.scaleTimeToPrefix(execTime));
		System.out.println("Time execute " + label + " = " + SCIENTIFIC_NOTATION.format(execTime));
		readFrom.check();
	}
	
	
	private static void handleProblem(Throwable t) {
		t.printStackTrace( System.err );
		System.exit(-1);
	}
	
	
	private static class WriteTo implements Runnable {
		
		private final byte[] bytesOriginal;
		protected final boolean doGZIP;
		private byte[] bytesWritten;
		
		private WriteTo(byte[] bytesOriginal, boolean doGZIP) {
			this.bytesOriginal = bytesOriginal;
			this.doGZIP = doGZIP;
		}
		
		public void run() {
			OutputStream os = null;
			try {
				try {
					ByteArrayOutputStream baos = new ByteArrayOutputStream();
					os = exec(baos);
					if (bytesWritten == null) {
						//os.flush();	// would think that this would do the trick...
						os.close();	// but it doesn't: GZIPOutputStream seems to require close in order for the lin ebelow to work
						bytesWritten = baos.toByteArray();
					}
				}
				finally {
					os.close();
				}
			}
			catch (Throwable t) {
				handleProblem(t);
			}
		}
		
		protected OutputStream exec(ByteArrayOutputStream baos) throws Exception {
			OutputStream os = (doGZIP) ? new GZIPOutputStream(baos) : baos;
			os.write(bytesOriginal);
			return os;
		}
		
	}
	
	
	private static class SerializeTo extends WriteTo {
		
		private final Object objectOriginal;
		
		private SerializeTo(Object objectOriginal, boolean doGZIP) {
			super(null, doGZIP);
			this.objectOriginal = objectOriginal;
		}
		
		protected ObjectOutputStream exec(ByteArrayOutputStream baos) throws Exception {
			ObjectOutputStream oos = new ObjectOutputStream( (doGZIP) ? new GZIPOutputStream(baos) : baos );
			oos.writeObject(objectOriginal);
			return oos;
		}
		
	}
	
	
	private static class ReadFrom implements Runnable {
		
		protected final WriteTo writeTo;
		private final byte[] bytesRead;
		
		private ReadFrom(WriteTo writeTo) {
			this.writeTo = writeTo;
			this.bytesRead = (writeTo.bytesOriginal != null) ? new byte[writeTo.bytesOriginal.length] : null;
		}
		
		public void run() {
			InputStream is = null;
			try {
				try {
					ByteArrayInputStream bais = new ByteArrayInputStream(writeTo.bytesWritten);
					is = exec(bais);
					if (is.read() != -1) throw new IllegalStateException("failed to fully drain is");
				}
				finally {
					is.close();
				}
			}
			catch (Throwable t) {
				handleProblem(t);
			}
		}
		
		protected InputStream exec(ByteArrayInputStream bais) throws Exception {
			InputStream is = (writeTo.doGZIP) ? new GZIPInputStream(bais) : bais;
			for (int n = 0; n < bytesRead.length; ) {	// this loop ensures that bytesRead gets fully filled with data
				int m = is.read(bytesRead, n, bytesRead.length - n);
				if (m == -1) throw new IllegalStateException("failed to fill bytesRead with data");
				n += m;
			}
			return is;
		}
		
		private void check() throws IllegalStateException {
			if (!Arrays.equals(writeTo.bytesOriginal, bytesRead)) throw new IllegalStateException("discrepancy in bytes written and read back");
		}
		
	}
	
	
	private static class DeserializeFrom extends ReadFrom {
		
		private Object objectRead;
		
		private DeserializeFrom(SerializeTo serializeTo) {
			super(serializeTo);
		}
		
		protected InputStream exec(ByteArrayInputStream bais) throws Exception {
			ObjectInputStream ois = new ObjectInputStream( (writeTo.doGZIP) ? new GZIPInputStream(bais) : bais );
			objectRead = ois.readObject();
			return ois;
		}
		
		private void check() throws IllegalStateException {
			SerializeTo serializeTo = (SerializeTo) writeTo;
			if (!serializeTo.objectOriginal.equals(objectRead)) throw new IllegalStateException("object serialized !equals object deserialized");
		}
		
	}
	
	
	/** Mimics a class used to hold stock market interval data. */
	private static class Interval implements Serializable {
		
		private static final long serialVersionUID = 1;
		
		private static int n = 0;
		
		private final Date date;
		private final double open;
		private final double high;
		private final double low;
		private final double close;
		private final int volume;
		
		private static List<Interval> makeList() {
			int size = 17790;
			List<Interval> intervals = new ArrayList<Interval>(size);
			n = 0;
			for (int i = 0; i < size; i++) {
				intervals.add( new Interval() );
			}
			return intervals;
		}
		
		private Interval() {
			date = new Date( nextByte() );
			open = nextByte();
			high = nextByte();
			low = nextByte();
			close = nextByte();
			volume = nextByte();
		}
		
		/** Returns the same sequence of bytes as bytesOriginal inside main in order to match entropies. */
		private static byte nextByte() {
			return (byte) (n++);
		}
		
		public final boolean equals(Object obj) {	// for why is final, see: D:\interestsTechnical\computerNotes\java\equalsImplementation.txt
			if (this == obj) return true;
			if (!(obj instanceof Interval)) return false;
			
			Interval other = (Interval) obj;
			return
				this.date.equals(other.date) &&
				(this.open == other.open) &&
				(this.high == other.high) &&
				(this.low == other.low) &&
				(this.close == other.close) &&
				(this.volume == other.volume);
		}
		
		public final int hashCode() {	// for why is final, see: D:\interestsTechnical\computerNotes\java\equalsImplementation.txt
			return date.hashCode();	// this should be sufficient
		}
		
	}
	
	
	/** This is a stripped down, cruder version of my personal library class that is inlined here for submission to sun. */
	private static class BenchmarkUtil {
		
		public static final int numberWarmupRuns_default = 100;
		
		public static final double minBenchmarkTime_default = 2.0;
		
		public static double measure(Runnable task) throws IllegalArgumentException, IllegalStateException {
			return measure(task, numberWarmupRuns_default, minBenchmarkTime_default);
		}
		
		public static double measure(Runnable task, int numberWarmupRuns, double minBenchmarkTime) throws IllegalArgumentException, IllegalStateException {
			if (task == null) throw new IllegalArgumentException("task == null");
			if (numberWarmupRuns < 0) throw new IllegalArgumentException("numberWarmupRuns = " + numberWarmupRuns + " < 0");
			if (minBenchmarkTime < 0) throw new IllegalArgumentException("minBenchmarkTime = " + minBenchmarkTime + " < 0");
			
			for (int numberOfRuns = numberWarmupRuns; true; numberOfRuns *= 2) {
				//MemoryMeasurer.restoreJvm();	// too much to inline; use the cruder lines below:
				System.runFinalization();
				System.gc();
				
				long t1 = System.nanoTime();
				for (int i = 0; i < numberOfRuns; i++) {
					task.run();
				}
				long t2 = System.nanoTime();
				double executionTime = calcDiffInSeconds(t1, t2);
				
				if (numberOfRuns == numberWarmupRuns) continue;
				else if (executionTime > minBenchmarkTime) return (executionTime/numberOfRuns);
				else continue;
			}
		}
		
		private static double calcDiffInSeconds(long t1, long t2) throws IllegalStateException {
			if (t1 > t2) throw new IllegalStateException("clock ran backwards: t1 = " + t1 + " > t2 = " + t2);
			
			long diff = t2 - t1;
			if (diff >= 0) {
				return diff * 1e-9;	// 1e-9 converts units from nanoseconds to seconds
			}
			else {	// overflow occured
				//throw new IllegalStateException("overflow occured: t2 - t1 = " + t2 + " - " + t1 + " = " + diff + " < 0");
					// decided that the above is perhaps too severe, and maybe it is OK to return a less accurate result than crash:
				double diffD = ((double) t1) - ((double) t2);	// compute a double diff, which may lose resolution, but will not overflow into a negative number
				return diffD * 1e-9;	// 1e-9 converts units from nanoseconds to seconds
			}
		}
		
	}
	
}
---------- END SOURCE ----------

CUSTOMER SUBMITTED WORKAROUND :
None that I know of.

Note: in the source code above ReadFrom.exec/DeserializeFrom.exec methods, if change
	new GZIPInputStream(bais) --> new GZIPInputStream(bais, 2*1024*1024)
(i.e. use massive buffers) the executions times actually get worse (due to more gc?), so that is NOT a workaround to the performance degradations.

The bad performance that I report above may be related to these previously noted bugs:

http://bugs.sun.com/bugdatabase/view_bug.do?bug_id=6438254
(above claimed to not be reproducible; but I provide source code here)

http://bugs.sun.com/bugdatabase/view_bug.do?bug_id=6409506
(this bug is claimed to be fixed; I claim that there is still an issue)

Comments
EVALUATION Closing as Not a Defect since the result is expected and there is a simple, straightforward workaround. The fix for 6206933 introduced some data copying; previously temporary pinning of user data buffers was done but this adversely impacted some applications resulting in OOM exceptions. The fix for 6206933 unfortunately does result in some performance degradation, however buffering GZIP streams results in reasonable performance in all known instances. For this particular case, I modified the testcase to use buffering (see attached); results are below. Notice in particular that, with buffering, the time to de/serialize the List has characteristics similar to de/serializing the String, namely that using gzip on the data takes about 2x as long as not using gzip. % jver 1.6.0_02 java BenchmarkGzip In the results below: Baos/Bais <--> ByteArrayOutputStream/ByteArrayInputStream Gos/Gis <--> GZIPOutputStream(ByteArrayOutputStream)/GZIPInputStream(ByteArrayInputStream) serialize/deserialize <--> ObjectOutputStream/ObjectInputStream wrap the indicated stream Time execute writeToBaos = 1.658730353125E-3 s; bytesWritten.length = 1048576 Time execute writeToGos = 2.211080619E-2 s; bytesWritten.length = 4408 Time execute serializeStringToBaos = 2.426869082E-2 s; bytesWritten.length = 2101252 Time execute serializeListToBaos = 2.905178934E-2 s; bytesWritten.length = 1049789 Time execute serializeStringToGos = 6.214866699500001E-2 s; bytesWritten.length = 9961 Time execute serializeListToGos = 2.129365924E-1 s; bytesWritten.length = 12173 Time execute readFromBais = 8.043189175000001E-4 Time execute readFromGis = 6.3102471025E-3 Time execute deserializeStringFromBais = 2.1597775685E-2 Time execute deserializeListFromBais = 2.107338303E-2 Time execute deserializeStringFromGis = 3.63517932E-2 Time execute deserializeListFromGis = 2.86267772315E-1 % jver 1.6.0_02 java BenchmarkBufferedGzip In the results below: Baos/Bais <--> ByteArrayOutputStream/ByteArrayInputStream Gos/Gis <--> GZIPOutputStream(ByteArrayOutputStream)/GZIPInputStream(ByteArrayInputStream) serialize/deserialize <--> ObjectOutputStream/ObjectInputStream wrap the indicated stream Time execute writeToBaos = 1.62249688125E-3 s; bytesWritten.length = 1048576 Time execute writeToGos = 2.2038503095E-2 s; bytesWritten.length = 4408 Time execute serializeStringToBaos = 2.4332981245E-2 s; bytesWritten.length = 2101252 Time execute serializeListToBaos = 2.9464312905E-2 s; bytesWritten.length = 1049797 Time execute serializeStringToGos = 6.2047871465E-2 s; bytesWritten.length = 9961 Time execute serializeListToGos = 5.4475389735E-2 s; bytesWritten.length = 12187 Time execute readFromBais = 6.66762229375E-4 Time execute readFromGis = 6.3885863175E-3 Time execute deserializeStringFromBais = 2.150565887E-2 Time execute deserializeListFromBais = 2.007905414E-2 Time execute deserializeStringFromGis = 3.240955713E-2 Time execute deserializeListFromGis = 2.911715762E-2
08-11-2007

WORK AROUND Wrap the GZIP streams with Buffered streams.
08-11-2007