[Mulgara-dev] Backups failing Mulgara 1.2 Windows

Tue Apr 8 01:34:15 UTC 2008

On 08/04/2008, at 12:21 AM, Ben Hysell wrote:
> I pulled down the latest from SVN this morning and started my testing
>
>> one number that is of possible interest is what is the
>> largest node-id you can include in the file before there are
>> problems?
>
> 3145727 is the largest node ID I can include in my backup file,
> (attached), before I start getting the following on the command line:
>
> java.lang.Error: Cleaner terminated abnormally
>         at sun.misc.Cleaner$1.run(Cleaner.java:130)
>         at java.security.AccessController.doPrivileged(Native Method)
>         at sun.misc.Cleaner.clean(Cleaner.java:127)
>         at
> java.lang.ref.Reference$ReferenceHandler.run(Reference.java:124)
> Caused by: java.io.IOException: The process cannot access the file
> because anoth
> er process has locked a portion of the file
>         at sun.nio.ch.FileChannelImpl.unmap0(Native Method)
>         at
> sun.nio.ch.FileChannelImpl.access$000(FileChannelImpl.java:26)
>         at
> sun.nio.ch.FileChannelImpl$Unmapper.run(FileChannelImpl.java:680)
>         at sun.misc.Cleaner.clean(Cleaner.java:125)
>         ... 1 more
>
> I'll be tracing the restore process this afternoon to see if I can
> narrow down the error to a section of code.  Is there a better  
> method to
> get a better more explicit thread dump that what is currently being
> produced?  Thanks

 From a command-line ctrl-\ under any unix - I believe ctrl-break  
under windows.  Also under unix sending SIGQUIT, but I don't know  
what the equivalent is under windows.

If you can identify a point in the code you are interested in you can  
also call Thread::getAllStackTraces(), or the various methods on  
java.lang.management.ThreadMXBean for even more detailed information.

For instance I've attached the Thread-dump of an idle mulgara started  
under OSX.  I encourage anyone who hasn't looked at one before to  
look at it, note all the various system-threads and the level of  
detail regarding locks held and the stacktrace of each thread.  There  
is enough here to debug most deadlock bugs on the spot.  In this case  
what I will be looking for is to see if IntFile or BlockFile or  
similar are being used when this is happening, and precisely what  
they are doing.

^\Full thread dump Java HotSpot(TM) Client VM (1.5.0_13-121 mixed  
mode, sharing):
"TripleWriteThread: /Users/andrae/src/mulgara/trunk/dist/server1/ 
xaStatementStore/xa.g_3201" daemon prio=5 tid=0x00517af0  
nid=0x182be00 in Object.wait() [0xf1295000..0xf1295b30]
         at java.lang.Object.wait(Native Method)
         - waiting on <0x265a3178> (a  
org.mulgara.store.statement.xa.TripleWriteThread)
         at java.lang.Object.wait(Object.java:474)
         at org.mulgara.store.statement.xa.TripleWriteThread.run 
(TripleWriteThread.java:143)
         - locked <0x265a3178> (a  
org.mulgara.store.statement.xa.TripleWriteThread)

"TripleWriteThread: /Users/andrae/src/mulgara/trunk/dist/server1/ 
xaStatementStore/xa.g_3120" daemon prio=5 tid=0x00517710  
nid=0x182ba00 in Object.wait() [0xf1214000..0xf1214b30]
         at java.lang.Object.wait(Native Method)
         - waiting on <0x26630000> (a  
org.mulgara.store.statement.xa.TripleWriteThread)
         at java.lang.Object.wait(Object.java:474)
         at org.mulgara.store.statement.xa.TripleWriteThread.run 
(TripleWriteThread.java:143)
         - locked <0x26630000> (a  
org.mulgara.store.statement.xa.TripleWriteThread)

