Issue with SYSCS_UTIL.SYSCS_COMPRESS_ TABLE

[Sai Pullabhotla]

Hello,

Our application using Derby 10.4 (in embedded mode) has a background process that runs the SYSCS_UTIL.SYSCS_COMPRESS_TABLE procedure periodically. We have been reported the following error while this procedure is being executed and a SELECT statement came in at the same time:

        com.linoma.dpa.dao.DAOException: The conglomerate (71,409) requested does not exist.
        com.linoma.dpa.runtime.JobFailedException: com.linoma.dpa.dao.DAOException: The conglomerate (71,409) requested does not exist.
            at com.linoma.dpa.runtime.Job.checkLogin(Unknown Source)
            at com.linoma.dpa.runtime.Job.run(Unknown Source)
            at com.linoma.dpa.runtime.Runtime.executeProject(Unknown Source)
            at com.linoma.dpa.runtime.Runtime.executeProject(Unknown Source)
            at com.linoma.dpa.j2ee.RunProjectCommandServlet.doPost(Unknown Source)
            at javax.servlet.http.HttpServlet.service(HttpServlet.java:637)
            at javax.servlet.http.HttpServlet.service(HttpServlet.java:717)
            at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290)
            at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
            at com.linoma.dpa.security.SecurityFilter.doFilter(Unknown Source)
            at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
            at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
            at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:233)
            at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191)
            at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:128)
            at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102)
            at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109)
            at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:286)
            at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:845)
            at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:583)
            at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:447)
            at java.lang.Thread.run(Thread.java:810)
        Caused by: com.linoma.dpa.security.LoginException: com.linoma.dpa.dao.DAOException: The conglomerate (71,409) requested does not exist.
            at com.linoma.dpa.security.LoginUtilities.getUserDetails(Unknown Source)
            ... 22 more
        Caused by: com.linoma.dpa.dao.DAOException: The conglomerate (71,409) requested does not exist.
            at com.linoma.dpa.dao.rdbms.UserDAOImpl.getConsolidatedRoles(Unknown Source)
            at com.linoma.dpa.dao.rdbms.UserDAOImpl.findUser(Unknown Source)
            ... 23 more
        Caused by: java.sql.SQLException: The conglomerate (71,409) requested does not exist.
            at org.apache.derby.impl.jdbc.SQLExceptionFactory.getSQLException(Unknown Source)
            at org.apache.derby.impl.jdbc.Util.generateCsSQLException(Unknown Source)
            at org.apache.derby.impl.jdbc.TransactionResourceImpl.wrapInSQLException(Unknown Source)
            at org.apache.derby.impl.jdbc.TransactionResourceImpl.handleException(Unknown Source)
            at org.apache.derby.impl.jdbc.EmbedConnection.handleException(Unknown Source)
            at org.apache.derby.impl.jdbc.ConnectionChild.handleException(Unknown Source)
            at org.apache.derby.impl.jdbc.EmbedStatement.executeStatement(Unknown Source)
            at org.apache.derby.impl.jdbc.EmbedPreparedStatement.executeStatement(Unknown Source)
            at org.apache.derby.impl.jdbc.EmbedPreparedStatement.executeQuery(Unknown Source)
            at org.apache.tomcat.dbcp.dbcp.DelegatingPreparedStatement.executeQuery(DelegatingPreparedStatement.java:93)
            ... 25 more
        Caused by: ERROR XSAI2: The conglomerate (71,409) requested does not exist.
            at org.apache.derby.iapi.error.StandardException.newException(Unknown Source)
            at org.apache.derby.impl.store.access.btree.index.B2IFactory.readConglomerate(Unknown Source)
            at org.apache.derby.impl.store.access.RAMAccessManager.conglomCacheFind(Unknown Source)
            at org.apache.derby.impl.store.access.RAMTransaction.findExistingConglomerate(Unknown Source)
            at org.apache.derby.impl.store.access.RAMTransaction.openScan(Unknown Source)
            at org.apache.derby.impl.store.access.BackingStoreHashTableFromScan.<init>(Unknown Source)
            at org.apache.derby.impl.store.access.RAMTransaction.createBackingStoreHashtableFromScan(Unknown Source)
            at org.apache.derby.impl.sql.execute.HashScanResultSet.openCore(Unknown Source)
            at org.apache.derby.impl.sql.execute.JoinResultSet.openRight(Unknown Source)
            at org.apache.derby.impl.sql.execute.JoinResultSet.openCore(Unknown Source)
            at org.apache.derby.impl.sql.execute.JoinResultSet.openCore(Unknown Source)
            at org.apache.derby.impl.sql.execute.ProjectRestrictResultSet.openCore(Unknown Source)
            at org.apache.derby.impl.sql.execute.UnionResultSet.getNextRowCore(Unknown Source)
            at org.apache.derby.impl.sql.execute.SortResultSet.getRowFromResultSet(Unknown Source)
            at org.apache.derby.impl.sql.execute.SortResultSet.getNextRowFromRS(Unknown Source)
            at org.apache.derby.impl.sql.execute.SortResultSet.loadSorter(Unknown Source)
            at org.apache.derby.impl.sql.execute.SortResultSet.openCore(Unknown Source)
            at org.apache.derby.impl.sql.execute.SortResultSet.openCore(Unknown Source)
            at org.apache.derby.impl.sql.execute.BasicNoPutResultSetImpl.open(Unknown Source)
            at org.apache.derby.impl.sql.GenericPreparedStatement.execute(Unknown Source)
            ... 29 more

