db-derby-user mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Matt Sanford <mzsanf...@aol.com>
Subject Re: Cannot flush the log file to disk error - may need some code changes here
Date Tue, 02 Aug 2005 18:53:17 GMT
<!DOCTYPE html PUBLIC "-//W3C//DTD HTML 4.01 Transitional//EN">
<html>
<head>
  <meta content="text/html;charset=ISO-8859-1" http-equiv="Content-Type">
</head>
<body bgcolor="#ffffff" text="#000000">
<font face="Helvetica, Arial, sans-serif">Hello all,<br>
<br>
&nbsp;&nbsp;&nbsp; Issue Fixed, below is the cause info for anyone interested
and for
the mail archives. Thanks again for all of the info. First rule of code
reuse: you screwed up, not them.<br>
<br>
&nbsp;&nbsp;&nbsp; I did a review of all code in my system calling interrupt()
and
found the problem in what I considered an unrelated place. Prior to my
database transaction my code was checking something that required a
timeout. If the thread timed out I sent it an interrupt. As it turned
out, to support the check taking less than the total allowed time it
could also interrupt it's parent to say it had completed. So, the
short-short version looked something like this :<br>
<br>
Thread-1 :<br>
<br>
try {<br>
&nbsp;&nbsp;&nbsp; doCheckInNewThread(childThread); // See Thread-2<br>
&nbsp;&nbsp;&nbsp; Thread.sleep(timeout * 1000);<br>
&nbsp;&nbsp;&nbsp; // timed out.<br>
&nbsp;&nbsp;&nbsp; </font><font face="Helvetica, Arial, sans-serif">childThread.stopCheck();&nbsp;
// interrupts and sets a var.<br>
&nbsp;&nbsp;&nbsp; // throw timeout exception here<br>
</font><font face="Helvetica, Arial, sans-serif">} catch
(InterruptedException ie) {<br>
&nbsp;&nbsp;&nbsp; // ignore. the child completed in less than the timeout<br>
} <br>
<br>
Thread-2<br>
</font><br>
<font face="Helvetica, Arial, sans-serif">// inside doCheckInNewThread</font><br>
try {<br>
&nbsp;&nbsp;&nbsp; // long check here<br>
} catch (InterruptedException ie) {<br>
&nbsp;&nbsp;&nbsp; // my parent has said it's time to come home for dinner.<br>
} finally {<br>
&nbsp;&nbsp;&nbsp; // tell my parent i finished<br>
&nbsp;&nbsp;&nbsp; parentThread.interrupt();<br>
}<br>
<br>
<br>
<br>
&nbsp;&nbsp;&nbsp; The time line to cause the problem was :<br>
<br>
1. Thread-1 starts check<br>
2. Thread-2 starts check that takes too long<br>
3. Thread-1 detects timeout, sends interrupt<br>
4. Thread-2 moves into catch block<br>
5. Thread-1 passes it's catch block, moves on to database work<br>
6. Thread-2 reaches finally, calls interrupt on parent<br>
7. Thread-1 barfs when interrupted awaiting I/O operation<br>
8. Matt weeps.<br>
<br>
&nbsp;&nbsp;&nbsp; This only happened under heavy load because it needed time-slicing
to get in between the catch and finally in Thread-2. Tricky little
sucker. Changed the finally in Thread-2 to check the quit variable (set
in stopCheck) before calling interrupt.<br>
<br>
Thanks;<br>
&nbsp; -- Matt Sanford<br>
<br>
<a class="moz-txt-link-abbreviated" href="mailto:mikem_app@sbcglobal.net">mikem_app@sbcglobal.net</a>
wrote:
<blockquote cite="mid42EFBAF7.9090004@sbcglobal.net" type="cite">
  <pre wrap="">As was pointed out your error is likely caused by something
sending an interrupt at an inopportune time to the derby thread.
These thread interrupts are a big problem for the database I/O
portion of derby, and so far I have not found an optimal way to
deal with these.  If any java experts have a good idea here I
would appreciate it.  In the "c" world I would just block
interrupts during the db I/O.