"TripleWriteThread: /Users/andrae/src/mulgara/trunk/dist/server1/ 
xaStatementStore/xa.g_3012" daemon prio=5 tid=0x005173e0  
nid=0x182b600 in Object.wait() [0xf1193000..0xf1193b30]
         at java.lang.Object.wait(Native Method)
         - waiting on <0x26630080> (a  
org.mulgara.store.statement.xa.TripleWriteThread)
         at java.lang.Object.wait(Object.java:474)
         at org.mulgara.store.statement.xa.TripleWriteThread.run 
(TripleWriteThread.java:143)
         - locked <0x26630080> (a  
org.mulgara.store.statement.xa.TripleWriteThread)

"TripleWriteThread: /Users/andrae/src/mulgara/trunk/dist/server1/ 
xaStatementStore/xa.g_2013" daemon prio=5 tid=0x00516f10  
nid=0x1856200 in Object.wait() [0xf1112000..0xf1112b30]
         at java.lang.Object.wait(Native Method)
         - waiting on <0x26630100> (a  
org.mulgara.store.statement.xa.TripleWriteThread)
         at java.lang.Object.wait(Object.java:474)
         at org.mulgara.store.statement.xa.TripleWriteThread.run 
(TripleWriteThread.java:143)
         - locked <0x26630100> (a  
org.mulgara.store.statement.xa.TripleWriteThread)

"TripleWriteThread: /Users/andrae/src/mulgara/trunk/dist/server1/ 
xaStatementStore/xa.g_1203" daemon prio=5 tid=0x00516bb0  
nid=0x1854400 in Object.wait() [0xf1091000..0xf1091b30]
         at java.lang.Object.wait(Native Method)
         - waiting on <0x26630180> (a  
org.mulgara.store.statement.xa.TripleWriteThread)
         at java.lang.Object.wait(Object.java:474)
         at org.mulgara.store.statement.xa.TripleWriteThread.run 
(TripleWriteThread.java:143)
         - locked <0x26630180> (a  
org.mulgara.store.statement.xa.TripleWriteThread)

"TripleWriteThread: /Users/andrae/src/mulgara/trunk/dist/server1/ 
xaStatementStore/xa.g_0123" daemon prio=5 tid=0x00516440  
nid=0x1854000 in Object.wait() [0xf1010000..0xf1010b30]
         at java.lang.Object.wait(Native Method)
         - waiting on <0x26da46d0> (a  
org.mulgara.store.statement.xa.TripleWriteThread)
         at java.lang.Object.wait(Object.java:474)
         at org.mulgara.store.statement.xa.TripleWriteThread.run 
(TripleWriteThread.java:143)
         - locked <0x26da46d0> (a  
org.mulgara.store.statement.xa.TripleWriteThread)

"JotmClock" daemon prio=5 tid=0x00515750 nid=0x1854800 waiting on  
condition [0xf0f8f000..0xf0f8fb30]
         at java.lang.Thread.sleep(Native Method)
         at org.objectweb.jotm.TimerManager.clock(TimerManager.java:169)
         at org.objectweb.jotm.Clock.run(TimerManager.java:65)

"JotmBatch" daemon prio=5 tid=0x00515310 nid=0x184c800 in Object.wait 
() [0xf0f0e000..0xf0f0eb30]
         at java.lang.Object.wait(Native Method)
         - waiting on <0x26d30870> (a java.util.Vector)
         at java.lang.Object.wait(Object.java:474)
         at org.objectweb.jotm.TimerManager.batch(TimerManager.java:221)
         - locked <0x26d30870> (a java.util.Vector)
         at org.objectweb.jotm.Batch.run(TimerManager.java:87)

"GC Daemon" daemon prio=2 tid=0x00514ad0 nid=0x184c400 in Object.wait 
() [0xf0e8d000..0xf0e8db30]
         at java.lang.Object.wait(Native Method)
         - waiting on <0x26d2b770> (a sun.misc.GC$LatencyLock)
         at sun.misc.GC$Daemon.run(GC.java:100)
         - locked <0x26d2b770> (a sun.misc.GC$LatencyLock)