I'm not sure if this is expected or not. I would like to know if it is (or is not) recommended to run the SYSCS_UTIL.SYSCS_COMPRESS_TABLE procedure during the normal operation of an application. What kind of locks are acquired during the execution of this procedure? The documentation says -

This procedure acquires an exclusive table lock on the table being compressed.
All statement plans dependent on the table or its indexes are invalidated. (I'm not sure what exactly this means).

The important thing to note is - all other subsequent SELECT queries after the compression was done have also failed with the same exact error referring to same conglomerate. We had to restart the database/application to fix the issue. Is this something expected too? Or is this something to do with the state of my connection in the connection pool.

We perform the following procedure to compress all the tables:

        String sql = "select schemaname, tablename from sys.sysschemas s, "
            + "sys.systables t where s.schemaid=t.schemaid and t.tabletype='T'";
        Statement stmt = conn.createStatement();
        ResultSet rs = null;
        CallableStatement cs = null;
        try {
            rs = stmt.executeQuery(sql);
            cs = conn.prepareCall("call SYSCS_UTIL.SYSCS_COMPRESS_TABLE(?, ?, ?)");
            while (rs.next()) {
                String schema = rs.getString(1).trim();
                String table = rs.getString(2).trim();
                cs.setString(1, schema);
                cs.setString(2, table);
                cs.setShort(3, (short) 1);
                cs.execute();
            }
        }

Your help/feedback is greatly appreciated.

Thanks.

[Kathey Marsden]

Sai Pullabhotla wrote:
> Hello,
>
>  
Hello and thank you for reporting this issue.
> Our application using Derby 10.4 (in embedded mode) has a background process
> that runs the SYSCS_UTIL.SYSCS_COMPRESS_TABLE procedure periodically. We
> have been reported the following error while this procedure is being
> executed and a SELECT statement came in at the same time:
>
> com.linoma.dpa.dao.DAOException: The conglomerate (71,409) requested does
> not exist.
>  
Mike just fixed a corruption issue related to inplace
compress,https://issues.apache.org/jira/browse/DERBY-4239  but my
understanding is that it should not be an issue with offline compress
and also I would expect your database to be unbootable even after you
completely shutdown your application and Derby.    Can you
1) Post the full nested stack trace from the derby.log.
2) Run a consistency check on your database.
http://wiki.apache.org/db-derby/DatabaseConsistencyCheck
4) Tell us the isolation level of your select statement.
3)   Modify the reproduction attached to DERBY-4239
https://issues.apache.org/jira/secure/attachment/12408948/reproBackgroundCheckpoint.zip
to use SYCS_UTIL.SYSCS_COMPRESS_TABLE and see if you can reproduce your
issue.  You might need to modify it to add in a select.


Thanks

Kathey

[Mike Matrigali]

Without a repro it is hard to say for sure what is going on.  But if I
had to guess, this has the feel of statement cache dependency being
broken.

Underneath what SYSCS_UTIL.SYSCS_COMPRESS_TABLE does is create a new
conglomerate and copy all the data from the old conglomerate to the
new conglomerate.  These conglomerate numbers are compiled into plans.
What is supposed to happen is that we get an exclusive lock on the
table which should stop all executing statements, and then the
dependency manager is supposed to invalidate all plans after this
ddl statement is executed.

The fact that restarting the db fixes it makes me think it is an
inmemory problem and not a database corruption problem.

compress doesn't really do anything special it counts on the standard
dependency code for all the ddl going through the alter table statement.

This error is not supposed to happen, but not sure what you can do until
the bug is fixed.

I can't tell from your program if autocommit is on or not. It would
probably be best if you commit after each compress, if you are not doing
so already.  In general doing queries directly against the system
catalogs can cause some concurrency problems for the whole system,
though should not cause the errors you are seeing.  To have the
background task have less affect on the rest of the system I might
suggest doing the query and sending the results either to a temp in
memory java structure or a temporary table so that you hold locks on
the system catalog for a little as possible.  This may mean that you
have to handle errors if ddl in your system from other threads is such
that tables might disappear from the time you gathered the list and when
you do the compress.



Sai Pullabhotla wrote:

