KahaDB + throughput configuration - disaster recovery

Start broker. Start producing long messages. Kill the broker. Check number of ack'd messes on P. Restart broker. Check recovery logs. Consume messages. Compare numbers.

Configuration: high throughput <kahaDB directory="${activemq.base}/data/kahadb" enableJournalDiskSyncs="false" indexWriteBatchSize="10000" indexCacheSize="1000"/>

• 95 msgs lost

2010-04-15 17:11:06,403 | INFO  | Using Persistence Adapter: org.apache.activemq.store.kahadb.KahaDBPersistenceAdapter@bcb23e | org.apache.activemq.broker.BrokerService | main
2010-04-15 17:11:06,513 | DEBUG | Recovering page file... | org.apache.kahadb.page.PageFile | main
2010-04-15 17:11:06,576 | DEBUG | Redo buffer was not fully intact:  | org.apache.kahadb.page.PageFile | main
java.io.EOFException
        at java.io.RandomAccessFile.readInt(RandomAccessFile.java:725)
        at java.io.RandomAccessFile.readLong(RandomAccessFile.java:758)
        at org.apache.kahadb.page.PageFile.redoRecoveryUpdates(PageFile.java:1085)
        at org.apache.kahadb.page.PageFile.load(PageFile.java:339)
        at org.apache.activemq.store.kahadb.MessageDatabase.loadPageFile(MessageDatabase.java:195)
        at org.apache.activemq.store.kahadb.MessageDatabase.open(MessageDatabase.java:277)
        at org.apache.activemq.store.kahadb.MessageDatabase.load(MessageDatabase.java:321)
        at org.apache.activemq.store.kahadb.MessageDatabase.start(MessageDatabase.java:182)
        at org.apache.activemq.store.kahadb.KahaDBPersistenceAdapter.start(KahaDBPersistenceAdapter.java:183)
        at org.apache.activemq.broker.BrokerService.start(BrokerService.java:470)
        at org.apache.activemq.xbean.XBeanBrokerService.afterPropertiesSet(XBeanBrokerService.java:85)
        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.beans.factory.support.AbstractAutowireCapableBeanFactory.invokeCustomInitMethod(AbstractAutowireCapableBeanFactory.java:1414)
        at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.invokeInitMethods(AbstractAutowireCapableBeanFactory.java:1375)
        at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.initializeBean(AbstractAutowireCapableBeanFactory.java:1335)
        at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java:473)
        at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory$1.run(AbstractAutowireCapableBeanFactory.java:409)
        at java.security.AccessController.doPrivileged(Native Method)
        at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:380)
        at org.springframework.beans.factory.support.AbstractBeanFactory$1.getObject(AbstractBeanFactory.java:264)
        at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.getSingleton(DefaultSingletonBeanRegistry.java:222)
        at org.springframework.beans.factory.support.AbstractBeanFactory.doGetBean(AbstractBeanFactory.java:261)
        at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:185)
        at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:164)
        at org.springframework.beans.factory.support.DefaultListableBeanFactory.preInstantiateSingletons(DefaultListableBeanFactory.java:429)
        at org.springframework.context.support.AbstractApplicationContext.finishBeanFactoryInitialization(AbstractApplicationContext.java:728)
        at org.springframework.context.support.AbstractApplicationContext.refresh(AbstractApplicationContext.java:380)
        at org.apache.xbean.spring.context.ResourceXmlApplicationContext.<init>(ResourceXmlApplicationContext.java:64)
        at org.apache.xbean.spring.context.ResourceXmlApplicationContext.<init>(ResourceXmlApplicationContext.java:52)
        at org.apache.activemq.xbean.XBeanBrokerFactory.createApplicationContext(XBeanBrokerFactory.java:96)
        at org.apache.activemq.xbean.XBeanBrokerFactory.createBroker(XBeanBrokerFactory.java:52)
        at org.apache.activemq.broker.BrokerFactory.createBroker(BrokerFactory.java:71)
        at org.apache.activemq.broker.BrokerFactory.createBroker(BrokerFactory.java:54)
        at org.apache.activemq.console.command.StartCommand.startBroker(StartCommand.java:115)
        at org.apache.activemq.console.command.StartCommand.runTask(StartCommand.java:74)
        at org.apache.activemq.console.command.AbstractCommand.execute(AbstractCommand.java:57)
        at org.apache.activemq.console.command.ShellCommand.runTask(ShellCommand.java:136)
        at org.apache.activemq.console.command.AbstractCommand.execute(AbstractCommand.java:57)
        at org.apache.activemq.console.command.ShellCommand.main(ShellCommand.java:82)
        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.apache.activemq.console.Main.runTaskClass(Main.java:251)
        at org.apache.activemq.console.Main.main(Main.java:107)