"RMI Reaper" prio=5 tid=0x005146b0 nid=0x1862800 in Object.wait()  
[0xf0e0c000..0xf0e0cb30]
         at java.lang.Object.wait(Native Method)
         - waiting on <0x26d02e20> (a java.lang.ref.ReferenceQueue$Lock)
         at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:116)
         - locked <0x26d02e20> (a java.lang.ref.ReferenceQueue$Lock)
         at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:132)
         at sun.rmi.transport.ObjectTable$Reaper.run(ObjectTable.java: 
336)
         at java.lang.Thread.run(Thread.java:613)

"RMI TCP Accept-0" daemon prio=5 tid=0x005142c0 nid=0x1862400  
runnable [0xf0d8b000..0xf0d8bb30]
         at java.net.PlainSocketImpl.socketAccept(Native Method)
         at java.net.PlainSocketImpl.accept(PlainSocketImpl.java:384)
         - locked <0x26d2b2c0> (a java.net.SocksSocketImpl)
         at java.net.ServerSocket.implAccept(ServerSocket.java:450)
         at java.net.ServerSocket.accept(ServerSocket.java:421)
         at sun.rmi.transport.tcp.TCPTransport.run(TCPTransport.java: 
340)
         at java.lang.Thread.run(Thread.java:613)

"RMI TCP Accept-1099" daemon prio=5 tid=0x00511810 nid=0x184bc00  
runnable [0xf0d0a000..0xf0d0ab30]
         at java.net.PlainSocketImpl.socketAccept(Native Method)
         at java.net.PlainSocketImpl.accept(PlainSocketImpl.java:384)
         - locked <0x26d00fc0> (a java.net.SocksSocketImpl)
         at java.net.ServerSocket.implAccept(ServerSocket.java:450)
         at java.net.ServerSocket.accept(ServerSocket.java:421)
         at sun.rmi.transport.tcp.TCPTransport.run(TCPTransport.java: 
340)
         at java.lang.Thread.run(Thread.java:613)

"Timer-0" daemon prio=5 tid=0x00511480 nid=0x184b800 in Object.wait()  
[0xf0c89000..0xf0c89b30]
         at java.lang.Object.wait(Native Method)
         - waiting on <0x26d01170> (a java.util.TaskQueue)
         at java.lang.Object.wait(Object.java:474)
         at java.util.TimerThread.mainLoop(Timer.java:483)
         - locked <0x26d01170> (a java.util.TaskQueue)
         at java.util.TimerThread.run(Timer.java:462)

"Low Memory Detector" daemon prio=5 tid=0x0050a700 nid=0x1815400  
runnable [0x00000000..0x00000000]

"CompilerThread0" daemon prio=9 tid=0x00509d20 nid=0x1815000 waiting  
on condition [0x00000000..0xf0b06450]

"Signal Dispatcher" daemon prio=9 tid=0x00509850 nid=0x1814c00  
waiting on condition [0x00000000..0x00000000]

"Finalizer" daemon prio=8 tid=0x00509010 nid=0x1808000 in Object.wait 
() [0xf0a04000..0xf0a04b30]
         at java.lang.Object.wait(Native Method)
         - waiting on <0x26cbffe8> (a java.lang.ref.ReferenceQueue$Lock)
         at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:116)
         - locked <0x26cbffe8> (a java.lang.ref.ReferenceQueue$Lock)
         at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:132)
         at java.lang.ref.Finalizer$FinalizerThread.run 
(Finalizer.java:159)

"Reference Handler" daemon prio=10 tid=0x00508c70 nid=0x1807200 in  
Object.wait() [0xf0983000..0xf0983b30]
         at java.lang.Object.wait(Native Method)
         - waiting on <0x26cc0068> (a java.lang.ref.Reference$Lock)
         at java.lang.Object.wait(Object.java:474)
         at java.lang.ref.Reference$ReferenceHandler.run 