> Hello,
>
> Our application using Derby 10.4 (in embedded mode) has a background process
> that runs the SYSCS_UTIL.SYSCS_COMPRESS_TABLE procedure periodically. We
> have been reported the following error while this procedure is being
> executed and a SELECT statement came in at the same time:
>
> com.linoma.dpa.dao.DAOException: The conglomerate (71,409) requested does
> not exist.
> com.linoma.dpa.runtime.JobFailedException: com.linoma.dpa.dao.DAOException:
> The conglomerate (71,409) requested does not exist.
>    at com.linoma.dpa.runtime.Job.checkLogin(Unknown Source)
>    at com.linoma.dpa.runtime.Job.run(Unknown Source)
>    at com.linoma.dpa.runtime.Runtime.executeProject(Unknown Source)
>    at com.linoma.dpa.runtime.Runtime.executeProject(Unknown Source)
>    at com.linoma.dpa.j2ee.RunProjectCommandServlet.doPost(Unknown Source)
>    at javax.servlet.http.HttpServlet.service(HttpServlet.java:637)
>    at javax.servlet.http.HttpServlet.service(HttpServlet.java:717)
>    at
> org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290)
>    at
> org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
>    at com.linoma.dpa.security.SecurityFilter.doFilter(Unknown Source)
>    at
> org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
>    at
> org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
>    at
> org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:233)
>    at
> org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191)
>    at
> org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:128)
>    at
> org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102)
>    at
> org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109)
>    at
> org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:286)
>    at
> org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:845)
>    at
> org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:583)
>    at
> org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:447)
>    at java.lang.Thread.run(Thread.java:810)
> Caused by: com.linoma.dpa.security.LoginException:
> com.linoma.dpa.dao.DAOException: The conglomerate (71,409) requested does
> not exist.
>    at com.linoma.dpa.security.LoginUtilities.getUserDetails(Unknown
> Source)
>    ... 22 more
> Caused by: com.linoma.dpa.dao.DAOException: The conglomerate (71,409)
> requested does not exist.
>    at com.linoma.dpa.dao.rdbms.UserDAOImpl.getConsolidatedRoles(Unknown
> Source)
>    at com.linoma.dpa.dao.rdbms.UserDAOImpl.findUser(Unknown Source)
>    ... 23 more
> Caused by: java.sql.SQLException: The conglomerate (71,409) requested does
> not exist.
>    at
> org.apache.derby.impl.jdbc.SQLExceptionFactory.getSQLException(Unknown
> Source)
>    at org.apache.derby.impl.jdbc.Util.generateCsSQLException(Unknown
> Source)
>    at
> org.apache.derby.impl.jdbc.TransactionResourceImpl.wrapInSQLException(Unknown
> Source)
>    at
> org.apache.derby.impl.jdbc.TransactionResourceImpl.handleException(Unknown
> Source)
>    at org.apache.derby.impl.jdbc.EmbedConnection.handleException(Unknown
> Source)
>    at org.apache.derby.impl.jdbc.ConnectionChild.handleException(Unknown
> Source)
>    at org.apache.derby.impl.jdbc.EmbedStatement.executeStatement(Unknown
> Source)
>    at
> org.apache.derby.impl.jdbc.EmbedPreparedStatement.executeStatement(Unknown
> Source)
>    at
> org.apache.derby.impl.jdbc.EmbedPreparedStatement.executeQuery(Unknown
> Source)
>    at
> org.apache.tomcat.dbcp.dbcp.DelegatingPreparedStatement.executeQuery(DelegatingPreparedStatement.java:93)
>    ... 25 more
> Caused by: ERROR XSAI2: The conglomerate (71,409) requested does not exist.
>    at org.apache.derby.iapi.error.StandardException.newException(Unknown
> Source)
>    at
> org.apache.derby.impl.store.access.btree.index.B2IFactory.readConglomerate(Unknown
> Source)
>    at
> org.apache.derby.impl.store.access.RAMAccessManager.conglomCacheFind(Unknown
> Source)
>    at
> org.apache.derby.impl.store.access.RAMTransaction.findExistingConglomerate(Unknown
> Source)
>    at org.apache.derby.impl.store.access.RAMTransaction.openScan(Unknown
> Source)
>    at
> org.apache.derby.impl.store.access.BackingStoreHashTableFromScan.<init>(Unknown
> Source)
>    at
> org.apache.derby.impl.store.access.RAMTransaction.createBackingStoreHashtableFromScan(Unknown
> Source)
>    at org.apache.derby.impl.sql.execute.HashScanResultSet.openCore(Unknown
> Source)
>    at org.apache.derby.impl.sql.execute.JoinResultSet.openRight(Unknown
> Source)
>    at org.apache.derby.impl.sql.execute.JoinResultSet.openCore(Unknown
> Source)
>    at org.apache.derby.impl.sql.execute.JoinResultSet.openCore(Unknown
> Source)
>    at
> org.apache.derby.impl.sql.execute.ProjectRestrictResultSet.openCore(Unknown
> Source)
>    at
> org.apache.derby.impl.sql.execute.UnionResultSet.getNextRowCore(Unknown
> Source)
>    at
> org.apache.derby.impl.sql.execute.SortResultSet.getRowFromResultSet(Unknown
> Source)
>    at
> org.apache.derby.impl.sql.execute.SortResultSet.getNextRowFromRS(Unknown
> Source)
>    at org.apache.derby.impl.sql.execute.SortResultSet.loadSorter(Unknown
> Source)
>    at org.apache.derby.impl.sql.execute.SortResultSet.openCore(Unknown
> Source)
>    at org.apache.derby.impl.sql.execute.SortResultSet.openCore(Unknown
> Source)
>    at
> org.apache.derby.impl.sql.execute.BasicNoPutResultSetImpl.open(Unknown
> Source)
>    at org.apache.derby.impl.sql.GenericPreparedStatement.execute(Unknown
> Source)
>    ... 29 more
>
> I'm not sure if this is expected or not. I would like to know if it is (or
> is not) recommended to run the SYSCS_UTIL.SYSCS_COMPRESS_TABLE procedure
> during the normal operation of an application. What kind of locks are
> acquired during the execution of this procedure? The documentation says -
>
> This procedure acquires an exclusive table lock on the table being
> compressed.
> All statement plans dependent on the table or its indexes are invalidated.
> (I'm not sure what exactly this means).
>
> The important thing to note is - all other subsequent SELECT queries after
> the compression was done have also failed with the same exact error
> referring to same conglomerate. We had to restart the database/application
> to fix the issue. Is this something expected too? Or is this something to do
> with the state of my connection in the connection pool.
>
> We perform the following procedure to compress all the tables:
>
>         String sql = "select schemaname, tablename from sys.sysschemas s, "
>             + "sys.systables t where s.schemaid=t.schemaid and
> t.tabletype='T'";
>         Statement stmt = conn.createStatement();
>         ResultSet rs = null;
>         CallableStatement cs = null;
>         try {
>             rs = stmt.executeQuery(sql);
>             cs = conn.prepareCall("call SYSCS_UTIL.SYSCS_COMPRESS_TABLE(?,
> ?, ?)");
>             while (rs.next()) {
>                 String schema = rs.getString(1).trim();
>                 String table = rs.getString(2).trim();
>                 cs.setString(1, schema);
>                 cs.setString(2, table);
>                 cs.setShort(3, (short) 1);
>                 cs.execute();
>             }
>         }
>
> Your help/feedback is greatly appreciated.
>
> Thanks.

[Sai Pullabhotla]

Kathey,

Thanks for replying. This error occurred on a production system at a customer's site and the stack trace I posted is what I've  available. Since the customer restarted the app, by the time we got the derby.log, it was empty (I guess the log is overwritten everytime?).

Here is the sequence on what happened when the failure occurred:

6/3/09 12:04:58 AM            INFO      Preparing to backup the database
6/3/09 12:05:14 AM            INFO      Database was successfully backed up to /linoma/goanywhere/userdata/database/backups/2009-06-03.zip.
6/3/09 12:05:14 AM            INFO      Backup operation took 16 seconds.
6/3/09 12:05:14 AM            INFO      Compressing and performance tuning the database tables...
6/3/09 12:05:39 AM            INFO      Job 1243782054134 started for project '/PTP Tax Upload'
6/3/09 12:05:40 AM            ERROR     Job 1243782054134 completed with an error
                                        com.linoma.dpa.dao.DAOException: The conglomerate (71,409) requested does not exist.
[STACK TRACE OMMITTED AS IT WAS POSTED IN THE ORIGINAL POST]
6/3/09 12:05:43 AM            INFO      Database compression completed successfully.  Operation took 28 seconds.
6/3/09 12:05:43 AM            INFO      Verifying the database consistency...
6/3/09 12:05:49 AM            INFO      Database consistency check completed successfully. Operation took 5 seconds.
6/3/09 12:10:39 AM            INFO      Job 1243782054135 started for project '/PTP Tax Upload'
6/3/09 12:10:39 AM            ERROR     Job 1243782054135 completed with an error
                                        com.linoma.dpa.dao.DAOException: The conglomerate (71,409) requested does not exist.
[SEVERAL JOBS FAILED WITH THE SAME EXCEPTION UNTIL THE SYSTEM WAS RESTARTED]

As you can see, we first did a backup using the stored procedure - SYSCS_UTIL.SYSCS_BACKUP_DATABASE.
Then we started the compression of all the tables... while the tables are being compressed, a SELECT statement was executed because of a job submission. This SELECT errored out. Then the compression completed normally. Then we performed a database consistency check using the following statement:

SELECT
    schemaname || '.' || tablename as TableName,
    SYSCS_UTIL.SYSCS_CHECK_TABLE(schemaname, tablename) AS OK
FROM
    sys.sysschemas s, sys.systables t
WHERE
    s.schemaid = t.schemaid and t.tabletype = 'T'

The consistency check succeeded with no issues. All subsequent queries failed with the same error until the app was restarted.

The isolation level is READ_COMMITTED (2).

I will try to see if I can reproduce the error here and send you any additional logs.

Sai Pullabhotla
www.jMethods.com

On Fri, Jun 5, 2009 at 1:25 PM, Kathey Marsden <kmarsdenderby@...> wrote:

Sai Pullabhotla wrote:

Hello,

 

Hello and thank you for reporting this issue.

Our application using Derby 10.4 (in embedded mode) has a background process
that runs the SYSCS_UTIL.SYSCS_COMPRESS_TABLE procedure periodically. We
have been reported the following error while this procedure is being
executed and a SELECT statement came in at the same time:

       com.linoma.dpa.dao.DAOException: The conglomerate (71,409) requested does
not exist.
 

Mike just fixed a corruption issue related to inplace compress,https://issues.apache.org/jira/browse/DERBY-4239  but my understanding is that it should not be an issue with offline compress and also I would expect your database to be unbootable even after you completely shutdown your application and Derby.    Can you
1) Post the full nested stack trace from the derby.log.
2) Run a consistency check on your database. http://wiki.apache.org/db-derby/DatabaseConsistencyCheck
4) Tell us the isolation level of your select statement.
3)   Modify the reproduction attached to DERBY-4239 https://issues.apache.org/jira/secure/attachment/12408948/reproBackgroundCheckpoint.zip
to use SYCS_UTIL.SYSCS_COMPRESS_TABLE and see if you can reproduce your issue.  You might need to modify it to add in a select.


