[Mulgara-dev] Exception stack trace while running a backup

David Moll DMoll at viewpointusa.com
Thu May 10 15:15:27 UTC 2007


Hi all,

 

Great news, we have moved production off of TKS2.1 and on to Mulgara!
The change was made on Tuesday, and so far it has been working much
better than TKS.  I'm watching the logging very closely to see if any
problems pop up, and I had a question about one occurance.  (As an
aside, I am no longer on the project that is using Mulgara on
production.  I am working on a separate project and still utilizing
Mulgara.  Ben Hysell, who has made several appearances on this list, is
the lead for production.)

 

We run automated backups every 4 hours, and Wednesday one of them
failed.  We are running Mulgara with the following command line options:

 

java -Xms2000m -Xmx4000m -XX:GCTimeRatio=19 -jar Mulgara.jar -k
xx.xx.xx.xx -o xx.xx.xx.x

 

On a machine with two quad core Xeon processors, 8 GB of RAM and Windows
Server 2003.  

 

Timestamp: 5/10/2007 20:36:51:26

Message: 2007-05-09 20:36:51:26 Successful Metastore Backup

Category: Email_Success

Machine: XXXXXXXXXXX

Process Name: C:\XXXXXX\bin\x86\Debug\XXXX.Backup.Client.exe

2007-05-09 20:30:00:48 Start Backup.  Attempt: 1

2007-05-09 20:32:54:40 Backup Failed. Attempt: 1

2007-05-09 20:32:54:90 Start Backup.  Attempt: 2

2007-05-09 20:36:50:60 Backup Finished Successfuly. Attempt: 2 

 

-------------------------------------------------

 

Email note that our code generates.

 

What's especially interesting to me about this error is that the stack
trace was printed twice, once at 08:29:09, and again at 08:29:24.  The
only difference between the two traces is the timestamp.  I am at a loss
as to why this is happening.  The only thing that I can think of is that
an insert was attempted while the backup was being processed, and the
insert was finalized, causing instance of the tree being backed up to be
lost.  That doesn't seem likely, as I would assume that a backup process
would get its own phased copy of the node tree to work on while the rest
of the system moved forward.  Any comments or suggestions are welcome.

 

And here is the stack trace:

 

2007-05-09 08:29:09,374 WARN  [PoolThread-7] itql.ItqlInterpreter -
Failed to backup server rmi://localhost/server1 to 

file:/d:/tksBackup/backup_2007-05-09_08-30.txt.gz

org.mulgara.query.QueryException: Unable to backup to
file:/d:/tksBackup/backup_2007-05-09_08-30.txt.gz

            at
org.mulgara.resolver.DatabaseSession.execute(DatabaseSession.java:634)

            at
org.mulgara.resolver.DatabaseSession.backup(DatabaseSession.java:589)

            at
org.mulgara.resolver.DatabaseSession.backup(DatabaseSession.java:337)

            at
org.mulgara.server.rmi.SessionWrapperRemoteSession.backup(SessionWrapper
RemoteSession.java:223)

            at sun.reflect.NativeMethodAccessorImpl.invoke0(Native
Method)

            at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.jav
a:39)

            at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessor
Impl.java:25)

            at java.lang.reflect.Method.invoke(Method.java:585)

            at
sun.rmi.server.UnicastServerRef.dispatch(UnicastServerRef.java:294)

            at sun.rmi.transport.Transport$1.run(Transport.java:153)

            at java.security.AccessController.doPrivileged(Native
Method)

            at
sun.rmi.transport.Transport.serviceCall(Transport.java:149)

            at
sun.rmi.transport.tcp.TCPTransport.handleMessages(TCPTransport.java:466)

            at
sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run(TCPTransport.ja
va:707)

            at java.lang.Thread.run(Thread.java:595)

            at
sun.rmi.transport.StreamRemoteCall.exceptionReceivedFromServer(StreamRem
oteCall.java:247)

            at
sun.rmi.transport.StreamRemoteCall.executeCall(StreamRemoteCall.java:223
)

            at sun.rmi.server.UnicastRef.invoke(UnicastRef.java:126)

            at
org.mulgara.server.rmi.RemoteSessionImpl_Stub.backup(Unknown Source)

            at
org.mulgara.server.rmi.RemoteSessionWrapperSession.backup(RemoteSessionW
rapperSession.java:299)

            at
org.mulgara.itql.ItqlInterpreter.outABackupCommand(ItqlInterpreter.java:
2325)

            at
