H2 AIOOOBE when connecting to H2 after forcible termination

[Atul Chowdhury]

Hi All -

 

I'm connected to H2 with these settings:

 

When I kill the java process (usually due to unresponsive queries / or application crashes (Java Swing)) and start it back up, I get this exception:

 

Exception =  org.h2.jdbc.JdbcSQLException: General error: "java.lang.ArrayIndexOutOfBoundsException: 61" [50000-158]
 at org.h2.message.DbException.getJdbcSQLException(DbException.java:329)
 at org.h2.message.DbException.get(DbException.java:158)
 at org.h2.message.DbException.convert(DbException.java:281)
 at org.h2.engine.Database.openDatabase(Database.java:250)
 at org.h2.engine.Database.<init>(Database.java:215)
 at org.h2.engine.Engine.openSession(Engine.java:56)
 at org.h2.engine.Engine.openSession(Engine.java:159)
 at org.h2.engine.Engine.createSessionAndValidate(Engine.java:138)
 at org.h2.engine.Engine.createSession(Engine.java:121)
 at org.h2.server.TcpServerThread.run(TcpServerThread.java:124)
 at java.lang.Thread.run(Thread.java:595)
Caused by: java.lang.ArrayIndexOutOfBoundsException: 61
 at org.h2.index.PageDataLeaf.getRowAt(PageDataLeaf.java:327)
 at org.h2.index.PageDataLeaf.getRowWithKey(PageDataLeaf.java:443)
 at org.h2.index.PageDataNode.getRowWithKey(PageDataNode.java:270)
 at org.h2.index.PageDataIndex.getRowWithKey(PageDataIndex.java:403)
 at org.h2.store.PageStore.redoDelete(PageStore.java:1448)
 at org.h2.store.PageLog.recover(PageLog.java:332)
 at org.h2.store.PageStore.recover(PageStore.java:1328)
 at org.h2.store.PageStore.openExisting(PageStore.java:349)
 at org.h2.store.PageStore.open(PageStore.java:273)
 at org.h2.engine.Database.getPageStore(Database.java:2049)
 at org.h2.engine.Database.open(Database.java:553)
 at org.h2.engine.Database.openDatabase(Database.java:220)
 ... 7 more
 | Stack =    at java.sql.DriverManager.getConnection(String , Properties , ClassLoader )
   at java.sql.DriverManager.getConnection(String url, String user, String password, CallerID )
   at java.sql.DriverManager.getConnection(String url, String user, String password)

 

I'm using H2 1.3.158 - it's about 550MB large.  When I gracefully start/stop it it seems to work OK.

 

My connection URL looks like:

 

dboptions=;CACHE_SIZE=262144;DB_CLOSE_ON_EXIT=FALSE;LOG=1;WRITE_DELAY=3000;MVCC=TRUE

 

Any thoughts?

 

Thanks in Advance -

 

AC

[Noel Grandin]

In the short term, I'd suggest turning MVCC off, until Thomas has a chance to figure out where the bug is.

> --
> You received this message because you are subscribed to the Google Groups "H2 Database" group.
> To post to this group, send email to h2-da...@googlegroups.com.
> To unsubscribe from this group, send email to h2-database...@googlegroups.com.
> For more options, visit this group at http://groups.google.com/group/h2-database?hl=en.

[andreis]

> dboptions=;CACHE_SIZE=262144;DB_CLOSE_ON_EXIT=FALSE;LOG=1;WRITE_DELAY=3000; MVCC=TRUE
> Any thoughts?

Try removing "LOG=1;WRITE_DELAY=3000;"

[Thomas Mueller]

Hi,

This looks like a corrupt database. To recover the data, use the tool org.h2.tools.Recover to create the SQL script file, and then re-create the database using this script. Does it work when you do this?

I am very interested in analyzing and solving this problem. Corruption problems have top priority for me. I have a few questions:

- Did you use SHUTDOWN DEFRAG or the database setting DEFRAG_ALWAYS with H2 version 1.3.159 or older?

- How many connections does your application use concurrently?

- Do you use temporary tables?

- With which version of H2 was this database created?
    You can find it out using:
    select * from information_schema.settings where name='CREATE_BUILD'
    or have a look in the SQL script created by the recover tool.

