You are viewing a plain text version of this content. The canonical link for it is here.
Posted to users@directory.apache.org by Slavomir Kocka <sl...@gmail.com> on 2013/07/09 10:27:13 UTC

apacheds @ 100% permanently

Hi,

We use apacheds as authentication storage for websphere application server cluster.
Versions are 2.0.0.M14 and Websphere is 8.0.0.5

We run it on redhat 5.8 (x64), and apacheds is allways running on 100%... :

22014 apacheds  22   0 4391m 1.7g  10m S 109.8 10.6 200:34.23 java 

Is this normal, or is it some configuration issue? When used (for writing, reading) we go up to 200% of CPU...
Any idea, what is going on, or how to analyze issue?

Thanks.

Slavomir Kocka

Re: apacheds @ 100% permanently

Posted by Emmanuel Lécharny <el...@gmail.com>.
Le 7/9/13 5:30 PM, Slavomir Kocka a écrit :
> Hi,
>
> Well. We do prepare some performance tests in concurrent environment, so we will definitely run
> current and redesigned version as well. So it would be interesting to compare. :)
> Questionable is only, if to use it in production...
>
> Is it going to be included in stable stream soon? Or is it some 2.1 branch?

We may push it in the next release, but beside the standard JDBM
backend, which will remain the default bacend, with a strong waring
about its youth.


-- 
Regards,
Cordialement,
Emmanuel Lécharny
www.iktek.com 


Re: apacheds @ 100% permanently

Posted by Slavomir Kocka <sl...@gmail.com>.
Hi,

Well. We do prepare some performance tests in concurrent environment, so we will definitely run
current and redesigned version as well. So it would be interesting to compare. :)
Questionable is only, if to use it in production...

Is it going to be included in stable stream soon? Or is it some 2.1 branch?

Thanks.

On Jul 9, 2013, at 16:04 , Emmanuel Lécharny <el...@gmail.com> wrote:

> Le 7/9/13 3:23 PM, Slavomir Kocka a écrit :
>> Ok,
>> 
>> Well, we are running inside VM on HDD for server usage (Guess 10000 spins/s), but I believe, there are not SSD drives.
>> In fact, we are using JMS to "buffer" writes, and simulate transactional behaviour (in case user is not added due to any reason, JMS container rolls back operation, and tries next time)
>> 
>> As I told we need to add accounts in normal speed. So really, tens of writes per sec. are just fine, and I believe, hardware is more than sufficient...
>> Target is like 6000 accounts within few hours. AS this addition is buffered by JMS, there is no HUGE load...
>> 
>> Today we will move those LDAP servers to dedicated VM machines (this time ubuntu), and will see...
>> I'll post here, if I get some results...
>> 
>> We will also review our JMS config...
>> 
>> Just last question for now. Do you have some syntetic tests with some parallel writes/reads?
> 
> No, but as I said, writes are really a bootleneck. We have tested the
> server with 100 clients reading entries in the server as fast as
> possible, and the server is capable of delivering around 13 000 entries
> per second to the 100 clients as a whole (ie, roughly 130/s to each
> client). If you have some writes at the same time, the performances will
> just be impacted heavily.
> 
> As I said, we are working on a better solution, based on a MVCC backend.
> The biggest advantage of MVCC is that reads can now be processed while a
> write is being processed. As writes will also be sequential, we will be
> able to remove many locks all over the server. We are not far from
> having something that work, we just have a couple of issues with indexes
> on Attributes accepting multiple values. Most of the tests are passing
> but two as of today, and we hope to fix them this week.
> 
> Btw, the read perfs are also better, with an improvement of around 50%
> 
> If you are interested in testing such a backend as soon as we get the
> bugs fixed, just let me know, we can provide some guidance.
> 
> 
> 
> -- 
> Regards,
> Cordialement,
> Emmanuel Lécharny
> www.iktek.com 
> 


Re: apacheds @ 100% permanently

Posted by Emmanuel Lécharny <el...@gmail.com>.
Le 7/9/13 3:23 PM, Slavomir Kocka a écrit :
> Ok,
>
> Well, we are running inside VM on HDD for server usage (Guess 10000 spins/s), but I believe, there are not SSD drives.
> In fact, we are using JMS to "buffer" writes, and simulate transactional behaviour (in case user is not added due to any reason, JMS container rolls back operation, and tries next time)
>
> As I told we need to add accounts in normal speed. So really, tens of writes per sec. are just fine, and I believe, hardware is more than sufficient...
> Target is like 6000 accounts within few hours. AS this addition is buffered by JMS, there is no HUGE load...
>
> Today we will move those LDAP servers to dedicated VM machines (this time ubuntu), and will see...
> I'll post here, if I get some results...
>
> We will also review our JMS config...
>
> Just last question for now. Do you have some syntetic tests with some parallel writes/reads?

No, but as I said, writes are really a bootleneck. We have tested the
server with 100 clients reading entries in the server as fast as
possible, and the server is capable of delivering around 13 000 entries
per second to the 100 clients as a whole (ie, roughly 130/s to each
client). If you have some writes at the same time, the performances will
just be impacted heavily.

As I said, we are working on a better solution, based on a MVCC backend.
The biggest advantage of MVCC is that reads can now be processed while a
write is being processed. As writes will also be sequential, we will be
able to remove many locks all over the server. We are not far from
having something that work, we just have a couple of issues with indexes
on Attributes accepting multiple values. Most of the tests are passing
but two as of today, and we hope to fix them this week.

Btw, the read perfs are also better, with an improvement of around 50%

If you are interested in testing such a backend as soon as we get the
bugs fixed, just let me know, we can provide some guidance.



-- 
Regards,
Cordialement,
Emmanuel Lécharny
www.iktek.com 


Re: apacheds @ 100% permanently

Posted by Slavomir Kocka <sl...@gmail.com>.
Ok,

Well, we are running inside VM on HDD for server usage (Guess 10000 spins/s), but I believe, there are not SSD drives.
In fact, we are using JMS to "buffer" writes, and simulate transactional behaviour (in case user is not added due to any reason, JMS container rolls back operation, and tries next time)

As I told we need to add accounts in normal speed. So really, tens of writes per sec. are just fine, and I believe, hardware is more than sufficient...
Target is like 6000 accounts within few hours. AS this addition is buffered by JMS, there is no HUGE load...

Today we will move those LDAP servers to dedicated VM machines (this time ubuntu), and will see...
I'll post here, if I get some results...

We will also review our JMS config...

Just last question for now. Do you have some syntetic tests with some parallel writes/reads?

On Jul 9, 2013, at 15:03 , Emmanuel Lécharny <el...@gmail.com> wrote:

> Le 7/9/13 2:17 PM, Slavomir Kocka a écrit :
>> Thanks for response.
>> 
>> I'll write into your answers...
>> 
>> 
>> On Jul 9, 2013, at 13:33 , Emmanuel Lécharny <el...@gmail.com> wrote:
>> 
>>> Le 7/9/13 12:35 PM, Slavomir Kocka a écrit :
>>>> The interesting point is, that we have two servers in mirror.
>>>> Not using replication from 2.0, but doing writes separately.
>>>> and the second server is just fine... In identical JVM and same hardware...
>>>> The difference is, that websphere uses first one as main source, and second, as spare...
>>>> 
>>>> Few questions anyway.
>>>> 1. Where I set memory limits? I didn't change it, so currently "top" command shows up to 2 GB RAM occupied by apacheds. Can you please point me out to doc, or just leave default? We are not using swap.
>>> There is no configuration in ApacheDS per se, it's about the JVM memory
>> I understand that, I just found some commented settings in wrapper.conf. I'm running application using command "/etc/init.d/apacheds-2.0.0_M14-default start".
>> So I'm not sure, where can I set JVM params, and if defaults are not sufficient...
> 
> Sorry, I thought you were starting the server in a different way. You
> can modify the wrapper.conf file to increase the default memory used by
> the server (the current default is 384Mb).
>> 
>>> you set when you start the server (or websphere).
>>>> 2. I cannot give you exact numbers, only if I enable logs. 
>>> Rough estimation is good enough. There is a huge difference between 2
>>> additions per second and 200...
>> I believe, now we have like 10 additions per second, if everything goes fine. If not, there is like one addition per 30 seconds... :(
> Damn... Are you using spinning disks or SSD ?
> 
> Also what is the underlying FS ? (and if it's a spinning disk, what is
> the disk speed)
>> What we do is: We run 4 servers in parallel. Each of these servers is doing write sequentially. 
> Are all the servers on the same physical machine ?
> 
> 
>> So in general, there are 4 threads trying to write... As these writes are synchronous (we do not start new write until old one finishes) amount of writes per second depends on apacheds server response... We need at least 10 writes/s.
> 
> Ok, let me give you some insight about the performances I get on my
> machine :
> - I have a SSD (256Gb), a OCX Vertex 3 (so it's not top-notch, but
> pretty decent).
> - when I run the AddPerf test we have, I can inject up to 73 entries per
> second (15 000 entries are injected)
> - the number of indexes are critical : the more index you have, the
> slower the server will be. The default server already uses 7 indexes.
> 
> So it should be enough, as soon as you uses a SSD.
> 
> On a spinning disk, the performances will be drastically worse (probably
> by an order of magnitude).
> 
> The reason is that we have to flush on disk every time we update the
> backend, in order not to lose any information. Ok, it's slightly more
> complicated than that, as we use a journal and a transction manager to
> guareantee that no data will be lost, even if the server crashes.
> 
> Bottom line the backend we use (JDBM) is nothing but the fastest backend
> on earth. We are currently working on a new backend (mavibot, see
> https://cwiki.apache.org/confluence/display/labs/Mavibot) which is at
> least 2.5 times faster (I re-ran the addPerf test and got 193 add/s, a
> 2.6x speed up), but it's not production ready yet.
> 
> We also did some perf tests with Berkeley DB JE, but the performances we
> get are pretty much similar with JDBM, for a li which licence is not
> compatible.
> 
>> 
>>>> What I can say, that there are four parallel servers doing writes... And Whole cell doing reads. So Writes up to 4 servers, reads up to 10 servers (4 as app reads, 10 as infrastructure reads)
>>> FYI, you have to know that while a server is writing, nothing else can
>>> be done (including reads). If you have clients poudning the server with
>>> writes, then it's likely that the other clients will be blocked, and in
>>> this case, it might have some impact on the performances.
>>> 
>> This is not completely clear to me. You say, that if I constantly write to LDAP, I cannot read? 
> No, in fact, between too writes, if some read requests have been
> received, they will be executed. It's just that while a write *is*
> processed, no other operation can run, and while a read is processed, no
> write can be executed (they will just be queued)
> 
> 
> 
> -- 
> Regards,
> Cordialement,
> Emmanuel Lécharny
> www.iktek.com 
> 


Re: apacheds @ 100% permanently

Posted by Emmanuel Lécharny <el...@gmail.com>.
Le 7/9/13 2:17 PM, Slavomir Kocka a écrit :
> Thanks for response.
>
> I'll write into your answers...
>
>
> On Jul 9, 2013, at 13:33 , Emmanuel Lécharny <el...@gmail.com> wrote:
>
>> Le 7/9/13 12:35 PM, Slavomir Kocka a écrit :
>>> The interesting point is, that we have two servers in mirror.
>>> Not using replication from 2.0, but doing writes separately.
>>> and the second server is just fine... In identical JVM and same hardware...
>>> The difference is, that websphere uses first one as main source, and second, as spare...
>>>
>>> Few questions anyway.
>>> 1. Where I set memory limits? I didn't change it, so currently "top" command shows up to 2 GB RAM occupied by apacheds. Can you please point me out to doc, or just leave default? We are not using swap.
>> There is no configuration in ApacheDS per se, it's about the JVM memory
> I understand that, I just found some commented settings in wrapper.conf. I'm running application using command "/etc/init.d/apacheds-2.0.0_M14-default start".
> So I'm not sure, where can I set JVM params, and if defaults are not sufficient...

Sorry, I thought you were starting the server in a different way. You
can modify the wrapper.conf file to increase the default memory used by
the server (the current default is 384Mb).
>
>> you set when you start the server (or websphere).
>>> 2. I cannot give you exact numbers, only if I enable logs. 
>> Rough estimation is good enough. There is a huge difference between 2
>> additions per second and 200...
> I believe, now we have like 10 additions per second, if everything goes fine. If not, there is like one addition per 30 seconds... :(
Damn... Are you using spinning disks or SSD ?

Also what is the underlying FS ? (and if it's a spinning disk, what is
the disk speed)
> What we do is: We run 4 servers in parallel. Each of these servers is doing write sequentially. 
Are all the servers on the same physical machine ?


> So in general, there are 4 threads trying to write... As these writes are synchronous (we do not start new write until old one finishes) amount of writes per second depends on apacheds server response... We need at least 10 writes/s.

Ok, let me give you some insight about the performances I get on my
machine :
- I have a SSD (256Gb), a OCX Vertex 3 (so it's not top-notch, but
pretty decent).
- when I run the AddPerf test we have, I can inject up to 73 entries per
second (15 000 entries are injected)
- the number of indexes are critical : the more index you have, the
slower the server will be. The default server already uses 7 indexes.

So it should be enough, as soon as you uses a SSD.

On a spinning disk, the performances will be drastically worse (probably
by an order of magnitude).

The reason is that we have to flush on disk every time we update the
backend, in order not to lose any information. Ok, it's slightly more
complicated than that, as we use a journal and a transction manager to
guareantee that no data will be lost, even if the server crashes.

Bottom line the backend we use (JDBM) is nothing but the fastest backend
on earth. We are currently working on a new backend (mavibot, see
https://cwiki.apache.org/confluence/display/labs/Mavibot) which is at
least 2.5 times faster (I re-ran the addPerf test and got 193 add/s, a
2.6x speed up), but it's not production ready yet.

We also did some perf tests with Berkeley DB JE, but the performances we
get are pretty much similar with JDBM, for a li which licence is not
compatible.

>
>>> What I can say, that there are four parallel servers doing writes... And Whole cell doing reads. So Writes up to 4 servers, reads up to 10 servers (4 as app reads, 10 as infrastructure reads)
>> FYI, you have to know that while a server is writing, nothing else can
>> be done (including reads). If you have clients poudning the server with
>> writes, then it's likely that the other clients will be blocked, and in
>> this case, it might have some impact on the performances.
>>
> This is not completely clear to me. You say, that if I constantly write to LDAP, I cannot read? 
No, in fact, between too writes, if some read requests have been
received, they will be executed. It's just that while a write *is*
processed, no other operation can run, and while a read is processed, no
write can be executed (they will just be queued)



-- 
Regards,
Cordialement,
Emmanuel Lécharny
www.iktek.com 


Re: apacheds @ 100% permanently

Posted by Slavomir Kocka <sl...@gmail.com>.
Thanks for response.

I'll write into your answers...


On Jul 9, 2013, at 13:33 , Emmanuel Lécharny <el...@gmail.com> wrote:

> Le 7/9/13 12:35 PM, Slavomir Kocka a écrit :
>> The interesting point is, that we have two servers in mirror.
>> Not using replication from 2.0, but doing writes separately.
>> and the second server is just fine... In identical JVM and same hardware...
>> The difference is, that websphere uses first one as main source, and second, as spare...
>> 
>> Few questions anyway.
>> 1. Where I set memory limits? I didn't change it, so currently "top" command shows up to 2 GB RAM occupied by apacheds. Can you please point me out to doc, or just leave default? We are not using swap.
> 
> There is no configuration in ApacheDS per se, it's about the JVM memory

I understand that, I just found some commented settings in wrapper.conf. I'm running application using command "/etc/init.d/apacheds-2.0.0_M14-default start".
So I'm not sure, where can I set JVM params, and if defaults are not sufficient...

> you set when you start the server (or websphere).
>> 2. I cannot give you exact numbers, only if I enable logs. 
> Rough estimation is good enough. There is a huge difference between 2
> additions per second and 200...

I believe, now we have like 10 additions per second, if everything goes fine. If not, there is like one addition per 30 seconds... :(
What we do is: We run 4 servers in parallel. Each of these servers is doing write sequentially. So in general, there are 4 threads trying to write... As these writes are synchronous (we do not start new write until old one finishes) amount of writes per second depends on apacheds server response... We need at least 10 writes/s.

> 
>> What I can say, that there are four parallel servers doing writes... And Whole cell doing reads. So Writes up to 4 servers, reads up to 10 servers (4 as app reads, 10 as infrastructure reads)
> FYI, you have to know that while a server is writing, nothing else can
> be done (including reads). If you have clients poudning the server with
> writes, then it's likely that the other clients will be blocked, and in
> this case, it might have some impact on the performances.
> 

This is not completely clear to me. You say, that if I constantly write to LDAP, I cannot read? I guess, that requests should be in queue, and when one write finishes, I should be able to read, and so on...
So requests one by one (readings might be parallel).

Thanks.

regards,

Slavomir Kocka

> 
> -- 
> Regards,
> Cordialement,
> Emmanuel Lécharny
> www.iktek.com 
> 


Re: apacheds @ 100% permanently

Posted by Emmanuel Lécharny <el...@gmail.com>.
Le 7/9/13 12:35 PM, Slavomir Kocka a écrit :
> The interesting point is, that we have two servers in mirror.
> Not using replication from 2.0, but doing writes separately.
> and the second server is just fine... In identical JVM and same hardware...
> The difference is, that websphere uses first one as main source, and second, as spare...
>
> Few questions anyway.
> 1. Where I set memory limits? I didn't change it, so currently "top" command shows up to 2 GB RAM occupied by apacheds. Can you please point me out to doc, or just leave default? We are not using swap.

There is no configuration in ApacheDS per se, it's about the JVM memory
you set when you start the server (or websphere).
> 2. I cannot give you exact numbers, only if I enable logs. 
Rough estimation is good enough. There is a huge difference between 2
additions per second and 200...

> What I can say, that there are four parallel servers doing writes... And Whole cell doing reads. So Writes up to 4 servers, reads up to 10 servers (4 as app reads, 10 as infrastructure reads)
FYI, you have to know that while a server is writing, nothing else can
be done (including reads). If you have clients poudning the server with
writes, then it's likely that the other clients will be blocked, and in
this case, it might have some impact on the performances.


-- 
Regards,
Cordialement,
Emmanuel Lécharny
www.iktek.com 


Re: apacheds @ 100% permanently

Posted by Slavomir Kocka <sl...@gmail.com>.
The interesting point is, that we have two servers in mirror.
Not using replication from 2.0, but doing writes separately.
and the second server is just fine... In identical JVM and same hardware...
The difference is, that websphere uses first one as main source, and second, as spare...

Few questions anyway.
1. Where I set memory limits? I didn't change it, so currently "top" command shows up to 2 GB RAM occupied by apacheds. Can you please point me out to doc, or just leave default? We are not using swap.
2. I cannot give you exact numbers, only if I enable logs. What I can say, that there are four parallel servers doing writes... And Whole cell doing reads. So Writes up to 4 servers, reads up to 10 servers (4 as app reads, 10 as infrastructure reads)
3. Will do that, and see the results tomorrow, when we shutdown servers...

On Jul 9, 2013, at 11:59 , Emmanuel Lécharny <el...@gmail.com> wrote:

> Le 7/9/13 11:41 AM, Slavomir Kocka a écrit :
>> Hi,
>> 
>> There is cluster of 4 servers writing intensively to LDAP. But even ,when there is no write, there is 100%...
> 
> Most certainly because the backend is tryong to catch up on the writes...
> 
> Also what is the memory configuration ? ApacheDS is very demanding, and
> if you keep the memory low, you will have a lot of GC and cache
> management. Try to increase the allocated memory.
> 
> At this point, a little mor einfo about the test you are running (ie,
> number of read/writes per second) and the configuration would help
> (especially if you are using replication).
> 
> Last, not least, which Java version are you using ? I think it's a 1.6
> version, you should try with Java 1.7
> 
> 
> -- 
> Regards,
> Cordialement,
> Emmanuel Lécharny
> www.iktek.com 
> 


Re: apacheds @ 100% permanently

Posted by Emmanuel Lécharny <el...@gmail.com>.
Le 7/9/13 11:41 AM, Slavomir Kocka a écrit :
> Hi,
>
> There is cluster of 4 servers writing intensively to LDAP. But even ,when there is no write, there is 100%...

Most certainly because the backend is tryong to catch up on the writes...

Also what is the memory configuration ? ApacheDS is very demanding, and
if you keep the memory low, you will have a lot of GC and cache
management. Try to increase the allocated memory.

At this point, a little mor einfo about the test you are running (ie,
number of read/writes per second) and the configuration would help
(especially if you are using replication).

Last, not least, which Java version are you using ? I think it's a 1.6
version, you should try with Java 1.7


-- 
Regards,
Cordialement,
Emmanuel Lécharny
www.iktek.com 


Re: apacheds @ 100% permanently

Posted by Slavomir Kocka <sl...@gmail.com>.
Hi,

There is cluster of 4 servers writing intensively to LDAP. But even ,when there is no write, there is 100%...
However I can wait to end of the tests, to try to make thread dump then, if it is needed...

after kill -3 I found this in wrapper.log:

INFO   | jvm 1    | 2013/07/09 11:38:16 | Full thread dump Java HotSpot(TM) 64-Bit Server VM (20.45-b01 mixed mode):
INFO   | jvm 1    | 2013/07/09 11:38:16 | 
INFO   | jvm 1    | 2013/07/09 11:38:16 | "pool-6-thread-49" prio=10 tid=0x00002aaab3645800 nid=0x1cc4 waiting for monitor entry [0x0000000043790000]
INFO   | jvm 1    | 2013/07/09 11:38:16 |    java.lang.Thread.State: BLOCKED (on object monitor)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at jdbm.btree.BTree.find(BTree.java:400)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	- waiting to lock <0x0000000705b0dc38> (a jdbm.btree.BTree)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.directory.server.core.partition.impl.btree.jdbm.JdbmTable.get(JdbmTable.java:325)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.directory.server.core.partition.impl.btree.AbstractBTreePartition.fetch(AbstractBTreePartition.java:1124)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.directory.server.core.partition.impl.btree.AbstractBTreePartition.fetch(AbstractBTreePartition.java:1085)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.directory.server.xdbm.search.evaluator.SubtreeScopeEvaluator.evaluate(SubtreeScopeEvaluator.java:169)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.directory.server.xdbm.search.evaluator.AndEvaluator.evaluate(AndEvaluator.java:110)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.directory.server.core.partition.impl.btree.EntryCursorAdaptor.get(EntryCursorAdaptor.java:169)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.directory.server.core.partition.impl.btree.EntryCursorAdaptor.get(EntryCursorAdaptor.java:45)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.directory.server.core.api.filtering.BaseEntryFilteringCursor.next(BaseEntryFilteringCursor.java:379)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.directory.server.ldap.handlers.request.SearchRequestHandler.writeResults(SearchRequestHandler.java:391)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.directory.server.ldap.handlers.request.SearchRequestHandler.doSimpleSearch(SearchRequestHandler.java:845)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.directory.server.ldap.handlers.request.SearchRequestHandler.handleIgnoringReferrals(SearchRequestHandler.java:1153)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.directory.server.ldap.handlers.request.SearchRequestHandler.handle(SearchRequestHandler.java:206)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.directory.server.ldap.handlers.request.SearchRequestHandler.handle(SearchRequestHandler.java:92)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.directory.server.ldap.handlers.LdapRequestHandler.handleMessage(LdapRequestHandler.java:206)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.directory.server.ldap.handlers.LdapRequestHandler.handleMessage(LdapRequestHandler.java:55)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.mina.handler.demux.DemuxingIoHandler.messageReceived(DemuxingIoHandler.java:221)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.directory.server.ldap.LdapProtocolHandler.messageReceived(LdapProtocolHandler.java:217)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.mina.core.filterchain.DefaultIoFilterChain$TailFilter.messageReceived(DefaultIoFilterChain.java:690)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextMessageReceived(DefaultIoFilterChain.java:417)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.mina.core.filterchain.DefaultIoFilterChain.access$1200(DefaultIoFilterChain.java:47)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.mina.core.filterchain.DefaultIoFilterChain$EntryImpl$1.messageReceived(DefaultIoFilterChain.java:765)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.mina.core.filterchain.IoFilterEvent.fire(IoFilterEvent.java:74)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.mina.core.session.IoEvent.run(IoEvent.java:63)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.mina.filter.executor.UnorderedThreadPoolExecutor$Worker.runTask(UnorderedThreadPoolExecutor.java:474)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.mina.filter.executor.UnorderedThreadPoolExecutor$Worker.run(UnorderedThreadPoolExecutor.java:428)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at java.lang.Thread.run(Thread.java:662)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 
INFO   | jvm 1    | 2013/07/09 11:38:16 | "pool-6-thread-48" prio=10 tid=0x00002aaab2cce000 nid=0x1cc3 waiting for monitor entry [0x000000004368f000]
INFO   | jvm 1    | 2013/07/09 11:38:16 |    java.lang.Thread.State: BLOCKED (on object monitor)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at jdbm.btree.BTree.find(BTree.java:400)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	- waiting to lock <0x0000000705b0dc38> (a jdbm.btree.BTree)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.directory.server.core.partition.impl.btree.jdbm.JdbmTable.get(JdbmTable.java:325)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.directory.server.core.partition.impl.btree.AbstractBTreePartition.fetch(AbstractBTreePartition.java:1124)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.directory.server.core.partition.impl.btree.AbstractBTreePartition.fetch(AbstractBTreePartition.java:1085)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.directory.server.xdbm.search.evaluator.SubtreeScopeEvaluator.evaluate(SubtreeScopeEvaluator.java:169)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.directory.server.xdbm.search.evaluator.AndEvaluator.evaluate(AndEvaluator.java:110)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.directory.server.core.partition.impl.btree.EntryCursorAdaptor.get(EntryCursorAdaptor.java:169)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.directory.server.core.partition.impl.btree.EntryCursorAdaptor.get(EntryCursorAdaptor.java:45)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.directory.server.core.api.filtering.BaseEntryFilteringCursor.next(BaseEntryFilteringCursor.java:379)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.directory.server.ldap.handlers.request.SearchRequestHandler.writeResults(SearchRequestHandler.java:391)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.directory.server.ldap.handlers.request.SearchRequestHandler.doSimpleSearch(SearchRequestHandler.java:845)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.directory.server.ldap.handlers.request.SearchRequestHandler.handleIgnoringReferrals(SearchRequestHandler.java:1153)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.directory.server.ldap.handlers.request.SearchRequestHandler.handle(SearchRequestHandler.java:206)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.directory.server.ldap.handlers.request.SearchRequestHandler.handle(SearchRequestHandler.java:92)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.directory.server.ldap.handlers.LdapRequestHandler.handleMessage(LdapRequestHandler.java:206)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.directory.server.ldap.handlers.LdapRequestHandler.handleMessage(LdapRequestHandler.java:55)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.mina.handler.demux.DemuxingIoHandler.messageReceived(DemuxingIoHandler.java:221)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.directory.server.ldap.LdapProtocolHandler.messageReceived(LdapProtocolHandler.java:217)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.mina.core.filterchain.DefaultIoFilterChain$TailFilter.messageReceived(DefaultIoFilterChain.java:690)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextMessageReceived(DefaultIoFilterChain.java:417)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.mina.core.filterchain.DefaultIoFilterChain.access$1200(DefaultIoFilterChain.java:47)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.mina.core.filterchain.DefaultIoFilterChain$EntryImpl$1.messageReceived(DefaultIoFilterChain.java:765)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.mina.core.filterchain.IoFilterEvent.fire(IoFilterEvent.java:74)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.mina.core.session.IoEvent.run(IoEvent.java:63)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.mina.filter.executor.UnorderedThreadPoolExecutor$Worker.runTask(UnorderedThreadPoolExecutor.java:474)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.mina.filter.executor.UnorderedThreadPoolExecutor$Worker.run(UnorderedThreadPoolExecutor.java:428)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at java.lang.Thread.run(Thread.java:662)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 
INFO   | jvm 1    | 2013/07/09 11:38:16 | "pool-6-thread-47" prio=10 tid=0x00002aaab2ccd800 nid=0x1cc0 waiting for monitor entry [0x000000004021c000]
INFO   | jvm 1    | 2013/07/09 11:38:16 |    java.lang.Thread.State: BLOCKED (on object monitor)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at jdbm.btree.BTree.find(BTree.java:400)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	- waiting to lock <0x0000000705b0dc38> (a jdbm.btree.BTree)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.directory.server.core.partition.impl.btree.jdbm.JdbmTable.get(JdbmTable.java:325)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.directory.server.core.partition.impl.btree.AbstractBTreePartition.fetch(AbstractBTreePartition.java:1124)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.directory.server.core.partition.impl.btree.AbstractBTreePartition.fetch(AbstractBTreePartition.java:1085)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.directory.server.xdbm.search.evaluator.SubtreeScopeEvaluator.evaluate(SubtreeScopeEvaluator.java:169)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.directory.server.xdbm.search.evaluator.AndEvaluator.evaluate(AndEvaluator.java:110)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.directory.server.core.partition.impl.btree.EntryCursorAdaptor.get(EntryCursorAdaptor.java:169)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.directory.server.core.partition.impl.btree.EntryCursorAdaptor.get(EntryCursorAdaptor.java:45)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.directory.server.core.api.filtering.BaseEntryFilteringCursor.next(BaseEntryFilteringCursor.java:379)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.directory.server.ldap.handlers.request.SearchRequestHandler.writeResults(SearchRequestHandler.java:391)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.directory.server.ldap.handlers.request.SearchRequestHandler.doSimpleSearch(SearchRequestHandler.java:845)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.directory.server.ldap.handlers.request.SearchRequestHandler.handleIgnoringReferrals(SearchRequestHandler.java:1153)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.directory.server.ldap.handlers.request.SearchRequestHandler.handle(SearchRequestHandler.java:206)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.directory.server.ldap.handlers.request.SearchRequestHandler.handle(SearchRequestHandler.java:92)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.directory.server.ldap.handlers.LdapRequestHandler.handleMessage(LdapRequestHandler.java:206)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.directory.server.ldap.handlers.LdapRequestHandler.handleMessage(LdapRequestHandler.java:55)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.mina.handler.demux.DemuxingIoHandler.messageReceived(DemuxingIoHandler.java:221)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.directory.server.ldap.LdapProtocolHandler.messageReceived(LdapProtocolHandler.java:217)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.mina.core.filterchain.DefaultIoFilterChain$TailFilter.messageReceived(DefaultIoFilterChain.java:690)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextMessageReceived(DefaultIoFilterChain.java:417)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.mina.core.filterchain.DefaultIoFilterChain.access$1200(DefaultIoFilterChain.java:47)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.mina.core.filterchain.DefaultIoFilterChain$EntryImpl$1.messageReceived(DefaultIoFilterChain.java:765)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.mina.core.filterchain.IoFilterEvent.fire(IoFilterEvent.java:74)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.mina.core.session.IoEvent.run(IoEvent.java:63)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.mina.filter.executor.UnorderedThreadPoolExecutor$Worker.runTask(UnorderedThreadPoolExecutor.java:474)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.mina.filter.executor.UnorderedThreadPoolExecutor$Worker.run(UnorderedThreadPoolExecutor.java:428)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at java.lang.Thread.run(Thread.java:662)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 
INFO   | jvm 1    | 2013/07/09 11:38:16 | "pool-6-thread-46" prio=10 tid=0x00002aaab3594800 nid=0x1b7c waiting for monitor entry [0x000000004348d000]
INFO   | jvm 1    | 2013/07/09 11:38:16 |    java.lang.Thread.State: BLOCKED (on object monitor)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at jdbm.btree.BTree.find(BTree.java:400)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	- waiting to lock <0x0000000705b0dc38> (a jdbm.btree.BTree)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.directory.server.core.partition.impl.btree.jdbm.JdbmTable.get(JdbmTable.java:325)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.directory.server.core.partition.impl.btree.AbstractBTreePartition.fetch(AbstractBTreePartition.java:1124)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.directory.server.core.partition.impl.btree.AbstractBTreePartition.fetch(AbstractBTreePartition.java:1085)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.directory.server.xdbm.search.evaluator.SubtreeScopeEvaluator.evaluate(SubtreeScopeEvaluator.java:169)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.directory.server.xdbm.search.evaluator.AndEvaluator.evaluate(AndEvaluator.java:110)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.directory.server.core.partition.impl.btree.EntryCursorAdaptor.get(EntryCursorAdaptor.java:169)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.directory.server.core.partition.impl.btree.EntryCursorAdaptor.get(EntryCursorAdaptor.java:45)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.directory.server.core.api.filtering.BaseEntryFilteringCursor.next(BaseEntryFilteringCursor.java:379)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.directory.server.ldap.handlers.request.SearchRequestHandler.writeResults(SearchRequestHandler.java:391)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.directory.server.ldap.handlers.request.SearchRequestHandler.doSimpleSearch(SearchRequestHandler.java:845)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.directory.server.ldap.handlers.request.SearchRequestHandler.handleIgnoringReferrals(SearchRequestHandler.java:1153)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.directory.server.ldap.handlers.request.SearchRequestHandler.handle(SearchRequestHandler.java:206)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.directory.server.ldap.handlers.request.SearchRequestHandler.handle(SearchRequestHandler.java:92)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.directory.server.ldap.handlers.LdapRequestHandler.handleMessage(LdapRequestHandler.java:206)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.directory.server.ldap.handlers.LdapRequestHandler.handleMessage(LdapRequestHandler.java:55)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.mina.handler.demux.DemuxingIoHandler.messageReceived(DemuxingIoHandler.java:221)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.directory.server.ldap.LdapProtocolHandler.messageReceived(LdapProtocolHandler.java:217)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.mina.core.filterchain.DefaultIoFilterChain$TailFilter.messageReceived(DefaultIoFilterChain.java:690)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextMessageReceived(DefaultIoFilterChain.java:417)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.mina.core.filterchain.DefaultIoFilterChain.access$1200(DefaultIoFilterChain.java:47)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.mina.core.filterchain.DefaultIoFilterChain$EntryImpl$1.messageReceived(DefaultIoFilterChain.java:765)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.mina.core.filterchain.IoFilterEvent.fire(IoFilterEvent.java:74)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.mina.core.session.IoEvent.run(IoEvent.java:63)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.mina.filter.executor.UnorderedThreadPoolExecutor$Worker.runTask(UnorderedThreadPoolExecutor.java:474)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.mina.filter.executor.UnorderedThreadPoolExecutor$Worker.run(UnorderedThreadPoolExecutor.java:428)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at java.lang.Thread.run(Thread.java:662)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 
INFO   | jvm 1    | 2013/07/09 11:38:16 | "pool-6-thread-45" prio=10 tid=0x00002aaab3594000 nid=0x1b6c waiting for monitor entry [0x0000000042e87000]
INFO   | jvm 1    | 2013/07/09 11:38:16 |    java.lang.Thread.State: BLOCKED (on object monitor)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at jdbm.btree.BTree.find(BTree.java:400)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	- waiting to lock <0x0000000705b0dc38> (a jdbm.btree.BTree)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.directory.server.core.partition.impl.btree.jdbm.JdbmTable.get(JdbmTable.java:325)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.directory.server.core.partition.impl.btree.AbstractBTreePartition.fetch(AbstractBTreePartition.java:1124)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.directory.server.core.partition.impl.btree.AbstractBTreePartition.fetch(AbstractBTreePartition.java:1085)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.directory.server.xdbm.search.evaluator.SubtreeScopeEvaluator.evaluate(SubtreeScopeEvaluator.java:169)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.directory.server.xdbm.search.evaluator.AndEvaluator.evaluate(AndEvaluator.java:110)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.directory.server.core.partition.impl.btree.EntryCursorAdaptor.get(EntryCursorAdaptor.java:169)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.directory.server.core.partition.impl.btree.EntryCursorAdaptor.get(EntryCursorAdaptor.java:45)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.directory.server.core.api.filtering.BaseEntryFilteringCursor.next(BaseEntryFilteringCursor.java:379)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.directory.server.ldap.handlers.request.SearchRequestHandler.writeResults(SearchRequestHandler.java:391)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.directory.server.ldap.handlers.request.SearchRequestHandler.doSimpleSearch(SearchRequestHandler.java:845)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.directory.server.ldap.handlers.request.SearchRequestHandler.handleIgnoringReferrals(SearchRequestHandler.java:1153)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.directory.server.ldap.handlers.request.SearchRequestHandler.handle(SearchRequestHandler.java:206)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.directory.server.ldap.handlers.request.SearchRequestHandler.handle(SearchRequestHandler.java:92)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.directory.server.ldap.handlers.LdapRequestHandler.handleMessage(LdapRequestHandler.java:206)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.directory.server.ldap.handlers.LdapRequestHandler.handleMessage(LdapRequestHandler.java:55)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.mina.handler.demux.DemuxingIoHandler.messageReceived(DemuxingIoHandler.java:221)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.directory.server.ldap.LdapProtocolHandler.messageReceived(LdapProtocolHandler.java:217)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.mina.core.filterchain.DefaultIoFilterChain$TailFilter.messageReceived(DefaultIoFilterChain.java:690)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextMessageReceived(DefaultIoFilterChain.java:417)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.mina.core.filterchain.DefaultIoFilterChain.access$1200(DefaultIoFilterChain.java:47)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.mina.core.filterchain.DefaultIoFilterChain$EntryImpl$1.messageReceived(DefaultIoFilterChain.java:765)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.mina.core.filterchain.IoFilterEvent.fire(IoFilterEvent.java:74)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.mina.core.session.IoEvent.run(IoEvent.java:63)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.mina.filter.executor.UnorderedThreadPoolExecutor$Worker.runTask(UnorderedThreadPoolExecutor.java:474)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.mina.filter.executor.UnorderedThreadPoolExecutor$Worker.run(UnorderedThreadPoolExecutor.java:428)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at java.lang.Thread.run(Thread.java:662)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 
INFO   | jvm 1    | 2013/07/09 11:38:16 | "pool-6-thread-44" prio=10 tid=0x00002aaab3052000 nid=0x1b69 waiting for monitor entry [0x000000004328b000]
INFO   | jvm 1    | 2013/07/09 11:38:16 |    java.lang.Thread.State: BLOCKED (on object monitor)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at jdbm.btree.BTree.find(BTree.java:400)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	- waiting to lock <0x0000000705b0dc38> (a jdbm.btree.BTree)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.directory.server.core.partition.impl.btree.jdbm.JdbmTable.get(JdbmTable.java:325)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.directory.server.core.partition.impl.btree.AbstractBTreePartition.fetch(AbstractBTreePartition.java:1124)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.directory.server.core.partition.impl.btree.AbstractBTreePartition.fetch(AbstractBTreePartition.java:1085)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.directory.server.xdbm.search.evaluator.SubtreeScopeEvaluator.evaluate(SubtreeScopeEvaluator.java:169)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.directory.server.xdbm.search.evaluator.AndEvaluator.evaluate(AndEvaluator.java:110)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.directory.server.core.partition.impl.btree.EntryCursorAdaptor.get(EntryCursorAdaptor.java:169)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.directory.server.core.partition.impl.btree.EntryCursorAdaptor.get(EntryCursorAdaptor.java:45)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.directory.server.core.api.filtering.BaseEntryFilteringCursor.next(BaseEntryFilteringCursor.java:379)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.directory.server.ldap.handlers.request.SearchRequestHandler.writeResults(SearchRequestHandler.java:391)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.directory.server.ldap.handlers.request.SearchRequestHandler.doSimpleSearch(SearchRequestHandler.java:845)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.directory.server.ldap.handlers.request.SearchRequestHandler.handleIgnoringReferrals(SearchRequestHandler.java:1153)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.directory.server.ldap.handlers.request.SearchRequestHandler.handle(SearchRequestHandler.java:206)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.directory.server.ldap.handlers.request.SearchRequestHandler.handle(SearchRequestHandler.java:92)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.directory.server.ldap.handlers.LdapRequestHandler.handleMessage(LdapRequestHandler.java:206)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.directory.server.ldap.handlers.LdapRequestHandler.handleMessage(LdapRequestHandler.java:55)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.mina.handler.demux.DemuxingIoHandler.messageReceived(DemuxingIoHandler.java:221)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.directory.server.ldap.LdapProtocolHandler.messageReceived(LdapProtocolHandler.java:217)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.mina.core.filterchain.DefaultIoFilterChain$TailFilter.messageReceived(DefaultIoFilterChain.java:690)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextMessageReceived(DefaultIoFilterChain.java:417)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.mina.core.filterchain.DefaultIoFilterChain.access$1200(DefaultIoFilterChain.java:47)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.mina.core.filterchain.DefaultIoFilterChain$EntryImpl$1.messageReceived(DefaultIoFilterChain.java:765)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.mina.core.filterchain.IoFilterEvent.fire(IoFilterEvent.java:74)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.mina.core.session.IoEvent.run(IoEvent.java:63)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.mina.filter.executor.UnorderedThreadPoolExecutor$Worker.runTask(UnorderedThreadPoolExecutor.java:474)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.mina.filter.executor.UnorderedThreadPoolExecutor$Worker.run(UnorderedThreadPoolExecutor.java:428)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at java.lang.Thread.run(Thread.java:662)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 
INFO   | jvm 1    | 2013/07/09 11:38:16 | "pool-6-thread-43" prio=10 tid=0x00002aaab3051800 nid=0x1b21 waiting for monitor entry [0x000000004338c000]
INFO   | jvm 1    | 2013/07/09 11:38:16 |    java.lang.Thread.State: BLOCKED (on object monitor)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at jdbm.btree.BTree.find(BTree.java:400)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	- waiting to lock <0x0000000705b0dc38> (a jdbm.btree.BTree)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.directory.server.core.partition.impl.btree.jdbm.JdbmTable.get(JdbmTable.java:325)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.directory.server.core.partition.impl.btree.AbstractBTreePartition.fetch(AbstractBTreePartition.java:1124)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.directory.server.core.partition.impl.btree.AbstractBTreePartition.fetch(AbstractBTreePartition.java:1085)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.directory.server.xdbm.search.evaluator.SubtreeScopeEvaluator.evaluate(SubtreeScopeEvaluator.java:169)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.directory.server.xdbm.search.evaluator.AndEvaluator.evaluate(AndEvaluator.java:110)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.directory.server.core.partition.impl.btree.EntryCursorAdaptor.get(EntryCursorAdaptor.java:169)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.directory.server.core.partition.impl.btree.EntryCursorAdaptor.get(EntryCursorAdaptor.java:45)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.directory.server.core.api.filtering.BaseEntryFilteringCursor.next(BaseEntryFilteringCursor.java:379)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.directory.server.ldap.handlers.request.SearchRequestHandler.writeResults(SearchRequestHandler.java:391)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.directory.server.ldap.handlers.request.SearchRequestHandler.doSimpleSearch(SearchRequestHandler.java:845)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.directory.server.ldap.handlers.request.SearchRequestHandler.handleIgnoringReferrals(SearchRequestHandler.java:1153)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.directory.server.ldap.handlers.request.SearchRequestHandler.handle(SearchRequestHandler.java:206)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.directory.server.ldap.handlers.request.SearchRequestHandler.handle(SearchRequestHandler.java:92)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.directory.server.ldap.handlers.LdapRequestHandler.handleMessage(LdapRequestHandler.java:206)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.directory.server.ldap.handlers.LdapRequestHandler.handleMessage(LdapRequestHandler.java:55)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.mina.handler.demux.DemuxingIoHandler.messageReceived(DemuxingIoHandler.java:221)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.directory.server.ldap.LdapProtocolHandler.messageReceived(LdapProtocolHandler.java:217)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.mina.core.filterchain.DefaultIoFilterChain$TailFilter.messageReceived(DefaultIoFilterChain.java:690)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextMessageReceived(DefaultIoFilterChain.java:417)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.mina.core.filterchain.DefaultIoFilterChain.access$1200(DefaultIoFilterChain.java:47)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.mina.core.filterchain.DefaultIoFilterChain$EntryImpl$1.messageReceived(DefaultIoFilterChain.java:765)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.mina.core.filterchain.IoFilterEvent.fire(IoFilterEvent.java:74)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.mina.core.session.IoEvent.run(IoEvent.java:63)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.mina.filter.executor.UnorderedThreadPoolExecutor$Worker.runTask(UnorderedThreadPoolExecutor.java:474)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.mina.filter.executor.UnorderedThreadPoolExecutor$Worker.run(UnorderedThreadPoolExecutor.java:428)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at java.lang.Thread.run(Thread.java:662)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 
INFO   | jvm 1    | 2013/07/09 11:38:16 | "NioProcessor-11" prio=10 tid=0x00002aaab4042800 nid=0x1b1f runnable [0x0000000042d86000]
INFO   | jvm 1    | 2013/07/09 11:38:16 |    java.lang.Thread.State: RUNNABLE
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at sun.nio.ch.EPollArrayWrapper.epollWait(Native Method)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at sun.nio.ch.EPollArrayWrapper.poll(EPollArrayWrapper.java:210)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at sun.nio.ch.EPollSelectorImpl.doSelect(EPollSelectorImpl.java:65)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:69)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	- locked <0x000000070794ee20> (a sun.nio.ch.Util$2)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	- locked <0x000000070794ee10> (a java.util.Collections$UnmodifiableSet)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	- locked <0x000000070794ec08> (a sun.nio.ch.EPollSelectorImpl)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:80)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.mina.transport.socket.nio.NioProcessor.select(NioProcessor.java:72)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.run(AbstractPollingIoProcessor.java:1077)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:64)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:895)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:918)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at java.lang.Thread.run(Thread.java:662)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 
INFO   | jvm 1    | 2013/07/09 11:38:16 | "NioProcessor-10" prio=10 tid=0x00002aaab4465800 nid=0x1b1b runnable [0x000000004358e000]
INFO   | jvm 1    | 2013/07/09 11:38:16 |    java.lang.Thread.State: RUNNABLE
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at sun.nio.ch.EPollArrayWrapper.epollWait(Native Method)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at sun.nio.ch.EPollArrayWrapper.poll(EPollArrayWrapper.java:210)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at sun.nio.ch.EPollSelectorImpl.doSelect(EPollSelectorImpl.java:65)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:69)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	- locked <0x0000000707964e38> (a sun.nio.ch.Util$2)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	- locked <0x0000000707964e28> (a java.util.Collections$UnmodifiableSet)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	- locked <0x0000000707964c20> (a sun.nio.ch.EPollSelectorImpl)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:80)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.mina.transport.socket.nio.NioProcessor.select(NioProcessor.java:72)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.run(AbstractPollingIoProcessor.java:1077)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:64)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:895)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:918)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at java.lang.Thread.run(Thread.java:662)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 
INFO   | jvm 1    | 2013/07/09 11:38:16 | "NioProcessor-6" prio=10 tid=0x00002aaab4041000 nid=0x1acf runnable [0x00000000415c3000]
INFO   | jvm 1    | 2013/07/09 11:38:16 |    java.lang.Thread.State: RUNNABLE
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at sun.nio.ch.EPollArrayWrapper.epollWait(Native Method)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at sun.nio.ch.EPollArrayWrapper.poll(EPollArrayWrapper.java:210)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at sun.nio.ch.EPollSelectorImpl.doSelect(EPollSelectorImpl.java:65)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:69)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	- locked <0x0000000707965e10> (a sun.nio.ch.Util$2)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	- locked <0x0000000707965e00> (a java.util.Collections$UnmodifiableSet)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	- locked <0x0000000707965bc8> (a sun.nio.ch.EPollSelectorImpl)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:80)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.mina.transport.socket.nio.NioProcessor.select(NioProcessor.java:72)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.run(AbstractPollingIoProcessor.java:1077)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:64)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:895)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:918)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at java.lang.Thread.run(Thread.java:662)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 
INFO   | jvm 1    | 2013/07/09 11:38:16 | "pool-6-thread-42" prio=10 tid=0x00002aaab3054800 nid=0x1acd runnable [0x0000000043189000]
INFO   | jvm 1    | 2013/07/09 11:38:16 |    java.lang.Thread.State: RUNNABLE
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at java.util.LinkedList.access$200(LinkedList.java:74)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at java.util.LinkedList$ListItr.remove(LinkedList.java:732)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at jdbm.recman.RecordFile.get(RecordFile.java:176)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at jdbm.recman.PageManager.getNext(PageManager.java:237)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at jdbm.recman.PageCursor.next(PageCursor.java:104)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at jdbm.recman.PhysicalRowIdManager.fetch(PhysicalRowIdManager.java:159)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at jdbm.recman.BaseRecordManager.fetch(BaseRecordManager.java:323)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	- locked <0x0000000705b01960> (a jdbm.recman.BaseRecordManager)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at jdbm.recman.CacheRecordManager.fetch(CacheRecordManager.java:264)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	- locked <0x0000000705b01948> (a jdbm.recman.CacheRecordManager)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at jdbm.btree.BPage.loadBPage(BPage.java:949)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at jdbm.btree.BPage.find(BPage.java:280)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at jdbm.btree.BTree.find(BTree.java:413)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	- locked <0x0000000705b0dc38> (a jdbm.btree.BTree)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.directory.server.core.partition.impl.btree.jdbm.JdbmTable.get(JdbmTable.java:325)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.directory.server.core.partition.impl.btree.AbstractBTreePartition.fetch(AbstractBTreePartition.java:1124)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.directory.server.core.partition.impl.btree.AbstractBTreePartition.fetch(AbstractBTreePartition.java:1085)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.directory.server.xdbm.search.evaluator.SubtreeScopeEvaluator.evaluate(SubtreeScopeEvaluator.java:169)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.directory.server.xdbm.search.evaluator.AndEvaluator.evaluate(AndEvaluator.java:110)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.directory.server.core.partition.impl.btree.EntryCursorAdaptor.get(EntryCursorAdaptor.java:169)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.directory.server.core.partition.impl.btree.EntryCursorAdaptor.get(EntryCursorAdaptor.java:45)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.directory.server.core.api.filtering.BaseEntryFilteringCursor.next(BaseEntryFilteringCursor.java:379)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.directory.server.ldap.handlers.request.SearchRequestHandler.writeResults(SearchRequestHandler.java:391)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.directory.server.ldap.handlers.request.SearchRequestHandler.doSimpleSearch(SearchRequestHandler.java:845)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.directory.server.ldap.handlers.request.SearchRequestHandler.handleIgnoringReferrals(SearchRequestHandler.java:1153)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.directory.server.ldap.handlers.request.SearchRequestHandler.handle(SearchRequestHandler.java:206)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.directory.server.ldap.handlers.request.SearchRequestHandler.handle(SearchRequestHandler.java:92)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.directory.server.ldap.handlers.LdapRequestHandler.handleMessage(LdapRequestHandler.java:206)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.directory.server.ldap.handlers.LdapRequestHandler.handleMessage(LdapRequestHandler.java:55)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.mina.handler.demux.DemuxingIoHandler.messageReceived(DemuxingIoHandler.java:221)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.directory.server.ldap.LdapProtocolHandler.messageReceived(LdapProtocolHandler.java:217)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.mina.core.filterchain.DefaultIoFilterChain$TailFilter.messageReceived(DefaultIoFilterChain.java:690)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextMessageReceived(DefaultIoFilterChain.java:417)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.mina.core.filterchain.DefaultIoFilterChain.access$1200(DefaultIoFilterChain.java:47)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.mina.core.filterchain.DefaultIoFilterChain$EntryImpl$1.messageReceived(DefaultIoFilterChain.java:765)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.mina.core.filterchain.IoFilterEvent.fire(IoFilterEvent.java:74)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.mina.core.session.IoEvent.run(IoEvent.java:63)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.mina.filter.executor.UnorderedThreadPoolExecutor$Worker.runTask(UnorderedThreadPoolExecutor.java:474)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.mina.filter.executor.UnorderedThreadPoolExecutor$Worker.run(UnorderedThreadPoolExecutor.java:428)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at java.lang.Thread.run(Thread.java:662)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 
INFO   | jvm 1    | 2013/07/09 11:38:16 | "NioProcessor-7" prio=10 tid=0x00002aaab42d8000 nid=0x660f runnable [0x0000000043089000]
INFO   | jvm 1    | 2013/07/09 11:38:16 |    java.lang.Thread.State: RUNNABLE
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at sun.nio.ch.EPollArrayWrapper.epollWait(Native Method)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at sun.nio.ch.EPollArrayWrapper.poll(EPollArrayWrapper.java:210)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at sun.nio.ch.EPollSelectorImpl.doSelect(EPollSelectorImpl.java:65)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:69)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	- locked <0x0000000707966688> (a sun.nio.ch.Util$2)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	- locked <0x0000000707966678> (a java.util.Collections$UnmodifiableSet)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	- locked <0x000000070794e5e0> (a sun.nio.ch.EPollSelectorImpl)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:80)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.mina.transport.socket.nio.NioProcessor.select(NioProcessor.java:72)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.run(AbstractPollingIoProcessor.java:1077)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:64)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:895)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:918)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at java.lang.Thread.run(Thread.java:662)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 
INFO   | jvm 1    | 2013/07/09 11:38:16 | "NioProcessor-8" prio=10 tid=0x00002aaab403e000 nid=0x660d runnable [0x000000004247d000]
INFO   | jvm 1    | 2013/07/09 11:38:16 |    java.lang.Thread.State: RUNNABLE
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at sun.nio.ch.EPollArrayWrapper.epollWait(Native Method)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at sun.nio.ch.EPollArrayWrapper.poll(EPollArrayWrapper.java:210)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at sun.nio.ch.EPollSelectorImpl.doSelect(EPollSelectorImpl.java:65)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:69)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	- locked <0x00000007079658a8> (a sun.nio.ch.Util$2)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	- locked <0x0000000707965898> (a java.util.Collections$UnmodifiableSet)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	- locked <0x0000000707965690> (a sun.nio.ch.EPollSelectorImpl)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:80)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.mina.transport.socket.nio.NioProcessor.select(NioProcessor.java:72)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.run(AbstractPollingIoProcessor.java:1077)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:64)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:895)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:918)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at java.lang.Thread.run(Thread.java:662)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 
INFO   | jvm 1    | 2013/07/09 11:38:16 | "NioProcessor-9" prio=10 tid=0x00002aaab403d000 nid=0x6609 runnable [0x000000004227b000]
INFO   | jvm 1    | 2013/07/09 11:38:16 |    java.lang.Thread.State: RUNNABLE
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at sun.nio.ch.EPollArrayWrapper.epollWait(Native Method)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at sun.nio.ch.EPollArrayWrapper.poll(EPollArrayWrapper.java:210)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at sun.nio.ch.EPollSelectorImpl.doSelect(EPollSelectorImpl.java:65)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:69)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	- locked <0x0000000707965370> (a sun.nio.ch.Util$2)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	- locked <0x0000000707965360> (a java.util.Collections$UnmodifiableSet)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	- locked <0x0000000707965158> (a sun.nio.ch.EPollSelectorImpl)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:80)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.mina.transport.socket.nio.NioProcessor.select(NioProcessor.java:72)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.run(AbstractPollingIoProcessor.java:1077)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:64)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:895)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:918)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at java.lang.Thread.run(Thread.java:662)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 
INFO   | jvm 1    | 2013/07/09 11:38:16 | "NioProcessor-5" prio=10 tid=0x00002aaab404e000 nid=0x6606 runnable [0x0000000042c85000]
INFO   | jvm 1    | 2013/07/09 11:38:16 |    java.lang.Thread.State: RUNNABLE
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at sun.nio.ch.EPollArrayWrapper.epollWait(Native Method)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at sun.nio.ch.EPollArrayWrapper.poll(EPollArrayWrapper.java:210)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at sun.nio.ch.EPollSelectorImpl.doSelect(EPollSelectorImpl.java:65)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:69)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	- locked <0x000000070794e3a0> (a sun.nio.ch.Util$2)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	- locked <0x000000070794e390> (a java.util.Collections$UnmodifiableSet)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	- locked <0x000000070794e158> (a sun.nio.ch.EPollSelectorImpl)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:80)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.mina.transport.socket.nio.NioProcessor.select(NioProcessor.java:72)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.run(AbstractPollingIoProcessor.java:1077)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:64)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:895)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:918)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at java.lang.Thread.run(Thread.java:662)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 
INFO   | jvm 1    | 2013/07/09 11:38:16 | "NioProcessor-4" prio=10 tid=0x00002aaab404d800 nid=0x586f runnable [0x0000000042f88000]
INFO   | jvm 1    | 2013/07/09 11:38:16 |    java.lang.Thread.State: RUNNABLE
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at sun.nio.ch.EPollArrayWrapper.epollWait(Native Method)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at sun.nio.ch.EPollArrayWrapper.poll(EPollArrayWrapper.java:210)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at sun.nio.ch.EPollSelectorImpl.doSelect(EPollSelectorImpl.java:65)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:69)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	- locked <0x00000007079664b0> (a sun.nio.ch.Util$2)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	- locked <0x00000007079664a0> (a java.util.Collections$UnmodifiableSet)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	- locked <0x0000000707966298> (a sun.nio.ch.EPollSelectorImpl)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:80)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.mina.transport.socket.nio.NioProcessor.select(NioProcessor.java:72)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.run(AbstractPollingIoProcessor.java:1077)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:64)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:895)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:918)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at java.lang.Thread.run(Thread.java:662)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 
INFO   | jvm 1    | 2013/07/09 11:38:16 | "NioSocketAcceptor-1" prio=10 tid=0x00002aaab460d800 nid=0x561c runnable [0x0000000042b84000]
INFO   | jvm 1    | 2013/07/09 11:38:16 |    java.lang.Thread.State: RUNNABLE
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at sun.nio.ch.EPollArrayWrapper.epollWait(Native Method)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at sun.nio.ch.EPollArrayWrapper.poll(EPollArrayWrapper.java:210)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at sun.nio.ch.EPollSelectorImpl.doSelect(EPollSelectorImpl.java:65)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:69)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	- locked <0x0000000707918b00> (a sun.nio.ch.Util$2)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	- locked <0x0000000707918af0> (a java.util.Collections$UnmodifiableSet)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	- locked <0x0000000707918638> (a sun.nio.ch.EPollSelectorImpl)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:80)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:84)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.mina.transport.socket.nio.NioSocketAcceptor.select(NioSocketAcceptor.java:234)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.mina.core.polling.AbstractPollingIoAcceptor$Acceptor.run(AbstractPollingIoAcceptor.java:417)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:64)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:895)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:918)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at java.lang.Thread.run(Thread.java:662)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 
INFO   | jvm 1    | 2013/07/09 11:38:16 | "NioSocketAcceptor-2" prio=10 tid=0x00002aaab4632800 nid=0x561b runnable [0x0000000042a83000]
INFO   | jvm 1    | 2013/07/09 11:38:16 |    java.lang.Thread.State: RUNNABLE
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at sun.nio.ch.EPollArrayWrapper.epollWait(Native Method)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at sun.nio.ch.EPollArrayWrapper.poll(EPollArrayWrapper.java:210)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at sun.nio.ch.EPollSelectorImpl.doSelect(EPollSelectorImpl.java:65)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:69)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	- locked <0x000000070793e560> (a sun.nio.ch.Util$2)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	- locked <0x000000070793e550> (a java.util.Collections$UnmodifiableSet)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	- locked <0x000000070793e088> (a sun.nio.ch.EPollSelectorImpl)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:80)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:84)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.mina.transport.socket.nio.NioSocketAcceptor.select(NioSocketAcceptor.java:234)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.mina.core.polling.AbstractPollingIoAcceptor$Acceptor.run(AbstractPollingIoAcceptor.java:417)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:64)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:895)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:918)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at java.lang.Thread.run(Thread.java:662)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 
INFO   | jvm 1    | 2013/07/09 11:38:16 | "Thread-2" daemon prio=10 tid=0x00002aaab450e000 nid=0x561a waiting on condition [0x0000000042982000]
INFO   | jvm 1    | 2013/07/09 11:38:16 |    java.lang.Thread.State: TIMED_WAITING (sleeping)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at java.lang.Thread.sleep(Native Method)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.directory.server.ldap.replication.provider.SyncReplRequestHandler$1.run(SyncReplRequestHandler.java:1098)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at java.lang.Thread.run(Thread.java:662)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 
INFO   | jvm 1    | 2013/07/09 11:38:16 | "Thread-1" daemon prio=10 tid=0x00002aaab45a3000 nid=0x5619 in Object.wait() [0x0000000042881000]
INFO   | jvm 1    | 2013/07/09 11:38:16 |    java.lang.Thread.State: TIMED_WAITING (on object monitor)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at java.lang.Object.wait(Native Method)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	- waiting on <0x000000070796ede0> (a java.lang.Object)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.apache.directory.server.ldap.replication.provider.ReplicaEventLogJanitor.run(ReplicaEventLogJanitor.java:172)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	- locked <0x000000070796ede0> (a java.lang.Object)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 
INFO   | jvm 1    | 2013/07/09 11:38:16 | "kdcReplayCache.data" daemon prio=10 tid=0x00002aaab2d09000 nid=0x5617 waiting on condition [0x0000000042780000]
INFO   | jvm 1    | 2013/07/09 11:38:16 |    java.lang.Thread.State: TIMED_WAITING (parking)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at sun.misc.Unsafe.park(Native Method)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	- parking to wait for  <0x000000070704fbe8> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:196)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2025)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at java.util.concurrent.DelayQueue.take(DelayQueue.java:164)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:609)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:602)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:957)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:917)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at java.lang.Thread.run(Thread.java:662)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 
INFO   | jvm 1    | 2013/07/09 11:38:16 | "groupCache.data" daemon prio=10 tid=0x00002aaab2f2a800 nid=0x5616 waiting on condition [0x000000004267f000]
INFO   | jvm 1    | 2013/07/09 11:38:16 |    java.lang.Thread.State: TIMED_WAITING (parking)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at sun.misc.Unsafe.park(Native Method)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	- parking to wait for  <0x0000000707069150> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:196)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2025)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at java.util.concurrent.DelayQueue.take(DelayQueue.java:164)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:609)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:602)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:957)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:917)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at java.lang.Thread.run(Thread.java:662)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 
INFO   | jvm 1    | 2013/07/09 11:38:16 | "ou=system.data" daemon prio=10 tid=0x00002aaab2c5f000 nid=0x5615 waiting on condition [0x000000004257e000]
INFO   | jvm 1    | 2013/07/09 11:38:16 |    java.lang.Thread.State: TIMED_WAITING (parking)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at sun.misc.Unsafe.park(Native Method)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	- parking to wait for  <0x0000000707046cb0> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:196)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2025)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at java.util.concurrent.DelayQueue.take(DelayQueue.java:164)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:609)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:602)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:957)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:917)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at java.lang.Thread.run(Thread.java:662)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 
INFO   | jvm 1    | 2013/07/09 11:38:16 | "changePwdReplayCache.data" daemon prio=10 tid=0x00000000410a4800 nid=0x5614 waiting on condition [0x00000000414c2000]
INFO   | jvm 1    | 2013/07/09 11:38:16 |    java.lang.Thread.State: TIMED_WAITING (parking)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at sun.misc.Unsafe.park(Native Method)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	- parking to wait for  <0x00000007070607a8> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:196)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2025)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at java.util.concurrent.DelayQueue.take(DelayQueue.java:164)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:609)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:602)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:957)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:917)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at java.lang.Thread.run(Thread.java:662)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 
INFO   | jvm 1    | 2013/07/09 11:38:16 | "apacheds" daemon prio=10 tid=0x00002aaab2cde800 nid=0x5613 in Object.wait() [0x00000000413c1000]
INFO   | jvm 1    | 2013/07/09 11:38:16 |    java.lang.Thread.State: WAITING (on object monitor)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at java.lang.Object.wait(Native Method)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	- waiting on <0x0000000707131ad8> (a java.util.TaskQueue)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at java.lang.Object.wait(Object.java:485)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at java.util.TimerThread.mainLoop(Timer.java:483)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	- locked <0x0000000707131ad8> (a java.util.TaskQueue)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at java.util.TimerThread.run(Timer.java:462)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 
INFO   | jvm 1    | 2013/07/09 11:38:16 | "DestroyJavaVM" prio=10 tid=0x00002aaab4091800 nid=0x55ff waiting on condition [0x0000000000000000]
INFO   | jvm 1    | 2013/07/09 11:38:16 |    java.lang.Thread.State: RUNNABLE
INFO   | jvm 1    | 2013/07/09 11:38:16 | 
INFO   | jvm 1    | 2013/07/09 11:38:16 | "Wrapper-Connection" daemon prio=10 tid=0x00002aaab404f000 nid=0x560f runnable [0x000000004237c000]
INFO   | jvm 1    | 2013/07/09 11:38:16 |    java.lang.Thread.State: RUNNABLE
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at java.net.SocketInputStream.socketRead0(Native Method)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at java.net.SocketInputStream.read(SocketInputStream.java:129)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at java.net.SocketInputStream.read(SocketInputStream.java:182)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at java.io.DataInputStream.readByte(DataInputStream.java:248)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.tanukisoftware.wrapper.WrapperManager.handleSocket(WrapperManager.java:3737)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.tanukisoftware.wrapper.WrapperManager.run(WrapperManager.java:4084)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at java.lang.Thread.run(Thread.java:662)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 
INFO   | jvm 1    | 2013/07/09 11:38:16 | "Wrapper-Control-Event-Monitor" daemon prio=10 tid=0x00002aaab4004800 nid=0x560d sleeping[0x000000004217a000]
INFO   | jvm 1    | 2013/07/09 11:38:16 |    java.lang.Thread.State: TIMED_WAITING (sleeping)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at java.lang.Thread.sleep(Native Method)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at org.tanukisoftware.wrapper.WrapperManager$3.run(WrapperManager.java:731)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 
INFO   | jvm 1    | 2013/07/09 11:38:16 | "Low Memory Detector" daemon prio=10 tid=0x0000000040fac000 nid=0x560a runnable [0x0000000000000000]
INFO   | jvm 1    | 2013/07/09 11:38:16 |    java.lang.Thread.State: RUNNABLE
INFO   | jvm 1    | 2013/07/09 11:38:16 | 
INFO   | jvm 1    | 2013/07/09 11:38:16 | "C2 CompilerThread1" daemon prio=10 tid=0x0000000040faa000 nid=0x5609 waiting on condition [0x0000000000000000]
INFO   | jvm 1    | 2013/07/09 11:38:16 |    java.lang.Thread.State: RUNNABLE
INFO   | jvm 1    | 2013/07/09 11:38:16 | 
INFO   | jvm 1    | 2013/07/09 11:38:16 | "C2 CompilerThread0" daemon prio=10 tid=0x0000000040fa4800 nid=0x5608 waiting on condition [0x0000000000000000]
INFO   | jvm 1    | 2013/07/09 11:38:16 |    java.lang.Thread.State: RUNNABLE
INFO   | jvm 1    | 2013/07/09 11:38:16 | 
INFO   | jvm 1    | 2013/07/09 11:38:16 | "Signal Dispatcher" daemon prio=10 tid=0x0000000040fa2800 nid=0x5607 waiting on condition [0x0000000000000000]
INFO   | jvm 1    | 2013/07/09 11:38:16 |    java.lang.Thread.State: RUNNABLE
INFO   | jvm 1    | 2013/07/09 11:38:16 | 
INFO   | jvm 1    | 2013/07/09 11:38:16 | "Finalizer" daemon prio=10 tid=0x0000000040f80800 nid=0x5606 in Object.wait() [0x0000000041deb000]
INFO   | jvm 1    | 2013/07/09 11:38:16 |    java.lang.Thread.State: WAITING (on object monitor)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at java.lang.Object.wait(Native Method)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	- waiting on <0x0000000707173c18> (a java.lang.ref.ReferenceQueue$Lock)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:118)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	- locked <0x0000000707173c18> (a java.lang.ref.ReferenceQueue$Lock)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:134)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:171)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 
INFO   | jvm 1    | 2013/07/09 11:38:16 | "Reference Handler" daemon prio=10 tid=0x0000000040f7e800 nid=0x5605 in Object.wait() [0x0000000041cea000]
INFO   | jvm 1    | 2013/07/09 11:38:16 |    java.lang.Thread.State: WAITING (on object monitor)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at java.lang.Object.wait(Native Method)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	- waiting on <0x00000007071cd088> (a java.lang.ref.Reference$Lock)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at java.lang.Object.wait(Object.java:485)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:116)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 	- locked <0x00000007071cd088> (a java.lang.ref.Reference$Lock)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 
INFO   | jvm 1    | 2013/07/09 11:38:16 | "VM Thread" prio=10 tid=0x0000000040f77800 nid=0x5604 runnable 
INFO   | jvm 1    | 2013/07/09 11:38:16 | 
INFO   | jvm 1    | 2013/07/09 11:38:16 | "GC task thread#0 (ParallelGC)" prio=10 tid=0x0000000040f2d000 nid=0x5600 runnable 
INFO   | jvm 1    | 2013/07/09 11:38:16 | 
INFO   | jvm 1    | 2013/07/09 11:38:16 | "GC task thread#1 (ParallelGC)" prio=10 tid=0x0000000040f2e800 nid=0x5601 runnable 
INFO   | jvm 1    | 2013/07/09 11:38:16 | 
INFO   | jvm 1    | 2013/07/09 11:38:16 | "GC task thread#2 (ParallelGC)" prio=10 tid=0x0000000040f30800 nid=0x5602 runnable 
INFO   | jvm 1    | 2013/07/09 11:38:16 | 
INFO   | jvm 1    | 2013/07/09 11:38:16 | "GC task thread#3 (ParallelGC)" prio=10 tid=0x0000000040f32800 nid=0x5603 runnable 
INFO   | jvm 1    | 2013/07/09 11:38:16 | 
INFO   | jvm 1    | 2013/07/09 11:38:16 | "VM Periodic Task Thread" prio=10 tid=0x0000000040fb7000 nid=0x560b waiting on condition 
INFO   | jvm 1    | 2013/07/09 11:38:16 | 
INFO   | jvm 1    | 2013/07/09 11:38:16 | JNI global references: 1725
INFO   | jvm 1    | 2013/07/09 11:38:16 | 
INFO   | jvm 1    | 2013/07/09 11:38:16 | Heap
INFO   | jvm 1    | 2013/07/09 11:38:16 |  PSYoungGen     
INFO   | jvm 1    | 2013/07/09 11:38:16 |  total 1352704K, used 292143K [0x00000007ac600000, 0x00000007fff70000, 0x0000000800000000)
INFO   | jvm 1    | 2013/07/09 11:38:16 |   eden space 1336064K, 21% used [0x00000007ac600000,0x00000007be0e38c0,0x00000007fdec0000)
INFO   | jvm 1    | 2013/07/09 11:38:16 |   from space 16640K, 70% used [0x00000007fdec0000,0x00000007fea28200,0x00000007fef00000)
INFO   | jvm 1    | 2013/07/09 11:38:16 |   to   space 16192K, 0% used [0x00000007fefa0000,0x00000007fefa0000,0x00000007fff70000)
INFO   | jvm 1    | 2013/07/09 11:38:16 |  PSOldGen        total 325568K, used 322302K [0x0000000705200000, 0x0000000718ff0000, 0x00000007ac600000)
INFO   | jvm 1    | 2013/07/09 11:38:16 |   object space 325568K, 98% used [0x0000000705200000,0x0000000718cbfb08,0x0000000718ff0000)
INFO   | jvm 1    | 2013/07/09 11:38:16 |  PSPermGen       total 23424K, used 23078K [0x0000000700000000, 0x00000007016e0000, 0x0000000705200000)
INFO   | jvm 1    | 2013/07/09 11:38:16 |   object space 23424K, 98% used [0x0000000700000000,0x00000007016898f8,0x00000007016e0000)
INFO   | jvm 1    | 2013/07/09 11:38:16 | 


