tests

[Stephen Haberman]

Hey,

So, is "ant test" supposed to run to completion on a reasonable
dev machine? I don't know that I've ever had it work, and so don't
generally run it.

But I was feeling guilty tonight, so tried again, went away for awhile,
and came back to my RAM (12gb) and CPUs both pegged. And lots of these
in the console:

[junit] Exception in thread "pool-1-thread-569"
java.lang.NullPointerException [junit] at
com.google.gwt.dev.util.DiskCache.transferToStream(DiskCache.java:187)
[junit] at
com.google.gwt.dev.util.DiskCacheToken.writeObject(DiskCacheToken.java:91)
[junit] at
sun.reflect.GeneratedMethodAccessor29.invoke(Unknown Source)
[junit] at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
[junit] at java.lang.reflect.Method.invoke(Method.java:597)
[junit] at
java.io.ObjectStreamClass.invokeWriteObject(ObjectStreamClass.java:945)
[junit] at
java.io.ObjectOutputStream.writeSerialData(ObjectOutputStream.java:1469)
[junit] at
java.io.ObjectOutputStream.writeOrdinaryObject(ObjectOutputStream.java:1400)
[junit] at
java.io.ObjectOutputStream.writeObject0(ObjectOutputStream.java:1158)
[junit] at
java.io.ObjectOutputStream.defaultWriteFields(ObjectOutputStream.java:1518)
[junit] at
java.io.ObjectOutputStream.defaultWriteObject(ObjectOutputStream.java:422)
[junit] at
com.google.gwt.dev.javac.CachedCompilationUnit.writeObject(CachedCompilationUnit.java:222)
[junit] at
sun.reflect.GeneratedMethodAccessor32.invoke(Unknown Source)
[junit] at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
[junit] at java.lang.reflect.Method.invoke(Method.java:597)
[junit] at
java.io.ObjectStreamClass.invokeWriteObject(ObjectStreamClass.java:945)
[junit] at
java.io.ObjectOutputStream.writeSerialData(ObjectOutputStream.java:1469)
[junit] at
java.io.ObjectOutputStream.writeOrdinaryObject(ObjectOutputStream.java:1400)
[junit] at
java.io.ObjectOutputStream.writeObject0(ObjectOutputStream.java:1158)
[junit] at
java.io.ObjectOutputStream.writeObject(ObjectOutputStream.java:330)
[junit] at
com.google.gwt.dev.javac.PersistentUnitCache$6.run(PersistentUnitCache.java:446)
[junit] at
java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
[junit] at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
[junit] at java.lang.Thread.run(Thread.java:662)

- Stephen

[John Tamplin]

On Sat, Jun 9, 2012 at 10:26 PM, Stephen Haberman <stephen....@gmail.com> wrote:

So, is "ant test" supposed to run to completion on a reasonable
dev machine? I don't know that I've ever had it work, and so don't
generally run it.

I don't run it that often (we have a distributed test farm to run everything in parallel at work), but my recollection is it took about 50min to finish on a 16G / dual Opteron desktop at work (yes, it is old) and about 40min on my home desktop (12G RAM, Core i7).  I don't know that I have run it in the last few months.

 

But I was feeling guilty tonight, so tried again, went away for awhile,
and came back to my RAM (12gb) and CPUs both pegged. And lots of these
in the console: 

 

   [junit] Exception in thread "pool-1-thread-569"
   java.lang.NullPointerException [junit]      at
   com.google.gwt.dev.util.DiskCache.transferToStream(DiskCache.java:187)
   [junit]     at
   com.google.gwt.dev.util.DiskCacheToken.writeObject(DiskCacheToken.java:91)

 

At the very least, that suggests there is a bug in the DiskCache code that lets an NPE leak out.  Do you have enough disk space?

--
John A. Tamplin
Software Engineer (GWT), Google

[Stephen Haberman]

>
> [junit] Exception in thread "pool-1-thread-569"
> > java.lang.NullPointerException [junit] at
> > com.google.gwt.dev.util.DiskCache.transferToStream(DiskCache.java:187)
> > [junit] at
> >
> > com.google.gwt.dev.util.DiskCacheToken.writeObject(DiskCacheToken.java:91)
> >
>
> At the very least, that suggests there is a bug in the DiskCache code
> that lets an NPE leak out. Do you have enough disk space?

