[prev in list] [next in list] [prev in thread] [next in thread] 

List:       activemq-users
Subject:    Re: Kahadb index updates taking too much time on ActiveMQ 5.11
From:       Tim Bain <tbain () alumni ! duke ! edu>
Date:       2017-09-27 4:56:35
Message-ID: CAPVVMa9Q15u4U+4fRNZPvx6nSLchT3N=+9X05-hAePd_vb5xtg () mail ! gmail ! com
[Download RAW message or body]


I've not seen anyone describe this set of symptoms, so I don't have
anything to suggest right from the outset, but I may be able to help you
figure out what's going on.

Could you attach a CPU sampler such as JVisualVM to the broker process and
capture CPU sampling (not profiling if this is an operational broker!) data
to determine where the broker is spending its time?

On Tue, Sep 26, 2017 at 6:51 AM, Raffi <raffi.onjava@gmail.com> wrote:

>
> In production with ActiveMQ 5.11 with multi-kahadb per destination on NFSv4
> M|S (Linux 7.1), we're seeing the following log messages intermittently
> during operations:
>
> *Slow KahaDB access: Journal append took: 2 ms, Index update took 16901 ms*
>
> Also, on startup, we see the following in our kahadb logs; this condition
> severely impacts start up time, sometimes taking up to 90m for the broker
> to
> start, and that's for relatively small persistent store (< 5Gb). We have
> not
> adjusted indexCacheSize, that will be our first attempt to resolve this; we
> also plan to benchmark NFSv4 file system performance. Aside from that, is
> there any other broker config
>
> 2017-09-25 14:35:27,352 [AMQ-1-thread-1 ] DEBUG ListIndex
> - loading
>  2017-09-25 14:35:27,365 [AMQ-1-thread-1 ] INFO  MessageDatabase
> - Recovering from the journal @1:76785
>  2017-09-25 14:35:27,365 [AMQ-1-thread-1 ] INFO  MessageDatabase
> - Recovering from the journal @1:76785
>  2017-09-25 14:35:27,366 [AMQ-1-thread-1 ] INFO  MessageDatabase
> - Recovery replayed 1 operations from the journal in 0.012 seconds.
>  2017-09-25 14:35:27,366 [AMQ-1-thread-1 ] INFO  MessageDatabase
> - Recovery replayed 1 operations from the journal in 0.012 seconds.
>  2017-09-25 14:35:27,366 [AMQ-1-thread-1 ] INFO  KahaDBStore
> - Stopping async queue tasks
>  2017-09-25 14:35:27,366 [AMQ-1-thread-1 ] INFO  KahaDBStore
> - Stopping async topic tasks
>  2017-09-25 14:35:27,366 [AMQ-1-thread-1 ] INFO  KahaDBStore
> - Stopped KahaDB
>  2017-09-25 14:35:27,855 [AMQ-1-thread-1 ] DEBUG KahaDBStore
> - Store OpenWire version configured as: 6
>  2017-09-25 14:35:30,234 [AMQ-1-thread-1 ] TRACE Journal
> - Startup took: 2372 ms
>  2017-09-25 14:35:30,276 [AMQ-1-thread-1 ] INFO  MessageDatabase
> - KahaDB is version 5
>  2017-09-25 14:35:30,276 [AMQ-1-thread-1 ] INFO  MessageDatabase
> - KahaDB is version 5
>  2017-09-25 14:35:30,281 [AMQ-1-thread-1 ] DEBUG ListIndex
> - loading
>  2017-09-25 14:35:30,282 [AMQ-1-thread-1 ] DEBUG ListIndex
> - loading
>  2017-09-25 14:35:30,296 [AMQ-1-thread-1 ] INFO  MessageDatabase
> - Recovering from the journal @1:70835
>  2017-09-25 14:35:30,296 [AMQ-1-thread-1 ] INFO  MessageDatabase
> - Recovering from the journal @1:70835
>  2017-09-25 14:35:30,296 [AMQ-1-thread-1 ] INFO  MessageDatabase
> - Recovery replayed 1 operations from the journal in 0.012 seconds.
>  2017-09-25 14:35:30,296 [AMQ-1-thread-1 ] INFO  MessageDatabase
> - Recovery replayed 1 operations from the journal in 0.012 seconds.
>  2017-09-25 14:35:30,297 [AMQ-1-thread-1 ] INFO  KahaDBStore
> - Stopping async queue tasks
>  2017-09-25 14:35:30,297 [AMQ-1-thread-1 ] INFO  KahaDBStore
> - Stopping async topic tasks
>  2017-09-25 14:35:30,297 [AMQ-1-thread-1 ] INFO  KahaDBStore
> - Stopped KahaDB
>  2017-09-25 14:35:30,785 [AMQ-1-thread-1 ] DEBUG KahaDBStore
> - Store OpenWire version configured as: 6
>  2017-09-25 14:35:33,023 [AMQ-1-thread-1 ] TRACE Journal
> - Startup took: 2231 ms
>  2017-09-25 14:35:33,060 [AMQ-1-thread-1 ] INFO  MessageDatabase
> - KahaDB is version 5
>  2017-09-25 14:35:33,060 [AMQ-1-thread-1 ] INFO  MessageDatabase
> - KahaDB is version 5
>  2017-09-25 14:35:33,065 [AMQ-1-thread-1 ] DEBUG ListIndex
> - loading
>  2017-09-25 14:35:33,066 [AMQ-1-thread-1 ] DEBUG ListIndex
> - loading
>  2017-09-25 14:35:33,080 [AMQ-1-thread-1 ] INFO  MessageDatabase
> - Recovering from the journal @1:55603
>  2017-09-25 14:35:33,080 [AMQ-1-thread-1 ] INFO  MessageDatabase
> - Recovering from the journal @1:55603
>  2017-09-25 14:35:33,081 [AMQ-1-thread-1 ] INFO  MessageDatabase
> - Recovery replayed 1 operations from the journal in 0.013 seconds.
>  2017-09-25 14:35:33,081 [AMQ-1-thread-1 ] INFO  MessageDatabase
> - Recovery replayed 1 operations from the journal in 0.013 seconds.
>  2017-09-25 14:35:33,081 [AMQ-1-thread-1 ] INFO  KahaDBStore
> - Stopping async queue tasks
>  2017-09-25 14:35:33,081 [AMQ-1-thread-1 ] INFO  KahaDBStore
> - Stopping async topic tasks
>  2017-09-25 14:35:33,081 [AMQ-1-thread-1 ] INFO  KahaDBStore
> - Stopped KahaDB
>
>
>
> --
> Sent from: http://activemq.2283324.n4.nabble.com/ActiveMQ-User-
> f2341805.html
>


[prev in list] [next in list] [prev in thread] [next in thread]