expected pos: 1442 got: 1357 on weblogic

[pierre-antoine pinard]

Hello,

We are using an embedded h2database into our web application.

We do 100000 inserts (with a commit every 20000 inserts) .

This piece of software works fine :
- on a standalone test program running with sun/Oracle hotspot jvm
- on a standalone test program running with Oracle jrockt jvm
- on a tomcat server running with sun/Oracle hotspot jvm

Sadly, it doesn't work on a webLogic application server (version
10.3.3.0) running with the jrockit jvm on a Windows Server 2008 RC2.

After about 50000 inserts, H2 starts to write a HUGE amount of logs
(in the data.trace file) ; it becomes very slow and the database is
corrupted (we have to erase the files otherwise on next startup, H2
complains the files are corrupted).

Here are small part of the error logs (the same error is repeated
during 90 MBytes of logs, always with 1442 and 1357 values):
02-08 12:53:36 jdbc[2]: exception
org.h2.jdbc.JdbcSQLException: General error:
"java.lang.RuntimeException: expected pos: 1442 got: 1357"; SQL
statement:
INSERT INTO LIBELLE VALUES (?,?) [50000-147]
at org.h2.message.DbException.getJdbcSQLException(DbException.java:
327)
at org.h2.message.DbException.get(DbException.java:156)
at org.h2.message.DbException.convert(DbException.java:279)
at org.h2.table.RegularTable.addRow(RegularTable.java:143)
at org.h2.command.dml.Insert.insertRows(Insert.java:126)
at org.h2.command.dml.Insert.update(Insert.java:86)
at org.h2.command.CommandContainer.update(CommandContainer.java:69)
at org.h2.command.Command.executeUpdate(Command.java:201)
at
org.h2.jdbc.JdbcPreparedStatement.execute(JdbcPreparedStatement.java:
181)
at
com.itnsa.fwk.i18n.cache.I18nCache.putListLibelleInCache(I18nCache.java:
267)
at
com.itnsa.fwk.i18n.cache.impl.I18nCacheSynchronizerServiceImpl.reloadCache(I18nCacheSynchronizerServiceImpl.java:
56)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:
39)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:
25)
at java.lang.reflect.Method.invoke(Method.java:597)
at
org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:
310)
at
org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:
182)
at
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:
149)
at
com.itnsa.assurance.util.PerformanceThresholdInterceptor.invoke(PerformanceThresholdInterceptor.java:
29)
at
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:
171)
at
com.itnsa.fwk.aop.MessageSerializationInterceptor.invoke(MessageSerializationInterceptor.java:
61)
at
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:
171)
at
com.itnsa.fwk.performance.PerformanceLogger.invoke(PerformanceLogger.java:
209)
at
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:
171)
at
org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:
106)
at
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:
171)
at
org.springframework.aop.framework.adapter.AfterReturningAdviceInterceptor.invoke(AfterReturningAdviceInterceptor.java:
50)
at
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:
171)
at
org.springframework.aop.framework.adapter.MethodBeforeAdviceInterceptor.invoke(MethodBeforeAdviceInterceptor.java:
50)
at
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:
171)
at
org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:
204)
at $Proxy76.reloadCache(Unknown Source)
at
com.itnsa.assurance.application.startup.I18nCacheLoader.startup(I18nCacheLoader.java:
16)
at
com.itnsa.fwk.application.ApplicationListener.doSteps(ApplicationListener.java:
75)
at
com.itnsa.fwk.application.ApplicationListener.onApplicationEvent(ApplicationListener.java:
56)
at org.springframework.context.event.SimpleApplicationEventMulticaster
$1.run(SimpleApplicationEventMulticaster.java:78)
at
org.springframework.core.task.SyncTaskExecutor.execute(SyncTaskExecutor.java:
49)
at
org.springframework.context.event.SimpleApplicationEventMulticaster.multicastEvent(SimpleApplicationEventMulticaster.java:
76)
at
org.springframework.context.support.AbstractApplicationContext.publishEvent(AbstractApplicationContext.java:
275)
at
org.springframework.context.support.AbstractApplicationContext.finishRefresh(AbstractApplicationContext.java:
737)
at
org.springframework.context.support.AbstractApplicationContext.refresh(AbstractApplicationContext.java:
384)
at
org.springframework.web.context.ContextLoader.createWebApplicationContext(ContextLoader.java:
255)
at
org.springframework.web.context.ContextLoader.initWebApplicationContext(ContextLoader.java:
199)
at
org.springframework.web.context.ContextLoaderListener.contextInitialized(ContextLoaderListener.java:
45)
at weblogic.servlet.internal.EventsManager
$FireContextListenerAction.run(EventsManager.java:481)
at
weblogic.security.acl.internal.AuthenticatedSubject.doAs(AuthenticatedSubject.java:
321)
at
weblogic.security.service.SecurityManager.runAs(SecurityManager.java:
121)
at
weblogic.servlet.internal.EventsManager.notifyContextCreatedEvent(EventsManager.java:
181)
at
weblogic.servlet.internal.WebAppServletContext.preloadResources(WebAppServletContext.java:
1863)
at
weblogic.servlet.internal.WebAppServletContext.start(WebAppServletContext.java:
3126)
at
weblogic.servlet.internal.WebAppModule.startContexts(WebAppModule.java:
1512)
at weblogic.servlet.internal.WebAppModule.start(WebAppModule.java:
486)
at weblogic.application.internal.flow.ModuleStateDriver
$3.next(ModuleStateDriver.java:425)
at
weblogic.application.utils.StateMachineDriver.nextState(StateMachineDriver.java:
41)
at
weblogic.application.internal.flow.ModuleStateDriver.start(ModuleStateDriver.java:
119)
at
weblogic.application.internal.flow.ScopedModuleDriver.start(ScopedModuleDriver.java:
200)
at
weblogic.application.internal.flow.ModuleListenerInvoker.start(ModuleListenerInvoker.java:
247)
at weblogic.application.internal.flow.ModuleStateDriver
$3.next(ModuleStateDriver.java:425)
at
weblogic.application.utils.StateMachineDriver.nextState(StateMachineDriver.java:
41)
at
weblogic.application.internal.flow.ModuleStateDriver.start(ModuleStateDriver.java:
119)
at
weblogic.application.internal.flow.StartModulesFlow.activate(StartModulesFlow.java:
27)
at weblogic.application.internal.BaseDeployment
$2.next(BaseDeployment.java:1267)
at
weblogic.application.utils.StateMachineDriver.nextState(StateMachineDriver.java:
41)
at
weblogic.application.internal.BaseDeployment.activate(BaseDeployment.java:
409)
at
weblogic.application.internal.EarDeployment.activate(EarDeployment.java:
58)
at
weblogic.application.internal.DeploymentStateChecker.activate(DeploymentStateChecker.java:
161)
at
weblogic.deploy.internal.targetserver.AppContainerInvoker.activate(AppContainerInvoker.java:
79)
at
weblogic.deploy.internal.targetserver.BasicDeployment.activate(BasicDeployment.java:
184)
at
weblogic.deploy.internal.targetserver.BasicDeployment.activateFromServerLifecycle(BasicDeployment.java:
361)
at weblogic.management.deploy.internal.DeploymentAdapter
$1.doActivate(DeploymentAdapter.java:51)
at
weblogic.management.deploy.internal.DeploymentAdapter.activate(DeploymentAdapter.java:
200)
at weblogic.management.deploy.internal.AppTransition
$2.transitionApp(AppTransition.java:30)
at
weblogic.management.deploy.internal.ConfiguredDeployments.transitionApps(ConfiguredDeployments.java:
240)
at
weblogic.management.deploy.internal.ConfiguredDeployments.activate(ConfiguredDeployments.java:
169)
at
weblogic.management.deploy.internal.ConfiguredDeployments.deploy(ConfiguredDeployments.java:
123)
at
weblogic.management.deploy.internal.DeploymentServerService.resume(DeploymentServerService.java:
180)
at
weblogic.management.deploy.internal.DeploymentServerService.start(DeploymentServerService.java:
96)
at weblogic.t3.srvr.SubsystemRequest.run(SubsystemRequest.java:64)
at weblogic.work.ExecuteThread.execute(ExecuteThread.java:201)
at weblogic.work.ExecuteThread.run(ExecuteThread.java:173)
Caused by: java.lang.RuntimeException: expected pos: 1442 got: 1357
at org.h2.message.DbException.throwInternalError(DbException.java:
226)
at org.h2.index.PageDataNode.writeData(PageDataNode.java:346)
at org.h2.index.PageDataNode.write(PageDataNode.java:315)
at org.h2.store.PageStore.writeBack(PageStore.java:983)
at org.h2.util.CacheLRU.removeOld(CacheLRU.java:183)
at org.h2.util.CacheLRU.removeOldIfRequired(CacheLRU.java:124)
at org.h2.util.CacheLRU.put(CacheLRU.java:102)
at org.h2.util.CacheLRU.update(CacheLRU.java:108)
at org.h2.store.PageStore.update(PageStore.java:1036)
at org.h2.index.PageDataLeaf.addRowTry(PageDataLeaf.java:204)
at org.h2.index.PageDataLeaf.split(PageDataLeaf.java:367)
at org.h2.index.PageDataNode.addRowTry(PageDataNode.java:137)
at org.h2.index.PageDataNode.addRowTry(PageDataNode.java:129)
at org.h2.index.PageDataIndex.addTry(PageDataIndex.java:161)
at org.h2.index.PageDataIndex.add(PageDataIndex.java:126)
at org.h2.table.RegularTable.addRow(RegularTable.java:125)
... 76 more