org.mulgara.itql.analysis.DepthFirstAdapter.caseABackupCommand(DepthFirs
tAdapter.java:157)

            at
org.mulgara.itql.node.ABackupCommand.apply(ABackupCommand.java:50)

            at
org.mulgara.itql.analysis.DepthFirstAdapter.caseACommandStart(DepthFirst
Adapter.java:51)

            at
org.mulgara.itql.node.ACommandStart.apply(ACommandStart.java:30)

            at
org.mulgara.itql.analysis.DepthFirstAdapter.caseStart(DepthFirstAdapter.
java:31)

            at org.mulgara.itql.node.Start.apply(Start.java:33)

            at
org.mulgara.itql.ItqlInterpreter.executeCommand(ItqlInterpreter.java:572
)

            at
org.mulgara.itql.ItqlInterpreterBean.execute(ItqlInterpreterBean.java:38
4)

            at
org.mulgara.itql.ItqlInterpreterBean.executeQueryToString(ItqlInterprete
rBean.java:439)

            at sun.reflect.GeneratedMethodAccessor20.invoke(Unknown
Source)

            at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessor
Impl.java:25)

            at java.lang.reflect.Method.invoke(Method.java:585)

            at
org.apache.axis.providers.java.RPCProvider.invokeMethod(RPCProvider.java
:402)

            at
org.apache.axis.providers.java.RPCProvider.processMessage(RPCProvider.ja
va:309)

            at
org.apache.axis.providers.java.JavaProvider.invoke(JavaProvider.java:333
)

            at
org.apache.axis.strategies.InvocationStrategy.visit(InvocationStrategy.j
ava:71)

            at
org.apache.axis.SimpleChain.doVisiting(SimpleChain.java:150)

            at org.apache.axis.SimpleChain.invoke(SimpleChain.java:120)

            at
org.apache.axis.handlers.soap.SOAPService.invoke(SOAPService.java:481)

            at
org.apache.axis.server.AxisServer.invoke(AxisServer.java:323)

            at
org.apache.axis.transport.http.AxisServlet.doPost(AxisServlet.java:854)

            at
javax.servlet.http.HttpServlet.service(HttpServlet.java:760)

            at
org.apache.axis.transport.http.AxisServletBase.service(AxisServletBase.j
ava:339)

            at
javax.servlet.http.HttpServlet.service(HttpServlet.java:853)

            at
org.mortbay.jetty.servlet.ServletHolder.handle(ServletHolder.java:354)

            at
org.mortbay.jetty.servlet.WebApplicationHandler.dispatch(WebApplicationH
andler.java:294)

            at
org.mortbay.jetty.servlet.ServletHandler.handle(ServletHandler.java:567)

            at
org.mortbay.http.HttpContext.handle(HttpContext.java:1808)

            at
org.mortbay.jetty.servlet.WebApplicationContext.handle(WebApplicationCon
text.java:525)

            at
org.mortbay.http.HttpContext.handle(HttpContext.java:1758)

            at org.mortbay.http.HttpServer.service(HttpServer.java:879)

            at
org.mortbay.http.HttpConnection.service(HttpConnection.java:790)

            at
org.mortbay.http.HttpConnection.handleNext(HttpConnection.java:952)

            at
org.mortbay.http.HttpConnection.handle(HttpConnection.java:807)

            at
org.mortbay.http.SocketListener.handleConnection(SocketListener.java:197
)

            at
org.mortbay.util.ThreadedServer.handle(ThreadedServer.java:289)

            at
org.mortbay.util.ThreadPool$PoolThread.run(ThreadPool.java:501)

Caused by: org.mulgara.query.QueryException:
org.mulgara.query.MulgaraTransactionException: Transaction rollback
triggered

            at
org.mulgara.resolver.MulgaraTransaction.implicitRollback(MulgaraTransact
ion.java:462)

            at
org.mulgara.resolver.MulgaraTransaction.execute(MulgaraTransaction.java:
552)

            at
org.mulgara.resolver.DatabaseSession.execute(DatabaseSession.java:631)

            at
org.mulgara.resolver.DatabaseSession.backup(DatabaseSession.java:589)

            at
org.mulgara.resolver.DatabaseSession.backup(DatabaseSession.java:337)

            at
org.mulgara.server.rmi.SessionWrapperRemoteSession.backup(SessionWrapper
RemoteSession.java:223)

            at sun.reflect.NativeMethodAccessorImpl.invoke0(Native
Method)

            at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.jav
a:39)

            at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessor
Impl.java:25)

            at java.lang.reflect.Method.invoke(Method.java:585)

            at