Thanks

Kathey

[Kathey Marsden]

Sai Pullabhotla wrote:
> Since the customer restarted the app, by the time we got the
> derby.log, it was empty (I guess the log is overwritten everytime?).
It does unless unless you set this property:
http://db.apache.org/derby/docs/10.5/ref/rrefproper13217.html#rrefproper13217
> I will try to see if I can reproduce the error here and send you any
> additional logs.
>
It looks like you have a good understanding of what was going on at the
time, so hopefully you can come up with a reproduction.   Even if you
cannot, post what you have tried and perhaps someone can offer some
suggestions or tweak it to pop the bug.

Kathey

[Sai Pullabhotla]

Attached are a couple of test programs to reproduce the error with Derby 10.4.1.3 in embedded mode:

CompressDBTest1.java - tries to read a table while it is being compressed. The select statement errors out with the following error:
java.sql.SQLException: Container 2,192 not found.
Subsequent SELECTs with a brand new connection also fail with a little bit different error:
The conglomerate (2,192) requested does not exist.

CompressDBTest2.java - tries to insert data into a table while it is being compressed. The insert errors out eventually with the following error:
A lock could not be obtained due to a deadlock, cycle of locks and waiters is:
Lock : TABLE, TEST, Tablelock
  Waiting XID : {236439, IX} , APP, insert into test values(?, ?, ?, ?, ?)
  Granted XID : {234342, X}
