Return-Path: Delivered-To: apmail-db-derby-user-archive@www.apache.org Received: (qmail 17462 invoked from network); 10 Oct 2006 17:30:53 -0000 Received: from hermes.apache.org (HELO mail.apache.org) (209.237.227.199) by minotaur.apache.org with SMTP; 10 Oct 2006 17:30:53 -0000 Received: (qmail 87132 invoked by uid 500); 10 Oct 2006 17:30:52 -0000 Delivered-To: apmail-db-derby-user-archive@db.apache.org Received: (qmail 87106 invoked by uid 500); 10 Oct 2006 17:30:51 -0000 Mailing-List: contact derby-user-help@db.apache.org; run by ezmlm Precedence: bulk list-help: list-unsubscribe: List-Post: List-Id: Reply-To: "Derby Discussion" Delivered-To: mailing list derby-user@db.apache.org Received: (qmail 87095 invoked by uid 99); 10 Oct 2006 17:30:51 -0000 Received: from asf.osuosl.org (HELO asf.osuosl.org) (140.211.166.49) by apache.org (qpsmtpd/0.29) with ESMTP; Tue, 10 Oct 2006 10:30:51 -0700 X-ASF-Spam-Status: No, hits=1.9 required=10.0 tests=DNS_FROM_RFC_ABUSE,DNS_FROM_RFC_POST X-Spam-Check-By: apache.org Received-SPF: neutral (asf.osuosl.org: local policy) Received: from [32.97.182.146] (HELO e6.ny.us.ibm.com) (32.97.182.146) by apache.org (qpsmtpd/0.29) with ESMTP; Tue, 10 Oct 2006 10:30:50 -0700 Received: from d01relay02.pok.ibm.com (d01relay02.pok.ibm.com [9.56.227.234]) by e6.ny.us.ibm.com (8.13.8/8.12.11) with ESMTP id k9AHUcp8015493 for ; Tue, 10 Oct 2006 13:30:38 -0400 Received: from d01av03.pok.ibm.com (d01av03.pok.ibm.com [9.56.224.217]) by d01relay02.pok.ibm.com (8.13.6/8.13.6/NCO v8.1.1) with ESMTP id k9AHURNb265966 for ; Tue, 10 Oct 2006 13:30:27 -0400 Received: from d01av03.pok.ibm.com (loopback [127.0.0.1]) by d01av03.pok.ibm.com (8.12.11.20060308/8.13.3) with ESMTP id k9AHURWN031930 for ; Tue, 10 Oct 2006 13:30:27 -0400 Received: from [127.0.0.1] (dyn9-72-133-74.usca.ibm.com [9.72.133.74]) by d01av03.pok.ibm.com (8.12.11.20060308/8.12.11) with ESMTP id k9AHUPh2031683 for ; Tue, 10 Oct 2006 13:30:27 -0400 Message-ID: <452BD8AC.3080402@sbcglobal.net> Date: Tue, 10 Oct 2006 10:30:20 -0700 From: Mike Matrigali Reply-To: mikem_app@sbcglobal.net User-Agent: Mozilla Thunderbird 1.0 (Windows/20041206) X-Accept-Language: en-us, en MIME-Version: 1.0 To: Derby Discussion Subject: Re: SQLSTATE: XSDG0Page Page(7,Container(0, 848)) could not be read from disk. References: <45259FBC.8040200@nuix.com.au> <452681E1.4080206@sbcglobal.net> <452B1A44.4000604@nuix.com.au> In-Reply-To: <452B1A44.4000604@nuix.com.au> Content-Type: text/plain; charset=ISO-8859-1; format=flowed Content-Transfer-Encoding: 7bit X-Virus-Checked: Checked by ClamAV on apache.org X-Spam-Rating: minotaur.apache.org 1.6.2 0/1000/N David Sitsky wrote: > Hi Mike, > > As promised, I have spoken with the client, and have some more > interesting data. > > At the end of my message, are the contents of the derby.log file, which > seem to indicate that perhaps the seg0/c350.dat file has been truncated > somehow, due to the EOFException being thrown? The times I have seen this, the file hasn't actually been truncated. The problem has been some issue where the log thinks a page should be there but it never got to the file. For instance assuming 4k pages it looks like there are 3 pages and recovery is trying to redo work for page 7 but the page does not exist. This should not be possible in 10.1 as we always forced allocation of pages before logging inserts onto the new page. In 10.2 we relaxed the forcing, so allow redo to pages that "don't" exist - going ahead and allocating the pages. Which would explaing why the db recovered in 10.2. But this has the feeling of missing log records for some reason and thus missing data for the recovery. The question then becomes if the log records are totally missing or if for some reason redo recovery has picked the wrong start recovery place - since it looks like the db has all of the log records. Some causes in the past are: o DERBY-700 o DERBY-1838 o using durability=test mode o running on hardware that doesn't actually sync disk when asked o running separate jvm's on 2 machines accessing the same db across a networked file system. > > For what its worth, the size of the seg0/c350.dat file is 12288 bytes. > I've included the directory listing of the database files in this > message in case there is any useful information here. Do you know the page size of the table? Default is 4k unless there are some blob/clob columns, but size is user setable. > > What is interesting, is I get the same error messages if I try and open > the database with release 10.1.1.0 and 10.1.3.1. I tried opening it > with 10.2.1.6, and the database can be opened fine (no errors reported > in derby.log). Did you boot 10.2.1.6 with the upgrade=true flag or not? > > This database contains three tables, one with just a few rows, which has > been preserved, but the other two tables, according to the client, > should have just over 500 rows each. I am only seeing 154 and 159 rows > in them. > > I tried running SYSCS_UTIL.SYSCS_CHECK_TABLE on the tables with > 10.2.1.6, but they all returned 1 as a result. This mostly catches errors between indexes and base tables, and does check the internal consistency/checksum of all the pages of the table. > > Any ideas on what can be done here to try and recover more data? Many > thanks again for your help. If the data is not sensitive posting the db to a jira issue may help, sounds like db is not that big. > > Cheers, > David > > Contents of derby.log: > > ---------------------------------------------------------------- > 2006-10-10 01:12:20.250 GMT: > Booting Derby version The Apache Software Foundation - Apache Derby - > 10.1.1.0 - (exported): instance c013800d-010e-2fc6-fd20-000042d2819b > on database directory C:\work\........ > > > ------------ BEGIN SHUTDOWN ERROR STACK ------------- > > ERROR XSLA7: Cannot redo operation Page Operation: Page(7,Container(0, > 848)) pageVersion 64 : Insert : Slot=62 recordId=68 in the log. > at > org.apache.derby.iapi.error.StandardException.newException(StandardException.java:315) > > at > org.apache.derby.impl.store.raw.log.FileLogger.redo(FileLogger.java:1515) > at > org.apache.derby.impl.store.raw.log.LogToFile.recover(LogToFile.java:798) > at org.apache.derby.impl.store.raw.RawStore.boot(RawStore.java:323) > at > org.apache.derby.impl.services.monitor.BaseMonitor.boot(BaseMonitor.java:1987) > > at > org.apache.derby.impl.services.monitor.TopService.bootModule(TopService.java:290) > > at > org.apache.derby.impl.services.monitor.BaseMonitor.startModule(BaseMonitor.java:539) > > at > org.apache.derby.iapi.services.monitor.Monitor.bootServiceModule(Monitor.java:418) > > at > org.apache.derby.impl.store.access.RAMAccessManager.boot(RAMAccessManager.java:994) > > at > org.apache.derby.impl.services.monitor.BaseMonitor.boot(BaseMonitor.java:1987) > > at > org.apache.derby.impl.services.monitor.TopService.bootModule(TopService.java:290) > > at > org.apache.derby.impl.services.monitor.BaseMonitor.startModule(BaseMonitor.java:539) > > at > org.apache.derby.iapi.services.monitor.Monitor.bootServiceModule(Monitor.java:418) > > at > org.apache.derby.impl.db.BasicDatabase.bootStore(BasicDatabase.java:757) > at org.apache.derby.impl.db.BasicDatabase.boot(BasicDatabase.java:178) > at > org.apache.derby.impl.services.monitor.BaseMonitor.boot(BaseMonitor.java:1987) > > at > org.apache.derby.impl.services.monitor.TopService.bootModule(TopService.java:290) > > at > org.apache.derby.impl.services.monitor.BaseMonitor.bootService(BaseMonitor.java:1834) > > at > org.apache.derby.impl.services.monitor.BaseMonitor.startProviderService(BaseMonitor.java:1700) > > at > org.apache.derby.impl.services.monitor.BaseMonitor.findProviderAndStartService(BaseMonitor.java:1526) > > at > org.apache.derby.impl.services.monitor.BaseMonitor.startPersistentService(BaseMonitor.java:996) > > at > org.apache.derby.impl.services.monitor.BaseMonitor.startPersistentService(BaseMonitor.java:988) > > at > org.apache.derby.iapi.services.monitor.Monitor.startPersistentService(Monitor.java:533) > > at > org.apache.derby.impl.jdbc.EmbedConnection.bootDatabase(EmbedConnection.java:1551) > > at > org.apache.derby.impl.jdbc.EmbedConnection.(EmbedConnection.java:196) > at > org.apache.derby.impl.jdbc.EmbedConnection30.(EmbedConnection30.java:72) > > at > org.apache.derby.jdbc.Driver30.getNewEmbedConnection(Driver30.java:73) > at > org.apache.derby.jdbc.InternalDriver.connect(InternalDriver.java:183) > at java.sql.DriverManager.getConnection(DriverManager.java:525) > at java.sql.DriverManager.getConnection(DriverManager.java:193) > at ... > ============= begin nested exception, level (1) =========== > ERROR XSDG0: Page Page(7,Container(0, 848)) could not be read from disk. > at > org.apache.derby.iapi.error.StandardException.newException(StandardException.java:326) > > at > org.apache.derby.impl.store.raw.data.CachedPage.readPage(CachedPage.java:563) > > at > org.apache.derby.impl.store.raw.data.CachedPage.setIdentity(CachedPage.java:184) > > at > org.apache.derby.impl.services.cache.CachedItem.takeOnIdentity(CachedItem.java:235) > > at org.apache.derby.impl.services.cache.Clock.addEntry(Clock.java:798) > at org.apache.derby.impl.services.cache.Clock.find(Clock.java:303) > at > org.apache.derby.impl.store.raw.data.FileContainer.getAnyPage(FileContainer.java:2437) > > at > org.apache.derby.impl.store.raw.data.BaseContainer.getAnyPage(BaseContainer.java:473) > > at > org.apache.derby.impl.store.raw.data.BaseContainerHandle.getAnyPage(BaseContainerHandle.java:590) > > at > org.apache.derby.impl.store.raw.data.PageBasicOperation.findpage(PageBasicOperation.java:303) > > at > org.apache.derby.impl.store.raw.data.PageBasicOperation.needsRedo(PageBasicOperation.java:159) > > at > org.apache.derby.impl.store.raw.log.FileLogger.redo(FileLogger.java:1394) > at > org.apache.derby.impl.store.raw.log.LogToFile.recover(LogToFile.java:798) > at org.apache.derby.impl.store.raw.RawStore.boot(RawStore.java:323) > at > org.apache.derby.impl.services.monitor.BaseMonitor.boot(BaseMonitor.java:1987) > > at > org.apache.derby.impl.services.monitor.TopService.bootModule(TopService.java:290) > > at > org.apache.derby.impl.services.monitor.BaseMonitor.startModule(BaseMonitor.java:539) > > at > org.apache.derby.iapi.services.monitor.Monitor.bootServiceModule(Monitor.java:418) > > at > org.apache.derby.impl.store.access.RAMAccessManager.boot(RAMAccessManager.java:994) > > at > org.apache.derby.impl.services.monitor.BaseMonitor.boot(BaseMonitor.java:1987) > > at > org.apache.derby.impl.services.monitor.TopService.bootModule(TopService.java:290) > > at > org.apache.derby.impl.services.monitor.BaseMonitor.startModule(BaseMonitor.java:539) > > at > org.apache.derby.iapi.services.monitor.Monitor.bootServiceModule(Monitor.java:418) > > at > org.apache.derby.impl.db.BasicDatabase.bootStore(BasicDatabase.java:757) > at org.apache.derby.impl.db.BasicDatabase.boot(BasicDatabase.java:178) > at > org.apache.derby.impl.services.monitor.BaseMonitor.boot(BaseMonitor.java:1987) > > at > org.apache.derby.impl.services.monitor.TopService.bootModule(TopService.java:290) > > at > org.apache.derby.impl.services.monitor.BaseMonitor.bootService(BaseMonitor.java:1834) > > at > org.apache.derby.impl.services.monitor.BaseMonitor.startProviderService(BaseMonitor.java:1700) > > at > org.apache.derby.impl.services.monitor.BaseMonitor.findProviderAndStartService(BaseMonitor.java:1526) > > at > org.apache.derby.impl.services.monitor.BaseMonitor.startPersistentService(BaseMonitor.java:996) > > at > org.apache.derby.impl.services.monitor.BaseMonitor.startPersistentService(BaseMonitor.java:988) > > at > org.apache.derby.iapi.services.monitor.Monitor.startPersistentService(Monitor.java:533) > > at > org.apache.derby.impl.jdbc.EmbedConnection.bootDatabase(EmbedConnection.java:1551) > > at > org.apache.derby.impl.jdbc.EmbedConnection.(EmbedConnection.java:196) > at > org.apache.derby.impl.jdbc.EmbedConnection30.(EmbedConnection30.java:72) > > at > org.apache.derby.jdbc.Driver30.getNewEmbedConnection(Driver30.java:73) > at > org.apache.derby.jdbc.InternalDriver.connect(InternalDriver.java:183) > at java.sql.DriverManager.getConnection(DriverManager.java:525) > at java.sql.DriverManager.getConnection(DriverManager.java:193) > at ... > ============= end nested exception, level (1) =========== > ============= begin nested exception, level (2) =========== > java.io.EOFException > at java.io.RandomAccessFile.readFully(RandomAccessFile.java:373) > at > org.apache.derby.impl.store.raw.data.RAFContainer.readPage(RAFContainer.java:201) > > at > org.apache.derby.impl.store.raw.data.CachedPage.readPage(CachedPage.java:550) > > at > org.apache.derby.impl.store.raw.data.CachedPage.setIdentity(CachedPage.java:184) > > at > org.apache.derby.impl.services.cache.CachedItem.takeOnIdentity(CachedItem.java:235) > > at org.apache.derby.impl.services.cache.Clock.addEntry(Clock.java:798) > at org.apache.derby.impl.services.cache.Clock.find(Clock.java:303) > at > org.apache.derby.impl.store.raw.data.FileContainer.getAnyPage(FileContainer.java:2437) > > at > org.apache.derby.impl.store.raw.data.BaseContainer.getAnyPage(BaseContainer.java:473) > > at > org.apache.derby.impl.store.raw.data.BaseContainerHandle.getAnyPage(BaseContainerHandle.java:590) > > at > org.apache.derby.impl.store.raw.data.PageBasicOperation.findpage(PageBasicOperation.java:303) > > at > org.apache.derby.impl.store.raw.data.PageBasicOperation.needsRedo(PageBasicOperation.java:159) > > at > org.apache.derby.impl.store.raw.log.FileLogger.redo(FileLogger.java:1394) > at > org.apache.derby.impl.store.raw.log.LogToFile.recover(LogToFile.java:798) > at org.apache.derby.impl.store.raw.RawStore.boot(RawStore.java:323) > at > org.apache.derby.impl.services.monitor.BaseMonitor.boot(BaseMonitor.java:1987) > > at > org.apache.derby.impl.services.monitor.TopService.bootModule(TopService.java:290) > > at > org.apache.derby.impl.services.monitor.BaseMonitor.startModule(BaseMonitor.java:539) > > at > org.apache.derby.iapi.services.monitor.Monitor.bootServiceModule(Monitor.java:418) > > at > org.apache.derby.impl.store.access.RAMAccessManager.boot(RAMAccessManager.java:994) > > at > org.apache.derby.impl.services.monitor.BaseMonitor.boot(BaseMonitor.java:1987) > > at > org.apache.derby.impl.services.monitor.TopService.bootModule(TopService.java:290) > > at > org.apache.derby.impl.services.monitor.BaseMonitor.startModule(BaseMonitor.java:539) > > at > org.apache.derby.iapi.services.monitor.Monitor.bootServiceModule(Monitor.java:418) > > at > org.apache.derby.impl.db.BasicDatabase.bootStore(BasicDatabase.java:757) > at org.apache.derby.impl.db.BasicDatabase.boot(BasicDatabase.java:178) > at > org.apache.derby.impl.services.monitor.BaseMonitor.boot(BaseMonitor.java:1987) > > at > org.apache.derby.impl.services.monitor.TopService.bootModule(TopService.java:290) > > at > org.apache.derby.impl.services.monitor.BaseMonitor.bootService(BaseMonitor.java:1834) > > at > org.apache.derby.impl.services.monitor.BaseMonitor.startProviderService(BaseMonitor.java:1700) > > at > org.apache.derby.impl.services.monitor.BaseMonitor.findProviderAndStartService(BaseMonitor.java:1526) > > at > org.apache.derby.impl.services.monitor.BaseMonitor.startPersistentService(BaseMonitor.java:996) > > at > org.apache.derby.impl.services.monitor.BaseMonitor.startPersistentService(BaseMonitor.java:988) > > at > org.apache.derby.iapi.services.monitor.Monitor.startPersistentService(Monitor.java:533) > > at > org.apache.derby.impl.jdbc.EmbedConnection.bootDatabase(EmbedConnection.java:1551) > > at > org.apache.derby.impl.jdbc.EmbedConnection.(EmbedConnection.java:196) > at > org.apache.derby.impl.jdbc.EmbedConnection30.(EmbedConnection30.java:72) > > at > org.apache.derby.jdbc.Driver30.getNewEmbedConnection(Driver30.java:73) > at > org.apache.derby.jdbc.InternalDriver.connect(InternalDriver.java:183) > at java.sql.DriverManager.getConnection(DriverManager.java:525) > at java.sql.DriverManager.getConnection(DriverManager.java:193) > at ... > ============= end nested exception, level (2) =========== > > > ------------ END SHUTDOWN ERROR STACK ------------- > > > 2006-10-10 01:12:22.640 GMT: > Shutting down instance c013800d-010e-2fc6-fd20-000042d2819b > ---------------------------------------------------------------- > > Contents of seg0: > > 16/08/2006 11:08a 8,192 c10.dat > 16/08/2006 11:08a 8,192 c101.dat > 16/08/2006 11:08a 8,192 c111.dat > 16/08/2006 11:08a 8,192 c121.dat > 16/08/2006 11:08a 8,192 c130.dat > 16/08/2006 11:08a 8,192 c141.dat > 16/08/2006 11:08a 8,192 c150.dat > 16/08/2006 11:08a 8,192 c161.dat > 16/08/2006 11:08a 8,192 c171.dat > 16/08/2006 11:08a 24,576 c180.dat > 16/08/2006 11:08a 8,192 c191.dat > 16/08/2006 11:08a 8,192 c1a1.dat > 16/08/2006 11:08a 8,192 c1b1.dat > 16/08/2006 11:08a 8,192 c1c0.dat > 16/08/2006 11:08a 8,192 c1d1.dat > 16/08/2006 11:08a 8,192 c1e0.dat > 16/08/2006 11:08a 8,192 c1f1.dat > 16/08/2006 11:08a 24,576 c20.dat > 16/08/2006 11:08a 8,192 c200.dat > 16/08/2006 11:08a 8,192 c211.dat > 16/08/2006 11:08a 8,192 c221.dat > 16/08/2006 11:08a 151,552 c230.dat > 16/08/2006 11:08a 8,192 c241.dat > 16/08/2006 11:08a 12,288 c251.dat > 16/08/2006 11:08a 8,192 c260.dat > 16/08/2006 11:08a 8,192 c271.dat > 16/08/2006 11:08a 8,192 c281.dat > 16/08/2006 11:08a 8,192 c290.dat > 16/08/2006 11:08a 8,192 c2a1.dat > 16/08/2006 11:08a 8,192 c2b1.dat > 16/08/2006 11:08a 8,192 c2c1.dat > 16/08/2006 11:08a 8,192 c2d0.dat > 16/08/2006 11:08a 8,192 c2e1.dat > 16/08/2006 11:08a 8,192 c2f0.dat > 07/09/2006 10:48a 12,288 c300.dat > 16/08/2006 11:08a 8,192 c31.dat > 18/09/2006 04:55p 16,384 c311.dat > 22/08/2006 03:13p 8,192 c320.dat > 22/08/2006 03:13p 8,192 c331.dat > 22/08/2006 03:13p 8,192 c341.dat > 22/08/2006 03:13p 12,288 c350.dat > 12/09/2006 01:25p 20,480 c361.dat > 22/08/2006 03:13p 65,536 c370.dat > 22/08/2006 03:13p 16,384 c381.dat > 22/08/2006 03:13p 8,192 c391.dat > 12/09/2006 12:33p 16,384 c3a1.dat > 25/09/2006 03:42p 294,912 c3b0.dat > 19/09/2006 12:32p 32,768 c3c1.dat > 19/09/2006 04:16p 69,632 c3d1.dat > 12/09/2006 01:23p 36,864 c3e1.dat > 25/09/2006 02:56p 69,632 c3f1.dat > 16/08/2006 11:08a 20,480 c41.dat > 16/08/2006 11:08a 8,192 c51.dat > 16/08/2006 11:08a 8,192 c60.dat > 16/08/2006 11:08a 8,192 c71.dat > 16/08/2006 11:08a 8,192 c81.dat > 22/08/2006 04:20p 20,480 c90.dat > 16/08/2006 11:08a 20,480 ca1.dat > 16/08/2006 11:08a 8,192 cb1.dat > 16/08/2006 11:08a 8,192 cc0.dat > 16/08/2006 11:08a 8,192 cd1.dat > 16/08/2006 11:08a 8,192 ce1.dat > 16/08/2006 11:08a 8,192 cf0.dat > > Contents of log: > > 10/10/2006 10:26a 48 log.ctrl > 12/09/2006 02:31p 1,048,752 log1.dat > 26/09/2006 08:22p 1,048,576 log2.dat > 28/09/2006 06:23p 1,049,141 log3.dat > 03/10/2006 02:04p 1,048,576 log4.dat > 10/10/2006 10:26a 48 logmirror.ctrl > > Mike Matrigali wrote: > >> There may or may not be more information in the derby.log. Are you >> getting any disk errors, does the file seg0/c350.dat exist and have >> reasonable permissions. My guess (but there really is not enough >> info here) is that recovery is trying to access page 7 of container >> 848 (seg0/c350.dat), and for some reason it can't. Those reasons >> could be >> that the file does not exist/bad permission, disk error reading that >> sector, file is not that long. >> >> What derby version are you using? >> >> >> >> David Sitsky wrote: >> >>> Hi, >>> >>> we have a client using a derby database, sometimes accessed in >>> networked mode, and sometimes as an embedded database. It can no >>> longer be opened successfully, as Derby is now returning the >>> following messages when the database is being opened: >>> >>> DERBY SQL error: SQLCODE: -1, SQLSTATE: XJ040, SQLERRMC: Failed to >>> start database '...', see the next exception for details. >>> >>> SQLSTATE: XSDG0Page Page(7,Container(0, 848)) could not be read from >>> disk. >>> >>> Is this a sign that the database has been corrupted, or is there >>> another issue here? Is there anything which can be done about this? >>> > >