What can we do to solve this problem ?

[Thomas Mueller]

Hi,

I can't really say what the problem is. If the test works fine with
other VMs, then it sounds like a VM bug, but I'm not sure. I don't see
anything obvious

> H2 starts to write a HUGE amount of logs
> (in the data.trace file) ; it becomes very slow and the database is
> corrupted (we have to erase the files otherwise on next startup, H2
> complains the files are corrupted).

I would need to know what the very first exceptions are in the first
.trace.db file (please note the file is renamed to .old after a while
- I would need the very first exceptions in the first .trace.db file).
Also, I guess I would need some more information:

- What is your database URL?
- How many connections does your application use concurrently?
- Do you use temporary tables?
- Did you use LOG=0 or LOG=1?
- 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?
- 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 it possible to reproduce this problem using a fresh database
(sometimes, or always)?

Regards,
Thomas

[guillaume Darona]

> I would need to know what the very first exceptions are in the first
> .trace.db file (please note the file is renamed to .old after a while

The first exception :
02-14 10:47:57 lock: 2 shared read lock requesting for LIBELLE
02-14 10:47:57 lock: 2 shared read lock ok LIBELLE
02-14 10:47:57 index: LIBELLE_DATA add ( /* key:1600750894 */
1600750894, 'Aanbrengcommissies')
02-14 10:47:57 pageStore: log undo 4 121
02-14 10:47:57 pageStore: updateRecord page[4121] data leaf table:4
LIBELLE entries:1 parent:3237 keys:[1600751431, 0, 0, 0, 0] offsets:
[2036, 0, 0, 0, 0]
02-14 10:47:57 pageStore: pageOut.storePage [3607] stream data key:4
pos:547 remaining:1501
02-14 10:47:57 pageStore: writeBack page[517] data leaf table:4
LIBELLE entries:18 parent:688 keys:[-2118252850, -2118252554,
-2118252258, -2118251962, -2118251666, -2118251370, -2118251074,
-2118250778, -2118250482, -2118250186, -2118249890, -2118249594,
-2118249298, -2118249002, -2118248706, -2118248410, -2118248114,
2176719478, 0, 0] offsets:[2025, 2002, 1979, 1956, 1933, 1910, 1887,
1864, 1841, 1818, 1795, 1772, 1749, 1726, 1703, 1680, 1657, 1634, 0,
0]
02-14 10:47:57 pageStore: writeBack page[543] data leaf table:4
LIBELLE entries:40 parent:750 keys:[-1672631482, -1672574650,
-1672517818, -1672460986, -1672404154, -1672347322, -1672290490,
-1672243912, -1672243875, -1672243838, -1672243801, -1672243764,
-1672243542, -1672243505, -1672243468, -1672243431, -1672243172,
-1672243098, -1672242802, -1672233658, -1672176826, -1672119994,
-1672063162, -1672006330, -1671949498, -1671892666, -1671835834,
-1671779002, -1671722170, -1671665338, -1671608506, -1671551674,
-1671494842, -1671438010, -1671381178, -1671324346, -1671267514,
-1671210682, -1671153850, 2623870278, 0, 0, 0] offsets:[2006, 1960,
1942, 1882, 1855, 1824, 1782, 1719, 1705, 1674, 1642, 1574, 1550,
1523, 1477, 1434, 1398, 1361, 1283, 1241, 1189, 1122, 1087, 1058,
1015, 983, 929, 907, 888, 873, 825, 809, 794, 760, 712, 687, 662, 638,
623, 580, 0, 0, 0]
02-14 10:47:57 pageStore: writeBack page[545] data leaf table:4
LIBELLE entries:32 parent:750 keys:[-1853073082, -1852479364,
-1852477995, -1852476626, -1852475257, -1852473888, -1852472223,
-1852472186, -1852472149, -1852472112, -1852472075, -1852472038,
-1852472001, -1852471113, -1852471076, -1852471039, -1852470854,
-1852470817, -1852470780, -1852470743, -1852470706, -1852470669,
-1852470632, -1852469744, -1852469707, -1852469670, -1852469485,
-1852469448, -1852469411, -1852469374, -1852469337, 2442497959]
offsets:[1986, 1948, 1935, 1928, 1921, 1914, 1876, 1838, 1800, 1762,
1724, 1686, 1648, 1610, 1572, 1534, 1521, 1508, 1495, 1482, 1469,
1456, 1443, 1430, 1417, 1404, 1382, 1349, 1319, 1286, 1250, 1215]
02-14 10:47:57 pageStore: writeBack page[549] data leaf table:4
LIBELLE entries:22 parent:750 keys:[-1772668051, -1772667681,
-1772667052, -1772666682, -1772666312, -1772665683, -1772665313,
-1772664943, -1772295866, -1771841210, -1771386554, -1770931898,
-1770477242, -1770022586, -1769567930, -1769113274, -1768658618,
-1768203962, -1767749306, -1767294650, -1766839994, 2528581958, 0, 0]
offsets:[2041, 2013, 2006, 1999, 1971, 1964, 1957, 1950, 1886, 1859,
1817, 1766, 1751, 1727, 1704, 1670, 1625, 1600, 1550, 1501, 1443,
1390, 0, 0]
02-14 10:47:57 pageStore: writeBack page[551] data leaf table:4
LIBELLE entries:19 parent:750 keys:[-1765930682, -1765476026,
-1765021370, -1764566714, -1764112058, -1763657402, -1763202746,
-1762748090, -1762293434, -1761838778, -1761384122, -1760929466,
-1760474810, -1760020154, -1759848472, -1759847103, -1759845734,
-1759565498, 2535856454, 0, 0] offsets:[1992, 1939, 1887, 1867, 1821,
1790, 1757, 1693, 1658, 1627, 1596, 1543, 1498, 1479, 1453, 1436,
1405, 1377, 1310, 0, 0]
02-14 10:47:57 pageStore: writeBack page[573] data leaf table:4
LIBELLE entries:47 parent:3101 keys:[-1668084922, -1668028090,
-1667971258, -1667914426, -1667857594, -1667800762, -1667743930,
-1667687098, -1667630266, -1667573434, -1667516602, -1667459770,
-1667402938, -1667346106, -1667289274, -1667232442, -1667175610,
-1667118778, -1667061946, -1667005114, -1666948282, -1666891450,
-1666834618, -1666777786, -1666720954, -1666664122, -1620149926,
-1620148557, -1620147188, -1620145819, -1620144450, -1612691281,
-1612690134, -1612689912, -1612688987, -1612688765, -1612688543,
-1612687840, -1612687618, -1612687396, -1612687174, -1612686471,
-1612686249, -1612686027, -1612685805, -1612685546, 2682281750, 0, 0,
0, 0] offsets:[1989, 1949, 1890, 1853, 1825, 1797, 1761, 1714, 1679,
1629, 1597, 1568, 1531, 1477, 1440, 1390, 1373, 1332, 1296, 1251,
1197, 1172, 1142, 1112, 1082, 1052, 1033, 1025, 1017, 1010, 1003, 984,
965, 953, 934, 922, 906, 887, 875, 856, 849, 837, 821, 814, 807, 788,
769, 0, 0, 0, 0]
02-14 10:47:57 pageStore: writeBack page[688] data node table:4
entries:72 [517, 3004, 2989, 2988, 2986, 2971, 2958, 2966, 2967, 2945,
2999, 2950, 2936, 2997, 2368, 2367, 2994, 2939, 2396, 2975, 2933,
2995, 3002, 2935, 2978, 2998, 2943, 2953, 2951, 3006, 2970, 2984,
3005, 2983, 2940, 2979, 2949, 2972, 2987, 2937, 2973, 2948, 2952,
2981, 2996, 2982, 2977, 2991, 2307, 2299, 2938, 2407, 2962, 2946,
2961, 2968, 2954, 2974, 2955, 2964, 2956, 2941, 2980, 2960, 2957,
2976, 2990, 2942, 2985, 2397, 2944, 2965, 2993, 0, 0, 0, 0]
02-14 10:47:57 lock: 2 shared read lock unlock LIBELLE
02-14 10:47:57 jdbc[2]: exception
org.h2.jdbc.JdbcSQLException: General error:
"java.lang.RuntimeException: expected pos: 1106 got: 1021"; SQL
statement:
INSERT INTO LIBELLE VALUES (?,?) [50000-150]

at org.h2.message.DbException.getJdbcSQLException(DbException.java:
327)
at org.h2.message.DbException.get(DbException.java:156)
at org.h2.message.DbException.convert(DbException.java:279)
at org.h2.table.RegularTable.addRow(RegularTable.java:143)
at org.h2.command.dml.Insert.insertRows(Insert.java:126)
at org.h2.command.dml.Insert.update(Insert.java:86)
at org.h2.command.CommandContainer.update(CommandContainer.java:69)

at org.h2.command.Command.executeUpdate(Command.java:209)

at
org.h2.jdbc.JdbcPreparedStatement.execute(JdbcPreparedStatement.java:
181)
at
com.itnsa.fwk.i18n.cache.I18nCache.putListLibelleInCache(I18nCache.java:

279)

Caused by: java.lang.RuntimeException: expected pos: 1106 got: 1021

at org.h2.message.DbException.throwInternalError(DbException.java:
226)
at org.h2.index.PageDataNode.writeData(PageDataNode.java:346)
at org.h2.index.PageDataNode.write(PageDataNode.java:315)

at org.h2.store.PageStore.writeBack(PageStore.java:988)
at org.h2.util.CacheLRU.removeOld(CacheLRU.java:207)
at org.h2.util.CacheLRU.removeOldIfRequired(CacheLRU.java:136)
at org.h2.util.CacheLRU.put(CacheLRU.java:112)
at org.h2.util.CacheLRU.update(CacheLRU.java:118)
at org.h2.store.PageStore.update(PageStore.java:1041)

at org.h2.index.PageDataLeaf.addRowTry(PageDataLeaf.java:204)
at org.h2.index.PageDataLeaf.split(PageDataLeaf.java:367)
at org.h2.index.PageDataNode.addRowTry(PageDataNode.java:137)
at org.h2.index.PageDataNode.addRowTry(PageDataNode.java:129)

at org.h2.index.PageDataIndex.addTry(PageDataIndex.java:158)
at org.h2.index.PageDataIndex.add(PageDataIndex.java:123)

at org.h2.table.RegularTable.addRow(RegularTable.java:125)
... 76 more

- What is your database URL?

> jdbc:h2:C:/deploy/201020/squish/h2/
data;CACHE_SIZE=8192;MVCC=TRUE;TRACE_LEVEL_FILE=3

- How many connections does your application use concurrently?

> 1

- Do you use temporary tables?

> no

- Did you use LOG=0 or LOG=1?

> I try with 0 and 3

- 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.

> 02-14 10:46:29 database: opening C:\deploy\201020\squish\h2\data
(build 150)

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

> no

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

> no

- Do you use any H2-specific system properties?

> MVCC (but we try to remove it, and it's changed nothing)

- Is the application multi-threaded?

> no

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

> jvm start with -Xms512m -Xmx4096m

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

> no

- How big is the database (file sizes)?

> 70m max

- How much heap memory does the Java process have?

> Java process have 4go memory but only 1.5Go are used during test.

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

> always

[guillaume Darona]

I successfully start my WebLogic server with some memory tunning.
I modify the TLA size of JRockit at startup to :
-XXtlasize:min=8k,preferred=64k
instead of default value :
-XXtlasize:min=2k,preferred=16k

It's work but I don't undestand why this parameters are necessary for
H2 in a JRockit VM.
For more information of TLA :
http://download.oracle.com/docs/cd/E13150_01/jrockit_jvm/jrockit/geninfo/diagnos/memman.html#wp1089132

Maybe the memory's synchronisation with the others threads of the
Application Server when the TLA is full is the problem.