Lock : ROW, SYSCONGLOMERATES, (5,14)
  Waiting XID : {234342, X} , APP, alter table "APP"."TEST" compress sequential
  Granted XID : {234342, S} , {236439, S}
. The selected victim is XID : 236439.

What the test classes do:

Both classes first create a database named test under the current working directory if a directory named test does not already exist. Then a table named test is created and populated with 100,000 random records. Two threads are started then with the first one repeatedly compressing the test table and the second one repeatedly executing a DML statement. If the DML statement errors out, the compression thread will be stopped. Finally the database is shutdown. The standard output of the program goes to stdout.log and standard error goes to stderr.log in the current working directory.

In my tests, it did not take more than 10 to 20 seconds to see the error(s). Hope this helps. Please let me know if you have any questions or need additional information.

On a side note, no exceptions or errors are reported in the derby.log. All I see is the booting info and the shutdown info.

Regards,

Sai Pullabhotla
www.jMethods.com

On Fri, Jun 5, 2009 at 2:44 PM, Kathey Marsden <kmarsdenderby@...> wrote:

Sai Pullabhotla wrote:

Since the customer restarted the app, by the time we got the derby.log, it was empty (I guess the log is overwritten everytime?).

It does unless unless you set this property: http://db.apache.org/derby/docs/10.5/ref/rrefproper13217.html#rrefproper13217

I will try to see if I can reproduce the error here and send you any additional logs.

It looks like you have a good understanding of what was going on at the time, so hopefully you can come up with a reproduction.   Even if you cannot, post what you have tried and perhaps someone can offer some suggestions or tweak it to pop the bug.

Kathey

[CompressDBTest1.java]

---

import java.io.File;
import java.io.FileNotFoundException;
import java.io.FileOutputStream;
import java.io.PrintStream;
import java.sql.CallableStatement;
import java.sql.Connection;
import java.sql.Date;
import java.sql.DriverManager;
import java.sql.PreparedStatement;
import java.sql.ResultSet;
import java.sql.SQLException;
import java.sql.Statement;
import java.sql.Timestamp;
import java.text.SimpleDateFormat;
import java.util.Random;

/**
 * A test program for reproducing the concurrency issue with database
 * compression procedure and DML statements.
 *
 * @author Sai Pullabhotla
 * @version $Revision: 1.1 $
 *
 */

public class CompressDBTest1 {

        /**
         * A random number generator to populate random data
         */
        private static Random random = null;

        /**
         * Database URL
         */
        private static final String DB_URL = "jdbc:derby:test";

        /**
         * Flag to indicate if either of the threads errored out.
         */
        private static boolean error = false;

        /**
         * Entry point for the program.
         *
         * @param args
         *            command line arguments
         * @throws ClassNotFoundException
         *             propagated
         * @throws SQLException
         *             propagated
         * @throws FileNotFoundException
         *             propagated
         */
        public static void main(String[] args) throws ClassNotFoundException,
                SQLException, FileNotFoundException {
                System.out.println("stdout is being redirected to stdout.log and stderr is being redirected to stderr.log. ");
                FileOutputStream stdout = new FileOutputStream("stdout.log");
                System.setOut(new PrintStream(stdout));
                FileOutputStream stderr = new FileOutputStream("stderr.log");
                System.setErr(new PrintStream(stderr));
                Thread.currentThread().setName("MainThread       ");
                init();
                File dbDir = new File("test");
                if (!dbDir.exists()) {
                        createDB();
                        populateTable();
                }
                else {
                        log("Database 'test' already exists");
                }
                CompressionThread compressionThread = new CompressionThread();
                compressionThread.start();
                SelectThread selectThread = new SelectThread();
                selectThread.start();
                try {
                        compressionThread.join();
                        selectThread.join();
                }
                catch (InterruptedException exp) {
                        log(exp);
                }
                shutdownDB();
        }

        /**
         * Initializes this program.
         *
         * @throws ClassNotFoundException
         *             propagated
         */
        private static void init() throws ClassNotFoundException {
                log("Initializing...");
                Class.forName("org.apache.derby.jdbc.EmbeddedDriver");
                random = new Random();
        }

        /**
         * Creates a database named test under the current working directory. Also
         * creates a table called test under the database.
         *
         * @throws SQLException
         *             propagated
         */
        private static void createDB() throws SQLException {
                log("Creating database 'test'...");
                Connection con = null;
                Statement stmt = null;
                try {
                        con = DriverManager.getConnection(DB_URL + ";create=true");
                        log("Database 'test' was created successfully");
                        log("Creating table 'test'...");
                        String sql = "create table test(col_int integer, col_char char(20), "
                                + "col_decimal decimal(10, 2), col_date date, col_timestamp timestamp)";
                        stmt = con.createStatement();
                        stmt.executeUpdate(sql);
                        log("Table 'test' was created successfully");
                }
                finally {
                        if (stmt != null) {
                                stmt.close();
                        }
                        if (con != null) {
                                con.close();
                        }
                }
        }