2010-04-15 17:11:06,600 | DEBUG | loading | org.apache.kahadb.index.BTreeIndex | main
2010-04-15 17:11:06,610 | DEBUG | loading | org.apache.kahadb.index.BTreeIndex | main
2010-04-15 17:11:06,613 | DEBUG | loading | org.apache.kahadb.index.BTreeIndex | main
2010-04-15 17:11:06,613 | DEBUG | loading | org.apache.kahadb.index.BTreeIndex | main
2010-04-15 17:11:06,613 | DEBUG | loading | org.apache.kahadb.index.BTreeIndex | main
2010-04-15 17:11:06,614 | DEBUG | loading | org.apache.kahadb.index.BTreeIndex | main
2010-04-15 17:11:06,614 | DEBUG | loading | org.apache.kahadb.index.BTreeIndex | main
2010-04-15 17:11:06,614 | DEBUG | loading | org.apache.kahadb.index.BTreeIndex | main
2010-04-15 17:11:06,616 | DEBUG | loading | org.apache.kahadb.index.BTreeIndex | main
2010-04-15 17:11:06,616 | DEBUG | loading | org.apache.kahadb.index.BTreeIndex | main
2010-04-15 17:11:06,616 | DEBUG | loading | org.apache.kahadb.index.BTreeIndex | main
2010-04-15 17:11:06,617 | DEBUG | loading | org.apache.kahadb.index.BTreeIndex | main
2010-04-15 17:11:06,617 | DEBUG | loading | org.apache.kahadb.index.BTreeIndex | main
2010-04-15 17:11:08,388 | INFO  | Replayed 5289 operations from the journal in 1.77 seconds. | org.apache.activemq.store.kahadb.MessageDatabase | main

Number of sent and received messages differs.

11888 in

11793 out

95 msgs difference

[kvs]:TestPerf.2 # ./msg-test-producer-perf -b localhost -p 61613 -n 1000000 -l /queue/test.testPerf_2
p: 4247 (4178) msgs in 4.957 secs; rate=856.8 (842.9) msgs/sec
p: 8781 (8719) msgs in 9.960 secs; rate=881.6 (875.4) msgs/sec
ERROR:stomp.py:Lost connection
total msgs sent : 11952
total msgs ackd : 11888
total time : 9.960
sent min: 856.8, max: 881.6, mean: 869.2
ackd min: 842.9, max: 875.4, mean: 859.2
[kvs]:TestPerf.2 #

[kvs]:TestPerf.2 # ./msg-test-consumer-perf -b localhost -p 61613 -n 12000 /queue/test.testPerf_2
Received : CONNECTED
Header   : session: ID:kvs-41412-1271344268526-4:0
c: 4490 msgs in 4.828 secs; rate=929.9 msgs/sec
c: 9995 msgs in 9.828 secs; rate=1016.9 msgs/sec
c: 11793 msgs in 14.828 secs; rate=795.3 msgs/sec
c: 11793 msgs in 19.828 secs; rate=594.8 msgs/sec
c: 11793 msgs in 24.828 secs; rate=475.0 msgs/sec
c: 11793 msgs in 29.828 secs; rate=395.4 msgs/sec
total msgs recv : 11793
total time : 29.828
min: 395.4, max: 1016.9, mean: 701.2
[kvs]:TestPerf.2 # 

• NO MESSAGES LOST