sun.rmi.server.UnicastServerRef.dispatch(UnicastServerRef.java:294)

            at sun.rmi.transport.Transport$1.run(Transport.java:153)

            at java.security.AccessController.doPrivileged(Native
Method)

            at
sun.rmi.transport.Transport.serviceCall(Transport.java:149)

            at
sun.rmi.transport.tcp.TCPTransport.handleMessages(TCPTransport.java:466)

            at
sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run(TCPTransport.ja
va:707)

            at java.lang.Thread.run(Thread.java:595)

Caused by: java.lang.AssertionError

            at org.mulgara.store.xa.Block.dispose(Block.java:524)

            at org.mulgara.store.xa.Block.release(Block.java:512)

            at org.mulgara.store.xa.AVLNode.release(AVLNode.java:1030)

            at
org.mulgara.store.stringpool.xa.XAStringPoolImpl$Phase$GNodeTuplesImpl.c
lose(XAStringPoolImpl.java:2728)

            at
org.mulgara.resolver.BackupOperation.backupDatabase(BackupOperation.java
:196)

            at
org.mulgara.resolver.BackupOperation.execute(BackupOperation.java:145)

            at
org.mulgara.resolver.MulgaraTransaction.execute(MulgaraTransaction.java:
547)

            ... 15 more

2007-05-09 08:29:09,374 ERROR [PoolThread-7] itql.ItqlInterpreterBean -
Execute query failed.  Returning error

org.mulgara.itql.ItqlInterpreterException:
org.mulgara.query.QueryException: Unable to backup to 

file:/d:/tksBackup/backup_2007-05-09_08-30.txt.gz

            at
org.mulgara.itql.ItqlInterpreter.setLastError(ItqlInterpreter.java:2479)

            at
org.mulgara.itql.ItqlInterpreter.outABackupCommand(ItqlInterpreter.java:
2342)

            at
org.mulgara.itql.analysis.DepthFirstAdapter.caseABackupCommand(DepthFirs
tAdapter.java:157)

            at
org.mulgara.itql.node.ABackupCommand.apply(ABackupCommand.java:50)

            at
org.mulgara.itql.analysis.DepthFirstAdapter.caseACommandStart(DepthFirst
Adapter.java:51)

            at
org.mulgara.itql.node.ACommandStart.apply(ACommandStart.java:30)

            at
org.mulgara.itql.analysis.DepthFirstAdapter.caseStart(DepthFirstAdapter.
java:31)

            at org.mulgara.itql.node.Start.apply(Start.java:33)

            at
org.mulgara.itql.ItqlInterpreter.executeCommand(ItqlInterpreter.java:572
)

            at
org.mulgara.itql.ItqlInterpreterBean.execute(ItqlInterpreterBean.java:38
4)

            at
org.mulgara.itql.ItqlInterpreterBean.executeQueryToString(ItqlInterprete
rBean.java:439)

            at sun.reflect.GeneratedMethodAccessor20.invoke(Unknown
Source)

            at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessor
Impl.java:25)

            at java.lang.reflect.Method.invoke(Method.java:585)

            at
org.apache.axis.providers.java.RPCProvider.invokeMethod(RPCProvider.java
:402)

            at
org.apache.axis.providers.java.RPCProvider.processMessage(RPCProvider.ja
va:309)

            at
org.apache.axis.providers.java.JavaProvider.invoke(JavaProvider.java:333
)

            at
org.apache.axis.strategies.InvocationStrategy.visit(InvocationStrategy.j
ava:71)

            at
org.apache.axis.SimpleChain.doVisiting(SimpleChain.java:150)

            at org.apache.axis.SimpleChain.invoke(SimpleChain.java:120)

            at
org.apache.axis.handlers.soap.SOAPService.invoke(SOAPService.java:481)

            at
org.apache.axis.server.AxisServer.invoke(AxisServer.java:323)

            at
org.apache.axis.transport.http.AxisServlet.doPost(AxisServlet.java:854)

            at
javax.servlet.http.HttpServlet.service(HttpServlet.java:760)

            at
org.apache.axis.transport.http.AxisServletBase.service(AxisServletBase.j
ava:339)

            at
javax.servlet.http.HttpServlet.service(HttpServlet.java:853)

            at
org.mortbay.jetty.servlet.ServletHolder.handle(ServletHolder.java:354)

            at
org.mortbay.jetty.servlet.WebApplicationHandler.dispatch(WebApplicationH
andler.java:294)

            at
