Slow KahaDB access

Question

After running activemq broker for about 3 months, it was much slow as below. When it is restarted, it came back normal (about 600ms - 1000ms).

I am looking for the cause of the problem. The HD is quite fast 1K rpm with not much IOs. Please tell me if you know/ (can guess) the cause of the problem and solution.

    2012-08-27 19:24:06,670 | INFO  | Slow KahaDB access: cleanup took 7190 | org.apache.activemq.store.kahadb.MessageDatabase | ActiveMQ Journal Checkpoint Worker
    2012-08-27 21:44:14,814 | INFO  | Slow KahaDB access: cleanup took 7176 | org.apache.activemq.store.kahadb.MessageDatabase | ActiveMQ Journal Checkpoint Worker
    2012-08-27 23:58:15,124 | INFO  | Slow KahaDB access: cleanup took 7210 | org.apache.activemq.store.kahadb.MessageDatabase | ActiveMQ Journal Checkpoint Worker
    2012-08-28 02:09:03,120 | INFO  | Slow KahaDB access: cleanup took 7212 | org.apache.activemq.store.kahadb.MessageDatabase | ActiveMQ Journal Checkpoint Worker
    2012-08-28 04:27:46,521 | INFO  | Slow KahaDB access: cleanup took 7196 | org.apache.activemq.store.kahadb.MessageDatabase | ActiveMQ Journal Checkpoint Worker
    2012-08-28 06:36:38,818 | INFO  | Slow KahaDB access: cleanup took 7191 | org.apache.activemq.store.kahadb.MessageDatabase | ActiveMQ Journal Checkpoint Worker
    2012-08-28 08:28:09,937 | INFO  | Slow KahaDB access: Journal append took: 13 ms, Index update took 7165 ms | org.apache.activemq.store.kahadb.MessageDatabase | ActiveMQ Transport: tcp:///127.0.0.1:39951
    2012-08-28 08:29:01,715 | INFO  | Slow KahaDB access: Journal append took: 18 ms, Index update took 7171 ms | org.apache.activemq.store.kahadb.MessageDatabase | ActiveMQ Transport: tcp:///127.0.0.1:39951
    2012-08-28 08:29:26,039 | INFO  | Slow KahaDB access: Journal append took: 30 ms, Index update took 7194 ms | org.apache.activemq.store.kahadb.MessageDatabase | ActiveMQ Transport: tcp:///127.0.0.1:39951
    2012-08-28 08:29:52,283 | INFO  | Slow KahaDB access: Journal append took: 7193 ms, Index update took 116 ms | org.apache.activemq.store.kahadb.MessageDatabase | ActiveMQ Transport: tcp:///127.0.0.1:39951
    2012-08-28 08:30:12,140 | INFO  | Slow KahaDB access: Journal append took: 0 ms, Index update took 7596 ms | org.apache.activemq.store.kahadb.MessageDatabase | ActiveMQ Transport: tcp:///127.0.0.1:39956
    2012-08-28 08:30:25,763 | INFO  | Slow KahaDB access: Journal append took: 11 ms, Index update took 7760 ms |

Thank you guys.

Answer 1

We had the same problem, and it turned out to be a memory leak (objects never getting dropped from a collection). Try running a java memory profiler and watch for gradual memory growth over several days. In our case, the JRockit "mission control" was fantastic.