Sorry for not replying sooner; I have ~25gb free now (down from 50gb
free a few days ago, but I had to install some IE VMs; crap they're
huge).

I would not be surprised if something terribly degenerate happened; I
have swap turned off on my machine, so whenever my ~12gb of RAM is
gone (which it was in this case), things start failing in really odd
ways. Chrome tabs crash, applications go wonky, etc.

I might poke at it a bit more but am probably not going to worry too
much about it.

- Stephen

[Rajeev Dayal]

Hey,

I'm running into the same thing on a Linux workstation. It's a virtual instance, so I'm not sure if that might have something to do with it, but it's definitely strange.

Here's one exception that I see:

  [junit] Exception in thread "pool-1-thread-1" java.lang.RuntimeException: Unable to read from byte cache
    [junit] 	at com.google.gwt.dev.util.DiskCache.transferToStream(DiskCache.java:201)
    [junit] 	at com.google.gwt.dev.util.DiskCacheToken.writeObject(DiskCacheToken.java:91)
    [junit] 	at sun.reflect.GeneratedMethodAccessor51.invoke(Unknown Source)
    [junit] 	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    [junit] 	at java.lang.reflect.Method.invoke(Method.java:616)
    [junit] 	at java.io.ObjectStreamClass.invokeWriteObject(ObjectStreamClass.java:962)
    [junit] 	at java.io.ObjectOutputStream.writeSerialData(ObjectOutputStream.java:1480)
    [junit] 	at java.io.ObjectOutputStream.writeOrdinaryObject(ObjectOutputStream.java:1416)
    [junit] 	at java.io.ObjectOutputStream.writeObject0(ObjectOutputStream.java:1174)
    [junit] 	at java.io.ObjectOutputStream.defaultWriteFields(ObjectOutputStream.java:1528)
    [junit] 	at java.io.ObjectOutputStream.writeSerialData(ObjectOutputStream.java:1493)
    [junit] 	at java.io.ObjectOutputStream.writeOrdinaryObject(ObjectOutputStream.java:1416)
    [junit] 	at java.io.ObjectOutputStream.writeObject0(ObjectOutputStream.java:1174)
    [junit] 	at java.io.ObjectOutputStream.writeObject(ObjectOutputStream.java:346)
    [junit] 	at java.util.ArrayList.writeObject(ArrayList.java:673)
    [junit] 	at sun.reflect.GeneratedMethodAccessor33.invoke(Unknown Source)
    [junit] 	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    [junit] 	at java.lang.reflect.Method.invoke(Method.java:616)
    [junit] 	at java.io.ObjectStreamClass.invokeWriteObject(ObjectStreamClass.java:962)
    [junit] 	at java.io.ObjectOutputStream.writeSerialData(ObjectOutputStream.java:1480)
    [junit] 	at java.io.ObjectOutputStream.writeOrdinaryObject(ObjectOutputStream.java:1416)
    [junit] 	at java.io.ObjectOutputStream.writeObject0(ObjectOutputStream.java:1174)
    [junit] 	at java.io.ObjectOutputStream.writeObject(ObjectOutputStream.java:346)
    [junit] 	at com.google.gwt.dev.javac.CachedCompilationUnit.writeObject(CachedCompilationUnit.java:223)
    [junit] 	at sun.reflect.GeneratedMethodAccessor65.invoke(Unknown Source)
    [junit] 	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    [junit] 	at java.lang.reflect.Method.invoke(Method.java:616)
    [junit] 	at java.io.ObjectStreamClass.invokeWriteObject(ObjectStreamClass.java:962)
    [junit] 	at java.io.ObjectOutputStream.writeSerialData(ObjectOutputStream.java:1480)
    [junit] 	at java.io.ObjectOutputStream.writeOrdinaryObject(ObjectOutputStream.java:1416)
    [junit] 	at java.io.ObjectOutputStream.writeObject0(ObjectOutputStream.java:1174)
    [junit] 	at java.io.ObjectOutputStream.writeObject(ObjectOutputStream.java:346)
    [junit] 	at com.google.gwt.dev.javac.PersistentUnitCache$6.run(PersistentUnitCache.java:446)
    [junit] 	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)
    [junit] 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
    [junit] 	at java.lang.Thread.run(Thread.java:679)
    [junit] Caused by: java.io.EOFException
    [junit] 	at java.io.RandomAccessFile.readInt(RandomAccessFile.java:776)
    [junit] 	at com.google.gwt.dev.util.DiskCache.transferToStream(DiskCache.java:188)
    [junit] 	... 35 more