- Did the application run out of memory (once, or multiple times)?

- Do you use any settings or special features (for example cache settings,
    two phase commit, linked tables)?

- Do you use any H2-specific system properties?

- Is the application multi-threaded?

- What operating system, file system, and virtual machine
    (java -version) do you use?

- How did you start the Java process (java -Xmx... and so on)?

- Is it (or was it at some point) a networked file system?

- How big is the database (file sizes)?

- How much heap memory does the Java process have?

- Is the database usually closed normally, or is process terminated
    forcefully or the computer switched off?

- Is it possible to reproduce this problem using a fresh database
    (sometimes, or always)?

- Are there any other exceptions (maybe in the .trace.db file)?
    Could you send them please?

- Do you still have any .trace.db files, and if yes could you send them?

- Could you send the .h2.db file where this exception occurs?

Regards,
Thomas

[Atul Chowdhury]

Hi Thomas -

 

I will reply with some more detail but briefly,

 

- No DEFRAG or SHUTDOWN flags are set

 

- The error appears usually after "javaw" (used to spawn H2) is forcefully terminated (Windows Task Manager -> End process)

- We start the server like this:

 

-Xmx512m -Xrs -cp h2-1.3.158.jar;ikfx.jar  org.h2.tools.Server -tcp -tcpAllowOthers -tcpPort 9092 -baseDir "D:/xxxxx/metaminer/db" -ifExists

 

- No temporary tables

 

- Three components are involved:

1) javaw server for H2

2) .NET windows service which uses an IKVM translation (h2-1.3.58.dll) to connect to our H2 DB to manipulate data

3) sometimes Swing client or reporting tool clients connected to the H2 db using tcp://<host>/<database file name>;ACCESS_MODE_DATA=r;AUTO_RECONNECT=TRUE;LOG=2

4) scheduled java routine (cmd called from the .NET service) to manipulate the H2 db

5) both java and .NET components in windows service call into H2 using this connection string:

 

;CACHE_SIZE=262144;DB_CLOSE_ON_EXIT=FALSE;LOG=2;MVCC=TRUE (before we had LOG=1;WRITE_DELAY=3000;MVCC=TRUE -- same cache and close on exit settings throughout though)

 

6) No temp tables used

7) No linked tables

8) Not multi-threaded; the service activities run serially

9) No H2-specific properties

10) doesn't run out of heap (we use 512m)

11) We have LOTS of indices; there's an index on virtually every "searchable" column in the database, and its a database used for reporting ...so ...

 