org.mortbay.jetty.servlet.ServletHandler.handle(ServletHandler.java:567)

            at
org.mortbay.http.HttpContext.handle(HttpContext.java:1808)

            at
org.mortbay.jetty.servlet.WebApplicationContext.handle(WebApplicationCon
text.java:525)

            at
org.mortbay.http.HttpContext.handle(HttpContext.java:1758)

            at org.mortbay.http.HttpServer.service(HttpServer.java:879)

            at
org.mortbay.http.HttpConnection.service(HttpConnection.java:790)

            at
org.mortbay.http.HttpConnection.handleNext(HttpConnection.java:952)

            at
org.mortbay.http.HttpConnection.handle(HttpConnection.java:807)

            at
org.mortbay.http.SocketListener.handleConnection(SocketListener.java:197
)

            at
org.mortbay.util.ThreadedServer.handle(ThreadedServer.java:289)

            at
org.mortbay.util.ThreadPool$PoolThread.run(ThreadPool.java:501)

Caused by: org.mulgara.query.QueryException: Unable to backup to
file:/d:/tksBackup/backup_2007-05-09_08-30.txt.gz

            at
org.mulgara.resolver.DatabaseSession.execute(DatabaseSession.java:634)

            at
org.mulgara.resolver.DatabaseSession.backup(DatabaseSession.java:589)

            at
org.mulgara.resolver.DatabaseSession.backup(DatabaseSession.java:337)

            at
org.mulgara.server.rmi.SessionWrapperRemoteSession.backup(SessionWrapper
RemoteSession.java:223)

            at sun.reflect.NativeMethodAccessorImpl.invoke0(Native
Method)

            at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.jav
a:39)

            at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessor
Impl.java:25)

            at java.lang.reflect.Method.invoke(Method.java:585)

            at
sun.rmi.server.UnicastServerRef.dispatch(UnicastServerRef.java:294)

            at sun.rmi.transport.Transport$1.run(Transport.java:153)

            at java.security.AccessController.doPrivileged(Native
Method)

            at
sun.rmi.transport.Transport.serviceCall(Transport.java:149)

            at
sun.rmi.transport.tcp.TCPTransport.handleMessages(TCPTransport.java:466)

            at
sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run(TCPTransport.ja
va:707)

            at java.lang.Thread.run(Thread.java:595)

            at
sun.rmi.transport.StreamRemoteCall.exceptionReceivedFromServer(StreamRem
oteCall.java:247)

            at
sun.rmi.transport.StreamRemoteCall.executeCall(StreamRemoteCall.java:223
)

            at sun.rmi.server.UnicastRef.invoke(UnicastRef.java:126)

            at
org.mulgara.server.rmi.RemoteSessionImpl_Stub.backup(Unknown Source)

            at
org.mulgara.server.rmi.RemoteSessionWrapperSession.backup(RemoteSessionW
rapperSession.java:299)

            at
org.mulgara.itql.ItqlInterpreter.outABackupCommand(ItqlInterpreter.java:
2325)

            ... 37 more

Caused by: org.mulgara.query.QueryException:
org.mulgara.query.MulgaraTransactionException: Transaction rollback
triggered

            at
org.mulgara.resolver.MulgaraTransaction.implicitRollback(MulgaraTransact
ion.java:462)

            at
org.mulgara.resolver.MulgaraTransaction.execute(MulgaraTransaction.java:
552)

            at
org.mulgara.resolver.DatabaseSession.execute(DatabaseSession.java:631)

            at
org.mulgara.resolver.DatabaseSession.backup(DatabaseSession.java:589)

            at
org.mulgara.resolver.DatabaseSession.backup(DatabaseSession.java:337)

            at
org.mulgara.server.rmi.SessionWrapperRemoteSession.backup(SessionWrapper
RemoteSession.java:223)

            at sun.reflect.NativeMethodAccessorImpl.invoke0(Native
Method)

            at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.jav
a:39)

            at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessor
Impl.java:25)

            at java.lang.reflect.Method.invoke(Method.java:585)

            at
sun.rmi.server.UnicastServerRef.dispatch(UnicastServerRef.java:294)

            at sun.rmi.transport.Transport$1.run(Transport.java:153)

            at java.security.AccessController.doPrivileged(Native
Method)

            at
sun.rmi.transport.Transport.serviceCall(Transport.java:149)

            at
sun.rmi.transport.tcp.TCPTransport.handleMessages(TCPTransport.java:466)

            at
sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run(TCPTransport.ja
va:707)

            at java.lang.Thread.run(Thread.java:595)