        /**
         * Populates the test table with random data.
         *
         * @throws SQLException
         *             propagated
         */
        private static void populateTable() throws SQLException {
                log("Populating table test with random data...");
                Connection con = DriverManager.getConnection(DB_URL);
                String sql = "insert into test values(?, ?, ?, ?, ?)";
                PreparedStatement stmt = con.prepareStatement(sql);
                int count = 0;
                int rowsNeeded = 100000;
                int updateCount = 0;
                while (count++ < rowsNeeded) {
                        stmt.setInt(1, getRandomInt());
                        stmt.setString(2, getRandomString(20));
                        stmt.setDouble(3, getRandomDecimal());
                        stmt.setDate(4, new Date(System.currentTimeMillis()));
                        stmt.setTimestamp(5, new Timestamp(System.currentTimeMillis()));
                        updateCount += stmt.executeUpdate();
                }
                stmt.close();
                con.close();
                log(updateCount + " record(s) were inserted");
        }

        /**
         * Returns a random integer.
         *
         * @return a random integer.
         */
        private static int getRandomInt() {
                return random.nextInt();
        }

        /**
         * Returns a random string of given length.
         *
         * @param length
         *            the length of the string
         * @return a random string of given length.
         */
        private static String getRandomString(int length) {
                StringBuilder buffer = new StringBuilder(length);
                for (int i = 0; i < length; i++) {
                        int ch = random.nextInt(26);
                        ch += 65;
                        buffer.append((char) ch);
                }
                return buffer.toString();
        }

        /**
         * Returns a random decimal number of size (10, 2).
         *
         * @return a random decimal number of size (10, 2).
         */
        private static double getRandomDecimal() {
                int val = random.nextInt(99999999);
                int precision = random.nextInt(99);
                return val + (precision / 100.0);
        }

        /**
         * Attempts to shutdown the database.
         */
        private static void shutdownDB() {
                log("Shutting down the databse...");
                try {
                        DriverManager.getConnection(DB_URL + ";shutdown=true");
                }
                catch (SQLException exp) {
                        log(exp);
                }
        }

        /**
         * A thread the constantly compresses the test table.
         *
         * @author Sai Pullabhotla
         * @version $Revision: 1.1 $
         *
         */
        private static class CompressionThread extends Thread {

                /**
                 * Creates a new instance of <code>CompressionThread</code>.
                 */
                public CompressionThread() {
                        super("CompressionThread");
                }

                @Override
                public void run() {
                        Connection con = null;
                        CallableStatement stmt = null;
                        for (int i = 0; i < 1000; i++) {
                                if (error) {
                                        break;
                                }
                                try {
                                        con = DriverManager.getConnection(DB_URL);
                                        stmt = con.prepareCall("call SYSCS_UTIL.SYSCS_COMPRESS_TABLE(?, ?, ?)");
                                        log("Comressing table 'TEST'...");
                                        stmt.setString(1, "APP");
                                        stmt.setString(2, "TEST");
                                        stmt.setShort(3, (short) 1);
                                        stmt.execute();
                                        log("Table 'TEST' was compressed successfully");
                                }
                                catch (SQLException exp) {
                                        error = true;
                                        log(exp);
                                }
                                finally {
                                        if (stmt != null) {
                                                try {
                                                        stmt.close();
                                                }
                                                catch (SQLException exp) {
                                                        log(exp);
                                                }
                                        }
                                        if (con != null) {
                                                try {
                                                        con.close();
                                                }
                                                catch (SQLException exp) {
                                                        log(exp);
                                                }
                                        }
                                }
                        }
                }
        }

        /**
         * A thread for querying the database table while it is being compressed.
         *
         * @author Sai Pullabhotla
         * @version $Revision: 1.1 $
         *
         */
        private static class SelectThread extends Thread {

                /**
                 * Creates a new instance of <code>SelectThread</code>.
                 */
                public SelectThread() {
                        super("SelectThread     ");
                }

                @Override
                public void run() {
                        Connection con = null;
                        PreparedStatement stmt = null;
                        final String sql = "select * from test where col_int=?";
                        for (int i = 0; i < 1000; i++) {
                                // if (error) {
                                // break;
                                // }

                                try {
                                        con = DriverManager.getConnection(DB_URL);
                                        stmt = con.prepareStatement(sql);
                                        int searchFor = getRandomInt();
                                        stmt.setInt(1, searchFor);
                                        ResultSet rs = stmt.executeQuery();
                                        if (!rs.next()) {
                                                log("No record(s) found matching the ID: " + searchFor);
                                        }
                                        else {
                                                log("At least one record exists with ID: " + searchFor);
                                        }
                                        rs.close();
                                }
                                catch (SQLException exp) {
                                        log(exp);
                                        error = true;
                                }
                                finally {
                                        if (stmt != null) {
                                                try {
                                                        stmt.close();
                                                }
                                                catch (SQLException exp) {
                                                        log(exp);
                                                }
                                        }
                                        if (con != null) {
                                                try {
                                                        con.close();
                                                }
                                                catch (SQLException exp) {
                                                        log(exp);
                                                }
                                        }
                                }
                        }
                }
        }