Which suggests that we're attempting to read data from the cache before we've added anything..

and then tons of the form:

  [junit] Exception in thread "pool-1-thread-3" java.lang.NullPointerException
    [junit] 	at com.google.gwt.dev.util.DiskCache.transferToStream(DiskCache.java:187)
    [junit] 	at com.google.gwt.dev.util.DiskCacheToken.writeObject(DiskCacheToken.java:91)
    [junit] 	at sun.reflect.GeneratedMethodAccessor51.invoke(Unknown Source)
    [junit] 	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    [junit] 	at java.lang.reflect.Method.invoke(Method.java:616)
    [junit] 	at java.io.ObjectStreamClass.invokeWriteObject(ObjectStreamClass.java:962)
    [junit] 	at java.io.ObjectOutputStream.writeSerialData(ObjectOutputStream.java:1480)
    [junit] 	at java.io.ObjectOutputStream.writeOrdinaryObject(ObjectOutputStream.java:1416)
    [junit] 	at java.io.ObjectOutputStream.writeObject0(ObjectOutputStream.java:1174)
    [junit] 	at java.io.ObjectOutputStream.defaultWriteFields(ObjectOutputStream.java:1528)
    [junit] 	at java.io.ObjectOutputStream.defaultWriteObject(ObjectOutputStream.java:438)
    [junit] 	at com.google.gwt.dev.javac.CachedCompilationUnit.writeObject(CachedCompilationUnit.java:222)
    [junit] 	at sun.reflect.GeneratedMethodAccessor65.invoke(Unknown Source)
    [junit] 	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    [junit] 	at java.lang.reflect.Method.invoke(Method.java:616)
    [junit] 	at java.io.ObjectStreamClass.invokeWriteObject(ObjectStreamClass.java:962)
    [junit] 	at java.io.ObjectOutputStream.writeSerialData(ObjectOutputStream.java:1480)
    [junit] 	at java.io.ObjectOutputStream.writeOrdinaryObject(ObjectOutputStream.java:1416)
    [junit] 	at java.io.ObjectOutputStream.writeObject0(ObjectOutputStream.java:1174)
    [junit] 	at java.io.ObjectOutputStream.writeObject(ObjectOutputStream.java:346)
    [junit] 	at com.google.gwt.dev.javac.PersistentUnitCache$6.run(PersistentUnitCache.java:446)
    [junit] 	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)
    [junit] 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
    [junit] 	at java.lang.Thread.run(Thread.java:679)

The only way this could happen is if the file object is null (line 187) - but that can only really happen if close() is called. It can't be called by another class directly, as it's private, so it must be invoked via the finalizer - but that should only happen on JVM shutdown.

Perhaps the finalizer gets run, but there are a ton of threads that were scheduled to write data at that time?

I don't know this area of code well enough to really know what's going on here..

- Stephen

--
http://groups.google.com/group/Google-Web-Toolkit-Contributors

[John Tamplin]

I have had periodic failures like this that go away when I re-run it.

[John Tamplin]

On Wed, Jun 20, 2012 at 6:48 AM, Eric Ayers <zun...@google.com> wrote:

Now, the problem with diagnosing this is that the file is set to be
deleted on exit.  So after the program exits, you can't see how
ridiculously huge the file might have been.  To test that theory, you
could try commenting out this line to test it, or you could keep track
of the # of bytes written and spit it out when this exception occurs.

Isn't there a way to disable this with a system property or command-line flag?