debug output problem in ObjectInputStream

debug output problem in ObjectInputStream

[Per Bothner]

[-- Attachment #1: Type: text/plain, Size: 2005 bytes --]

(This problem was reported to me by L. Peter Deutsch.)

The class java/io/ObjectInputStream.java contains a lot
of calls to dumpElement and dumpElementln, which prints
the argument is debugging is enabled. By default the
DEBUG flag is false, so debugging is disabled.  Ideally
a compiler will be able to inline and eliminate the
calls to dumpElement[ln].

The problem is that the argument to dumpElement[ln] is
still evaluated, even when DEBUG is false.  In many cases
these arguments are non-trivial string concatenation expressions,
so we will get a temporary StringBuffer allocated, appended
to and thrown away.  A smart compiler might be able to
figure out that the result of the concatenation is unused,
and so avoid it.  Even worse though is that it calls
toString for each element of an array (and also for exceptions).
Since toString of an unknown class can do anything, the
compiler can't eliminate the call to toString.  It is even
possible that toString for a large (or cyclic) data structure
could do a large(or even an infinite) amount of work.

I've appended one fix, but I'm not sure what the best approach is.
The simplest would be to just rip out all the dumpElement code.
Next simplest is to move all the Configuration.DEBUG && dump
tests out of dumpElement[ln] and to the call sites.  One could
even do what my patches does, and convert the string concatenations
to multiple print calls.  Having dumpElement[ln] as separate
methods has the advantage that it could over overridden, but
it seems like poinles generality.  So if we want to keep the
debugging printout, I suggest:

   if (Configuration.DEBUG && dump)
     for (int i=0, len=Array.getLength(array); i < len; i++)
       System.out.println("  ELEMENT[" + i + "]=" + Array.get(array, i));

This makes it possible for a compiler to do the optimization to
multiple print calls that my patch does.

Alteratively, I suggest just removing all the dumpElement calls.
-- 
	--Per Bothner
per@bothner.com   http://www.bothner.com/per/

[-- Attachment #2: OIS.patch --]
[-- Type: text/plain, Size: 949 bytes --]

Index: ObjectInputStream.java
===================================================================
RCS file: /cvs/gcc/gcc/libjava/java/io/ObjectInputStream.java,v
retrieving revision 1.11
diff -u -r1.11 ObjectInputStream.java
--- ObjectInputStream.java	2002/01/22 22:40:14	1.11
+++ ObjectInputStream.java	2002/04/02 20:45:49
@@ -243,8 +243,16 @@
 	Object array = Array.newInstance (componentType, length);
 	int handle = assignNewHandle (array);
 	readArrayElements (array, componentType);
-	for (int i=0, len=Array.getLength(array); i < len; i++)
-	  dumpElementln ("  ELEMENT[" + i + "]=" + Array.get(array, i).toString());
+	if (Configuration.DEBUG && dump)
+	  {
+	    for (int i=0, len=Array.getLength(array); i < len; i++)
+	      {
+		System.out.print("  ELEMENT[");
+		System.out.print(i);
+		System.out.print("]=");
+		System.out.println(Array.get(array, i));
+	      }
+	  }
 	ret_val = processResolution (array, handle);
 	break;
       }

Re: debug output problem in ObjectInputStream

[Tom Tromey]

>>>>> "Per" == Per Bothner <per@bothner.com> writes:

Per> So if we want to keep the debugging printout, I suggest:

Per>    if (Configuration.DEBUG && dump)
Per>      for (int i=0, len=Array.getLength(array); i < len; i++)
Per>        System.out.println("  ELEMENT[" + i + "]=" + Array.get(array, i));

As I recall, Warren wrote all the debugging code.  He's probably in
the best position to say how useful it really is.  I've CC'd him.
(Warren, I'll forward you Per's note separately.)

Tom

Re: debug output problem in ObjectInputStream

[Warren Levy]

Per Bothner wrote:
> I've appended one fix, but I'm not sure what the best approach is.
> The simplest would be to just rip out all the dumpElement code.

Well, I'd hesitate to just rip it out.  The dumping code is extremely
helpful when dealing with serialization issues.

> Next simplest is to move all the Configuration.DEBUG && dump
> tests out of dumpElement[ln] and to the call sites.

I'd rather go with this approach than losing the capability to dump.

> Having dumpElement[ln] as separate
> methods has the advantage that it could over overridden, but
> it seems like poinles generality.

It wasn't so much an issue of it being overridden, as it seemed like
a much cleaner approach than having separate conditionals and println's
spread throughout the code.  I found it very helpful when debugging to
just set a breakpoint for dumpElement; if we get rid of the method and
sprinkle the code with the conditional and prints, we'll lose that ease
in debugging.  Having a separate dumpElement method also certainly improved 
readability of the code (at least IMO).  I'm fine though with readability 
and ease of debugging suffering a little bit, if it avoids needless 
processing in the typical case.

> So if we want to keep the
> debugging printout, I suggest:
> 
>    if (Configuration.DEBUG && dump)
>      for (int i=0, len=Array.getLength(array); i < len; i++)
>        System.out.println("  ELEMENT[" + i + "]=" + Array.get(array, i));

This seems cleaner than also breaking it out into multiple print calls.

I'd offer to make the changes myself but I'm not in a position to get
them in on the 3.1 branch at this time (nor the trunk for that matter).
I'm updating my paperwork with the GNU Project and then I'll be able to 
get my cvs access updated to allow me to commit changes to both gcj and 
Classpath.
--warrenl

Re: debug output problem in ObjectInputStream

[Bryce McKinlay]

[-- Attachment #1: Type: text/plain, Size: 1144 bytes --]

Per Bothner wrote:

> Having dumpElement[ln] as separate
> methods has the advantage that it could over overridden, but
> it seems like poinles generality.  So if we want to keep the
> debugging printout, I suggest:
>
>   if (Configuration.DEBUG && dump)
>     for (int i=0, len=Array.getLength(array); i < len; i++)
>       System.out.println("  ELEMENT[" + i + "]=" + Array.get(array, i));
>
> This makes it possible for a compiler to do the optimization to
> multiple print calls that my patch does. 


I was originally hoping that the dumpElement() methods would get inlined 
and the compiler would figure out that the code could be removed, but 
you're right in that even if inlining worked properly the arguments 
would still have to be evaluated unless it could also figure out that 
the StringBuffer methods etc had no side-effects.

I agree that we should put the "if (Configuration.DEBUG ..." at the call 
site to fix this. However, fixing this doesn't really help our extremely 
crap serialization performance. eg the attached test runs more than 45X 
slower with GCJ than JDK 1.4! Serialization needs some work...

regards

Bryce.


[-- Attachment #2: SerTest3.java --]
[-- Type: text/plain, Size: 1351 bytes --]

import java.util.*;
import java.io.*;

public class SerTest3
{
  static void showUsage()
  {
    System.err.println("Usage: SerTest3 <read|write>");
    System.exit(1);  
  }
  
  public static void main(String[] args) 
    throws IOException, FileNotFoundException, ClassNotFoundException
  {
    if (args.length == 0)
      showUsage();
    
    HashMap hm = null;    
    long start = System.currentTimeMillis();
    
    if (args[0].equals("write"))
      {
        hm = makeHugeHashMap();
	System.out.println ("map created, writing it out...");
	ObjectOutputStream out = 
	  new ObjectOutputStream(new FileOutputStream("test.ser"));

	out.writeObject(hm);
	out.close();
      }
    else if (args[0].equals("read"))
      {      
	ObjectInputStream in = 
	  new ObjectInputStream(new FileInputStream("test.ser"));

	hm = (HashMap) in.readObject();
      }
    else
      showUsage();
      
    System.out.println(hm.hashCode());
    System.out.println(System.currentTimeMillis() - start + "ms elapsed.");
  }
  
  static HashMap makeHugeHashMap()
  {
    HashMap hm = new HashMap();
    for (int i=0; i < 200; i++)
    {
      ArrayList al = new ArrayList();
      for (int j=0; j < 1000; j++)
      {
        al.add (Integer.toString(i - j));
      }
      Integer integer = new Integer(i);
      hm.put(integer, al);
    }
    return hm;
  }
}