        /**
         * Logs the given message with the timestamp information and the thread that
         * called for this message to be logged.
         *
         * @param message
         *            the message to be logged.
         */
        private static synchronized void log(String message) {
                SimpleDateFormat formatter = new SimpleDateFormat(
                        "MM/dd/yyyy HH:mm:ss.SSS");
                System.out.print(formatter.format(new java.util.Date()));
                System.out.print("    ");
                System.out.print(Thread.currentThread().getName());
                System.out.print("    ");
                System.out.print(message);
                System.out.println();
        }

        /**
         * Logs the given message with the timestamp information and the thread that
         * called for this message to be logged.
         *
         * @param t
         *            the exception to be logged
         */
        private static synchronized void log(Throwable t) {
                log(t.getMessage());
                log("See the stderr.log for the stacktrace of the above exception");
                t.printStackTrace();
        }

}

---

[CompressDBTest2.java]

---

import java.io.File;
import java.io.FileNotFoundException;
import java.io.FileOutputStream;
import java.io.PrintStream;
import java.sql.CallableStatement;
import java.sql.Connection;
import java.sql.Date;
import java.sql.DriverManager;
import java.sql.PreparedStatement;
import java.sql.SQLException;
import java.sql.Statement;
import java.sql.Timestamp;
import java.text.SimpleDateFormat;
import java.util.Random;

/**
 * A test program for reproducing the concurrency issue with database
 * compression procedure and DML statements.
 *
 * @author Sai Pullabhotla
 * @version $Revision: 1.1 $
 *
 */

public class CompressDBTest2 {

        /**
         * A random number generator to populate random data
         */
        private static Random random = null;

        /**
         * Database URL
         */
        private static final String DB_URL = "jdbc:derby:test";

        /**
         * Flag to indicate if the DML thread errored out.
         */
        private static boolean error = false;

        /**
         * Entry point for the program.
         *
         * @param args
         *            command line arguments
         * @throws ClassNotFoundException
         *             propagated
         * @throws SQLException
         *             propagated
         * @throws FileNotFoundException
         *             propagated
         */
        public static void main(String[] args) throws ClassNotFoundException,
                SQLException, FileNotFoundException {
                System.out.println("stdout is being redirected to stdout.log and stderr is being redirected to stderr.log. ");
                FileOutputStream stdout = new FileOutputStream("stdout.log");
                System.setOut(new PrintStream(stdout));
                FileOutputStream stderr = new FileOutputStream("stderr.log");
                System.setErr(new PrintStream(stderr));
                Thread.currentThread().setName("MainThread       ");
                init();
                File dbDir = new File("test");
                if (!dbDir.exists()) {
                        createDB();
                        populateTable();
                }
                else {
                        log("Database 'test' already exists");
                }
                CompressionThread compressionThread = new CompressionThread();
                compressionThread.start();
                InsertThread selectThread = new InsertThread();
                selectThread.start();
                try {
                        compressionThread.join();
                        selectThread.join();
                }
                catch (InterruptedException exp) {
                        log(exp);
                }
                shutdownDB();
        }

        /**
         * Initializes this program.
         *
         * @throws ClassNotFoundException
         *             propagated
         */
        private static void init() throws ClassNotFoundException {
                log("Initializing...");
                Class.forName("org.apache.derby.jdbc.EmbeddedDriver");
                random = new Random();
        }

        /**
         * Creates a database named test under the current working directory. Also
         * creates a table called test under the database.
         *
         * @throws SQLException
         *             propagated
         */
        private static void createDB() throws SQLException {
                log("Creating database 'test'...");
                Connection con = null;
                Statement stmt = null;
                try {
                        con = DriverManager.getConnection(DB_URL + ";create=true");
                        log("Database 'test' was created successfully");
                        log("Creating table 'test'...");
                        String sql = "create table test(col_int integer, col_char char(20), "
                                + "col_decimal decimal(10, 2), col_date date, col_timestamp timestamp)";
                        stmt = con.createStatement();
                        stmt.executeUpdate(sql);
                        log("Table 'test' was created successfully");
                }
                finally {
                        if (stmt != null) {
                                stmt.close();
                        }
                        if (con != null) {
                                con.close();
                        }
                }
        }

        /**
         * Populates the test table with random data.
         *
         * @throws SQLException
         *             propagated
         */
        private static void populateTable() throws SQLException {
                log("Populating table test with random data...");
                Connection con = DriverManager.getConnection(DB_URL);
                String sql = "insert into test values(?, ?, ?, ?, ?)";
                PreparedStatement stmt = con.prepareStatement(sql);
                int count = 0;
                int rowsNeeded = 100000;
                int updateCount = 0;
                while (count++ < rowsNeeded) {
                        stmt.setInt(1, getRandomInt());
                        stmt.setString(2, getRandomString(20));
                        stmt.setDouble(3, getRandomDecimal());
                        stmt.setDate(4, new Date(System.currentTimeMillis()));
                        stmt.setTimestamp(5, new Timestamp(System.currentTimeMillis()));
                        updateCount += stmt.executeUpdate();
                }
                stmt.close();
                con.close();
                log(updateCount + " record(s) were inserted");
        }

        /**
         * Returns a random integer.
         *
         * @return a random integer.
         */
        private static int getRandomInt() {
                return random.nextInt();
        }