Getting an interrupt while attempting to sync the log file is
especially bad as there are only 2 options available to maintain
a recoverable database: retry or crash the database server.  In
key pieces of code we have tried to code retry logic, and this
has addressed most of the issues in the past.  It looks like
this one is a relatively new code path in the code and is JVM
specific to derby usage on jdk 1.4 and higher.

LogAccessFile.syncLogAccessFile attempts to retry, but it looks
like the exception being thrown is probably different depending
on the JVM.  We currently retry for SyncFailedException in
LogAccessFile, but in
this case it is getting a ClosedByInterruptException - see code
in org.apache.derby.impl.io.DirRandomAccessFile4.sync.

So the question is, should we retry for a ClosedByInterruptException?
My guess is that just doing another force call just gets the same
exception, so we may have reopen the whole channel.  I lean toward
that we should do whatever necessary to retry, as this error just
causes too many problems for applications.



Matt Sanford wrote:

  </pre>
  <blockquote type="cite">
    <pre wrap="">Thanks for the speedy assistance. I added code to display the next
SQLException via getNextMessage() and got back :

java.nio.channels.ClosedByInterruptException
at
java.nio.channels.spi.AbstractInterruptibleChannel.end(AbstractInterruptibleChannel.java:184)

at sun.nio.ch.FileChannelImpl.force(FileChannelImpl.java:359)
at org.apache.derby.impl.io.DirRandomAccessFile4.sync(Unknown Source)
at
org.apache.derby.impl.store.raw.log.LogAccessFile.syncLogAccessFile(Unknown
Source)
at org.apache.derby.impl.store.raw.log.LogToFile.flush(Unknown Source)
at org.apache.derby.impl.store.raw.log.LogToFile.flush(Unknown Source)
at org.apache.derby.impl.store.raw.log.FileLogger.flush(Unknown Source)
at org.apache.derby.impl.store.raw.xact.Xact.prepareCommit(Unknown Source)
at org.apache.derby.impl.store.raw.xact.Xact.commit(Unknown Source)
at org.apache.derby.impl.store.raw.xact.Xact.commit(Unknown Source)
at org.apache.derby.impl.store.access.RAMTransaction.commit(Unknown Source)
at
org.apache.derby.impl.sql.conn.GenericLanguageConnectionContext.doCommit(Unknown
Source)
at
org.apache.derby.impl.sql.conn.GenericLanguageConnectionContext.userCommit(Unknown
Source)
at org.apache.derby.impl.jdbc.TransactionResourceImpl.commit(Unknown
Source)
at org.apache.derby.impl.jdbc.EmbedConnection.commit(Unknown Source)
...
...

Based on the info in the JDK javadocs it looks like I may have some
concurrent access somewhere. I will try and make a smallest-possible
test scenario and see if I can remove the problem.

Thanks again;
-- Matt Sanford


<a class="moz-txt-link-abbreviated" href="mailto:suresh.thalamati@gmail.com">suresh.thalamati@gmail.com</a>
wrote:

    </pre>
    <blockquote type="cite">
      <pre wrap="">Hi Matt ,

I came across this error only when the disk is full or when there are
file system errors. Surprised to find that you don't see log flush SQL
Exception in the derby.log. May be the error log is getting
reinitialized when you reboot after a shutdown inside your program.
You can avoid reinitialization of error log by adding
derby.infolog.append=true to the derby.properties.

On the side note , if u are using Derby version before 10.1 , nested
exception were not getting logged into the derby.log file in some
cases. I think log can not flush log exception is also one of them.
This issue is fixed in 10.1 ( JIRA ENTRY : DERBY-237) .

If you can not change the derby version , In your program , you may
want to print the nested SQL Exceptions, real IO error might show up
if you do that.

calling SYSCS_UTIL.SYSCS_CHECKPOINT_DATABASE() can only clean up log
files , if the log files are not needed for recovery.
On rare cases I came across programs that starts a transaction in the
beginning and never commits them, when that happens log files can not
be reclaimed; because log files will be needed to rollback that
particular transaction. This can lead to disk full scenario. Your log
file number is small(log10) , so I doubt that is the case!.

