100% CPU usage after resume WinXP from stand-by: appears to be in MINA
----------------------------------------------------------------------

Key: DIRSERVER-608
URL: http://issues.apache.org/jira/browse/DIRSERVER-608
Project: Directory ApacheDS
Type: Bug

Components: core
Versions: 1.0-RC1
Environment: Windows XP 2002 SP2, JDK  1.4.2_04-b05
Reporter: Norbert Reilly


I've noticed that when ApacheDS is running on my laptop and I close the lid 
and later open it that the ApacheDS Java process is using 100% CPU. When log
ging at the DEBUG level the 100% CPU usage seems to coincide with messages l
ike this (the 20 second per
iodic sync):

============================
2006-04-19 12:46:08,833 101464 [SynchWorkerThread] (org.apache.directory
.shared.ldap.name.DnParser:184) DEBUG org.apache.directory.shared.ldap.name.
DnParser  - Parsing DN 'ou=system'
2006-04-19 12:46:08,883 101514 [SynchWorkerThread] (org.apache.directory
.shared.ldap.name.DnParser:184) DEBUG org.apache.directory.shared.ldap.name.
DnParser  - Parsing DN 'uid=admin,ou=system'
2006-04-19 12:46:08,943 101574 [SynchWorkerThread] (org.apache.directory
.shared.ldap.name.DnParser:184) DEBUG org.apache.directory.shared.ldap.name.
DnParser  - Parsing DN 'uid=admin,ou=system'
2006-04-19 12:46:09,013 101644 [SynchWorkerThread] (org.apache.directory
.server.core.authn.AuthenticationService:248) DEBUG org.apache.directory.ser
ver.core.authn.AuthenticationService  - Testing if entry name = 'ou=system' 
exists
2006-04-19 12:46:09,063 101694 [SynchWorkerThread] (org.apache.directory
.server.core.partition.DefaultDirectoryPartitionNexus:722) DEBUG org.apache.
directory.server.core.partition.DefaultDirectoryPartitionNexus  - Check if D
N 'ou=system' exists.
2006-04-19 12:46:09,123 101754 [SynchWorkerThread] (org.apache.directory
.shared.ldap.name.DnParser:184) DEBUG org.apache.directory.shared.ldap.name.
DnParser  - Parsing DN  'ou=services,ou=configuration,ou=system'

2006-04-19 12:46:09,223 101854 [SynchWorkerThread] (org.apache.directory
.shared.ldap.name.DnParser:184) DEBUG org.apache.directory.shared.ldap.name.
DnParser  - Parsing DN 'ou=system'
2006-04-19 12:46:09,304 101935 [SynchWorkerThread] (org.apache.directory
.shared.ldap.name.DnParser:184) DEBUG org.apache.directory.shared.ldap.name.
DnParser  - Parsing DN  'ou=interceptors,ou=configuration,ou=sys
tem'
2006-04-19 12:46:09,424 102055 [SynchWorkerThread] (org.apache.directory
.shared.ldap.name.DnParser:184) DEBUG org.apache.directory.shared.ldap.name.
DnParser  - Parsing DN 'ou=system'
2006-04-19 12:46:09,504 102135 [SynchWorkerThread] (org.apache.directory
.shared.ldap.name.DnParser:184) DEBUG org.apache.directory.shared.ldap.name.
DnParser  - Parsing DN 'ou=configuration,ou=system'
2006-04-19 12:46:09,604 102235 [SynchWorkerThread] (org.apache.directory
.shared.ldap.name.DnParser:184) DEBUG org.apache.directory.shared.ldap.name.
DnParser  - Parsing DN 'ou=system'
============================

This is a dump of the threads when I pause the debugger:

DestroyJavaVM@6d0, priority=5, in group 'main', status: 'RUNNING'

SynchWorkerThread@6ae, priority=5, in group 'main', status: 'WAIT'
wait():-1, Object.java
run():155, Service.java
run():534, Thread.java

SocketAcceptor-0@69f, priority=5, in group 'main', status: 'RUNNING'
poll0():-1, WindowsSelectorImpl.java
poll():263, WindowsSelectorImpl.java
access$400():245, WindowsSelectorImpl.java
doSelect():128, WindowsSelectorImpl.java
lockAndDoSelect():59, SelectorImpl.java
select():70, SelectorImpl.java
select():74, SelectorImpl.java
run():326, SocketAcceptorDelegate.java

Signal Dispatcher@e0 daemon, priority=10, in group 'system', status: 'RUNNIN
G'

Finalizer@e1 daemon, priority=8, in group 'system', status: 'WAIT'
wait():-1, Object.java
remove():111, ReferenceQueue.java
remove():127, ReferenceQueue.java
run():159, Finalizer.java

Reference Handler@e2 daemon, priority=10, in group 'system', status: 'WAIT'
wait():-1, Object.java
wait():429, Object.java
run():115, Reference.java

The busy loop is in org.apache.mina.transport.socket.nio.support.SocketAccep
torDelegate.Worker.run() and appears to be because the line:

int nKeys = selector.select();

never blocks after the resume, and hence the run() method becomes a busy loo
p. This may well be a bug in the JDK's nio package but a quick web search di
dn't turn up a match. At any rate it seems like a problem that will need to 
be worked around in MINA un
til the JDK is patched (if my diagnosis is correct) at it seems the selector
 is rendered inoperable by the close-lid/resume sequence.

I presume the same problem could be triggered on a desk-top machine with eno
ugh understanding about what WinXP does during a suspend, and why this upset
s the NIO package.

--
This message is automatically generated by JIRA.
-
If you think it was sent incorrectly contact one of the administrators:
http://issues.apache.org/jira/secur...nistrators.jspa
-
For more information on JIRA, see:
http://www.atlassian.com/software/jira

[ Post a follow-up to this message ]