Regards,

Slavomir Kocka

On Jul 9, 2013, at 11:26 , Emmanuel Lécharny <el...@gmail.com> wrote:

> Le 7/9/13 10:27 AM, Slavomir Kocka a écrit :
>> Hi,
>> 
>> We use apacheds as authentication storage for websphere application server cluster.
>> Versions are 2.0.0.M14 and Websphere is 8.0.0.5
>> 
>> We run it on redhat 5.8 (x64), and apacheds is allways running on 100%... :
>> 
>> 22014 apacheds  22   0 4391m 1.7g  10m S 109.8 10.6 200:34.23 java 
>> 
>> Is this normal, or is it some configuration issue? When used (for writing, reading) we go up to 200% of CPU...
>> Any idea, what is going on, or how to analyze issue?
> 
> Can you produce a thread dump ?
> 
> 
> -- 
> Regards,
> Cordialement,
> Emmanuel Lécharny
> www.iktek.com 
> 


Re: apacheds @ 100% permanently

Posted by Emmanuel Lécharny <el...@gmail.com>.
Le 7/9/13 10:27 AM, Slavomir Kocka a écrit :
> Hi,
>
> We use apacheds as authentication storage for websphere application server cluster.
> Versions are 2.0.0.M14 and Websphere is 8.0.0.5
>
> We run it on redhat 5.8 (x64), and apacheds is allways running on 100%... :
>
> 22014 apacheds  22   0 4391m 1.7g  10m S 109.8 10.6 200:34.23 java 
>
> Is this normal, or is it some configuration issue? When used (for writing, reading) we go up to 200% of CPU...
> Any idea, what is going on, or how to analyze issue?

Can you produce a thread dump ?


-- 
Regards,
Cordialement,
Emmanuel Lécharny
www.iktek.com