        /**
         * Returns a random string of given length.
         *
         * @param length
         *            the length of the string
         * @return a random string of given length.
         */
        private static String getRandomString(int length) {
                StringBuilder buffer = new StringBuilder(length);
                for (int i = 0; i < length; i++) {
                        int ch = random.nextInt(26);
                        ch += 65;
                        buffer.append((char) ch);
                }
                return buffer.toString();
        }

        /**
         * Returns a random decimal number of size (10, 2).
         *
         * @return a random decimal number of size (10, 2).
         */
        private static double getRandomDecimal() {
                int val = random.nextInt(99999999);
                int precision = random.nextInt(99);
                return val + (precision / 100.0);
        }

        /**
         * Attempts to shutdown the database.
         */
        private static void shutdownDB() {
                log("Shutting down the databse...");
                try {
                        DriverManager.getConnection(DB_URL + ";shutdown=true");
                }
                catch (SQLException exp) {
                        log(exp);
                }
        }

        /**
         * A thread the constantly compresses the test table.
         *
         * @author Sai Pullabhotla
         * @version $Revision: 1.1 $
         *
         */
        private static class CompressionThread extends Thread {

                /**
                 * Creates a new instance of <code>CompressionThread</code>.
                 */
                public CompressionThread() {
                        super("CompressionThread");
                }

                @Override
                public void run() {
                        Connection con = null;
                        CallableStatement stmt = null;
                        for (int i = 0; i < 1000; i++) {
                                if (error) {
                                        break;
                                }
                                try {
                                        con = DriverManager.getConnection(DB_URL);
                                        stmt = con.prepareCall("call SYSCS_UTIL.SYSCS_COMPRESS_TABLE(?, ?, ?)");
                                        log("Comressing table 'TEST'...");
                                        stmt.setString(1, "APP");
                                        stmt.setString(2, "TEST");
                                        stmt.setShort(3, (short) 1);
                                        stmt.execute();
                                        log("Table 'TEST' was compressed successfully");
                                }
                                catch (SQLException exp) {
                                        error = true;
                                        log(exp);
                                }
                                finally {
                                        if (stmt != null) {
                                                try {
                                                        stmt.close();
                                                }
                                                catch (SQLException exp) {
                                                        log(exp);
                                                }
                                        }
                                        if (con != null) {
                                                try {
                                                        con.close();
                                                }
                                                catch (SQLException exp) {
                                                        log(exp);
                                                }
                                        }
                                }
                        }
                }
        }

        /**
         * A thread for inserting records into the database table while it is being
         * compressed.
         *
         * @author Sai Pullabhotla
         * @version $Revision: 1.1 $
         *
         */
        private static class InsertThread extends Thread {

                /**
                 * Creates a new instance of <code>SelectThread</code>.
                 */
                public InsertThread() {
                        super("InsertThread     ");
                }

                @Override
                public void run() {
                        try {
                                populateTable();
                        }
                        catch (SQLException exp) {
                                error = true;
                                log(exp);
                        }
                }
        }

        /**
         * Logs the given message with the timestamp information and the thread that
         * called for this message to be logged.
         *
         * @param message
         *            the message to be logged.
         */
        private static synchronized void log(String message) {
                SimpleDateFormat formatter = new SimpleDateFormat(
                        "MM/dd/yyyy HH:mm:ss.SSS");
                System.out.print(formatter.format(new java.util.Date()));
                System.out.print("    ");
                System.out.print(Thread.currentThread().getName());
                System.out.print("    ");
                System.out.print(message);
                System.out.println();
        }

        /**
         * Logs the given message with the timestamp information and the thread that
         * called for this message to be logged.
         *
         * @param t
         *            the exception to be logged
         */
        private static synchronized void log(Throwable t) {
                log(t.getMessage());
                log("See the stderr.log for the stacktrace of the above exception");
                t.printStackTrace();
        }

}

---

[Knut Anders Hatlen]

Sai Pullabhotla <sai.pullabhotla@...> writes:

> Attached are a couple of test programs to reproduce the error with Derby
> 10.4.1.3 in embedded mode:
>
> CompressDBTest1.java - tries to read a table while it is being compressed. The
> select statement errors out with the following error:
> java.sql.SQLException: Container 2,192 not found.
> Subsequent SELECTs with a brand new connection also fail with a little bit
> different error:
> The conglomerate (2,192) requested does not exist.

There's some discussion about a similar problem in this bug report:
https://issues.apache.org/jira/browse/DERBY-637

The reporter of that bug did not mention that the table had been
compressed, but others have commented on the bug saying they have seen
the same error message after SYSCS_COMPRESS_TABLE.

--
Knut Anders

[Sai Pullabhotla]

Has any of the developers looked into this to see if it can be fixed easily? If not, I will look into working around this issue (not sure at this time what can be done).

Thanks for your time and feedback.

Regards,

Sai Pullabhotla
www.jMethods.com

[Kathey Marsden]

Sai Pullabhotla wrote:
> Has any of the developers looked into this to see if it can be fixed
> easily? If not, I will look into working around this issue (not sure
> at this time what can be done).
Even though the error in DERBY-637 looks similar, I think you should
file a new issue and attach your reproduction.    I don't see that a
compress was involved and it looks like the error in DERBY-637 comes
from a system table which I don't think can be compressed.  Regardless,  
we could close DERBY-637 as a dup if  that ends up to be the case.'

See http://db.apache.org/derby/DerbyBugGuidelines.html for instructions
on filing a bug.
Please click grant license to Apache for your reproduction.

Once the bug is filed it is much more likely someone will pick it up but
I can't say who or when that will be.

Kathey