Caused by: java.lang.AssertionError

            at org.mulgara.store.xa.Block.dispose(Block.java:524)

            at org.mulgara.store.xa.Block.release(Block.java:512)

            at org.mulgara.store.xa.AVLNode.release(AVLNode.java:1030)

            at
org.mulgara.store.stringpool.xa.XAStringPoolImpl$Phase$GNodeTuplesImpl.c
lose(XAStringPoolImpl.java:2728)

            at
org.mulgara.resolver.BackupOperation.backupDatabase(BackupOperation.java
:196)

            at
org.mulgara.resolver.BackupOperation.execute(BackupOperation.java:145)

            at
org.mulgara.resolver.MulgaraTransaction.execute(MulgaraTransaction.java:
547)

            ... 15 more

2007-05-09 08:29:09,374 ERROR [PoolThread-7] itql.ItqlInterpreterBean -
Failed to execute query

javax.xml.soap.SOAPException: ItqlInterpreter error -
org.mulgara.query.QueryException: Unable to backup to 

file:/d:/tksBackup/backup_2007-05-09_08-30.txt.gz

Caused by: (QueryException) Unable to backup to
file:/d:/tksBackup/backup_2007-05-09_08-30.txt.gz

Caused by: (QueryException)
org.mulgara.query.MulgaraTransactionException: Transaction rollback
triggered

Caused by: (AssertionError) 

            at
org.mulgara.itql.ItqlInterpreterBean.execute(ItqlInterpreterBean.java:40
5)

            at
org.mulgara.itql.ItqlInterpreterBean.executeQueryToString(ItqlInterprete
rBean.java:439)

            at sun.reflect.GeneratedMethodAccessor20.invoke(Unknown
Source)

            at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessor
Impl.java:25)

            at java.lang.reflect.Method.invoke(Method.java:585)

            at
org.apache.axis.providers.java.RPCProvider.invokeMethod(RPCProvider.java
:402)

            at
org.apache.axis.providers.java.RPCProvider.processMessage(RPCProvider.ja
va:309)

            at
org.apache.axis.providers.java.JavaProvider.invoke(JavaProvider.java:333
)

            at
org.apache.axis.strategies.InvocationStrategy.visit(InvocationStrategy.j
ava:71)

            at
org.apache.axis.SimpleChain.doVisiting(SimpleChain.java:150)

            at org.apache.axis.SimpleChain.invoke(SimpleChain.java:120)

            at
org.apache.axis.handlers.soap.SOAPService.invoke(SOAPService.java:481)

            at
org.apache.axis.server.AxisServer.invoke(AxisServer.java:323)

            at
org.apache.axis.transport.http.AxisServlet.doPost(AxisServlet.java:854)

            at
javax.servlet.http.HttpServlet.service(HttpServlet.java:760)

            at
org.apache.axis.transport.http.AxisServletBase.service(AxisServletBase.j
ava:339)

            at
javax.servlet.http.HttpServlet.service(HttpServlet.java:853)

            at
org.mortbay.jetty.servlet.ServletHolder.handle(ServletHolder.java:354)

            at
org.mortbay.jetty.servlet.WebApplicationHandler.dispatch(WebApplicationH
andler.java:294)

            at
org.mortbay.jetty.servlet.ServletHandler.handle(ServletHandler.java:567)

            at
org.mortbay.http.HttpContext.handle(HttpContext.java:1808)

            at
org.mortbay.jetty.servlet.WebApplicationContext.handle(WebApplicationCon
text.java:525)

            at
org.mortbay.http.HttpContext.handle(HttpContext.java:1758)

            at org.mortbay.http.HttpServer.service(HttpServer.java:879)

            at
org.mortbay.http.HttpConnection.service(HttpConnection.java:790)

            at
org.mortbay.http.HttpConnection.handleNext(HttpConnection.java:952)

            at
org.mortbay.http.HttpConnection.handle(HttpConnection.java:807)

            at
org.mortbay.http.SocketListener.handleConnection(SocketListener.java:197
)

            at
org.mortbay.util.ThreadedServer.handle(ThreadedServer.java:289)

            at
org.mortbay.util.ThreadPool$PoolThread.run(ThreadPool.java:501)

 

David Moll

Software Engineer

dmoll at viewpointusa.com

Viewpoint Data Management LLC

 

 

-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.mulgara.org/pipermail/mulgara-dev/attachments/20070510/53e38003/attachment.htm>


More information about the Mulgara-dev mailing list