(Reference.java:116)
         - locked <0x26cc0068> (a java.lang.ref.Reference$Lock)

"main" prio=5 tid=0x005013b0 nid=0x1804600 runnable  
[0xf07fe000..0xf07fff70]
         at java.io.RandomAccessFile.setLength(Native Method)
         at org.mulgara.util.MappedIntFile.mapFile(MappedIntFile.java: 
350)
         - locked <0x26dc4070> (a org.mulgara.util.MappedIntFile)
         at org.mulgara.util.MappedIntFile.setSize(MappedIntFile.java: 
123)
         at org.mulgara.store.xa.FreeList$Phase.init(FreeList.java:1367)
         at org.mulgara.store.xa.FreeList$Phase.<init>(FreeList.java: 
1186)
         - locked <0x26dbc4b0> (a org.mulgara.store.xa.FreeList)
         at org.mulgara.store.xa.FreeList$Phase.<init>(FreeList.java: 
1154)
         at org.mulgara.store.xa.ManagedBlockFile$Phase.<init> 
(ManagedBlockFile.java:267)
         at org.mulgara.store.statement.xa.TripleAVLFile$Phase.<init> 
(TripleAVLFile.java:620)
         at org.mulgara.store.statement.xa.XAStatementStoreImpl 
$Phase.<init>(XAStatementStoreImpl.java:1513)
         at  
org.mulgara.store.statement.xa.XAStatementStoreImpl.selectPhase 
(XAStatementStoreImpl.java:1000)
         - locked <0x26daedb8> (a java.lang.Object)
         - locked <0x26da47d8> (a  
org.mulgara.store.statement.xa.XAStatementStoreImpl)
         at  
org.mulgara.resolver.store.StatementStoreResolverFactory.selectPhase 
(StatementStoreResolverFactory.java:167)
         at org.mulgara.resolver.Database.selectCommonPhase 
(Database.java:1089)
         at org.mulgara.resolver.Database.recoverDatabase 
(Database.java:1032)
         at org.mulgara.resolver.Database.<init>(Database.java:657)
         at org.mulgara.resolver.Database.<init>(Database.java:320)
         at sun.reflect.NativeConstructorAccessorImpl.newInstance0 
(Native Method)
         at sun.reflect.NativeConstructorAccessorImpl.newInstance 
(NativeConstructorAccessorImpl.java:39)
         at sun.reflect.DelegatingConstructorAccessorImpl.newInstance 
(DelegatingConstructorAccessorImpl.java:27)
         at java.lang.reflect.Constructor.newInstance 
(Constructor.java:494)
         at org.mulgara.server.AbstractServer.init 
(AbstractServer.java:355)
         at org.mulgara.server.EmbeddedMulgaraServer.startServer 
(EmbeddedMulgaraServer.java:1581)
         at org.mulgara.server.EmbeddedMulgaraServer.main 
(EmbeddedMulgaraServer.java:500)
         at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
         at sun.reflect.NativeMethodAccessorImpl.invoke 
(NativeMethodAccessorImpl.java:39)
         at sun.reflect.DelegatingMethodAccessorImpl.invoke 
(DelegatingMethodAccessorImpl.java:25)
         at java.lang.reflect.Method.invoke(Method.java:585)
         at org.mulgara.util.Bootstrap.invokeClass(Bootstrap.java:525)
         at org.mulgara.util.Bootstrap.main(Bootstrap.java:229)

"VM Thread" prio=9 tid=0x00508420 nid=0x1803c00 runnable

"VM Periodic Task Thread" prio=9 tid=0x0050be40 nid=0x1815800 waiting  
on condition

"Exception Catcher Thread" prio=10 tid=0x005015f0 nid=0x1804a00 runnable

Andrae

-- 
Andrae Muys
andrae at netymon.com
Senior RDF/Semantic-Web Consultant
Netymon Pty Ltd