You may also want to check the permissions for the files.


Thanks
-suresht

Matt Sanford wrote:

      </pre>
      <blockquote type="cite">
        <pre wrap="">Hello,

I am using and embedded Derby database to replace a large SortedSet
in an RMI server program running on linux[1]. This program is
allowing both submission of new data and reading of data to manage a
queue of work. My program works fine at low load, but at high load I
am getting a SQLException with the message "Cannot flush the log file
to disk /usr/workSetDB/log/log10.dat" (filename varies). All access
to the Derby code is being synchronized to prevent problems with
transactional integrity. I followed the stack trace for the exception
(shown below[2]) but it is unclear to me what would be causing the
problem in the flush method. There are no disk or other errors in the
/var/log/messages file and I have attempted to move the logs dir off
to another device to see if that would help, but no luck.
        </pre>
      </blockquote>
      <pre wrap="">

      </pre>
      <blockquote type="cite">
        <pre wrap="">To try and correct the problem I have also tried a spare thread
calling SYSCS_UTIL.SYSCS_CHECKPOINT_DATABASE() at an interval (1
second and 5 seconds) but that has also not helped the problem. Once
the problem occurs my program shuts down[3] the database and
reconnects using the same code it used during initial startup. On
doing the shutdown and reconnect my code calls setReadOnly(false),
which throws an exception with the message "A read-only user or a
user in a read-only database is not permitted to disable read-only
mode on a connection.". Stopping my program completely and restarting
under a new JVM seems to correct the problem.
I have turned up the logging with some derby.properties changes[4],
but the final SQL statement logged is not the insert that failed but
rather the select prior to it and the only error in the log file is
for the read-only problem, not the cause of the initial problem. Has
anyone seen problems with the transaction log flushing under heavy
write load ? I could find almost no reports of these errors when
searching.

Thanks;
-- Matt Sanford

[1] RedHat AS 2.1 with 4 CPUs and 4GB RAM. Using ext3 file systems.
Java Version : Sun j2sdk1.4.2_03, using options : -server -Xms1600M
-Xmx1600M -XX:+AggressiveHeap

[2] -- Stack Trace --
ERROR XSLA0: Cannot flush the log file to disk
/usr/workSetDB/log/log10.dat.
at org.apache.derby.iapi.error.StandardException.newException(Unknown
Source)
at org.apache.derby.impl.store.raw.log.LogToFile.flush(Unknown Source)
at org.apache.derby.impl.store.raw.log.LogToFile.flush(Unknown Source)
at org.apache.derby.impl.store.raw.log.FileLogger.flush(Unknown Source)
at org.apache.derby.impl.store.raw.xact.Xact.prepareCommit(Unknown
Source)
at org.apache.derby.impl.store.raw.xact.Xact.commit(Unknown Source)
at org.apache.derby.impl.store.raw.xact.Xact.commit(Unknown Source)
at org.apache.derby.impl.store.access.RAMTransaction.commit(Unknown
Source)
at
org.apache.derby.impl.sql.conn.GenericLanguageConnectionContext.doCommit(Unknown
Source)
at
org.apache.derby.impl.sql.conn.GenericLanguageConnectionContext.userCommit(Unknown
Source)
at org.apache.derby.impl.jdbc.TransactionResourceImpl.commit(Unknown
Source)
at org.apache.derby.impl.jdbc.EmbedConnection.commit(Unknown Source)
at
com.mycode.workset.collection.JDBCPendingWorkCollection.addPendingWork(JDBCPendingWorkCollection.java:182)

...
...


[3] Shutting down with :

try {
DriverManager.getConnection(myurl + ";shutdown=true");
} catch (SQLException e) {
// catch the "SQL Exception: Derby system shutdown." message.
log.info("Database shutdown complete.");
}

[4] derby.properties

derby.stream.error.file=/tmp/derby.log
derby.language.logStatementText=true
derby.stream.error.logSeverityLevel=0


        </pre>
      </blockquote>
      <pre wrap="">
      </pre>
    </blockquote>
  </blockquote>
</blockquote>
<br>
</body>
</html>

Mime
View raw message