2010-04-15 17:46:21,696 | INFO  | Using Persistence Adapter: org.apache.activemq.store.kahadb.KahaDBPersistenceAdapter@257f1b | org.apache.activemq.broker.BrokerService | main
2010-04-15 17:46:22,374 | DEBUG | Recovering page file... | org.apache.kahadb.page.PageFile | main
2010-04-15 17:46:22,391 | DEBUG | Redo buffer was not fully intact:  | org.apache.kahadb.page.PageFile | main
java.io.EOFException
        at java.io.RandomAccessFile.readInt(RandomAccessFile.java:725)
        at java.io.RandomAccessFile.readLong(RandomAccessFile.java:758)
        at org.apache.kahadb.page.PageFile.redoRecoveryUpdates(PageFile.java:1085)
        at org.apache.kahadb.page.PageFile.load(PageFile.java:339)
        at org.apache.activemq.store.kahadb.MessageDatabase.loadPageFile(MessageDatabase.java:195)
        at org.apache.activemq.store.kahadb.MessageDatabase.open(MessageDatabase.java:277)
        at org.apache.activemq.store.kahadb.MessageDatabase.load(MessageDatabase.java:321)
        at org.apache.activemq.store.kahadb.MessageDatabase.start(MessageDatabase.java:182)
        at org.apache.activemq.store.kahadb.KahaDBPersistenceAdapter.start(KahaDBPersistenceAdapter.java:183)
        at org.apache.activemq.broker.BrokerService.start(BrokerService.java:470)
        at org.apache.activemq.xbean.XBeanBrokerService.afterPropertiesSet(XBeanBrokerService.java:85)
        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.beans.factory.support.AbstractAutowireCapableBeanFactory.invokeCustomInitMethod(AbstractAutowireCapableBeanFactory.java:1414)
        at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.invokeInitMethods(AbstractAutowireCapableBeanFactory.java:1375)
        at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.initializeBean(AbstractAutowireCapableBeanFactory.java:1335)
        at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java:473)
        at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory$1.run(AbstractAutowireCapableBeanFactory.java:409)
        at java.security.AccessController.doPrivileged(Native Method)
        at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:380)
        at org.springframework.beans.factory.support.AbstractBeanFactory$1.getObject(AbstractBeanFactory.java:264)
        at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.getSingleton(DefaultSingletonBeanRegistry.java:222)
        at org.springframework.beans.factory.support.AbstractBeanFactory.doGetBean(AbstractBeanFactory.java:261)
        at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:185)
        at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:164)
        at org.springframework.beans.factory.support.DefaultListableBeanFactory.preInstantiateSingletons(DefaultListableBeanFactory.java:429)
        at org.springframework.context.support.AbstractApplicationContext.finishBeanFactoryInitialization(AbstractApplicationContext.java:728)
        at org.springframework.context.support.AbstractApplicationContext.refresh(AbstractApplicationContext.java:380)
        at org.apache.xbean.spring.context.ResourceXmlApplicationContext.<init>(ResourceXmlApplicationContext.java:64)
        at org.apache.xbean.spring.context.ResourceXmlApplicationContext.<init>(ResourceXmlApplicationContext.java:52)
        at org.apache.activemq.xbean.XBeanBrokerFactory.createApplicationContext(XBeanBrokerFactory.java:96)
        at org.apache.activemq.xbean.XBeanBrokerFactory.createBroker(XBeanBrokerFactory.java:52)
        at org.apache.activemq.broker.BrokerFactory.createBroker(BrokerFactory.java:71)
        at org.apache.activemq.broker.BrokerFactory.createBroker(BrokerFactory.java:54)
        at org.apache.activemq.console.command.StartCommand.startBroker(StartCommand.java:115)
        at org.apache.activemq.console.command.StartCommand.runTask(StartCommand.java:74)
        at org.apache.activemq.console.command.AbstractCommand.execute(AbstractCommand.java:57)
        at org.apache.activemq.console.command.ShellCommand.runTask(ShellCommand.java:136)
        at org.apache.activemq.console.command.AbstractCommand.execute(AbstractCommand.java:57)
        at org.apache.activemq.console.command.ShellCommand.main(ShellCommand.java:82)
        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.apache.activemq.console.Main.runTaskClass(Main.java:251)
        at org.apache.activemq.console.Main.main(Main.java:107)
2010-04-15 17:46:22,422 | DEBUG | loading | org.apache.kahadb.index.BTreeIndex | main
2010-04-15 17:46:22,431 | DEBUG | loading | org.apache.kahadb.index.BTreeIndex | main
2010-04-15 17:46:22,434 | DEBUG | loading | org.apache.kahadb.index.BTreeIndex | main
2010-04-15 17:46:22,434 | DEBUG | loading | org.apache.kahadb.index.BTreeIndex | main
2010-04-15 17:46:24,409 | INFO  | Replayed 7356 operations from the journal in 1.974 seconds. | org.apache.activemq.store.kahadb.MessageDatabase | main

no msgs lost

• 3 MORE MESSAGES

   same stack trace

got 3 more messages!

[kvs]:TestPerf.2 # ./msg-test-producer-perf -b localhost -p 61613 -n 1000000 -l /queue/test.testPerf_2
p: 4631 (4565) msgs in 4.957 secs; rate=934.2 (920.9) msgs/sec
p: 9929 (9881) msgs in 9.957 secs; rate=997.1 (992.3) msgs/sec
p: 15343 (15277) msgs in 14.959 secs; rate=1025.7 (1021.3) msgs/sec
p: 21912 (21879) msgs in 19.990 secs; rate=1096.1 (1094.5) msgs/sec
p: 28828 (28751) msgs in 24.990 secs; rate=1153.6 (1150.5) msgs/sec
ERROR:stomp.py:Lost connection
total msgs sent : 31893
total msgs ackd : 31817
total time : 24.990
sent min: 934.2, max: 1153.6, mean: 1041.3
ackd min: 920.9, max: 1150.5, mean: 1035.9
[kvs]:TestPerf.2 #

[kvs]:TestPerf.2 # ./msg-dump-strict  -b localhost -p 61613 -e -n 100000 /queue/test.testPerf_2
....
msgs received: 31820
[kvs]:TestPerf.2 # 

-- KonstantinSkaburskas - 15-Apr-2010