I'll try to replicate the issue w/ the trace.db for you.  I don't see this happening until we connect our swing app to the h2 db - then one of our queries (which takes a while to retrieve data) takes "too long" (people don't wait for it to come back) and then kill javaw (h2 server) and upon restart (when .NET IKVM connects to H2 using ;CACHE_SIZE=262144;DB_CLOSE_ON_EXIT=FALSE;LOG=2;MVCC=TRUE it displays the errors discussed)

 

 

Here's another stack trace encountered on start-up:

 

12/12/2011 2:12:04 PM Service Java Metaserver path: -Xmx512m -Xrs -cp h2-1.3.158.jar;ikfx.jar  org.h2.tools.Server -tcp -tcpAllowOthers -tcpPort 9092 -baseDir "D:/xxxxx/metaminer/db" -ifExists
12/12/2011 2:12:04 PM Service WorkingDirectory: D:\xxxxx\metaminer\bin
12/12/2011 2:12:04 PM Service AppStrings._JavaPath: D:/xxxxx/javasdk/jre/bin/javaw.exe
12/12/2011 2:12:04 PM Service Proc FileName: D:/xxxxx/javasdk/jre/bin/javaw.exe
12/12/2011 2:12:04 PM Service MMDB init sent
12/12/2011 2:12:05 PM Infrastructure [ERROR][buildMVCCConnection][DbHelperN2.ctor()][Exception =  org.h2.jdbc.JdbcSQLException: File corrupted while reading record: "Table not found:244 for ( /* key:248 */ 247, 1, 244, 109, 'OFF,0,,', '1') meta:{190=T190_DATA, 214=T214_DATA, 171=I171:171:org.h2.index.PageBtreeIndex@1d009b4, 158=T158_DATA, 95=I95:95:org.h2.index.PageDelegateIndex@12d15a9, 123=I123:123:org.h2.index.PageBtreeIndex@e91f5d, 223=I223:223:org.h2.index.PageBtreeIndex@10a3b24, 213=T213_DATA, 318=T318_DATA, 159=I159:159:org.h2.index.PageDelegateIndex@b0ce8f, 118=T118_DATA, 59=I59:59:org.h2.index.PageBtreeIndex@1c92535, 225=I225:225:org.h2.index.PageDelegateIndex@a9c09e, 124=I124:124:org.h2.index.PageBtreeIndex@a4e743, 169=I169:169:org.h2.index.PageBtreeIndex@4aeb52, 201=I201:201:org.h2.index.PageDelegateIndex@9f671b, 117=I117:117:org.h2.index.PageBtreeIndex@12a3793, 60=I60:60:org.h2.index.PageBtreeIndex@a6d51e, 85=I85:85:org.h2.index.PageDelegateIndex@f1bb78, 61=T61_DATA, 189=I189:189:org.h2.index.PageBtreeIndex@4b035d, 157=I157:157:org.h2.index.PageDelegateIndex@ca0115, 234=I234:234:org.h2.index.PageBtreeIndex@d1fa5, 122=I122:122:org.h2.index.PageBtreeIndex@198a455, 100=I100:100:org.h2.index.PageBtreeIndex@4cee32, 68=I68:68:org.h2.index.PageBtreeIndex@aa37a6, 146=I146:146:org.h2.index.PageDelegateIndex@12b7eea, 119=I119:119:org.h2.index.PageDelegateIndex@99353f, 378=T378_DATA, 58=I58:58:org.h2.index.PageBtreeIndex@76e369, 82=I82:82:org.h2.index.PageBtreeIndex@14c194d, 203=I203:203:org.h2.index.PageBtreeIndex@1112783, 63=T63_DATA, -1=PAGE_INDEX_DATA, 194=I194:194:org.h2.index.PageBtreeIndex@1394894, 145=T145_DATA, 140=I140:140:org.h2.index.PageDelegateIndex@1cbfe9d, 172=I172:172:org.h2.index.PageBtreeIndex@1b8f864, 81=I81:81:org.h2.index.PageBtreeIndex@bb7759, 191=I191:191:org.h2.index.PageDelegateIndex@1989f84, 64=I64:64:org.h2.index.PageDelegateIndex@110c424, 212=I212:212:org.h2.index.PageBtreeIndex@1bd2664, 121=I121:121:org.h2.index.PageBtreeIndex@1238bd2, 57=I57:57:org.h2.index.PageBtreeIndex@b0bad7, 232=I232:232:org.h2.index.PageBtreeIndex@ba9340, 163=I163:163:org.h2.index.PageBtreeIndex@1198891, 136=I136:136:org.h2.index.PageBtreeIndex@1551d7f, 168=I168:168:org.h2.index.PageBtreeIndex@10382a9, 87=I87:87:org.h2.index.PageBtreeIndex@17725c4, 199=I199:199:org.h2.index.PageDelegateIndex@1506dc4, 263=T263_DATA, 150=T150_DATA, 54=I54:54:org.h2.index.PageBtreeIndex@15663a2, 291=T291_DATA, 161=I161:161:org.h2.index.PageBtreeIndex@a761fe, 105=I105:105:org.h2.index.PageBtreeIndex@1126b07, 193=I193:193:org.h2.index.PageBtreeIndex@30d082, 53=I53:53:org.h2.index.PageBtreeIndex@c931fc, 33=T33_DATA, 233=I233:233:org.h2.index.PageBtreeIndex@f0c0d3, 116=I116:116:org.h2.index.PageBtreeIndex@3820e, 289=T289_DATA, 93=I93:93:org.h2.index.PageDelegateIndex@4f80d6, 196=I196:196:org.h2.index.PageBtreeIndex@193722c, 125=I125:125:org.h2.index.PageBtreeIndex@12cc95d, 24=T24_DATA, 88=T88_DATA, 195=I195:195:org.h2.index.PageBtreeIndex@157fb52, 36=I36:36:org.h2.index.PageDelegateIndex@134e4fb, 114=I114:114:org.h2.index.PageDelegateIndex@1a52fdf, 55=I55:55:org.h2.index.PageBtreeIndex@1ea0252, 154=I154:154:org.h2.index.PageBtreeIndex@3e89c3, 127=I127:127:org.h2.index.PageDelegateIndex@1c695a6, 67=I67:67:org.h2.index.PageBtreeIndex@8acf6e, 167=I167:167:org.h2.index.PageBtreeIndex@1386918, 362=T362_DATA, 76=I76:76:org.h2.index.PageBtreeIndex@7bb290, 281=T281_DATA, 204=T204_DATA, 128=T128_DATA, 343=T343_DATA, 197=I197:197:org.h2.index.PageBtreeIndex@10849bc, 164=T164_DATA, 301=T301_DATA, 56=I56:56:org.h2.index.PageBtreeIndex@120d62b, 202=I202:202:org.h2.index.PageBtreeIndex@ccc588, 358=T358_DATA, 107=I107:107:org.h2.index.PageDelegateIndex@1bc82e7, 207=T207_DATA, 363=T363_DATA, 143=I143:143:org.h2.index.PageDelegateIndex@1362012, 16=T16_DATA, 112=T112_DATA, 80=I80:80:org.h2.index.PageBtreeIndex@73a34b, 230=I230:230:org.h2.index.PageBtreeIndex@1e59128, 187=I187:187:org.h2.index.PageBtreeIndex@9ced8e, 208=T208_DATA, 335=T335_DATA, 73=I73:73:org.h2.index.PageDelegateIndex@b02efa, 129=I129:129:org.h2.index.PageDelegateIndex@dc57db, 188=I188:188:org.h2.index.PageBtreeIndex@c24c0, 97=I97:97:org.h2.index.PageBtreeIndex@140c281, 70=I70:70:org.h2.index.PageBtreeIndex@a1d1f4, 270=T270_DATA, 353=T353_DATA, 106=I106:106:org.h2.index.PageBtreeIndex@1df280b, 14=T14_DATA, 142=T142_DATA, 322=T322_DATA, 83=T83_DATA, 131=I131:131:org.h2.index.PageBtreeIndex@1be0f0a, 47=T47_DATA, 210=I210:210:org.h2.index.PageBtreeIndex@cd5f8b, 75=I75:75:org.h2.index.PageBtreeIndex@13bd574, 186=I186:186:org.h2.index.PageBtreeIndex@13adc56, 231=I231:231:org.h2.index.PageBtreeIndex@157aa53, 175=I175:175:org.h2.index.PageBtreeIndex@6f50a8, 209=I209:209:org.h2.index.PageBtreeIndex@187814, 162=I162:162:org.h2.index.PageBtreeIndex@73a7ab, 155=I155:155:org.h2.index.PageBtreeIndex@104faf8, 66=I66:66:org.h2.index.PageBtreeIndex@1f8c6df, 103=I103:103:org.h2.index.PageBtreeIndex@1c86be5, 98=I98:98:org.h2.index.PageBtreeIndex@123b25c, 44=I44:44:org.h2.index.PageDelegateIndex@92bbba, 17=T17_DATA, 205=I205:205:org.h2.index.PageDelegateIndex@162dbb6, 77=T77_DATA, 156=I156:156:org.h2.index.PageBtreeIndex@146c1d4, 229=I229:229:org.h2.index.PageBtreeIndex@5f8172, 165=I165:165:org.h2.index.PageDelegateIndex@2ba11b, 102=I102:102:org.h2.index.PageBtreeIndex@5e179a, 84=T84_DATA, 228=I228:228:org.h2.index.PageBtreeIndex@15fadcf, 185=I185:185:org.h2.index.PageBtreeIndex@8c1dd9, 101=I101:101:org.h2.index.PageBtreeIndex@fbb7cb, 227=I227:227:org.h2.index.PageBtreeIndex@1df8b99, 222=I222:222:org.h2.index.PageBtreeIndex@1462851, 215=I215:215:org.h2.index.PageDelegateIndex@1010058, 40=T40_DATA, 104=I104:104:org.h2.index.PageBtreeIndex@bdab91, 72=T72_DATA, 177=I177:177:org.h2.index.PageDelegateIndex@4ac00c, 182=T182_DATA, 135=I135:135:org.h2.index.PageBtreeIndex@1865b28, 71=I71:71:org.h2.index.PageBtreeIndex@1cac6db, 180=I180:180:org.h2.index.PageDelegateIndex@1c56c60, 298=T298_DATA, 134=I134:134:org.h2.index.PageBtreeIndex@4e280c, 137=I137:137:org.h2.index.PageBtreeIndex@1275d39, 307=T307_DATA, 221=I221:221:org.h2.index.PageBtreeIndex@1595f51, 211=I211:211:org.h2.index.PageBtreeIndex@80d1ff, 179=T179_DATA, 152=I152:152:org.h2.index.PageDelegateIndex@15ac3c9, 78=I78:78:org.h2.index.PageDelegateIndex@1ebd75b, 52=I52:52:org.h2.index.PageBtreeIndex@87c268, 170=I170:170:org.h2.index.PageBtreeIndex@ec4a87, 111=T111_DATA, 183=I183:183:org.h2.index.PageDelegateIndex@110fe28, 139=T139_DATA, 218=I218:218:org.h2.index.PageBtreeIndex@9e29fb, 295=T295_DATA, 91=I91:91:org.h2.index.PageBtreeIndex@1d64c37, 219=I219:219:org.h2.index.PageBtreeIndex@25d2b2, 148=T148_DATA, 173=I173:173:org.h2.index.PageBtreeIndex@12be1bd, 109=I109:109:org.h2.index.PageBtreeIndex@1f17e77, 92=T92_DATA, 220=I220:220:org.h2.index.PageBtreeIndex@1a5f739, 133=I133:133:org.h2.index.PageBtreeIndex@109fd93, 89=I89:89:org.h2.index.PageBtreeIndex@e6ff0d, 325=T325_DATA, 174=I174:174:org.h2.index.PageBtreeIndex@172e449, 217=I217:217:org.h2.index.PageBtreeIndex@1e97f9f, 138=I138:138:org.h2.index.PageBtreeIndex@b9b538, 0=T0_DATA, 69=I69:69:org.h2.index.PageBtreeIndex@288051}". Possible solution: use the recovery tool [90030-158]
        at org.h2.message.DbException.getJdbcSQLException(DbException.java:329)
        at org.h2.message.DbException.get(DbException.java:169)
        at org.h2.message.DbException.get(DbException.java:146)
        at org.h2.store.PageStore.addMeta(PageStore.java:1599)
        at org.h2.store.PageStore.readMetaData(PageStore.java:1533)
        at org.h2.store.PageStore.recover(PageStore.java:1327)

        at org.h2.store.PageStore.openExisting(PageStore.java:349)
        at org.h2.store.PageStore.open(PageStore.java:273)
        at org.h2.engine.Database.getPageStore(Database.java:2049)
        at org.h2.engine.Database.open(Database.java:553)
        at org.h2.engine.Database.openDatabase(Database.java:220)

        at org.h2.engine.Database.<init>(Database.java:215)
        at org.h2.engine.Engine.openSession(Engine.java:56)
        at org.h2.engine.Engine.openSession(Engine.java:159)
        at org.h2.engine.Engine.createSessionAndValidate(Engine.java:138)
        at org.h2.engine.Engine.createSession(Engine.java:121)
        at org.h2.server.TcpServerThread.run(TcpServerThread.java:124)
        at java.lang.Thread.run(Thread.java:595)

| Stack =    at java.sql.DriverManager.getConnection(String , Properties , ClassLoader )
   at java.sql.DriverManager.getConnection(String url, String user, String password, CallerID )
   at java.sql.DriverManager.getConnection(String url, String user, String password)

   at MetaBridge.DbHelperN2.buildMVCCConnection() | Source = IKVM.OpenJDK.Jdbc ]