You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@mina.apache.org by "Matt Yates (JIRA)" <ji...@apache.org> on 2011/04/10 18:52:05 UTC
[jira] [Created] (DIRMINA-827) NioSocketConnector leaks the last
open NioSocketSession after close
NioSocketConnector leaks the last open NioSocketSession after close
-------------------------------------------------------------------
Key: DIRMINA-827
URL: https://issues.apache.org/jira/browse/DIRMINA-827
Project: MINA
Issue Type: Bug
Components: Core
Affects Versions: 2.0.2
Environment: Windows 7/Solaris SPARC/Solaris x86
Java versions 6u18 & 6u24
Reporter: Matt Yates
Priority: Critical
My company's program uses MINA makes multiple (usually) simultaneous connections to various other machines, while reusing the same NioSocketConnector for each new connection. For better or worse, we store various objects in the IoSession's attributes, which we expect to get released on close, however, said session remains in memory until either a new connection is made or the connector is disposed. After writing the simplest Connector program I could (I have several servers available on my network, so I did not write a matching Acceptor), and performing some profiling and debugging, I was able to confirm the leak and identify the issue.
Below is my Connector test program
{code}
public class MinaMain {
private static final Logger LOGGER = LoggerFactory.getLogger(MinaMain.class);
public static void main(String[] args) throws InterruptedException {
LOGGER.trace("Waiting for YourKit to start");
Thread.sleep(15000);
NioSocketConnector connector = new NioSocketConnector();
connector.setHandler(new IoHandlerAdapter());
closeSession(getConnectedSession(connector));
// LOGGER.info("Creating and closing 5 sessions in series");
//
// for (int x = 0; x < 5; x++) {
// IoSession session = getConnectedSession(connector);
//
// if (session == null) {
// continue;
// }
//
// closeSession(session);
// }
//
// LOGGER.info("Creating 5 sessions and then closing 5 sessions");
// IoSession[] sessions = new IoSession[5];
//
// for (int x = 0; x < 5; x++) {
// sessions[x] = getConnectedSession(connector);
// }
//
// for (int x = 0; x < 5; x++) {
// IoSession session = sessions[x];
//
// if (session != null) {
// closeSession(session);
// sessions[x] = null;
// }
// }
LOGGER.info("Test complete. Sleeping for 60s");
Thread.sleep(60000);
}
private static IoSession getConnectedSession(IoConnector connector) throws InterruptedException {
IoSession session = null;
try {
ConnectFuture future = connector.connect(new InetSocketAddress("134.64.37.183", 11109));
future.addListener(new IoFutureListener<ConnectFuture>() {
@Override
public void operationComplete(ConnectFuture future) {
LOGGER.debug("Connection completed callback for session " + future.getSession().getId());
}
});
future.awaitUninterruptibly();
LOGGER.debug("Connection created for session " + future.getSession().getId());
session = future.getSession();
Thread.sleep(15000);
}
catch (Exception e) {
LOGGER.error("Failed to connect", e);
}
return session;
}
private static void closeSession(IoSession session) throws InterruptedException {
try {
CloseFuture closeFuture = session.getCloseFuture();
closeFuture.addListener(new IoFutureListener<CloseFuture>() {
@Override
public void operationComplete(CloseFuture future) {
LOGGER.debug("Session closed callback for session " + future.getSession().getId());
}
});
LOGGER.debug("Attempting to close session " + session.getId());
session.close(false);
LOGGER.debug("IoSession.close(false) returned. Awaiting uninterruptibily for session " + session.getId());
closeFuture.awaitUninterruptibly();
LOGGER.debug("Close completed for session " + session.getId());
}
catch (Exception e) {
LOGGER.error("Failed to close session " + session.getId());
session.close(true);
}
Thread.sleep(15000);
}
}
{/code}
Attached is the hprof file of my program, taken after the program has run (during the 60 second sleep at the end) and a screen shot of the GC Root of the leaked NioSocketSession.
After a couple days of debugging, I've identified why this is happening. Below is a snippet from the AbstractPollingIoConnector.Connector thread
{code}private class Connector implements Runnable {
public void run() {
int nHandles = 0;
while (selectable) {
try {
// the timeout for select shall be smaller of the connect
// timeout or 1 second...
int timeout = (int)Math.min(getConnectTimeoutMillis(), 1000L);
int selected = select(timeout);
nHandles += registerNew();
if (selected > 0) {
nHandles -= processConnections(selectedHandles());
}
processTimedOutSessions(allHandles());
nHandles -= cancelKeys();
if (nHandles == 0) {
synchronized (lock) {
if (connectQueue.isEmpty()) {
connector = null;
break;
}
}
}
}
...
{/code}
When IoSession.close(boolean) is called, the above Connector thread cancels the SelectionKey associated with the session, which reduces the number of handles from 1 to 0. Immediately afterwards, the thread stops executing because there are no handles and nothing in the connetQueue, however, the previously cancelled key is still in the Selector because its cancelledKeys Set is not processed until the next call to select(int)
Calling dispose on the IoConnector restarts the Connector thread, which calls Selector.select(int), at which time, the Selector cleans out its canclledKeys.
Creating a new connection causes the same thing to happen, because the new session also recreates the AbstractPollingIoConnector.Connector thread, as there is a new handle to be processed.
--
This message is automatically generated by JIRA.
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] [Commented] (DIRMINA-827) NioSocketConnector leaks the last
open NioSocketSession after close
Posted by "Matt Yates (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/DIRMINA-827?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13018866#comment-13018866 ]
Matt Yates commented on DIRMINA-827:
------------------------------------
I can't really tell if it's blocking, b/c it never blocks for more that 1 second, even if you set a large timeout
int timeout = (int)Math.min(getConnectTimeoutMillis(), 1000L);
Regardless, moving the check for zero handles works, and with the extra insurance of the wakeup() call, I think we have a winner.
Thank you very much for your attention/work on this issue!
> NioSocketConnector leaks the last open NioSocketSession after close
> -------------------------------------------------------------------
>
> Key: DIRMINA-827
> URL: https://issues.apache.org/jira/browse/DIRMINA-827
> Project: MINA
> Issue Type: Bug
> Components: Core
> Affects Versions: 2.0.2
> Environment: Windows 7/Solaris SPARC/Solaris x86
> Java versions 6u18 & 6u24
> Reporter: Matt Yates
> Assignee: Emmanuel Lecharny
> Priority: Critical
> Labels: connector, mina, session
> Attachments: IoConnectorWithCleanSelector.jpg, MinaMain-2011-04-10.hprof, mina-core-2.0.4-SNAPSHOT.jar, mina-core-2.0.4-SNAPSHOT.jar, sessionGcRoot.jpg
>
>
> My company's program uses MINA to make multiple (usually) simultaneous connections to various other machines, while reusing the same NioSocketConnector for each new connection. For better or worse, we store various objects in the IoSession's attributes, which we expect to get released on close. This is not always the case, however, as said session remains in memory until either a new connection is made or the IoConnector is disposed. After writing the simplest Connector program I could (I have several servers available on my network, so I did not write a matching Acceptor), and performing some profiling and debugging, I was able to confirm the leak and identify the issue.
> Below is my Connector test program
> {code}
> public class MinaMain {
> private static final Logger LOGGER = LoggerFactory.getLogger(MinaMain.class);
> public static void main(String[] args) throws InterruptedException {
> LOGGER.trace("Waiting for YourKit to start");
> Thread.sleep(15000);
> NioSocketConnector connector = new NioSocketConnector();
> connector.setHandler(new IoHandlerAdapter());
> closeSession(getConnectedSession(connector));
> // LOGGER.info("Creating and closing 5 sessions in series");
> //
> // for (int x = 0; x < 5; x++) {
> // IoSession session = getConnectedSession(connector);
> //
> // if (session == null) {
> // continue;
> // }
> //
> // closeSession(session);
> // }
> //
> // LOGGER.info("Creating 5 sessions and then closing 5 sessions");
> // IoSession[] sessions = new IoSession[5];
> //
> // for (int x = 0; x < 5; x++) {
> // sessions[x] = getConnectedSession(connector);
> // }
> //
> // for (int x = 0; x < 5; x++) {
> // IoSession session = sessions[x];
> //
> // if (session != null) {
> // closeSession(session);
> // sessions[x] = null;
> // }
> // }
> LOGGER.info("Test complete. Sleeping for 60s");
> Thread.sleep(60000);
> }
> private static IoSession getConnectedSession(IoConnector connector) throws InterruptedException {
> IoSession session = null;
> try {
> ConnectFuture future = connector.connect(new InetSocketAddress("134.64.37.183", 11109));
> future.addListener(new IoFutureListener<ConnectFuture>() {
> @Override
> public void operationComplete(ConnectFuture future) {
> LOGGER.debug("Connection completed callback for session " + future.getSession().getId());
> }
> });
> future.awaitUninterruptibly();
> LOGGER.debug("Connection created for session " + future.getSession().getId());
> session = future.getSession();
> Thread.sleep(15000);
> }
> catch (Exception e) {
> LOGGER.error("Failed to connect", e);
> }
> return session;
> }
> private static void closeSession(IoSession session) throws InterruptedException {
> try {
> CloseFuture closeFuture = session.getCloseFuture();
> closeFuture.addListener(new IoFutureListener<CloseFuture>() {
> @Override
> public void operationComplete(CloseFuture future) {
> LOGGER.debug("Session closed callback for session " + future.getSession().getId());
> }
> });
> LOGGER.debug("Attempting to close session " + session.getId());
> session.close(false);
> LOGGER.debug("IoSession.close(false) returned. Awaiting uninterruptibily for session " + session.getId());
> closeFuture.awaitUninterruptibly();
> LOGGER.debug("Close completed for session " + session.getId());
> }
> catch (Exception e) {
> LOGGER.error("Failed to close session " + session.getId());
> session.close(true);
> }
> Thread.sleep(15000);
> }
> }
> {code}
> Attached is the hprof file of my program, taken after the program has run (during the 60 second sleep at the end) and a screen shot of the GC Root of the leaked NioSocketSession.
> After a couple days of debugging, I've identified why this is happening. Below is a snippet from the AbstractPollingIoConnector.Connector thread
> {code}
> private class Connector implements Runnable {
> public void run() {
> int nHandles = 0;
> while (selectable) {
> try {
> // the timeout for select shall be smaller of the connect
> // timeout or 1 second...
> int timeout = (int)Math.min(getConnectTimeoutMillis(), 1000L);
> int selected = select(timeout);
> nHandles += registerNew();
> if (selected > 0) {
> nHandles -= processConnections(selectedHandles());
> }
> processTimedOutSessions(allHandles());
> nHandles -= cancelKeys();
> if (nHandles == 0) {
> synchronized (lock) {
> if (connectQueue.isEmpty()) {
> connector = null;
> break;
> }
> }
> }
> }
> ...
> {code}
> When IoSession.close(boolean) is called, the above Connector thread cancels the SelectionKey associated with the session, which reduces the number of handles from 1 to 0. Immediately afterwards, the thread stops executing because there are no handles and nothing in the connetQueue, however, the previously cancelled key is still in the Selector because its cancelledKeys Set is not processed until the next call to select(int)
> Calling dispose on the IoConnector restarts the Connector thread, which calls Selector.select(int), at which time, the Selector cleans out its canclledKeys.
> Creating a new connection causes the same thing to happen, because the new session also recreates the AbstractPollingIoConnector.Connector thread, as there is a new handle to be processed.
--
This message is automatically generated by JIRA.
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] [Commented] (DIRMINA-827) NioSocketConnector leaks the last
open NioSocketSession after close
Posted by "Matt Yates (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/DIRMINA-827?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13020344#comment-13020344 ]
Matt Yates commented on DIRMINA-827:
------------------------------------
Is this going into 2.0.3? There is no fix-version assigned... Also, is there an ETA for 2.0.3? Thanks!
> NioSocketConnector leaks the last open NioSocketSession after close
> -------------------------------------------------------------------
>
> Key: DIRMINA-827
> URL: https://issues.apache.org/jira/browse/DIRMINA-827
> Project: MINA
> Issue Type: Bug
> Components: Core
> Affects Versions: 2.0.2
> Environment: Windows 7/Solaris SPARC/Solaris x86
> Java versions 6u18 & 6u24
> Reporter: Matt Yates
> Assignee: Emmanuel Lecharny
> Priority: Critical
> Labels: connector, mina, session
> Attachments: IoConnectorWithCleanSelector.jpg, MinaMain-2011-04-10.hprof, mina-core-2.0.4-SNAPSHOT.jar, mina-core-2.0.4-SNAPSHOT.jar, sessionGcRoot.jpg
>
>
> My company's program uses MINA to make multiple (usually) simultaneous connections to various other machines, while reusing the same NioSocketConnector for each new connection. For better or worse, we store various objects in the IoSession's attributes, which we expect to get released on close. This is not always the case, however, as said session remains in memory until either a new connection is made or the IoConnector is disposed. After writing the simplest Connector program I could (I have several servers available on my network, so I did not write a matching Acceptor), and performing some profiling and debugging, I was able to confirm the leak and identify the issue.
> Below is my Connector test program
> {code}
> public class MinaMain {
> private static final Logger LOGGER = LoggerFactory.getLogger(MinaMain.class);
> public static void main(String[] args) throws InterruptedException {
> LOGGER.trace("Waiting for YourKit to start");
> Thread.sleep(15000);
> NioSocketConnector connector = new NioSocketConnector();
> connector.setHandler(new IoHandlerAdapter());
> closeSession(getConnectedSession(connector));
> // LOGGER.info("Creating and closing 5 sessions in series");
> //
> // for (int x = 0; x < 5; x++) {
> // IoSession session = getConnectedSession(connector);
> //
> // if (session == null) {
> // continue;
> // }
> //
> // closeSession(session);
> // }
> //
> // LOGGER.info("Creating 5 sessions and then closing 5 sessions");
> // IoSession[] sessions = new IoSession[5];
> //
> // for (int x = 0; x < 5; x++) {
> // sessions[x] = getConnectedSession(connector);
> // }
> //
> // for (int x = 0; x < 5; x++) {
> // IoSession session = sessions[x];
> //
> // if (session != null) {
> // closeSession(session);
> // sessions[x] = null;
> // }
> // }
> LOGGER.info("Test complete. Sleeping for 60s");
> Thread.sleep(60000);
> }
> private static IoSession getConnectedSession(IoConnector connector) throws InterruptedException {
> IoSession session = null;
> try {
> ConnectFuture future = connector.connect(new InetSocketAddress("134.64.37.183", 11109));
> future.addListener(new IoFutureListener<ConnectFuture>() {
> @Override
> public void operationComplete(ConnectFuture future) {
> LOGGER.debug("Connection completed callback for session " + future.getSession().getId());
> }
> });
> future.awaitUninterruptibly();
> LOGGER.debug("Connection created for session " + future.getSession().getId());
> session = future.getSession();
> Thread.sleep(15000);
> }
> catch (Exception e) {
> LOGGER.error("Failed to connect", e);
> }
> return session;
> }
> private static void closeSession(IoSession session) throws InterruptedException {
> try {
> CloseFuture closeFuture = session.getCloseFuture();
> closeFuture.addListener(new IoFutureListener<CloseFuture>() {
> @Override
> public void operationComplete(CloseFuture future) {
> LOGGER.debug("Session closed callback for session " + future.getSession().getId());
> }
> });
> LOGGER.debug("Attempting to close session " + session.getId());
> session.close(false);
> LOGGER.debug("IoSession.close(false) returned. Awaiting uninterruptibily for session " + session.getId());
> closeFuture.awaitUninterruptibly();
> LOGGER.debug("Close completed for session " + session.getId());
> }
> catch (Exception e) {
> LOGGER.error("Failed to close session " + session.getId());
> session.close(true);
> }
> Thread.sleep(15000);
> }
> }
> {code}
> Attached is the hprof file of my program, taken after the program has run (during the 60 second sleep at the end) and a screen shot of the GC Root of the leaked NioSocketSession.
> After a couple days of debugging, I've identified why this is happening. Below is a snippet from the AbstractPollingIoConnector.Connector thread
> {code}
> private class Connector implements Runnable {
> public void run() {
> int nHandles = 0;
> while (selectable) {
> try {
> // the timeout for select shall be smaller of the connect
> // timeout or 1 second...
> int timeout = (int)Math.min(getConnectTimeoutMillis(), 1000L);
> int selected = select(timeout);
> nHandles += registerNew();
> if (selected > 0) {
> nHandles -= processConnections(selectedHandles());
> }
> processTimedOutSessions(allHandles());
> nHandles -= cancelKeys();
> if (nHandles == 0) {
> synchronized (lock) {
> if (connectQueue.isEmpty()) {
> connector = null;
> break;
> }
> }
> }
> }
> ...
> {code}
> When IoSession.close(boolean) is called, the above Connector thread cancels the SelectionKey associated with the session, which reduces the number of handles from 1 to 0. Immediately afterwards, the thread stops executing because there are no handles and nothing in the connetQueue, however, the previously cancelled key is still in the Selector because its cancelledKeys Set is not processed until the next call to select(int)
> Calling dispose on the IoConnector restarts the Connector thread, which calls Selector.select(int), at which time, the Selector cleans out its canclledKeys.
> Creating a new connection causes the same thing to happen, because the new session also recreates the AbstractPollingIoConnector.Connector thread, as there is a new handle to be processed.
--
This message is automatically generated by JIRA.
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] [Commented] (DIRMINA-827) NioSocketConnector leaks the last
open NioSocketSession after close
Posted by "Victor N (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/DIRMINA-827?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13018196#comment-13018196 ]
Victor N commented on DIRMINA-827:
----------------------------------
Can confirm that the problem exists - we are using connector too.
> NioSocketConnector leaks the last open NioSocketSession after close
> -------------------------------------------------------------------
>
> Key: DIRMINA-827
> URL: https://issues.apache.org/jira/browse/DIRMINA-827
> Project: MINA
> Issue Type: Bug
> Components: Core
> Affects Versions: 2.0.2
> Environment: Windows 7/Solaris SPARC/Solaris x86
> Java versions 6u18 & 6u24
> Reporter: Matt Yates
> Priority: Critical
> Labels: connector, mina, session
> Attachments: MinaMain-2011-04-10.hprof, sessionGcRoot.jpg
>
>
> My company's program uses MINA to make multiple (usually) simultaneous connections to various other machines, while reusing the same NioSocketConnector for each new connection. For better or worse, we store various objects in the IoSession's attributes, which we expect to get released on close. This is not always the case, however, as said session remains in memory until either a new connection is made or the IoConnector is disposed. After writing the simplest Connector program I could (I have several servers available on my network, so I did not write a matching Acceptor), and performing some profiling and debugging, I was able to confirm the leak and identify the issue.
> Below is my Connector test program
> {code}
> public class MinaMain {
> private static final Logger LOGGER = LoggerFactory.getLogger(MinaMain.class);
> public static void main(String[] args) throws InterruptedException {
> LOGGER.trace("Waiting for YourKit to start");
> Thread.sleep(15000);
> NioSocketConnector connector = new NioSocketConnector();
> connector.setHandler(new IoHandlerAdapter());
> closeSession(getConnectedSession(connector));
> // LOGGER.info("Creating and closing 5 sessions in series");
> //
> // for (int x = 0; x < 5; x++) {
> // IoSession session = getConnectedSession(connector);
> //
> // if (session == null) {
> // continue;
> // }
> //
> // closeSession(session);
> // }
> //
> // LOGGER.info("Creating 5 sessions and then closing 5 sessions");
> // IoSession[] sessions = new IoSession[5];
> //
> // for (int x = 0; x < 5; x++) {
> // sessions[x] = getConnectedSession(connector);
> // }
> //
> // for (int x = 0; x < 5; x++) {
> // IoSession session = sessions[x];
> //
> // if (session != null) {
> // closeSession(session);
> // sessions[x] = null;
> // }
> // }
> LOGGER.info("Test complete. Sleeping for 60s");
> Thread.sleep(60000);
> }
> private static IoSession getConnectedSession(IoConnector connector) throws InterruptedException {
> IoSession session = null;
> try {
> ConnectFuture future = connector.connect(new InetSocketAddress("134.64.37.183", 11109));
> future.addListener(new IoFutureListener<ConnectFuture>() {
> @Override
> public void operationComplete(ConnectFuture future) {
> LOGGER.debug("Connection completed callback for session " + future.getSession().getId());
> }
> });
> future.awaitUninterruptibly();
> LOGGER.debug("Connection created for session " + future.getSession().getId());
> session = future.getSession();
> Thread.sleep(15000);
> }
> catch (Exception e) {
> LOGGER.error("Failed to connect", e);
> }
> return session;
> }
> private static void closeSession(IoSession session) throws InterruptedException {
> try {
> CloseFuture closeFuture = session.getCloseFuture();
> closeFuture.addListener(new IoFutureListener<CloseFuture>() {
> @Override
> public void operationComplete(CloseFuture future) {
> LOGGER.debug("Session closed callback for session " + future.getSession().getId());
> }
> });
> LOGGER.debug("Attempting to close session " + session.getId());
> session.close(false);
> LOGGER.debug("IoSession.close(false) returned. Awaiting uninterruptibily for session " + session.getId());
> closeFuture.awaitUninterruptibly();
> LOGGER.debug("Close completed for session " + session.getId());
> }
> catch (Exception e) {
> LOGGER.error("Failed to close session " + session.getId());
> session.close(true);
> }
> Thread.sleep(15000);
> }
> }
> {code}
> Attached is the hprof file of my program, taken after the program has run (during the 60 second sleep at the end) and a screen shot of the GC Root of the leaked NioSocketSession.
> After a couple days of debugging, I've identified why this is happening. Below is a snippet from the AbstractPollingIoConnector.Connector thread
> {code}
> private class Connector implements Runnable {
> public void run() {
> int nHandles = 0;
> while (selectable) {
> try {
> // the timeout for select shall be smaller of the connect
> // timeout or 1 second...
> int timeout = (int)Math.min(getConnectTimeoutMillis(), 1000L);
> int selected = select(timeout);
> nHandles += registerNew();
> if (selected > 0) {
> nHandles -= processConnections(selectedHandles());
> }
> processTimedOutSessions(allHandles());
> nHandles -= cancelKeys();
> if (nHandles == 0) {
> synchronized (lock) {
> if (connectQueue.isEmpty()) {
> connector = null;
> break;
> }
> }
> }
> }
> ...
> {code}
> When IoSession.close(boolean) is called, the above Connector thread cancels the SelectionKey associated with the session, which reduces the number of handles from 1 to 0. Immediately afterwards, the thread stops executing because there are no handles and nothing in the connetQueue, however, the previously cancelled key is still in the Selector because its cancelledKeys Set is not processed until the next call to select(int)
> Calling dispose on the IoConnector restarts the Connector thread, which calls Selector.select(int), at which time, the Selector cleans out its canclledKeys.
> Creating a new connection causes the same thing to happen, because the new session also recreates the AbstractPollingIoConnector.Connector thread, as there is a new handle to be processed.
--
This message is automatically generated by JIRA.
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] [Updated] (DIRMINA-827) NioSocketConnector leaks the last
open NioSocketSession after close
Posted by "Matt Yates (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/DIRMINA-827?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Matt Yates updated DIRMINA-827:
-------------------------------
Description:
My company's program uses MINA to make multiple (usually) simultaneous connections to various other machines, while reusing the same NioSocketConnector for each new connection. For better or worse, we store various objects in the IoSession's attributes, which we expect to get released on close. This is not always the case, however, as said session remains in memory until either a new connection is made or the IoConnector is disposed. After writing the simplest Connector program I could (I have several servers available on my network, so I did not write a matching Acceptor), and performing some profiling and debugging, I was able to confirm the leak and identify the issue.
Below is my Connector test program
{code}
public class MinaMain {
private static final Logger LOGGER = LoggerFactory.getLogger(MinaMain.class);
public static void main(String[] args) throws InterruptedException {
LOGGER.trace("Waiting for YourKit to start");
Thread.sleep(15000);
NioSocketConnector connector = new NioSocketConnector();
connector.setHandler(new IoHandlerAdapter());
closeSession(getConnectedSession(connector));
// LOGGER.info("Creating and closing 5 sessions in series");
//
// for (int x = 0; x < 5; x++) {
// IoSession session = getConnectedSession(connector);
//
// if (session == null) {
// continue;
// }
//
// closeSession(session);
// }
//
// LOGGER.info("Creating 5 sessions and then closing 5 sessions");
// IoSession[] sessions = new IoSession[5];
//
// for (int x = 0; x < 5; x++) {
// sessions[x] = getConnectedSession(connector);
// }
//
// for (int x = 0; x < 5; x++) {
// IoSession session = sessions[x];
//
// if (session != null) {
// closeSession(session);
// sessions[x] = null;
// }
// }
LOGGER.info("Test complete. Sleeping for 60s");
Thread.sleep(60000);
}
private static IoSession getConnectedSession(IoConnector connector) throws InterruptedException {
IoSession session = null;
try {
ConnectFuture future = connector.connect(new InetSocketAddress("134.64.37.183", 11109));
future.addListener(new IoFutureListener<ConnectFuture>() {
@Override
public void operationComplete(ConnectFuture future) {
LOGGER.debug("Connection completed callback for session " + future.getSession().getId());
}
});
future.awaitUninterruptibly();
LOGGER.debug("Connection created for session " + future.getSession().getId());
session = future.getSession();
Thread.sleep(15000);
}
catch (Exception e) {
LOGGER.error("Failed to connect", e);
}
return session;
}
private static void closeSession(IoSession session) throws InterruptedException {
try {
CloseFuture closeFuture = session.getCloseFuture();
closeFuture.addListener(new IoFutureListener<CloseFuture>() {
@Override
public void operationComplete(CloseFuture future) {
LOGGER.debug("Session closed callback for session " + future.getSession().getId());
}
});
LOGGER.debug("Attempting to close session " + session.getId());
session.close(false);
LOGGER.debug("IoSession.close(false) returned. Awaiting uninterruptibily for session " + session.getId());
closeFuture.awaitUninterruptibly();
LOGGER.debug("Close completed for session " + session.getId());
}
catch (Exception e) {
LOGGER.error("Failed to close session " + session.getId());
session.close(true);
}
Thread.sleep(15000);
}
}
Attached is the hprof file of my program, taken after the program has run (during the 60 second sleep at the end) and a screen shot of the GC Root of the leaked NioSocketSession.
After a couple days of debugging, I've identified why this is happening. Below is a snippet from the AbstractPollingIoConnector.Connector thread
private class Connector implements Runnable {
public void run() {
int nHandles = 0;
while (selectable) {
try {
// the timeout for select shall be smaller of the connect
// timeout or 1 second...
int timeout = (int)Math.min(getConnectTimeoutMillis(), 1000L);
int selected = select(timeout);
nHandles += registerNew();
if (selected > 0) {
nHandles -= processConnections(selectedHandles());
}
processTimedOutSessions(allHandles());
nHandles -= cancelKeys();
if (nHandles == 0) {
synchronized (lock) {
if (connectQueue.isEmpty()) {
connector = null;
break;
}
}
}
}
...
When IoSession.close(boolean) is called, the above Connector thread cancels the SelectionKey associated with the session, which reduces the number of handles from 1 to 0. Immediately afterwards, the thread stops executing because there are no handles and nothing in the connetQueue, however, the previously cancelled key is still in the Selector because its cancelledKeys Set is not processed until the next call to select(int)
Calling dispose on the IoConnector restarts the Connector thread, which calls Selector.select(int), at which time, the Selector cleans out its canclledKeys.
Creating a new connection causes the same thing to happen, because the new session also recreates the AbstractPollingIoConnector.Connector thread, as there is a new handle to be processed.
was:
My company's program uses MINA makes multiple (usually) simultaneous connections to various other machines, while reusing the same NioSocketConnector for each new connection. For better or worse, we store various objects in the IoSession's attributes, which we expect to get released on close, however, said session remains in memory until either a new connection is made or the connector is disposed. After writing the simplest Connector program I could (I have several servers available on my network, so I did not write a matching Acceptor), and performing some profiling and debugging, I was able to confirm the leak and identify the issue.
Below is my Connector test program
{code}
public class MinaMain {
private static final Logger LOGGER = LoggerFactory.getLogger(MinaMain.class);
public static void main(String[] args) throws InterruptedException {
LOGGER.trace("Waiting for YourKit to start");
Thread.sleep(15000);
NioSocketConnector connector = new NioSocketConnector();
connector.setHandler(new IoHandlerAdapter());
closeSession(getConnectedSession(connector));
// LOGGER.info("Creating and closing 5 sessions in series");
//
// for (int x = 0; x < 5; x++) {
// IoSession session = getConnectedSession(connector);
//
// if (session == null) {
// continue;
// }
//
// closeSession(session);
// }
//
// LOGGER.info("Creating 5 sessions and then closing 5 sessions");
// IoSession[] sessions = new IoSession[5];
//
// for (int x = 0; x < 5; x++) {
// sessions[x] = getConnectedSession(connector);
// }
//
// for (int x = 0; x < 5; x++) {
// IoSession session = sessions[x];
//
// if (session != null) {
// closeSession(session);
// sessions[x] = null;
// }
// }
LOGGER.info("Test complete. Sleeping for 60s");
Thread.sleep(60000);
}
private static IoSession getConnectedSession(IoConnector connector) throws InterruptedException {
IoSession session = null;
try {
ConnectFuture future = connector.connect(new InetSocketAddress("134.64.37.183", 11109));
future.addListener(new IoFutureListener<ConnectFuture>() {
@Override
public void operationComplete(ConnectFuture future) {
LOGGER.debug("Connection completed callback for session " + future.getSession().getId());
}
});
future.awaitUninterruptibly();
LOGGER.debug("Connection created for session " + future.getSession().getId());
session = future.getSession();
Thread.sleep(15000);
}
catch (Exception e) {
LOGGER.error("Failed to connect", e);
}
return session;
}
private static void closeSession(IoSession session) throws InterruptedException {
try {
CloseFuture closeFuture = session.getCloseFuture();
closeFuture.addListener(new IoFutureListener<CloseFuture>() {
@Override
public void operationComplete(CloseFuture future) {
LOGGER.debug("Session closed callback for session " + future.getSession().getId());
}
});
LOGGER.debug("Attempting to close session " + session.getId());
session.close(false);
LOGGER.debug("IoSession.close(false) returned. Awaiting uninterruptibily for session " + session.getId());
closeFuture.awaitUninterruptibly();
LOGGER.debug("Close completed for session " + session.getId());
}
catch (Exception e) {
LOGGER.error("Failed to close session " + session.getId());
session.close(true);
}
Thread.sleep(15000);
}
}
{/code}
Attached is the hprof file of my program, taken after the program has run (during the 60 second sleep at the end) and a screen shot of the GC Root of the leaked NioSocketSession.
After a couple days of debugging, I've identified why this is happening. Below is a snippet from the AbstractPollingIoConnector.Connector thread
{code}private class Connector implements Runnable {
public void run() {
int nHandles = 0;
while (selectable) {
try {
// the timeout for select shall be smaller of the connect
// timeout or 1 second...
int timeout = (int)Math.min(getConnectTimeoutMillis(), 1000L);
int selected = select(timeout);
nHandles += registerNew();
if (selected > 0) {
nHandles -= processConnections(selectedHandles());
}
processTimedOutSessions(allHandles());
nHandles -= cancelKeys();
if (nHandles == 0) {
synchronized (lock) {
if (connectQueue.isEmpty()) {
connector = null;
break;
}
}
}
}
...
{/code}
When IoSession.close(boolean) is called, the above Connector thread cancels the SelectionKey associated with the session, which reduces the number of handles from 1 to 0. Immediately afterwards, the thread stops executing because there are no handles and nothing in the connetQueue, however, the previously cancelled key is still in the Selector because its cancelledKeys Set is not processed until the next call to select(int)
Calling dispose on the IoConnector restarts the Connector thread, which calls Selector.select(int), at which time, the Selector cleans out its canclledKeys.
Creating a new connection causes the same thing to happen, because the new session also recreates the AbstractPollingIoConnector.Connector thread, as there is a new handle to be processed.
> NioSocketConnector leaks the last open NioSocketSession after close
> -------------------------------------------------------------------
>
> Key: DIRMINA-827
> URL: https://issues.apache.org/jira/browse/DIRMINA-827
> Project: MINA
> Issue Type: Bug
> Components: Core
> Affects Versions: 2.0.2
> Environment: Windows 7/Solaris SPARC/Solaris x86
> Java versions 6u18 & 6u24
> Reporter: Matt Yates
> Priority: Critical
> Labels: connector, mina, session
>
> My company's program uses MINA to make multiple (usually) simultaneous connections to various other machines, while reusing the same NioSocketConnector for each new connection. For better or worse, we store various objects in the IoSession's attributes, which we expect to get released on close. This is not always the case, however, as said session remains in memory until either a new connection is made or the IoConnector is disposed. After writing the simplest Connector program I could (I have several servers available on my network, so I did not write a matching Acceptor), and performing some profiling and debugging, I was able to confirm the leak and identify the issue.
> Below is my Connector test program
> {code}
> public class MinaMain {
> private static final Logger LOGGER = LoggerFactory.getLogger(MinaMain.class);
> public static void main(String[] args) throws InterruptedException {
> LOGGER.trace("Waiting for YourKit to start");
> Thread.sleep(15000);
> NioSocketConnector connector = new NioSocketConnector();
> connector.setHandler(new IoHandlerAdapter());
> closeSession(getConnectedSession(connector));
> // LOGGER.info("Creating and closing 5 sessions in series");
> //
> // for (int x = 0; x < 5; x++) {
> // IoSession session = getConnectedSession(connector);
> //
> // if (session == null) {
> // continue;
> // }
> //
> // closeSession(session);
> // }
> //
> // LOGGER.info("Creating 5 sessions and then closing 5 sessions");
> // IoSession[] sessions = new IoSession[5];
> //
> // for (int x = 0; x < 5; x++) {
> // sessions[x] = getConnectedSession(connector);
> // }
> //
> // for (int x = 0; x < 5; x++) {
> // IoSession session = sessions[x];
> //
> // if (session != null) {
> // closeSession(session);
> // sessions[x] = null;
> // }
> // }
> LOGGER.info("Test complete. Sleeping for 60s");
> Thread.sleep(60000);
> }
> private static IoSession getConnectedSession(IoConnector connector) throws InterruptedException {
> IoSession session = null;
> try {
> ConnectFuture future = connector.connect(new InetSocketAddress("134.64.37.183", 11109));
> future.addListener(new IoFutureListener<ConnectFuture>() {
> @Override
> public void operationComplete(ConnectFuture future) {
> LOGGER.debug("Connection completed callback for session " + future.getSession().getId());
> }
> });
> future.awaitUninterruptibly();
> LOGGER.debug("Connection created for session " + future.getSession().getId());
> session = future.getSession();
> Thread.sleep(15000);
> }
> catch (Exception e) {
> LOGGER.error("Failed to connect", e);
> }
> return session;
> }
> private static void closeSession(IoSession session) throws InterruptedException {
> try {
> CloseFuture closeFuture = session.getCloseFuture();
> closeFuture.addListener(new IoFutureListener<CloseFuture>() {
> @Override
> public void operationComplete(CloseFuture future) {
> LOGGER.debug("Session closed callback for session " + future.getSession().getId());
> }
> });
> LOGGER.debug("Attempting to close session " + session.getId());
> session.close(false);
> LOGGER.debug("IoSession.close(false) returned. Awaiting uninterruptibily for session " + session.getId());
> closeFuture.awaitUninterruptibly();
> LOGGER.debug("Close completed for session " + session.getId());
> }
> catch (Exception e) {
> LOGGER.error("Failed to close session " + session.getId());
> session.close(true);
> }
> Thread.sleep(15000);
> }
> }
> Attached is the hprof file of my program, taken after the program has run (during the 60 second sleep at the end) and a screen shot of the GC Root of the leaked NioSocketSession.
> After a couple days of debugging, I've identified why this is happening. Below is a snippet from the AbstractPollingIoConnector.Connector thread
> private class Connector implements Runnable {
> public void run() {
> int nHandles = 0;
> while (selectable) {
> try {
> // the timeout for select shall be smaller of the connect
> // timeout or 1 second...
> int timeout = (int)Math.min(getConnectTimeoutMillis(), 1000L);
> int selected = select(timeout);
> nHandles += registerNew();
> if (selected > 0) {
> nHandles -= processConnections(selectedHandles());
> }
> processTimedOutSessions(allHandles());
> nHandles -= cancelKeys();
> if (nHandles == 0) {
> synchronized (lock) {
> if (connectQueue.isEmpty()) {
> connector = null;
> break;
> }
> }
> }
> }
> ...
> When IoSession.close(boolean) is called, the above Connector thread cancels the SelectionKey associated with the session, which reduces the number of handles from 1 to 0. Immediately afterwards, the thread stops executing because there are no handles and nothing in the connetQueue, however, the previously cancelled key is still in the Selector because its cancelledKeys Set is not processed until the next call to select(int)
> Calling dispose on the IoConnector restarts the Connector thread, which calls Selector.select(int), at which time, the Selector cleans out its canclledKeys.
> Creating a new connection causes the same thing to happen, because the new session also recreates the AbstractPollingIoConnector.Connector thread, as there is a new handle to be processed.
--
This message is automatically generated by JIRA.
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] [Commented] (DIRMINA-827) NioSocketConnector leaks the last
open NioSocketSession after close
Posted by "Emmanuel Lecharny (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/DIRMINA-827?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13018507#comment-13018507 ]
Emmanuel Lecharny commented on DIRMINA-827:
-------------------------------------------
Ok, great.
i'll cancel the vote for 2.0.3 right now, wait for your feedback about teh wakeup() (it should have no impact), and start a new vote tomorrow morning.
It's quite a good timing, as we just fixed a couple of other issues in the code base, so I don't really mind cancelling the release. All in all, it's just 20 minutes to cut a new one, and 72 hours to wait before it's official.
Tahnks !
> NioSocketConnector leaks the last open NioSocketSession after close
> -------------------------------------------------------------------
>
> Key: DIRMINA-827
> URL: https://issues.apache.org/jira/browse/DIRMINA-827
> Project: MINA
> Issue Type: Bug
> Components: Core
> Affects Versions: 2.0.2
> Environment: Windows 7/Solaris SPARC/Solaris x86
> Java versions 6u18 & 6u24
> Reporter: Matt Yates
> Assignee: Emmanuel Lecharny
> Priority: Critical
> Labels: connector, mina, session
> Attachments: IoConnectorWithCleanSelector.jpg, MinaMain-2011-04-10.hprof, mina-core-2.0.4-SNAPSHOT.jar, mina-core-2.0.4-SNAPSHOT.jar, sessionGcRoot.jpg
>
>
> My company's program uses MINA to make multiple (usually) simultaneous connections to various other machines, while reusing the same NioSocketConnector for each new connection. For better or worse, we store various objects in the IoSession's attributes, which we expect to get released on close. This is not always the case, however, as said session remains in memory until either a new connection is made or the IoConnector is disposed. After writing the simplest Connector program I could (I have several servers available on my network, so I did not write a matching Acceptor), and performing some profiling and debugging, I was able to confirm the leak and identify the issue.
> Below is my Connector test program
> {code}
> public class MinaMain {
> private static final Logger LOGGER = LoggerFactory.getLogger(MinaMain.class);
> public static void main(String[] args) throws InterruptedException {
> LOGGER.trace("Waiting for YourKit to start");
> Thread.sleep(15000);
> NioSocketConnector connector = new NioSocketConnector();
> connector.setHandler(new IoHandlerAdapter());
> closeSession(getConnectedSession(connector));
> // LOGGER.info("Creating and closing 5 sessions in series");
> //
> // for (int x = 0; x < 5; x++) {
> // IoSession session = getConnectedSession(connector);
> //
> // if (session == null) {
> // continue;
> // }
> //
> // closeSession(session);
> // }
> //
> // LOGGER.info("Creating 5 sessions and then closing 5 sessions");
> // IoSession[] sessions = new IoSession[5];
> //
> // for (int x = 0; x < 5; x++) {
> // sessions[x] = getConnectedSession(connector);
> // }
> //
> // for (int x = 0; x < 5; x++) {
> // IoSession session = sessions[x];
> //
> // if (session != null) {
> // closeSession(session);
> // sessions[x] = null;
> // }
> // }
> LOGGER.info("Test complete. Sleeping for 60s");
> Thread.sleep(60000);
> }
> private static IoSession getConnectedSession(IoConnector connector) throws InterruptedException {
> IoSession session = null;
> try {
> ConnectFuture future = connector.connect(new InetSocketAddress("134.64.37.183", 11109));
> future.addListener(new IoFutureListener<ConnectFuture>() {
> @Override
> public void operationComplete(ConnectFuture future) {
> LOGGER.debug("Connection completed callback for session " + future.getSession().getId());
> }
> });
> future.awaitUninterruptibly();
> LOGGER.debug("Connection created for session " + future.getSession().getId());
> session = future.getSession();
> Thread.sleep(15000);
> }
> catch (Exception e) {
> LOGGER.error("Failed to connect", e);
> }
> return session;
> }
> private static void closeSession(IoSession session) throws InterruptedException {
> try {
> CloseFuture closeFuture = session.getCloseFuture();
> closeFuture.addListener(new IoFutureListener<CloseFuture>() {
> @Override
> public void operationComplete(CloseFuture future) {
> LOGGER.debug("Session closed callback for session " + future.getSession().getId());
> }
> });
> LOGGER.debug("Attempting to close session " + session.getId());
> session.close(false);
> LOGGER.debug("IoSession.close(false) returned. Awaiting uninterruptibily for session " + session.getId());
> closeFuture.awaitUninterruptibly();
> LOGGER.debug("Close completed for session " + session.getId());
> }
> catch (Exception e) {
> LOGGER.error("Failed to close session " + session.getId());
> session.close(true);
> }
> Thread.sleep(15000);
> }
> }
> {code}
> Attached is the hprof file of my program, taken after the program has run (during the 60 second sleep at the end) and a screen shot of the GC Root of the leaked NioSocketSession.
> After a couple days of debugging, I've identified why this is happening. Below is a snippet from the AbstractPollingIoConnector.Connector thread
> {code}
> private class Connector implements Runnable {
> public void run() {
> int nHandles = 0;
> while (selectable) {
> try {
> // the timeout for select shall be smaller of the connect
> // timeout or 1 second...
> int timeout = (int)Math.min(getConnectTimeoutMillis(), 1000L);
> int selected = select(timeout);
> nHandles += registerNew();
> if (selected > 0) {
> nHandles -= processConnections(selectedHandles());
> }
> processTimedOutSessions(allHandles());
> nHandles -= cancelKeys();
> if (nHandles == 0) {
> synchronized (lock) {
> if (connectQueue.isEmpty()) {
> connector = null;
> break;
> }
> }
> }
> }
> ...
> {code}
> When IoSession.close(boolean) is called, the above Connector thread cancels the SelectionKey associated with the session, which reduces the number of handles from 1 to 0. Immediately afterwards, the thread stops executing because there are no handles and nothing in the connetQueue, however, the previously cancelled key is still in the Selector because its cancelledKeys Set is not processed until the next call to select(int)
> Calling dispose on the IoConnector restarts the Connector thread, which calls Selector.select(int), at which time, the Selector cleans out its canclledKeys.
> Creating a new connection causes the same thing to happen, because the new session also recreates the AbstractPollingIoConnector.Connector thread, as there is a new handle to be processed.
--
This message is automatically generated by JIRA.
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] [Issue Comment Edited] (DIRMINA-827) NioSocketConnector
leaks the last open NioSocketSession after close
Posted by "Matt Yates (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/DIRMINA-827?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13018866#comment-13018866 ]
Matt Yates edited comment on DIRMINA-827 at 4/12/11 3:21 PM:
-------------------------------------------------------------
I can't really tell if it's blocking, b/c it never blocks for more than 1 second, even if you set a large timeout
int timeout = (int)Math.min(getConnectTimeoutMillis(), 1000L);
Regardless, moving the check for zero handles works, and with the extra insurance of the wakeup() call, I think we have a winner.
Thank you very much for your attention/work on this issue!
was (Author: myates):
I can't really tell if it's blocking, b/c it never blocks for more that 1 second, even if you set a large timeout
int timeout = (int)Math.min(getConnectTimeoutMillis(), 1000L);
Regardless, moving the check for zero handles works, and with the extra insurance of the wakeup() call, I think we have a winner.
Thank you very much for your attention/work on this issue!
> NioSocketConnector leaks the last open NioSocketSession after close
> -------------------------------------------------------------------
>
> Key: DIRMINA-827
> URL: https://issues.apache.org/jira/browse/DIRMINA-827
> Project: MINA
> Issue Type: Bug
> Components: Core
> Affects Versions: 2.0.2
> Environment: Windows 7/Solaris SPARC/Solaris x86
> Java versions 6u18 & 6u24
> Reporter: Matt Yates
> Assignee: Emmanuel Lecharny
> Priority: Critical
> Labels: connector, mina, session
> Attachments: IoConnectorWithCleanSelector.jpg, MinaMain-2011-04-10.hprof, mina-core-2.0.4-SNAPSHOT.jar, mina-core-2.0.4-SNAPSHOT.jar, sessionGcRoot.jpg
>
>
> My company's program uses MINA to make multiple (usually) simultaneous connections to various other machines, while reusing the same NioSocketConnector for each new connection. For better or worse, we store various objects in the IoSession's attributes, which we expect to get released on close. This is not always the case, however, as said session remains in memory until either a new connection is made or the IoConnector is disposed. After writing the simplest Connector program I could (I have several servers available on my network, so I did not write a matching Acceptor), and performing some profiling and debugging, I was able to confirm the leak and identify the issue.
> Below is my Connector test program
> {code}
> public class MinaMain {
> private static final Logger LOGGER = LoggerFactory.getLogger(MinaMain.class);
> public static void main(String[] args) throws InterruptedException {
> LOGGER.trace("Waiting for YourKit to start");
> Thread.sleep(15000);
> NioSocketConnector connector = new NioSocketConnector();
> connector.setHandler(new IoHandlerAdapter());
> closeSession(getConnectedSession(connector));
> // LOGGER.info("Creating and closing 5 sessions in series");
> //
> // for (int x = 0; x < 5; x++) {
> // IoSession session = getConnectedSession(connector);
> //
> // if (session == null) {
> // continue;
> // }
> //
> // closeSession(session);
> // }
> //
> // LOGGER.info("Creating 5 sessions and then closing 5 sessions");
> // IoSession[] sessions = new IoSession[5];
> //
> // for (int x = 0; x < 5; x++) {
> // sessions[x] = getConnectedSession(connector);
> // }
> //
> // for (int x = 0; x < 5; x++) {
> // IoSession session = sessions[x];
> //
> // if (session != null) {
> // closeSession(session);
> // sessions[x] = null;
> // }
> // }
> LOGGER.info("Test complete. Sleeping for 60s");
> Thread.sleep(60000);
> }
> private static IoSession getConnectedSession(IoConnector connector) throws InterruptedException {
> IoSession session = null;
> try {
> ConnectFuture future = connector.connect(new InetSocketAddress("134.64.37.183", 11109));
> future.addListener(new IoFutureListener<ConnectFuture>() {
> @Override
> public void operationComplete(ConnectFuture future) {
> LOGGER.debug("Connection completed callback for session " + future.getSession().getId());
> }
> });
> future.awaitUninterruptibly();
> LOGGER.debug("Connection created for session " + future.getSession().getId());
> session = future.getSession();
> Thread.sleep(15000);
> }
> catch (Exception e) {
> LOGGER.error("Failed to connect", e);
> }
> return session;
> }
> private static void closeSession(IoSession session) throws InterruptedException {
> try {
> CloseFuture closeFuture = session.getCloseFuture();
> closeFuture.addListener(new IoFutureListener<CloseFuture>() {
> @Override
> public void operationComplete(CloseFuture future) {
> LOGGER.debug("Session closed callback for session " + future.getSession().getId());
> }
> });
> LOGGER.debug("Attempting to close session " + session.getId());
> session.close(false);
> LOGGER.debug("IoSession.close(false) returned. Awaiting uninterruptibily for session " + session.getId());
> closeFuture.awaitUninterruptibly();
> LOGGER.debug("Close completed for session " + session.getId());
> }
> catch (Exception e) {
> LOGGER.error("Failed to close session " + session.getId());
> session.close(true);
> }
> Thread.sleep(15000);
> }
> }
> {code}
> Attached is the hprof file of my program, taken after the program has run (during the 60 second sleep at the end) and a screen shot of the GC Root of the leaked NioSocketSession.
> After a couple days of debugging, I've identified why this is happening. Below is a snippet from the AbstractPollingIoConnector.Connector thread
> {code}
> private class Connector implements Runnable {
> public void run() {
> int nHandles = 0;
> while (selectable) {
> try {
> // the timeout for select shall be smaller of the connect
> // timeout or 1 second...
> int timeout = (int)Math.min(getConnectTimeoutMillis(), 1000L);
> int selected = select(timeout);
> nHandles += registerNew();
> if (selected > 0) {
> nHandles -= processConnections(selectedHandles());
> }
> processTimedOutSessions(allHandles());
> nHandles -= cancelKeys();
> if (nHandles == 0) {
> synchronized (lock) {
> if (connectQueue.isEmpty()) {
> connector = null;
> break;
> }
> }
> }
> }
> ...
> {code}
> When IoSession.close(boolean) is called, the above Connector thread cancels the SelectionKey associated with the session, which reduces the number of handles from 1 to 0. Immediately afterwards, the thread stops executing because there are no handles and nothing in the connetQueue, however, the previously cancelled key is still in the Selector because its cancelledKeys Set is not processed until the next call to select(int)
> Calling dispose on the IoConnector restarts the Connector thread, which calls Selector.select(int), at which time, the Selector cleans out its canclledKeys.
> Creating a new connection causes the same thing to happen, because the new session also recreates the AbstractPollingIoConnector.Connector thread, as there is a new handle to be processed.
--
This message is automatically generated by JIRA.
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] [Updated] (DIRMINA-827) NioSocketConnector leaks the last
open NioSocketSession after close
Posted by "Matt Yates (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/DIRMINA-827?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Matt Yates updated DIRMINA-827:
-------------------------------
Attachment: sessionGcRoot.jpg
Here is the path of strong references that are keeping the session from being released
> NioSocketConnector leaks the last open NioSocketSession after close
> -------------------------------------------------------------------
>
> Key: DIRMINA-827
> URL: https://issues.apache.org/jira/browse/DIRMINA-827
> Project: MINA
> Issue Type: Bug
> Components: Core
> Affects Versions: 2.0.2
> Environment: Windows 7/Solaris SPARC/Solaris x86
> Java versions 6u18 & 6u24
> Reporter: Matt Yates
> Priority: Critical
> Labels: connector, mina, session
> Attachments: MinaMain-2011-04-10.hprof, sessionGcRoot.jpg
>
>
> My company's program uses MINA to make multiple (usually) simultaneous connections to various other machines, while reusing the same NioSocketConnector for each new connection. For better or worse, we store various objects in the IoSession's attributes, which we expect to get released on close. This is not always the case, however, as said session remains in memory until either a new connection is made or the IoConnector is disposed. After writing the simplest Connector program I could (I have several servers available on my network, so I did not write a matching Acceptor), and performing some profiling and debugging, I was able to confirm the leak and identify the issue.
> Below is my Connector test program
> {code}
> public class MinaMain {
> private static final Logger LOGGER = LoggerFactory.getLogger(MinaMain.class);
> public static void main(String[] args) throws InterruptedException {
> LOGGER.trace("Waiting for YourKit to start");
> Thread.sleep(15000);
> NioSocketConnector connector = new NioSocketConnector();
> connector.setHandler(new IoHandlerAdapter());
> closeSession(getConnectedSession(connector));
> // LOGGER.info("Creating and closing 5 sessions in series");
> //
> // for (int x = 0; x < 5; x++) {
> // IoSession session = getConnectedSession(connector);
> //
> // if (session == null) {
> // continue;
> // }
> //
> // closeSession(session);
> // }
> //
> // LOGGER.info("Creating 5 sessions and then closing 5 sessions");
> // IoSession[] sessions = new IoSession[5];
> //
> // for (int x = 0; x < 5; x++) {
> // sessions[x] = getConnectedSession(connector);
> // }
> //
> // for (int x = 0; x < 5; x++) {
> // IoSession session = sessions[x];
> //
> // if (session != null) {
> // closeSession(session);
> // sessions[x] = null;
> // }
> // }
> LOGGER.info("Test complete. Sleeping for 60s");
> Thread.sleep(60000);
> }
> private static IoSession getConnectedSession(IoConnector connector) throws InterruptedException {
> IoSession session = null;
> try {
> ConnectFuture future = connector.connect(new InetSocketAddress("134.64.37.183", 11109));
> future.addListener(new IoFutureListener<ConnectFuture>() {
> @Override
> public void operationComplete(ConnectFuture future) {
> LOGGER.debug("Connection completed callback for session " + future.getSession().getId());
> }
> });
> future.awaitUninterruptibly();
> LOGGER.debug("Connection created for session " + future.getSession().getId());
> session = future.getSession();
> Thread.sleep(15000);
> }
> catch (Exception e) {
> LOGGER.error("Failed to connect", e);
> }
> return session;
> }
> private static void closeSession(IoSession session) throws InterruptedException {
> try {
> CloseFuture closeFuture = session.getCloseFuture();
> closeFuture.addListener(new IoFutureListener<CloseFuture>() {
> @Override
> public void operationComplete(CloseFuture future) {
> LOGGER.debug("Session closed callback for session " + future.getSession().getId());
> }
> });
> LOGGER.debug("Attempting to close session " + session.getId());
> session.close(false);
> LOGGER.debug("IoSession.close(false) returned. Awaiting uninterruptibily for session " + session.getId());
> closeFuture.awaitUninterruptibly();
> LOGGER.debug("Close completed for session " + session.getId());
> }
> catch (Exception e) {
> LOGGER.error("Failed to close session " + session.getId());
> session.close(true);
> }
> Thread.sleep(15000);
> }
> }
> Attached is the hprof file of my program, taken after the program has run (during the 60 second sleep at the end) and a screen shot of the GC Root of the leaked NioSocketSession.
> After a couple days of debugging, I've identified why this is happening. Below is a snippet from the AbstractPollingIoConnector.Connector thread
> private class Connector implements Runnable {
> public void run() {
> int nHandles = 0;
> while (selectable) {
> try {
> // the timeout for select shall be smaller of the connect
> // timeout or 1 second...
> int timeout = (int)Math.min(getConnectTimeoutMillis(), 1000L);
> int selected = select(timeout);
> nHandles += registerNew();
> if (selected > 0) {
> nHandles -= processConnections(selectedHandles());
> }
> processTimedOutSessions(allHandles());
> nHandles -= cancelKeys();
> if (nHandles == 0) {
> synchronized (lock) {
> if (connectQueue.isEmpty()) {
> connector = null;
> break;
> }
> }
> }
> }
> ...
> When IoSession.close(boolean) is called, the above Connector thread cancels the SelectionKey associated with the session, which reduces the number of handles from 1 to 0. Immediately afterwards, the thread stops executing because there are no handles and nothing in the connetQueue, however, the previously cancelled key is still in the Selector because its cancelledKeys Set is not processed until the next call to select(int)
> Calling dispose on the IoConnector restarts the Connector thread, which calls Selector.select(int), at which time, the Selector cleans out its canclledKeys.
> Creating a new connection causes the same thing to happen, because the new session also recreates the AbstractPollingIoConnector.Connector thread, as there is a new handle to be processed.
--
This message is automatically generated by JIRA.
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] [Commented] (DIRMINA-827) NioSocketConnector leaks the last
open NioSocketSession after close
Posted by "Emmanuel Lecharny (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/DIRMINA-827?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13018257#comment-13018257 ]
Emmanuel Lecharny commented on DIRMINA-827:
-------------------------------------------
I have patched the code to call the sessionClosed() event when the sessions are being closed in the cancelKeys() loop. The mina-core har is attached to this JIRA
Can you give it a try and tell me if it fixes the issue ?
Thanks !
> NioSocketConnector leaks the last open NioSocketSession after close
> -------------------------------------------------------------------
>
> Key: DIRMINA-827
> URL: https://issues.apache.org/jira/browse/DIRMINA-827
> Project: MINA
> Issue Type: Bug
> Components: Core
> Affects Versions: 2.0.2
> Environment: Windows 7/Solaris SPARC/Solaris x86
> Java versions 6u18 & 6u24
> Reporter: Matt Yates
> Priority: Critical
> Labels: connector, mina, session
> Attachments: MinaMain-2011-04-10.hprof, mina-core-2.0.4-SNAPSHOT.jar, sessionGcRoot.jpg
>
>
> My company's program uses MINA to make multiple (usually) simultaneous connections to various other machines, while reusing the same NioSocketConnector for each new connection. For better or worse, we store various objects in the IoSession's attributes, which we expect to get released on close. This is not always the case, however, as said session remains in memory until either a new connection is made or the IoConnector is disposed. After writing the simplest Connector program I could (I have several servers available on my network, so I did not write a matching Acceptor), and performing some profiling and debugging, I was able to confirm the leak and identify the issue.
> Below is my Connector test program
> {code}
> public class MinaMain {
> private static final Logger LOGGER = LoggerFactory.getLogger(MinaMain.class);
> public static void main(String[] args) throws InterruptedException {
> LOGGER.trace("Waiting for YourKit to start");
> Thread.sleep(15000);
> NioSocketConnector connector = new NioSocketConnector();
> connector.setHandler(new IoHandlerAdapter());
> closeSession(getConnectedSession(connector));
> // LOGGER.info("Creating and closing 5 sessions in series");
> //
> // for (int x = 0; x < 5; x++) {
> // IoSession session = getConnectedSession(connector);
> //
> // if (session == null) {
> // continue;
> // }
> //
> // closeSession(session);
> // }
> //
> // LOGGER.info("Creating 5 sessions and then closing 5 sessions");
> // IoSession[] sessions = new IoSession[5];
> //
> // for (int x = 0; x < 5; x++) {
> // sessions[x] = getConnectedSession(connector);
> // }
> //
> // for (int x = 0; x < 5; x++) {
> // IoSession session = sessions[x];
> //
> // if (session != null) {
> // closeSession(session);
> // sessions[x] = null;
> // }
> // }
> LOGGER.info("Test complete. Sleeping for 60s");
> Thread.sleep(60000);
> }
> private static IoSession getConnectedSession(IoConnector connector) throws InterruptedException {
> IoSession session = null;
> try {
> ConnectFuture future = connector.connect(new InetSocketAddress("134.64.37.183", 11109));
> future.addListener(new IoFutureListener<ConnectFuture>() {
> @Override
> public void operationComplete(ConnectFuture future) {
> LOGGER.debug("Connection completed callback for session " + future.getSession().getId());
> }
> });
> future.awaitUninterruptibly();
> LOGGER.debug("Connection created for session " + future.getSession().getId());
> session = future.getSession();
> Thread.sleep(15000);
> }
> catch (Exception e) {
> LOGGER.error("Failed to connect", e);
> }
> return session;
> }
> private static void closeSession(IoSession session) throws InterruptedException {
> try {
> CloseFuture closeFuture = session.getCloseFuture();
> closeFuture.addListener(new IoFutureListener<CloseFuture>() {
> @Override
> public void operationComplete(CloseFuture future) {
> LOGGER.debug("Session closed callback for session " + future.getSession().getId());
> }
> });
> LOGGER.debug("Attempting to close session " + session.getId());
> session.close(false);
> LOGGER.debug("IoSession.close(false) returned. Awaiting uninterruptibily for session " + session.getId());
> closeFuture.awaitUninterruptibly();
> LOGGER.debug("Close completed for session " + session.getId());
> }
> catch (Exception e) {
> LOGGER.error("Failed to close session " + session.getId());
> session.close(true);
> }
> Thread.sleep(15000);
> }
> }
> {code}
> Attached is the hprof file of my program, taken after the program has run (during the 60 second sleep at the end) and a screen shot of the GC Root of the leaked NioSocketSession.
> After a couple days of debugging, I've identified why this is happening. Below is a snippet from the AbstractPollingIoConnector.Connector thread
> {code}
> private class Connector implements Runnable {
> public void run() {
> int nHandles = 0;
> while (selectable) {
> try {
> // the timeout for select shall be smaller of the connect
> // timeout or 1 second...
> int timeout = (int)Math.min(getConnectTimeoutMillis(), 1000L);
> int selected = select(timeout);
> nHandles += registerNew();
> if (selected > 0) {
> nHandles -= processConnections(selectedHandles());
> }
> processTimedOutSessions(allHandles());
> nHandles -= cancelKeys();
> if (nHandles == 0) {
> synchronized (lock) {
> if (connectQueue.isEmpty()) {
> connector = null;
> break;
> }
> }
> }
> }
> ...
> {code}
> When IoSession.close(boolean) is called, the above Connector thread cancels the SelectionKey associated with the session, which reduces the number of handles from 1 to 0. Immediately afterwards, the thread stops executing because there are no handles and nothing in the connetQueue, however, the previously cancelled key is still in the Selector because its cancelledKeys Set is not processed until the next call to select(int)
> Calling dispose on the IoConnector restarts the Connector thread, which calls Selector.select(int), at which time, the Selector cleans out its canclledKeys.
> Creating a new connection causes the same thing to happen, because the new session also recreates the AbstractPollingIoConnector.Connector thread, as there is a new handle to be processed.
--
This message is automatically generated by JIRA.
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] [Updated] (DIRMINA-827) NioSocketConnector leaks the last
open NioSocketSession after close
Posted by "Emmanuel Lecharny (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/DIRMINA-827?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Emmanuel Lecharny updated DIRMINA-827:
--------------------------------------
Attachment: mina-core-2.0.4-SNAPSHOT.jar
Same jar, with a wakeup()
> NioSocketConnector leaks the last open NioSocketSession after close
> -------------------------------------------------------------------
>
> Key: DIRMINA-827
> URL: https://issues.apache.org/jira/browse/DIRMINA-827
> Project: MINA
> Issue Type: Bug
> Components: Core
> Affects Versions: 2.0.2
> Environment: Windows 7/Solaris SPARC/Solaris x86
> Java versions 6u18 & 6u24
> Reporter: Matt Yates
> Assignee: Emmanuel Lecharny
> Priority: Critical
> Labels: connector, mina, session
> Attachments: MinaMain-2011-04-10.hprof, mina-core-2.0.4-SNAPSHOT.jar, mina-core-2.0.4-SNAPSHOT.jar, sessionGcRoot.jpg
>
>
> My company's program uses MINA to make multiple (usually) simultaneous connections to various other machines, while reusing the same NioSocketConnector for each new connection. For better or worse, we store various objects in the IoSession's attributes, which we expect to get released on close. This is not always the case, however, as said session remains in memory until either a new connection is made or the IoConnector is disposed. After writing the simplest Connector program I could (I have several servers available on my network, so I did not write a matching Acceptor), and performing some profiling and debugging, I was able to confirm the leak and identify the issue.
> Below is my Connector test program
> {code}
> public class MinaMain {
> private static final Logger LOGGER = LoggerFactory.getLogger(MinaMain.class);
> public static void main(String[] args) throws InterruptedException {
> LOGGER.trace("Waiting for YourKit to start");
> Thread.sleep(15000);
> NioSocketConnector connector = new NioSocketConnector();
> connector.setHandler(new IoHandlerAdapter());
> closeSession(getConnectedSession(connector));
> // LOGGER.info("Creating and closing 5 sessions in series");
> //
> // for (int x = 0; x < 5; x++) {
> // IoSession session = getConnectedSession(connector);
> //
> // if (session == null) {
> // continue;
> // }
> //
> // closeSession(session);
> // }
> //
> // LOGGER.info("Creating 5 sessions and then closing 5 sessions");
> // IoSession[] sessions = new IoSession[5];
> //
> // for (int x = 0; x < 5; x++) {
> // sessions[x] = getConnectedSession(connector);
> // }
> //
> // for (int x = 0; x < 5; x++) {
> // IoSession session = sessions[x];
> //
> // if (session != null) {
> // closeSession(session);
> // sessions[x] = null;
> // }
> // }
> LOGGER.info("Test complete. Sleeping for 60s");
> Thread.sleep(60000);
> }
> private static IoSession getConnectedSession(IoConnector connector) throws InterruptedException {
> IoSession session = null;
> try {
> ConnectFuture future = connector.connect(new InetSocketAddress("134.64.37.183", 11109));
> future.addListener(new IoFutureListener<ConnectFuture>() {
> @Override
> public void operationComplete(ConnectFuture future) {
> LOGGER.debug("Connection completed callback for session " + future.getSession().getId());
> }
> });
> future.awaitUninterruptibly();
> LOGGER.debug("Connection created for session " + future.getSession().getId());
> session = future.getSession();
> Thread.sleep(15000);
> }
> catch (Exception e) {
> LOGGER.error("Failed to connect", e);
> }
> return session;
> }
> private static void closeSession(IoSession session) throws InterruptedException {
> try {
> CloseFuture closeFuture = session.getCloseFuture();
> closeFuture.addListener(new IoFutureListener<CloseFuture>() {
> @Override
> public void operationComplete(CloseFuture future) {
> LOGGER.debug("Session closed callback for session " + future.getSession().getId());
> }
> });
> LOGGER.debug("Attempting to close session " + session.getId());
> session.close(false);
> LOGGER.debug("IoSession.close(false) returned. Awaiting uninterruptibily for session " + session.getId());
> closeFuture.awaitUninterruptibly();
> LOGGER.debug("Close completed for session " + session.getId());
> }
> catch (Exception e) {
> LOGGER.error("Failed to close session " + session.getId());
> session.close(true);
> }
> Thread.sleep(15000);
> }
> }
> {code}
> Attached is the hprof file of my program, taken after the program has run (during the 60 second sleep at the end) and a screen shot of the GC Root of the leaked NioSocketSession.
> After a couple days of debugging, I've identified why this is happening. Below is a snippet from the AbstractPollingIoConnector.Connector thread
> {code}
> private class Connector implements Runnable {
> public void run() {
> int nHandles = 0;
> while (selectable) {
> try {
> // the timeout for select shall be smaller of the connect
> // timeout or 1 second...
> int timeout = (int)Math.min(getConnectTimeoutMillis(), 1000L);
> int selected = select(timeout);
> nHandles += registerNew();
> if (selected > 0) {
> nHandles -= processConnections(selectedHandles());
> }
> processTimedOutSessions(allHandles());
> nHandles -= cancelKeys();
> if (nHandles == 0) {
> synchronized (lock) {
> if (connectQueue.isEmpty()) {
> connector = null;
> break;
> }
> }
> }
> }
> ...
> {code}
> When IoSession.close(boolean) is called, the above Connector thread cancels the SelectionKey associated with the session, which reduces the number of handles from 1 to 0. Immediately afterwards, the thread stops executing because there are no handles and nothing in the connetQueue, however, the previously cancelled key is still in the Selector because its cancelledKeys Set is not processed until the next call to select(int)
> Calling dispose on the IoConnector restarts the Connector thread, which calls Selector.select(int), at which time, the Selector cleans out its canclledKeys.
> Creating a new connection causes the same thing to happen, because the new session also recreates the AbstractPollingIoConnector.Connector thread, as there is a new handle to be processed.
--
This message is automatically generated by JIRA.
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] [Commented] (DIRMINA-827) NioSocketConnector leaks the last
open NioSocketSession after close
Posted by "Emmanuel Lecharny (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/DIRMINA-827?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13018495#comment-13018495 ]
Emmanuel Lecharny commented on DIRMINA-827:
-------------------------------------------
Adding this portion of code in the cancelKeys method could help :
private int cancelKeys() {
int nHandles = 0;
for (; ;) {
...
}
// If we had some cancelled keys, wake up the selector.
if ( nHandles > 0 ) {
wakeup();
}
return nHandles;
}
> NioSocketConnector leaks the last open NioSocketSession after close
> -------------------------------------------------------------------
>
> Key: DIRMINA-827
> URL: https://issues.apache.org/jira/browse/DIRMINA-827
> Project: MINA
> Issue Type: Bug
> Components: Core
> Affects Versions: 2.0.2
> Environment: Windows 7/Solaris SPARC/Solaris x86
> Java versions 6u18 & 6u24
> Reporter: Matt Yates
> Assignee: Emmanuel Lecharny
> Priority: Critical
> Labels: connector, mina, session
> Attachments: MinaMain-2011-04-10.hprof, mina-core-2.0.4-SNAPSHOT.jar, mina-core-2.0.4-SNAPSHOT.jar, sessionGcRoot.jpg
>
>
> My company's program uses MINA to make multiple (usually) simultaneous connections to various other machines, while reusing the same NioSocketConnector for each new connection. For better or worse, we store various objects in the IoSession's attributes, which we expect to get released on close. This is not always the case, however, as said session remains in memory until either a new connection is made or the IoConnector is disposed. After writing the simplest Connector program I could (I have several servers available on my network, so I did not write a matching Acceptor), and performing some profiling and debugging, I was able to confirm the leak and identify the issue.
> Below is my Connector test program
> {code}
> public class MinaMain {
> private static final Logger LOGGER = LoggerFactory.getLogger(MinaMain.class);
> public static void main(String[] args) throws InterruptedException {
> LOGGER.trace("Waiting for YourKit to start");
> Thread.sleep(15000);
> NioSocketConnector connector = new NioSocketConnector();
> connector.setHandler(new IoHandlerAdapter());
> closeSession(getConnectedSession(connector));
> // LOGGER.info("Creating and closing 5 sessions in series");
> //
> // for (int x = 0; x < 5; x++) {
> // IoSession session = getConnectedSession(connector);
> //
> // if (session == null) {
> // continue;
> // }
> //
> // closeSession(session);
> // }
> //
> // LOGGER.info("Creating 5 sessions and then closing 5 sessions");
> // IoSession[] sessions = new IoSession[5];
> //
> // for (int x = 0; x < 5; x++) {
> // sessions[x] = getConnectedSession(connector);
> // }
> //
> // for (int x = 0; x < 5; x++) {
> // IoSession session = sessions[x];
> //
> // if (session != null) {
> // closeSession(session);
> // sessions[x] = null;
> // }
> // }
> LOGGER.info("Test complete. Sleeping for 60s");
> Thread.sleep(60000);
> }
> private static IoSession getConnectedSession(IoConnector connector) throws InterruptedException {
> IoSession session = null;
> try {
> ConnectFuture future = connector.connect(new InetSocketAddress("134.64.37.183", 11109));
> future.addListener(new IoFutureListener<ConnectFuture>() {
> @Override
> public void operationComplete(ConnectFuture future) {
> LOGGER.debug("Connection completed callback for session " + future.getSession().getId());
> }
> });
> future.awaitUninterruptibly();
> LOGGER.debug("Connection created for session " + future.getSession().getId());
> session = future.getSession();
> Thread.sleep(15000);
> }
> catch (Exception e) {
> LOGGER.error("Failed to connect", e);
> }
> return session;
> }
> private static void closeSession(IoSession session) throws InterruptedException {
> try {
> CloseFuture closeFuture = session.getCloseFuture();
> closeFuture.addListener(new IoFutureListener<CloseFuture>() {
> @Override
> public void operationComplete(CloseFuture future) {
> LOGGER.debug("Session closed callback for session " + future.getSession().getId());
> }
> });
> LOGGER.debug("Attempting to close session " + session.getId());
> session.close(false);
> LOGGER.debug("IoSession.close(false) returned. Awaiting uninterruptibily for session " + session.getId());
> closeFuture.awaitUninterruptibly();
> LOGGER.debug("Close completed for session " + session.getId());
> }
> catch (Exception e) {
> LOGGER.error("Failed to close session " + session.getId());
> session.close(true);
> }
> Thread.sleep(15000);
> }
> }
> {code}
> Attached is the hprof file of my program, taken after the program has run (during the 60 second sleep at the end) and a screen shot of the GC Root of the leaked NioSocketSession.
> After a couple days of debugging, I've identified why this is happening. Below is a snippet from the AbstractPollingIoConnector.Connector thread
> {code}
> private class Connector implements Runnable {
> public void run() {
> int nHandles = 0;
> while (selectable) {
> try {
> // the timeout for select shall be smaller of the connect
> // timeout or 1 second...
> int timeout = (int)Math.min(getConnectTimeoutMillis(), 1000L);
> int selected = select(timeout);
> nHandles += registerNew();
> if (selected > 0) {
> nHandles -= processConnections(selectedHandles());
> }
> processTimedOutSessions(allHandles());
> nHandles -= cancelKeys();
> if (nHandles == 0) {
> synchronized (lock) {
> if (connectQueue.isEmpty()) {
> connector = null;
> break;
> }
> }
> }
> }
> ...
> {code}
> When IoSession.close(boolean) is called, the above Connector thread cancels the SelectionKey associated with the session, which reduces the number of handles from 1 to 0. Immediately afterwards, the thread stops executing because there are no handles and nothing in the connetQueue, however, the previously cancelled key is still in the Selector because its cancelledKeys Set is not processed until the next call to select(int)
> Calling dispose on the IoConnector restarts the Connector thread, which calls Selector.select(int), at which time, the Selector cleans out its canclledKeys.
> Creating a new connection causes the same thing to happen, because the new session also recreates the AbstractPollingIoConnector.Connector thread, as there is a new handle to be processed.
--
This message is automatically generated by JIRA.
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] [Updated] (DIRMINA-827) NioSocketConnector leaks the last
open NioSocketSession after close
Posted by "Matt Yates (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/DIRMINA-827?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Matt Yates updated DIRMINA-827:
-------------------------------
Description:
My company's program uses MINA to make multiple (usually) simultaneous connections to various other machines, while reusing the same NioSocketConnector for each new connection. For better or worse, we store various objects in the IoSession's attributes, which we expect to get released on close. This is not always the case, however, as said session remains in memory until either a new connection is made or the IoConnector is disposed. After writing the simplest Connector program I could (I have several servers available on my network, so I did not write a matching Acceptor), and performing some profiling and debugging, I was able to confirm the leak and identify the issue.
Below is my Connector test program
{code}
public class MinaMain {
private static final Logger LOGGER = LoggerFactory.getLogger(MinaMain.class);
public static void main(String[] args) throws InterruptedException {
LOGGER.trace("Waiting for YourKit to start");
Thread.sleep(15000);
NioSocketConnector connector = new NioSocketConnector();
connector.setHandler(new IoHandlerAdapter());
closeSession(getConnectedSession(connector));
// LOGGER.info("Creating and closing 5 sessions in series");
//
// for (int x = 0; x < 5; x++) {
// IoSession session = getConnectedSession(connector);
//
// if (session == null) {
// continue;
// }
//
// closeSession(session);
// }
//
// LOGGER.info("Creating 5 sessions and then closing 5 sessions");
// IoSession[] sessions = new IoSession[5];
//
// for (int x = 0; x < 5; x++) {
// sessions[x] = getConnectedSession(connector);
// }
//
// for (int x = 0; x < 5; x++) {
// IoSession session = sessions[x];
//
// if (session != null) {
// closeSession(session);
// sessions[x] = null;
// }
// }
LOGGER.info("Test complete. Sleeping for 60s");
Thread.sleep(60000);
}
private static IoSession getConnectedSession(IoConnector connector) throws InterruptedException {
IoSession session = null;
try {
ConnectFuture future = connector.connect(new InetSocketAddress("134.64.37.183", 11109));
future.addListener(new IoFutureListener<ConnectFuture>() {
@Override
public void operationComplete(ConnectFuture future) {
LOGGER.debug("Connection completed callback for session " + future.getSession().getId());
}
});
future.awaitUninterruptibly();
LOGGER.debug("Connection created for session " + future.getSession().getId());
session = future.getSession();
Thread.sleep(15000);
}
catch (Exception e) {
LOGGER.error("Failed to connect", e);
}
return session;
}
private static void closeSession(IoSession session) throws InterruptedException {
try {
CloseFuture closeFuture = session.getCloseFuture();
closeFuture.addListener(new IoFutureListener<CloseFuture>() {
@Override
public void operationComplete(CloseFuture future) {
LOGGER.debug("Session closed callback for session " + future.getSession().getId());
}
});
LOGGER.debug("Attempting to close session " + session.getId());
session.close(false);
LOGGER.debug("IoSession.close(false) returned. Awaiting uninterruptibily for session " + session.getId());
closeFuture.awaitUninterruptibly();
LOGGER.debug("Close completed for session " + session.getId());
}
catch (Exception e) {
LOGGER.error("Failed to close session " + session.getId());
session.close(true);
}
Thread.sleep(15000);
}
}
{code}
Attached is the hprof file of my program, taken after the program has run (during the 60 second sleep at the end) and a screen shot of the GC Root of the leaked NioSocketSession.
After a couple days of debugging, I've identified why this is happening. Below is a snippet from the AbstractPollingIoConnector.Connector thread
{code}
private class Connector implements Runnable {
public void run() {
int nHandles = 0;
while (selectable) {
try {
// the timeout for select shall be smaller of the connect
// timeout or 1 second...
int timeout = (int)Math.min(getConnectTimeoutMillis(), 1000L);
int selected = select(timeout);
nHandles += registerNew();
if (selected > 0) {
nHandles -= processConnections(selectedHandles());
}
processTimedOutSessions(allHandles());
nHandles -= cancelKeys();
if (nHandles == 0) {
synchronized (lock) {
if (connectQueue.isEmpty()) {
connector = null;
break;
}
}
}
}
...
{code}
When IoSession.close(boolean) is called, the above Connector thread cancels the SelectionKey associated with the session, which reduces the number of handles from 1 to 0. Immediately afterwards, the thread stops executing because there are no handles and nothing in the connetQueue, however, the previously cancelled key is still in the Selector because its cancelledKeys Set is not processed until the next call to select(int)
Calling dispose on the IoConnector restarts the Connector thread, which calls Selector.select(int), at which time, the Selector cleans out its canclledKeys.
Creating a new connection causes the same thing to happen, because the new session also recreates the AbstractPollingIoConnector.Connector thread, as there is a new handle to be processed.
was:
My company's program uses MINA to make multiple (usually) simultaneous connections to various other machines, while reusing the same NioSocketConnector for each new connection. For better or worse, we store various objects in the IoSession's attributes, which we expect to get released on close. This is not always the case, however, as said session remains in memory until either a new connection is made or the IoConnector is disposed. After writing the simplest Connector program I could (I have several servers available on my network, so I did not write a matching Acceptor), and performing some profiling and debugging, I was able to confirm the leak and identify the issue.
Below is my Connector test program
{code}
public class MinaMain {
private static final Logger LOGGER = LoggerFactory.getLogger(MinaMain.class);
public static void main(String[] args) throws InterruptedException {
LOGGER.trace("Waiting for YourKit to start");
Thread.sleep(15000);
NioSocketConnector connector = new NioSocketConnector();
connector.setHandler(new IoHandlerAdapter());
closeSession(getConnectedSession(connector));
// LOGGER.info("Creating and closing 5 sessions in series");
//
// for (int x = 0; x < 5; x++) {
// IoSession session = getConnectedSession(connector);
//
// if (session == null) {
// continue;
// }
//
// closeSession(session);
// }
//
// LOGGER.info("Creating 5 sessions and then closing 5 sessions");
// IoSession[] sessions = new IoSession[5];
//
// for (int x = 0; x < 5; x++) {
// sessions[x] = getConnectedSession(connector);
// }
//
// for (int x = 0; x < 5; x++) {
// IoSession session = sessions[x];
//
// if (session != null) {
// closeSession(session);
// sessions[x] = null;
// }
// }
LOGGER.info("Test complete. Sleeping for 60s");
Thread.sleep(60000);
}
private static IoSession getConnectedSession(IoConnector connector) throws InterruptedException {
IoSession session = null;
try {
ConnectFuture future = connector.connect(new InetSocketAddress("134.64.37.183", 11109));
future.addListener(new IoFutureListener<ConnectFuture>() {
@Override
public void operationComplete(ConnectFuture future) {
LOGGER.debug("Connection completed callback for session " + future.getSession().getId());
}
});
future.awaitUninterruptibly();
LOGGER.debug("Connection created for session " + future.getSession().getId());
session = future.getSession();
Thread.sleep(15000);
}
catch (Exception e) {
LOGGER.error("Failed to connect", e);
}
return session;
}
private static void closeSession(IoSession session) throws InterruptedException {
try {
CloseFuture closeFuture = session.getCloseFuture();
closeFuture.addListener(new IoFutureListener<CloseFuture>() {
@Override
public void operationComplete(CloseFuture future) {
LOGGER.debug("Session closed callback for session " + future.getSession().getId());
}
});
LOGGER.debug("Attempting to close session " + session.getId());
session.close(false);
LOGGER.debug("IoSession.close(false) returned. Awaiting uninterruptibily for session " + session.getId());
closeFuture.awaitUninterruptibly();
LOGGER.debug("Close completed for session " + session.getId());
}
catch (Exception e) {
LOGGER.error("Failed to close session " + session.getId());
session.close(true);
}
Thread.sleep(15000);
}
}
Attached is the hprof file of my program, taken after the program has run (during the 60 second sleep at the end) and a screen shot of the GC Root of the leaked NioSocketSession.
After a couple days of debugging, I've identified why this is happening. Below is a snippet from the AbstractPollingIoConnector.Connector thread
private class Connector implements Runnable {
public void run() {
int nHandles = 0;
while (selectable) {
try {
// the timeout for select shall be smaller of the connect
// timeout or 1 second...
int timeout = (int)Math.min(getConnectTimeoutMillis(), 1000L);
int selected = select(timeout);
nHandles += registerNew();
if (selected > 0) {
nHandles -= processConnections(selectedHandles());
}
processTimedOutSessions(allHandles());
nHandles -= cancelKeys();
if (nHandles == 0) {
synchronized (lock) {
if (connectQueue.isEmpty()) {
connector = null;
break;
}
}
}
}
...
When IoSession.close(boolean) is called, the above Connector thread cancels the SelectionKey associated with the session, which reduces the number of handles from 1 to 0. Immediately afterwards, the thread stops executing because there are no handles and nothing in the connetQueue, however, the previously cancelled key is still in the Selector because its cancelledKeys Set is not processed until the next call to select(int)
Calling dispose on the IoConnector restarts the Connector thread, which calls Selector.select(int), at which time, the Selector cleans out its canclledKeys.
Creating a new connection causes the same thing to happen, because the new session also recreates the AbstractPollingIoConnector.Connector thread, as there is a new handle to be processed.
> NioSocketConnector leaks the last open NioSocketSession after close
> -------------------------------------------------------------------
>
> Key: DIRMINA-827
> URL: https://issues.apache.org/jira/browse/DIRMINA-827
> Project: MINA
> Issue Type: Bug
> Components: Core
> Affects Versions: 2.0.2
> Environment: Windows 7/Solaris SPARC/Solaris x86
> Java versions 6u18 & 6u24
> Reporter: Matt Yates
> Priority: Critical
> Labels: connector, mina, session
> Attachments: MinaMain-2011-04-10.hprof, sessionGcRoot.jpg
>
>
> My company's program uses MINA to make multiple (usually) simultaneous connections to various other machines, while reusing the same NioSocketConnector for each new connection. For better or worse, we store various objects in the IoSession's attributes, which we expect to get released on close. This is not always the case, however, as said session remains in memory until either a new connection is made or the IoConnector is disposed. After writing the simplest Connector program I could (I have several servers available on my network, so I did not write a matching Acceptor), and performing some profiling and debugging, I was able to confirm the leak and identify the issue.
> Below is my Connector test program
> {code}
> public class MinaMain {
> private static final Logger LOGGER = LoggerFactory.getLogger(MinaMain.class);
> public static void main(String[] args) throws InterruptedException {
> LOGGER.trace("Waiting for YourKit to start");
> Thread.sleep(15000);
> NioSocketConnector connector = new NioSocketConnector();
> connector.setHandler(new IoHandlerAdapter());
> closeSession(getConnectedSession(connector));
> // LOGGER.info("Creating and closing 5 sessions in series");
> //
> // for (int x = 0; x < 5; x++) {
> // IoSession session = getConnectedSession(connector);
> //
> // if (session == null) {
> // continue;
> // }
> //
> // closeSession(session);
> // }
> //
> // LOGGER.info("Creating 5 sessions and then closing 5 sessions");
> // IoSession[] sessions = new IoSession[5];
> //
> // for (int x = 0; x < 5; x++) {
> // sessions[x] = getConnectedSession(connector);
> // }
> //
> // for (int x = 0; x < 5; x++) {
> // IoSession session = sessions[x];
> //
> // if (session != null) {
> // closeSession(session);
> // sessions[x] = null;
> // }
> // }
> LOGGER.info("Test complete. Sleeping for 60s");
> Thread.sleep(60000);
> }
> private static IoSession getConnectedSession(IoConnector connector) throws InterruptedException {
> IoSession session = null;
> try {
> ConnectFuture future = connector.connect(new InetSocketAddress("134.64.37.183", 11109));
> future.addListener(new IoFutureListener<ConnectFuture>() {
> @Override
> public void operationComplete(ConnectFuture future) {
> LOGGER.debug("Connection completed callback for session " + future.getSession().getId());
> }
> });
> future.awaitUninterruptibly();
> LOGGER.debug("Connection created for session " + future.getSession().getId());
> session = future.getSession();
> Thread.sleep(15000);
> }
> catch (Exception e) {
> LOGGER.error("Failed to connect", e);
> }
> return session;
> }
> private static void closeSession(IoSession session) throws InterruptedException {
> try {
> CloseFuture closeFuture = session.getCloseFuture();
> closeFuture.addListener(new IoFutureListener<CloseFuture>() {
> @Override
> public void operationComplete(CloseFuture future) {
> LOGGER.debug("Session closed callback for session " + future.getSession().getId());
> }
> });
> LOGGER.debug("Attempting to close session " + session.getId());
> session.close(false);
> LOGGER.debug("IoSession.close(false) returned. Awaiting uninterruptibily for session " + session.getId());
> closeFuture.awaitUninterruptibly();
> LOGGER.debug("Close completed for session " + session.getId());
> }
> catch (Exception e) {
> LOGGER.error("Failed to close session " + session.getId());
> session.close(true);
> }
> Thread.sleep(15000);
> }
> }
> {code}
> Attached is the hprof file of my program, taken after the program has run (during the 60 second sleep at the end) and a screen shot of the GC Root of the leaked NioSocketSession.
> After a couple days of debugging, I've identified why this is happening. Below is a snippet from the AbstractPollingIoConnector.Connector thread
> {code}
> private class Connector implements Runnable {
> public void run() {
> int nHandles = 0;
> while (selectable) {
> try {
> // the timeout for select shall be smaller of the connect
> // timeout or 1 second...
> int timeout = (int)Math.min(getConnectTimeoutMillis(), 1000L);
> int selected = select(timeout);
> nHandles += registerNew();
> if (selected > 0) {
> nHandles -= processConnections(selectedHandles());
> }
> processTimedOutSessions(allHandles());
> nHandles -= cancelKeys();
> if (nHandles == 0) {
> synchronized (lock) {
> if (connectQueue.isEmpty()) {
> connector = null;
> break;
> }
> }
> }
> }
> ...
> {code}
> When IoSession.close(boolean) is called, the above Connector thread cancels the SelectionKey associated with the session, which reduces the number of handles from 1 to 0. Immediately afterwards, the thread stops executing because there are no handles and nothing in the connetQueue, however, the previously cancelled key is still in the Selector because its cancelledKeys Set is not processed until the next call to select(int)
> Calling dispose on the IoConnector restarts the Connector thread, which calls Selector.select(int), at which time, the Selector cleans out its canclledKeys.
> Creating a new connection causes the same thing to happen, because the new session also recreates the AbstractPollingIoConnector.Connector thread, as there is a new handle to be processed.
--
This message is automatically generated by JIRA.
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] [Closed] (DIRMINA-827) NioSocketConnector leaks the last
open NioSocketSession after close
Posted by "Emmanuel Lecharny (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/DIRMINA-827?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Emmanuel Lecharny closed DIRMINA-827.
-------------------------------------
> NioSocketConnector leaks the last open NioSocketSession after close
> -------------------------------------------------------------------
>
> Key: DIRMINA-827
> URL: https://issues.apache.org/jira/browse/DIRMINA-827
> Project: MINA
> Issue Type: Bug
> Components: Core
> Affects Versions: 2.0.2
> Environment: Windows 7/Solaris SPARC/Solaris x86
> Java versions 6u18 & 6u24
> Reporter: Matt Yates
> Assignee: Emmanuel Lecharny
> Priority: Critical
> Labels: connector, mina, session
> Fix For: 2.0.3
>
> Attachments: IoConnectorWithCleanSelector.jpg, MinaMain-2011-04-10.hprof, mina-core-2.0.4-SNAPSHOT.jar, mina-core-2.0.4-SNAPSHOT.jar, sessionGcRoot.jpg
>
>
> My company's program uses MINA to make multiple (usually) simultaneous connections to various other machines, while reusing the same NioSocketConnector for each new connection. For better or worse, we store various objects in the IoSession's attributes, which we expect to get released on close. This is not always the case, however, as said session remains in memory until either a new connection is made or the IoConnector is disposed. After writing the simplest Connector program I could (I have several servers available on my network, so I did not write a matching Acceptor), and performing some profiling and debugging, I was able to confirm the leak and identify the issue.
> Below is my Connector test program
> {code}
> public class MinaMain {
> private static final Logger LOGGER = LoggerFactory.getLogger(MinaMain.class);
> public static void main(String[] args) throws InterruptedException {
> LOGGER.trace("Waiting for YourKit to start");
> Thread.sleep(15000);
> NioSocketConnector connector = new NioSocketConnector();
> connector.setHandler(new IoHandlerAdapter());
> closeSession(getConnectedSession(connector));
> // LOGGER.info("Creating and closing 5 sessions in series");
> //
> // for (int x = 0; x < 5; x++) {
> // IoSession session = getConnectedSession(connector);
> //
> // if (session == null) {
> // continue;
> // }
> //
> // closeSession(session);
> // }
> //
> // LOGGER.info("Creating 5 sessions and then closing 5 sessions");
> // IoSession[] sessions = new IoSession[5];
> //
> // for (int x = 0; x < 5; x++) {
> // sessions[x] = getConnectedSession(connector);
> // }
> //
> // for (int x = 0; x < 5; x++) {
> // IoSession session = sessions[x];
> //
> // if (session != null) {
> // closeSession(session);
> // sessions[x] = null;
> // }
> // }
> LOGGER.info("Test complete. Sleeping for 60s");
> Thread.sleep(60000);
> }
> private static IoSession getConnectedSession(IoConnector connector) throws InterruptedException {
> IoSession session = null;
> try {
> ConnectFuture future = connector.connect(new InetSocketAddress("134.64.37.183", 11109));
> future.addListener(new IoFutureListener<ConnectFuture>() {
> @Override
> public void operationComplete(ConnectFuture future) {
> LOGGER.debug("Connection completed callback for session " + future.getSession().getId());
> }
> });
> future.awaitUninterruptibly();
> LOGGER.debug("Connection created for session " + future.getSession().getId());
> session = future.getSession();
> Thread.sleep(15000);
> }
> catch (Exception e) {
> LOGGER.error("Failed to connect", e);
> }
> return session;
> }
> private static void closeSession(IoSession session) throws InterruptedException {
> try {
> CloseFuture closeFuture = session.getCloseFuture();
> closeFuture.addListener(new IoFutureListener<CloseFuture>() {
> @Override
> public void operationComplete(CloseFuture future) {
> LOGGER.debug("Session closed callback for session " + future.getSession().getId());
> }
> });
> LOGGER.debug("Attempting to close session " + session.getId());
> session.close(false);
> LOGGER.debug("IoSession.close(false) returned. Awaiting uninterruptibily for session " + session.getId());
> closeFuture.awaitUninterruptibly();
> LOGGER.debug("Close completed for session " + session.getId());
> }
> catch (Exception e) {
> LOGGER.error("Failed to close session " + session.getId());
> session.close(true);
> }
> Thread.sleep(15000);
> }
> }
> {code}
> Attached is the hprof file of my program, taken after the program has run (during the 60 second sleep at the end) and a screen shot of the GC Root of the leaked NioSocketSession.
> After a couple days of debugging, I've identified why this is happening. Below is a snippet from the AbstractPollingIoConnector.Connector thread
> {code}
> private class Connector implements Runnable {
> public void run() {
> int nHandles = 0;
> while (selectable) {
> try {
> // the timeout for select shall be smaller of the connect
> // timeout or 1 second...
> int timeout = (int)Math.min(getConnectTimeoutMillis(), 1000L);
> int selected = select(timeout);
> nHandles += registerNew();
> if (selected > 0) {
> nHandles -= processConnections(selectedHandles());
> }
> processTimedOutSessions(allHandles());
> nHandles -= cancelKeys();
> if (nHandles == 0) {
> synchronized (lock) {
> if (connectQueue.isEmpty()) {
> connector = null;
> break;
> }
> }
> }
> }
> ...
> {code}
> When IoSession.close(boolean) is called, the above Connector thread cancels the SelectionKey associated with the session, which reduces the number of handles from 1 to 0. Immediately afterwards, the thread stops executing because there are no handles and nothing in the connetQueue, however, the previously cancelled key is still in the Selector because its cancelledKeys Set is not processed until the next call to select(int)
> Calling dispose on the IoConnector restarts the Connector thread, which calls Selector.select(int), at which time, the Selector cleans out its canclledKeys.
> Creating a new connection causes the same thing to happen, because the new session also recreates the AbstractPollingIoConnector.Connector thread, as there is a new handle to be processed.
--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators: https://issues.apache.org/jira/secure/ContactAdministrators!default.jspa
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] [Commented] (DIRMINA-827) NioSocketConnector leaks the last
open NioSocketSession after close
Posted by "Matt Yates (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/DIRMINA-827?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13018500#comment-13018500 ]
Matt Yates commented on DIRMINA-827:
------------------------------------
I'll play around with wakeup vs non wakeup later today
> NioSocketConnector leaks the last open NioSocketSession after close
> -------------------------------------------------------------------
>
> Key: DIRMINA-827
> URL: https://issues.apache.org/jira/browse/DIRMINA-827
> Project: MINA
> Issue Type: Bug
> Components: Core
> Affects Versions: 2.0.2
> Environment: Windows 7/Solaris SPARC/Solaris x86
> Java versions 6u18 & 6u24
> Reporter: Matt Yates
> Assignee: Emmanuel Lecharny
> Priority: Critical
> Labels: connector, mina, session
> Attachments: IoConnectorWithCleanSelector.jpg, MinaMain-2011-04-10.hprof, mina-core-2.0.4-SNAPSHOT.jar, mina-core-2.0.4-SNAPSHOT.jar, sessionGcRoot.jpg
>
>
> My company's program uses MINA to make multiple (usually) simultaneous connections to various other machines, while reusing the same NioSocketConnector for each new connection. For better or worse, we store various objects in the IoSession's attributes, which we expect to get released on close. This is not always the case, however, as said session remains in memory until either a new connection is made or the IoConnector is disposed. After writing the simplest Connector program I could (I have several servers available on my network, so I did not write a matching Acceptor), and performing some profiling and debugging, I was able to confirm the leak and identify the issue.
> Below is my Connector test program
> {code}
> public class MinaMain {
> private static final Logger LOGGER = LoggerFactory.getLogger(MinaMain.class);
> public static void main(String[] args) throws InterruptedException {
> LOGGER.trace("Waiting for YourKit to start");
> Thread.sleep(15000);
> NioSocketConnector connector = new NioSocketConnector();
> connector.setHandler(new IoHandlerAdapter());
> closeSession(getConnectedSession(connector));
> // LOGGER.info("Creating and closing 5 sessions in series");
> //
> // for (int x = 0; x < 5; x++) {
> // IoSession session = getConnectedSession(connector);
> //
> // if (session == null) {
> // continue;
> // }
> //
> // closeSession(session);
> // }
> //
> // LOGGER.info("Creating 5 sessions and then closing 5 sessions");
> // IoSession[] sessions = new IoSession[5];
> //
> // for (int x = 0; x < 5; x++) {
> // sessions[x] = getConnectedSession(connector);
> // }
> //
> // for (int x = 0; x < 5; x++) {
> // IoSession session = sessions[x];
> //
> // if (session != null) {
> // closeSession(session);
> // sessions[x] = null;
> // }
> // }
> LOGGER.info("Test complete. Sleeping for 60s");
> Thread.sleep(60000);
> }
> private static IoSession getConnectedSession(IoConnector connector) throws InterruptedException {
> IoSession session = null;
> try {
> ConnectFuture future = connector.connect(new InetSocketAddress("134.64.37.183", 11109));
> future.addListener(new IoFutureListener<ConnectFuture>() {
> @Override
> public void operationComplete(ConnectFuture future) {
> LOGGER.debug("Connection completed callback for session " + future.getSession().getId());
> }
> });
> future.awaitUninterruptibly();
> LOGGER.debug("Connection created for session " + future.getSession().getId());
> session = future.getSession();
> Thread.sleep(15000);
> }
> catch (Exception e) {
> LOGGER.error("Failed to connect", e);
> }
> return session;
> }
> private static void closeSession(IoSession session) throws InterruptedException {
> try {
> CloseFuture closeFuture = session.getCloseFuture();
> closeFuture.addListener(new IoFutureListener<CloseFuture>() {
> @Override
> public void operationComplete(CloseFuture future) {
> LOGGER.debug("Session closed callback for session " + future.getSession().getId());
> }
> });
> LOGGER.debug("Attempting to close session " + session.getId());
> session.close(false);
> LOGGER.debug("IoSession.close(false) returned. Awaiting uninterruptibily for session " + session.getId());
> closeFuture.awaitUninterruptibly();
> LOGGER.debug("Close completed for session " + session.getId());
> }
> catch (Exception e) {
> LOGGER.error("Failed to close session " + session.getId());
> session.close(true);
> }
> Thread.sleep(15000);
> }
> }
> {code}
> Attached is the hprof file of my program, taken after the program has run (during the 60 second sleep at the end) and a screen shot of the GC Root of the leaked NioSocketSession.
> After a couple days of debugging, I've identified why this is happening. Below is a snippet from the AbstractPollingIoConnector.Connector thread
> {code}
> private class Connector implements Runnable {
> public void run() {
> int nHandles = 0;
> while (selectable) {
> try {
> // the timeout for select shall be smaller of the connect
> // timeout or 1 second...
> int timeout = (int)Math.min(getConnectTimeoutMillis(), 1000L);
> int selected = select(timeout);
> nHandles += registerNew();
> if (selected > 0) {
> nHandles -= processConnections(selectedHandles());
> }
> processTimedOutSessions(allHandles());
> nHandles -= cancelKeys();
> if (nHandles == 0) {
> synchronized (lock) {
> if (connectQueue.isEmpty()) {
> connector = null;
> break;
> }
> }
> }
> }
> ...
> {code}
> When IoSession.close(boolean) is called, the above Connector thread cancels the SelectionKey associated with the session, which reduces the number of handles from 1 to 0. Immediately afterwards, the thread stops executing because there are no handles and nothing in the connetQueue, however, the previously cancelled key is still in the Selector because its cancelledKeys Set is not processed until the next call to select(int)
> Calling dispose on the IoConnector restarts the Connector thread, which calls Selector.select(int), at which time, the Selector cleans out its canclledKeys.
> Creating a new connection causes the same thing to happen, because the new session also recreates the AbstractPollingIoConnector.Connector thread, as there is a new handle to be processed.
--
This message is automatically generated by JIRA.
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] [Commented] (DIRMINA-827) NioSocketConnector leaks the last
open NioSocketSession after close
Posted by "Matt Yates (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/DIRMINA-827?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13018157#comment-13018157 ]
Matt Yates commented on DIRMINA-827:
------------------------------------
close(true) has the same issue. All it does is skip the processor.flush(session) part of the socket shutdown data flow. The AbstractPollingIoConnector.Connector thread still dies before Selector.select(int) is called again, preventing the SelectionKey (and therefore the session) from being cleaned up
> NioSocketConnector leaks the last open NioSocketSession after close
> -------------------------------------------------------------------
>
> Key: DIRMINA-827
> URL: https://issues.apache.org/jira/browse/DIRMINA-827
> Project: MINA
> Issue Type: Bug
> Components: Core
> Affects Versions: 2.0.2
> Environment: Windows 7/Solaris SPARC/Solaris x86
> Java versions 6u18 & 6u24
> Reporter: Matt Yates
> Priority: Critical
> Labels: connector, mina, session
> Attachments: MinaMain-2011-04-10.hprof, sessionGcRoot.jpg
>
>
> My company's program uses MINA to make multiple (usually) simultaneous connections to various other machines, while reusing the same NioSocketConnector for each new connection. For better or worse, we store various objects in the IoSession's attributes, which we expect to get released on close. This is not always the case, however, as said session remains in memory until either a new connection is made or the IoConnector is disposed. After writing the simplest Connector program I could (I have several servers available on my network, so I did not write a matching Acceptor), and performing some profiling and debugging, I was able to confirm the leak and identify the issue.
> Below is my Connector test program
> {code}
> public class MinaMain {
> private static final Logger LOGGER = LoggerFactory.getLogger(MinaMain.class);
> public static void main(String[] args) throws InterruptedException {
> LOGGER.trace("Waiting for YourKit to start");
> Thread.sleep(15000);
> NioSocketConnector connector = new NioSocketConnector();
> connector.setHandler(new IoHandlerAdapter());
> closeSession(getConnectedSession(connector));
> // LOGGER.info("Creating and closing 5 sessions in series");
> //
> // for (int x = 0; x < 5; x++) {
> // IoSession session = getConnectedSession(connector);
> //
> // if (session == null) {
> // continue;
> // }
> //
> // closeSession(session);
> // }
> //
> // LOGGER.info("Creating 5 sessions and then closing 5 sessions");
> // IoSession[] sessions = new IoSession[5];
> //
> // for (int x = 0; x < 5; x++) {
> // sessions[x] = getConnectedSession(connector);
> // }
> //
> // for (int x = 0; x < 5; x++) {
> // IoSession session = sessions[x];
> //
> // if (session != null) {
> // closeSession(session);
> // sessions[x] = null;
> // }
> // }
> LOGGER.info("Test complete. Sleeping for 60s");
> Thread.sleep(60000);
> }
> private static IoSession getConnectedSession(IoConnector connector) throws InterruptedException {
> IoSession session = null;
> try {
> ConnectFuture future = connector.connect(new InetSocketAddress("134.64.37.183", 11109));
> future.addListener(new IoFutureListener<ConnectFuture>() {
> @Override
> public void operationComplete(ConnectFuture future) {
> LOGGER.debug("Connection completed callback for session " + future.getSession().getId());
> }
> });
> future.awaitUninterruptibly();
> LOGGER.debug("Connection created for session " + future.getSession().getId());
> session = future.getSession();
> Thread.sleep(15000);
> }
> catch (Exception e) {
> LOGGER.error("Failed to connect", e);
> }
> return session;
> }
> private static void closeSession(IoSession session) throws InterruptedException {
> try {
> CloseFuture closeFuture = session.getCloseFuture();
> closeFuture.addListener(new IoFutureListener<CloseFuture>() {
> @Override
> public void operationComplete(CloseFuture future) {
> LOGGER.debug("Session closed callback for session " + future.getSession().getId());
> }
> });
> LOGGER.debug("Attempting to close session " + session.getId());
> session.close(false);
> LOGGER.debug("IoSession.close(false) returned. Awaiting uninterruptibily for session " + session.getId());
> closeFuture.awaitUninterruptibly();
> LOGGER.debug("Close completed for session " + session.getId());
> }
> catch (Exception e) {
> LOGGER.error("Failed to close session " + session.getId());
> session.close(true);
> }
> Thread.sleep(15000);
> }
> }
> {code}
> Attached is the hprof file of my program, taken after the program has run (during the 60 second sleep at the end) and a screen shot of the GC Root of the leaked NioSocketSession.
> After a couple days of debugging, I've identified why this is happening. Below is a snippet from the AbstractPollingIoConnector.Connector thread
> {code}
> private class Connector implements Runnable {
> public void run() {
> int nHandles = 0;
> while (selectable) {
> try {
> // the timeout for select shall be smaller of the connect
> // timeout or 1 second...
> int timeout = (int)Math.min(getConnectTimeoutMillis(), 1000L);
> int selected = select(timeout);
> nHandles += registerNew();
> if (selected > 0) {
> nHandles -= processConnections(selectedHandles());
> }
> processTimedOutSessions(allHandles());
> nHandles -= cancelKeys();
> if (nHandles == 0) {
> synchronized (lock) {
> if (connectQueue.isEmpty()) {
> connector = null;
> break;
> }
> }
> }
> }
> ...
> {code}
> When IoSession.close(boolean) is called, the above Connector thread cancels the SelectionKey associated with the session, which reduces the number of handles from 1 to 0. Immediately afterwards, the thread stops executing because there are no handles and nothing in the connetQueue, however, the previously cancelled key is still in the Selector because its cancelledKeys Set is not processed until the next call to select(int)
> Calling dispose on the IoConnector restarts the Connector thread, which calls Selector.select(int), at which time, the Selector cleans out its canclledKeys.
> Creating a new connection causes the same thing to happen, because the new session also recreates the AbstractPollingIoConnector.Connector thread, as there is a new handle to be processed.
--
This message is automatically generated by JIRA.
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] [Assigned] (DIRMINA-827) NioSocketConnector leaks the last
open NioSocketSession after close
Posted by "Emmanuel Lecharny (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/DIRMINA-827?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Emmanuel Lecharny reassigned DIRMINA-827:
-----------------------------------------
Assignee: Emmanuel Lecharny
> NioSocketConnector leaks the last open NioSocketSession after close
> -------------------------------------------------------------------
>
> Key: DIRMINA-827
> URL: https://issues.apache.org/jira/browse/DIRMINA-827
> Project: MINA
> Issue Type: Bug
> Components: Core
> Affects Versions: 2.0.2
> Environment: Windows 7/Solaris SPARC/Solaris x86
> Java versions 6u18 & 6u24
> Reporter: Matt Yates
> Assignee: Emmanuel Lecharny
> Priority: Critical
> Labels: connector, mina, session
> Attachments: MinaMain-2011-04-10.hprof, mina-core-2.0.4-SNAPSHOT.jar, mina-core-2.0.4-SNAPSHOT.jar, sessionGcRoot.jpg
>
>
> My company's program uses MINA to make multiple (usually) simultaneous connections to various other machines, while reusing the same NioSocketConnector for each new connection. For better or worse, we store various objects in the IoSession's attributes, which we expect to get released on close. This is not always the case, however, as said session remains in memory until either a new connection is made or the IoConnector is disposed. After writing the simplest Connector program I could (I have several servers available on my network, so I did not write a matching Acceptor), and performing some profiling and debugging, I was able to confirm the leak and identify the issue.
> Below is my Connector test program
> {code}
> public class MinaMain {
> private static final Logger LOGGER = LoggerFactory.getLogger(MinaMain.class);
> public static void main(String[] args) throws InterruptedException {
> LOGGER.trace("Waiting for YourKit to start");
> Thread.sleep(15000);
> NioSocketConnector connector = new NioSocketConnector();
> connector.setHandler(new IoHandlerAdapter());
> closeSession(getConnectedSession(connector));
> // LOGGER.info("Creating and closing 5 sessions in series");
> //
> // for (int x = 0; x < 5; x++) {
> // IoSession session = getConnectedSession(connector);
> //
> // if (session == null) {
> // continue;
> // }
> //
> // closeSession(session);
> // }
> //
> // LOGGER.info("Creating 5 sessions and then closing 5 sessions");
> // IoSession[] sessions = new IoSession[5];
> //
> // for (int x = 0; x < 5; x++) {
> // sessions[x] = getConnectedSession(connector);
> // }
> //
> // for (int x = 0; x < 5; x++) {
> // IoSession session = sessions[x];
> //
> // if (session != null) {
> // closeSession(session);
> // sessions[x] = null;
> // }
> // }
> LOGGER.info("Test complete. Sleeping for 60s");
> Thread.sleep(60000);
> }
> private static IoSession getConnectedSession(IoConnector connector) throws InterruptedException {
> IoSession session = null;
> try {
> ConnectFuture future = connector.connect(new InetSocketAddress("134.64.37.183", 11109));
> future.addListener(new IoFutureListener<ConnectFuture>() {
> @Override
> public void operationComplete(ConnectFuture future) {
> LOGGER.debug("Connection completed callback for session " + future.getSession().getId());
> }
> });
> future.awaitUninterruptibly();
> LOGGER.debug("Connection created for session " + future.getSession().getId());
> session = future.getSession();
> Thread.sleep(15000);
> }
> catch (Exception e) {
> LOGGER.error("Failed to connect", e);
> }
> return session;
> }
> private static void closeSession(IoSession session) throws InterruptedException {
> try {
> CloseFuture closeFuture = session.getCloseFuture();
> closeFuture.addListener(new IoFutureListener<CloseFuture>() {
> @Override
> public void operationComplete(CloseFuture future) {
> LOGGER.debug("Session closed callback for session " + future.getSession().getId());
> }
> });
> LOGGER.debug("Attempting to close session " + session.getId());
> session.close(false);
> LOGGER.debug("IoSession.close(false) returned. Awaiting uninterruptibily for session " + session.getId());
> closeFuture.awaitUninterruptibly();
> LOGGER.debug("Close completed for session " + session.getId());
> }
> catch (Exception e) {
> LOGGER.error("Failed to close session " + session.getId());
> session.close(true);
> }
> Thread.sleep(15000);
> }
> }
> {code}
> Attached is the hprof file of my program, taken after the program has run (during the 60 second sleep at the end) and a screen shot of the GC Root of the leaked NioSocketSession.
> After a couple days of debugging, I've identified why this is happening. Below is a snippet from the AbstractPollingIoConnector.Connector thread
> {code}
> private class Connector implements Runnable {
> public void run() {
> int nHandles = 0;
> while (selectable) {
> try {
> // the timeout for select shall be smaller of the connect
> // timeout or 1 second...
> int timeout = (int)Math.min(getConnectTimeoutMillis(), 1000L);
> int selected = select(timeout);
> nHandles += registerNew();
> if (selected > 0) {
> nHandles -= processConnections(selectedHandles());
> }
> processTimedOutSessions(allHandles());
> nHandles -= cancelKeys();
> if (nHandles == 0) {
> synchronized (lock) {
> if (connectQueue.isEmpty()) {
> connector = null;
> break;
> }
> }
> }
> }
> ...
> {code}
> When IoSession.close(boolean) is called, the above Connector thread cancels the SelectionKey associated with the session, which reduces the number of handles from 1 to 0. Immediately afterwards, the thread stops executing because there are no handles and nothing in the connetQueue, however, the previously cancelled key is still in the Selector because its cancelledKeys Set is not processed until the next call to select(int)
> Calling dispose on the IoConnector restarts the Connector thread, which calls Selector.select(int), at which time, the Selector cleans out its canclledKeys.
> Creating a new connection causes the same thing to happen, because the new session also recreates the AbstractPollingIoConnector.Connector thread, as there is a new handle to be processed.
--
This message is automatically generated by JIRA.
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] [Commented] (DIRMINA-827) NioSocketConnector leaks the last
open NioSocketSession after close
Posted by "Emmanuel Lecharny (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/DIRMINA-827?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13018130#comment-13018130 ]
Emmanuel Lecharny commented on DIRMINA-827:
-------------------------------------------
Try with session.close(true)
> NioSocketConnector leaks the last open NioSocketSession after close
> -------------------------------------------------------------------
>
> Key: DIRMINA-827
> URL: https://issues.apache.org/jira/browse/DIRMINA-827
> Project: MINA
> Issue Type: Bug
> Components: Core
> Affects Versions: 2.0.2
> Environment: Windows 7/Solaris SPARC/Solaris x86
> Java versions 6u18 & 6u24
> Reporter: Matt Yates
> Priority: Critical
> Labels: connector, mina, session
> Attachments: MinaMain-2011-04-10.hprof, sessionGcRoot.jpg
>
>
> My company's program uses MINA to make multiple (usually) simultaneous connections to various other machines, while reusing the same NioSocketConnector for each new connection. For better or worse, we store various objects in the IoSession's attributes, which we expect to get released on close. This is not always the case, however, as said session remains in memory until either a new connection is made or the IoConnector is disposed. After writing the simplest Connector program I could (I have several servers available on my network, so I did not write a matching Acceptor), and performing some profiling and debugging, I was able to confirm the leak and identify the issue.
> Below is my Connector test program
> {code}
> public class MinaMain {
> private static final Logger LOGGER = LoggerFactory.getLogger(MinaMain.class);
> public static void main(String[] args) throws InterruptedException {
> LOGGER.trace("Waiting for YourKit to start");
> Thread.sleep(15000);
> NioSocketConnector connector = new NioSocketConnector();
> connector.setHandler(new IoHandlerAdapter());
> closeSession(getConnectedSession(connector));
> // LOGGER.info("Creating and closing 5 sessions in series");
> //
> // for (int x = 0; x < 5; x++) {
> // IoSession session = getConnectedSession(connector);
> //
> // if (session == null) {
> // continue;
> // }
> //
> // closeSession(session);
> // }
> //
> // LOGGER.info("Creating 5 sessions and then closing 5 sessions");
> // IoSession[] sessions = new IoSession[5];
> //
> // for (int x = 0; x < 5; x++) {
> // sessions[x] = getConnectedSession(connector);
> // }
> //
> // for (int x = 0; x < 5; x++) {
> // IoSession session = sessions[x];
> //
> // if (session != null) {
> // closeSession(session);
> // sessions[x] = null;
> // }
> // }
> LOGGER.info("Test complete. Sleeping for 60s");
> Thread.sleep(60000);
> }
> private static IoSession getConnectedSession(IoConnector connector) throws InterruptedException {
> IoSession session = null;
> try {
> ConnectFuture future = connector.connect(new InetSocketAddress("134.64.37.183", 11109));
> future.addListener(new IoFutureListener<ConnectFuture>() {
> @Override
> public void operationComplete(ConnectFuture future) {
> LOGGER.debug("Connection completed callback for session " + future.getSession().getId());
> }
> });
> future.awaitUninterruptibly();
> LOGGER.debug("Connection created for session " + future.getSession().getId());
> session = future.getSession();
> Thread.sleep(15000);
> }
> catch (Exception e) {
> LOGGER.error("Failed to connect", e);
> }
> return session;
> }
> private static void closeSession(IoSession session) throws InterruptedException {
> try {
> CloseFuture closeFuture = session.getCloseFuture();
> closeFuture.addListener(new IoFutureListener<CloseFuture>() {
> @Override
> public void operationComplete(CloseFuture future) {
> LOGGER.debug("Session closed callback for session " + future.getSession().getId());
> }
> });
> LOGGER.debug("Attempting to close session " + session.getId());
> session.close(false);
> LOGGER.debug("IoSession.close(false) returned. Awaiting uninterruptibily for session " + session.getId());
> closeFuture.awaitUninterruptibly();
> LOGGER.debug("Close completed for session " + session.getId());
> }
> catch (Exception e) {
> LOGGER.error("Failed to close session " + session.getId());
> session.close(true);
> }
> Thread.sleep(15000);
> }
> }
> {code}
> Attached is the hprof file of my program, taken after the program has run (during the 60 second sleep at the end) and a screen shot of the GC Root of the leaked NioSocketSession.
> After a couple days of debugging, I've identified why this is happening. Below is a snippet from the AbstractPollingIoConnector.Connector thread
> {code}
> private class Connector implements Runnable {
> public void run() {
> int nHandles = 0;
> while (selectable) {
> try {
> // the timeout for select shall be smaller of the connect
> // timeout or 1 second...
> int timeout = (int)Math.min(getConnectTimeoutMillis(), 1000L);
> int selected = select(timeout);
> nHandles += registerNew();
> if (selected > 0) {
> nHandles -= processConnections(selectedHandles());
> }
> processTimedOutSessions(allHandles());
> nHandles -= cancelKeys();
> if (nHandles == 0) {
> synchronized (lock) {
> if (connectQueue.isEmpty()) {
> connector = null;
> break;
> }
> }
> }
> }
> ...
> {code}
> When IoSession.close(boolean) is called, the above Connector thread cancels the SelectionKey associated with the session, which reduces the number of handles from 1 to 0. Immediately afterwards, the thread stops executing because there are no handles and nothing in the connetQueue, however, the previously cancelled key is still in the Selector because its cancelledKeys Set is not processed until the next call to select(int)
> Calling dispose on the IoConnector restarts the Connector thread, which calls Selector.select(int), at which time, the Selector cleans out its canclledKeys.
> Creating a new connection causes the same thing to happen, because the new session also recreates the AbstractPollingIoConnector.Connector thread, as there is a new handle to be processed.
--
This message is automatically generated by JIRA.
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] [Issue Comment Edited] (DIRMINA-827) NioSocketConnector
leaks the last open NioSocketSession after close
Posted by "Matt Yates (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/DIRMINA-827?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13018446#comment-13018446 ]
Matt Yates edited comment on DIRMINA-827 at 4/11/11 5:27 PM:
-------------------------------------------------------------
I'm not sure what 'sessionClosed()' event to which you are referring, but it does not seem to fix the problem. What if you simply moved the 'if (nHandles == 0)' block up to happen before the handle count potentially shrinks?
Currently:
...
int selected = select(timeout);
nHandles += registerNew();
if (selected > 0) {
nHandles -= processConnections(selectedHandles());
}
processTimedOutSessions(allHandles());
nHandles -= cancelKeys();
if (nHandles == 0) {
synchronized (lock) {
if (connectQueue.isEmpty()) {
connector = null;
break;
}
}
}
...
Proposed:
...
int selected = select(timeout);
nHandles += registerNew()
if (nHandles == 0) {
synchronized (lock) {
if (connectQueue.isEmpty()) {
connector = null;
break;
}
}
}
if (selected > 0) {
nHandles -= processConnections(selectedHandles());
}
processTimedOutSessions(allHandles());
nHandles -= cancelKeys();
...
This way if processConnections(Iterator<SocketChannel>) or cancelKeys() removes a handle, the Selector still gets one last select(int) call to clean up the next time through, and if a new connection is created in that time, the thread won't be destroyed and immediately recreated.
was (Author: myates):
I'm not sure what 'sessionClosed()' event to which you are referring, but it does not seem to fix the problem. What if you simply moved the 'if (nHandles == 0)' block up to happen before the handle count potentially shrinks?
Currently:
...
int selected = select(timeout);
nHandles += registerNew();
if (selected > 0) {
nHandles -= processConnections(selectedHandles());
}
processTimedOutSessions(allHandles());
nHandles -= cancelKeys();
if (nHandles == 0) {
synchronized (lock) {
if (connectQueue.isEmpty()) {
connector = null;
break;
}
}
}
...
Proposed:
...
int selected = select(timeout);
nHandles += registerNew()
if (nHandles == 0) {
synchronized (lock) {
if (connectQueue.isEmpty()) {
connector = null;
break;
}
}
};
if (selected > 0) {
nHandles -= processConnections(selectedHandles());
}
processTimedOutSessions(allHandles());
nHandles -= cancelKeys();
...
This way if processConnections(Iterator<SocketChannel>) or cancelKeys() removes a handle, the Selector still gets one last select(int) call to clean up the next time through, and if a new connection is created in that time, the thread won't be destroyed and immediately recreated.
> NioSocketConnector leaks the last open NioSocketSession after close
> -------------------------------------------------------------------
>
> Key: DIRMINA-827
> URL: https://issues.apache.org/jira/browse/DIRMINA-827
> Project: MINA
> Issue Type: Bug
> Components: Core
> Affects Versions: 2.0.2
> Environment: Windows 7/Solaris SPARC/Solaris x86
> Java versions 6u18 & 6u24
> Reporter: Matt Yates
> Priority: Critical
> Labels: connector, mina, session
> Attachments: MinaMain-2011-04-10.hprof, mina-core-2.0.4-SNAPSHOT.jar, sessionGcRoot.jpg
>
>
> My company's program uses MINA to make multiple (usually) simultaneous connections to various other machines, while reusing the same NioSocketConnector for each new connection. For better or worse, we store various objects in the IoSession's attributes, which we expect to get released on close. This is not always the case, however, as said session remains in memory until either a new connection is made or the IoConnector is disposed. After writing the simplest Connector program I could (I have several servers available on my network, so I did not write a matching Acceptor), and performing some profiling and debugging, I was able to confirm the leak and identify the issue.
> Below is my Connector test program
> {code}
> public class MinaMain {
> private static final Logger LOGGER = LoggerFactory.getLogger(MinaMain.class);
> public static void main(String[] args) throws InterruptedException {
> LOGGER.trace("Waiting for YourKit to start");
> Thread.sleep(15000);
> NioSocketConnector connector = new NioSocketConnector();
> connector.setHandler(new IoHandlerAdapter());
> closeSession(getConnectedSession(connector));
> // LOGGER.info("Creating and closing 5 sessions in series");
> //
> // for (int x = 0; x < 5; x++) {
> // IoSession session = getConnectedSession(connector);
> //
> // if (session == null) {
> // continue;
> // }
> //
> // closeSession(session);
> // }
> //
> // LOGGER.info("Creating 5 sessions and then closing 5 sessions");
> // IoSession[] sessions = new IoSession[5];
> //
> // for (int x = 0; x < 5; x++) {
> // sessions[x] = getConnectedSession(connector);
> // }
> //
> // for (int x = 0; x < 5; x++) {
> // IoSession session = sessions[x];
> //
> // if (session != null) {
> // closeSession(session);
> // sessions[x] = null;
> // }
> // }
> LOGGER.info("Test complete. Sleeping for 60s");
> Thread.sleep(60000);
> }
> private static IoSession getConnectedSession(IoConnector connector) throws InterruptedException {
> IoSession session = null;
> try {
> ConnectFuture future = connector.connect(new InetSocketAddress("134.64.37.183", 11109));
> future.addListener(new IoFutureListener<ConnectFuture>() {
> @Override
> public void operationComplete(ConnectFuture future) {
> LOGGER.debug("Connection completed callback for session " + future.getSession().getId());
> }
> });
> future.awaitUninterruptibly();
> LOGGER.debug("Connection created for session " + future.getSession().getId());
> session = future.getSession();
> Thread.sleep(15000);
> }
> catch (Exception e) {
> LOGGER.error("Failed to connect", e);
> }
> return session;
> }
> private static void closeSession(IoSession session) throws InterruptedException {
> try {
> CloseFuture closeFuture = session.getCloseFuture();
> closeFuture.addListener(new IoFutureListener<CloseFuture>() {
> @Override
> public void operationComplete(CloseFuture future) {
> LOGGER.debug("Session closed callback for session " + future.getSession().getId());
> }
> });
> LOGGER.debug("Attempting to close session " + session.getId());
> session.close(false);
> LOGGER.debug("IoSession.close(false) returned. Awaiting uninterruptibily for session " + session.getId());
> closeFuture.awaitUninterruptibly();
> LOGGER.debug("Close completed for session " + session.getId());
> }
> catch (Exception e) {
> LOGGER.error("Failed to close session " + session.getId());
> session.close(true);
> }
> Thread.sleep(15000);
> }
> }
> {code}
> Attached is the hprof file of my program, taken after the program has run (during the 60 second sleep at the end) and a screen shot of the GC Root of the leaked NioSocketSession.
> After a couple days of debugging, I've identified why this is happening. Below is a snippet from the AbstractPollingIoConnector.Connector thread
> {code}
> private class Connector implements Runnable {
> public void run() {
> int nHandles = 0;
> while (selectable) {
> try {
> // the timeout for select shall be smaller of the connect
> // timeout or 1 second...
> int timeout = (int)Math.min(getConnectTimeoutMillis(), 1000L);
> int selected = select(timeout);
> nHandles += registerNew();
> if (selected > 0) {
> nHandles -= processConnections(selectedHandles());
> }
> processTimedOutSessions(allHandles());
> nHandles -= cancelKeys();
> if (nHandles == 0) {
> synchronized (lock) {
> if (connectQueue.isEmpty()) {
> connector = null;
> break;
> }
> }
> }
> }
> ...
> {code}
> When IoSession.close(boolean) is called, the above Connector thread cancels the SelectionKey associated with the session, which reduces the number of handles from 1 to 0. Immediately afterwards, the thread stops executing because there are no handles and nothing in the connetQueue, however, the previously cancelled key is still in the Selector because its cancelledKeys Set is not processed until the next call to select(int)
> Calling dispose on the IoConnector restarts the Connector thread, which calls Selector.select(int), at which time, the Selector cleans out its canclledKeys.
> Creating a new connection causes the same thing to happen, because the new session also recreates the AbstractPollingIoConnector.Connector thread, as there is a new handle to be processed.
--
This message is automatically generated by JIRA.
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] [Commented] (DIRMINA-827) NioSocketConnector leaks the last
open NioSocketSession after close
Posted by "Emmanuel Lecharny (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/DIRMINA-827?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13018493#comment-13018493 ]
Emmanuel Lecharny commented on DIRMINA-827:
-------------------------------------------
wakeup() just makes sure that select() won't block. I haven't added it in the code atm, but I think I have to, because I'm not sure the select(TIMEOUT) won't block if we just have some cancelledKeys.
The best way to check would be to use a longer timeount (like 30s) and see what happens.
> NioSocketConnector leaks the last open NioSocketSession after close
> -------------------------------------------------------------------
>
> Key: DIRMINA-827
> URL: https://issues.apache.org/jira/browse/DIRMINA-827
> Project: MINA
> Issue Type: Bug
> Components: Core
> Affects Versions: 2.0.2
> Environment: Windows 7/Solaris SPARC/Solaris x86
> Java versions 6u18 & 6u24
> Reporter: Matt Yates
> Assignee: Emmanuel Lecharny
> Priority: Critical
> Labels: connector, mina, session
> Attachments: MinaMain-2011-04-10.hprof, mina-core-2.0.4-SNAPSHOT.jar, mina-core-2.0.4-SNAPSHOT.jar, sessionGcRoot.jpg
>
>
> My company's program uses MINA to make multiple (usually) simultaneous connections to various other machines, while reusing the same NioSocketConnector for each new connection. For better or worse, we store various objects in the IoSession's attributes, which we expect to get released on close. This is not always the case, however, as said session remains in memory until either a new connection is made or the IoConnector is disposed. After writing the simplest Connector program I could (I have several servers available on my network, so I did not write a matching Acceptor), and performing some profiling and debugging, I was able to confirm the leak and identify the issue.
> Below is my Connector test program
> {code}
> public class MinaMain {
> private static final Logger LOGGER = LoggerFactory.getLogger(MinaMain.class);
> public static void main(String[] args) throws InterruptedException {
> LOGGER.trace("Waiting for YourKit to start");
> Thread.sleep(15000);
> NioSocketConnector connector = new NioSocketConnector();
> connector.setHandler(new IoHandlerAdapter());
> closeSession(getConnectedSession(connector));
> // LOGGER.info("Creating and closing 5 sessions in series");
> //
> // for (int x = 0; x < 5; x++) {
> // IoSession session = getConnectedSession(connector);
> //
> // if (session == null) {
> // continue;
> // }
> //
> // closeSession(session);
> // }
> //
> // LOGGER.info("Creating 5 sessions and then closing 5 sessions");
> // IoSession[] sessions = new IoSession[5];
> //
> // for (int x = 0; x < 5; x++) {
> // sessions[x] = getConnectedSession(connector);
> // }
> //
> // for (int x = 0; x < 5; x++) {
> // IoSession session = sessions[x];
> //
> // if (session != null) {
> // closeSession(session);
> // sessions[x] = null;
> // }
> // }
> LOGGER.info("Test complete. Sleeping for 60s");
> Thread.sleep(60000);
> }
> private static IoSession getConnectedSession(IoConnector connector) throws InterruptedException {
> IoSession session = null;
> try {
> ConnectFuture future = connector.connect(new InetSocketAddress("134.64.37.183", 11109));
> future.addListener(new IoFutureListener<ConnectFuture>() {
> @Override
> public void operationComplete(ConnectFuture future) {
> LOGGER.debug("Connection completed callback for session " + future.getSession().getId());
> }
> });
> future.awaitUninterruptibly();
> LOGGER.debug("Connection created for session " + future.getSession().getId());
> session = future.getSession();
> Thread.sleep(15000);
> }
> catch (Exception e) {
> LOGGER.error("Failed to connect", e);
> }
> return session;
> }
> private static void closeSession(IoSession session) throws InterruptedException {
> try {
> CloseFuture closeFuture = session.getCloseFuture();
> closeFuture.addListener(new IoFutureListener<CloseFuture>() {
> @Override
> public void operationComplete(CloseFuture future) {
> LOGGER.debug("Session closed callback for session " + future.getSession().getId());
> }
> });
> LOGGER.debug("Attempting to close session " + session.getId());
> session.close(false);
> LOGGER.debug("IoSession.close(false) returned. Awaiting uninterruptibily for session " + session.getId());
> closeFuture.awaitUninterruptibly();
> LOGGER.debug("Close completed for session " + session.getId());
> }
> catch (Exception e) {
> LOGGER.error("Failed to close session " + session.getId());
> session.close(true);
> }
> Thread.sleep(15000);
> }
> }
> {code}
> Attached is the hprof file of my program, taken after the program has run (during the 60 second sleep at the end) and a screen shot of the GC Root of the leaked NioSocketSession.
> After a couple days of debugging, I've identified why this is happening. Below is a snippet from the AbstractPollingIoConnector.Connector thread
> {code}
> private class Connector implements Runnable {
> public void run() {
> int nHandles = 0;
> while (selectable) {
> try {
> // the timeout for select shall be smaller of the connect
> // timeout or 1 second...
> int timeout = (int)Math.min(getConnectTimeoutMillis(), 1000L);
> int selected = select(timeout);
> nHandles += registerNew();
> if (selected > 0) {
> nHandles -= processConnections(selectedHandles());
> }
> processTimedOutSessions(allHandles());
> nHandles -= cancelKeys();
> if (nHandles == 0) {
> synchronized (lock) {
> if (connectQueue.isEmpty()) {
> connector = null;
> break;
> }
> }
> }
> }
> ...
> {code}
> When IoSession.close(boolean) is called, the above Connector thread cancels the SelectionKey associated with the session, which reduces the number of handles from 1 to 0. Immediately afterwards, the thread stops executing because there are no handles and nothing in the connetQueue, however, the previously cancelled key is still in the Selector because its cancelledKeys Set is not processed until the next call to select(int)
> Calling dispose on the IoConnector restarts the Connector thread, which calls Selector.select(int), at which time, the Selector cleans out its canclledKeys.
> Creating a new connection causes the same thing to happen, because the new session also recreates the AbstractPollingIoConnector.Connector thread, as there is a new handle to be processed.
--
This message is automatically generated by JIRA.
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] [Updated] (DIRMINA-827) NioSocketConnector leaks the last
open NioSocketSession after close
Posted by "Emmanuel Lecharny (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/DIRMINA-827?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Emmanuel Lecharny updated DIRMINA-827:
--------------------------------------
Attachment: mina-core-2.0.4-SNAPSHOT.jar
> NioSocketConnector leaks the last open NioSocketSession after close
> -------------------------------------------------------------------
>
> Key: DIRMINA-827
> URL: https://issues.apache.org/jira/browse/DIRMINA-827
> Project: MINA
> Issue Type: Bug
> Components: Core
> Affects Versions: 2.0.2
> Environment: Windows 7/Solaris SPARC/Solaris x86
> Java versions 6u18 & 6u24
> Reporter: Matt Yates
> Priority: Critical
> Labels: connector, mina, session
> Attachments: MinaMain-2011-04-10.hprof, mina-core-2.0.4-SNAPSHOT.jar, sessionGcRoot.jpg
>
>
> My company's program uses MINA to make multiple (usually) simultaneous connections to various other machines, while reusing the same NioSocketConnector for each new connection. For better or worse, we store various objects in the IoSession's attributes, which we expect to get released on close. This is not always the case, however, as said session remains in memory until either a new connection is made or the IoConnector is disposed. After writing the simplest Connector program I could (I have several servers available on my network, so I did not write a matching Acceptor), and performing some profiling and debugging, I was able to confirm the leak and identify the issue.
> Below is my Connector test program
> {code}
> public class MinaMain {
> private static final Logger LOGGER = LoggerFactory.getLogger(MinaMain.class);
> public static void main(String[] args) throws InterruptedException {
> LOGGER.trace("Waiting for YourKit to start");
> Thread.sleep(15000);
> NioSocketConnector connector = new NioSocketConnector();
> connector.setHandler(new IoHandlerAdapter());
> closeSession(getConnectedSession(connector));
> // LOGGER.info("Creating and closing 5 sessions in series");
> //
> // for (int x = 0; x < 5; x++) {
> // IoSession session = getConnectedSession(connector);
> //
> // if (session == null) {
> // continue;
> // }
> //
> // closeSession(session);
> // }
> //
> // LOGGER.info("Creating 5 sessions and then closing 5 sessions");
> // IoSession[] sessions = new IoSession[5];
> //
> // for (int x = 0; x < 5; x++) {
> // sessions[x] = getConnectedSession(connector);
> // }
> //
> // for (int x = 0; x < 5; x++) {
> // IoSession session = sessions[x];
> //
> // if (session != null) {
> // closeSession(session);
> // sessions[x] = null;
> // }
> // }
> LOGGER.info("Test complete. Sleeping for 60s");
> Thread.sleep(60000);
> }
> private static IoSession getConnectedSession(IoConnector connector) throws InterruptedException {
> IoSession session = null;
> try {
> ConnectFuture future = connector.connect(new InetSocketAddress("134.64.37.183", 11109));
> future.addListener(new IoFutureListener<ConnectFuture>() {
> @Override
> public void operationComplete(ConnectFuture future) {
> LOGGER.debug("Connection completed callback for session " + future.getSession().getId());
> }
> });
> future.awaitUninterruptibly();
> LOGGER.debug("Connection created for session " + future.getSession().getId());
> session = future.getSession();
> Thread.sleep(15000);
> }
> catch (Exception e) {
> LOGGER.error("Failed to connect", e);
> }
> return session;
> }
> private static void closeSession(IoSession session) throws InterruptedException {
> try {
> CloseFuture closeFuture = session.getCloseFuture();
> closeFuture.addListener(new IoFutureListener<CloseFuture>() {
> @Override
> public void operationComplete(CloseFuture future) {
> LOGGER.debug("Session closed callback for session " + future.getSession().getId());
> }
> });
> LOGGER.debug("Attempting to close session " + session.getId());
> session.close(false);
> LOGGER.debug("IoSession.close(false) returned. Awaiting uninterruptibily for session " + session.getId());
> closeFuture.awaitUninterruptibly();
> LOGGER.debug("Close completed for session " + session.getId());
> }
> catch (Exception e) {
> LOGGER.error("Failed to close session " + session.getId());
> session.close(true);
> }
> Thread.sleep(15000);
> }
> }
> {code}
> Attached is the hprof file of my program, taken after the program has run (during the 60 second sleep at the end) and a screen shot of the GC Root of the leaked NioSocketSession.
> After a couple days of debugging, I've identified why this is happening. Below is a snippet from the AbstractPollingIoConnector.Connector thread
> {code}
> private class Connector implements Runnable {
> public void run() {
> int nHandles = 0;
> while (selectable) {
> try {
> // the timeout for select shall be smaller of the connect
> // timeout or 1 second...
> int timeout = (int)Math.min(getConnectTimeoutMillis(), 1000L);
> int selected = select(timeout);
> nHandles += registerNew();
> if (selected > 0) {
> nHandles -= processConnections(selectedHandles());
> }
> processTimedOutSessions(allHandles());
> nHandles -= cancelKeys();
> if (nHandles == 0) {
> synchronized (lock) {
> if (connectQueue.isEmpty()) {
> connector = null;
> break;
> }
> }
> }
> }
> ...
> {code}
> When IoSession.close(boolean) is called, the above Connector thread cancels the SelectionKey associated with the session, which reduces the number of handles from 1 to 0. Immediately afterwards, the thread stops executing because there are no handles and nothing in the connetQueue, however, the previously cancelled key is still in the Selector because its cancelledKeys Set is not processed until the next call to select(int)
> Calling dispose on the IoConnector restarts the Connector thread, which calls Selector.select(int), at which time, the Selector cleans out its canclledKeys.
> Creating a new connection causes the same thing to happen, because the new session also recreates the AbstractPollingIoConnector.Connector thread, as there is a new handle to be processed.
--
This message is automatically generated by JIRA.
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] [Commented] (DIRMINA-827) NioSocketConnector leaks the last
open NioSocketSession after close
Posted by "Emmanuel Lecharny (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/DIRMINA-827?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13018168#comment-13018168 ]
Emmanuel Lecharny commented on DIRMINA-827:
-------------------------------------------
I have to investigate more closely the problem.
Just wondering if catching the sessionClosed() event in your handler, and clean up the context there, could help.
i'll do that tomorrow, and if the problem can't be fixed in the application, I'll try to fix it n the code, which means I'll psotpone the release '(2.0.3 is currently being voted), and start a new vote as soon as I get a fix for your problem.
> NioSocketConnector leaks the last open NioSocketSession after close
> -------------------------------------------------------------------
>
> Key: DIRMINA-827
> URL: https://issues.apache.org/jira/browse/DIRMINA-827
> Project: MINA
> Issue Type: Bug
> Components: Core
> Affects Versions: 2.0.2
> Environment: Windows 7/Solaris SPARC/Solaris x86
> Java versions 6u18 & 6u24
> Reporter: Matt Yates
> Priority: Critical
> Labels: connector, mina, session
> Attachments: MinaMain-2011-04-10.hprof, sessionGcRoot.jpg
>
>
> My company's program uses MINA to make multiple (usually) simultaneous connections to various other machines, while reusing the same NioSocketConnector for each new connection. For better or worse, we store various objects in the IoSession's attributes, which we expect to get released on close. This is not always the case, however, as said session remains in memory until either a new connection is made or the IoConnector is disposed. After writing the simplest Connector program I could (I have several servers available on my network, so I did not write a matching Acceptor), and performing some profiling and debugging, I was able to confirm the leak and identify the issue.
> Below is my Connector test program
> {code}
> public class MinaMain {
> private static final Logger LOGGER = LoggerFactory.getLogger(MinaMain.class);
> public static void main(String[] args) throws InterruptedException {
> LOGGER.trace("Waiting for YourKit to start");
> Thread.sleep(15000);
> NioSocketConnector connector = new NioSocketConnector();
> connector.setHandler(new IoHandlerAdapter());
> closeSession(getConnectedSession(connector));
> // LOGGER.info("Creating and closing 5 sessions in series");
> //
> // for (int x = 0; x < 5; x++) {
> // IoSession session = getConnectedSession(connector);
> //
> // if (session == null) {
> // continue;
> // }
> //
> // closeSession(session);
> // }
> //
> // LOGGER.info("Creating 5 sessions and then closing 5 sessions");
> // IoSession[] sessions = new IoSession[5];
> //
> // for (int x = 0; x < 5; x++) {
> // sessions[x] = getConnectedSession(connector);
> // }
> //
> // for (int x = 0; x < 5; x++) {
> // IoSession session = sessions[x];
> //
> // if (session != null) {
> // closeSession(session);
> // sessions[x] = null;
> // }
> // }
> LOGGER.info("Test complete. Sleeping for 60s");
> Thread.sleep(60000);
> }
> private static IoSession getConnectedSession(IoConnector connector) throws InterruptedException {
> IoSession session = null;
> try {
> ConnectFuture future = connector.connect(new InetSocketAddress("134.64.37.183", 11109));
> future.addListener(new IoFutureListener<ConnectFuture>() {
> @Override
> public void operationComplete(ConnectFuture future) {
> LOGGER.debug("Connection completed callback for session " + future.getSession().getId());
> }
> });
> future.awaitUninterruptibly();
> LOGGER.debug("Connection created for session " + future.getSession().getId());
> session = future.getSession();
> Thread.sleep(15000);
> }
> catch (Exception e) {
> LOGGER.error("Failed to connect", e);
> }
> return session;
> }
> private static void closeSession(IoSession session) throws InterruptedException {
> try {
> CloseFuture closeFuture = session.getCloseFuture();
> closeFuture.addListener(new IoFutureListener<CloseFuture>() {
> @Override
> public void operationComplete(CloseFuture future) {
> LOGGER.debug("Session closed callback for session " + future.getSession().getId());
> }
> });
> LOGGER.debug("Attempting to close session " + session.getId());
> session.close(false);
> LOGGER.debug("IoSession.close(false) returned. Awaiting uninterruptibily for session " + session.getId());
> closeFuture.awaitUninterruptibly();
> LOGGER.debug("Close completed for session " + session.getId());
> }
> catch (Exception e) {
> LOGGER.error("Failed to close session " + session.getId());
> session.close(true);
> }
> Thread.sleep(15000);
> }
> }
> {code}
> Attached is the hprof file of my program, taken after the program has run (during the 60 second sleep at the end) and a screen shot of the GC Root of the leaked NioSocketSession.
> After a couple days of debugging, I've identified why this is happening. Below is a snippet from the AbstractPollingIoConnector.Connector thread
> {code}
> private class Connector implements Runnable {
> public void run() {
> int nHandles = 0;
> while (selectable) {
> try {
> // the timeout for select shall be smaller of the connect
> // timeout or 1 second...
> int timeout = (int)Math.min(getConnectTimeoutMillis(), 1000L);
> int selected = select(timeout);
> nHandles += registerNew();
> if (selected > 0) {
> nHandles -= processConnections(selectedHandles());
> }
> processTimedOutSessions(allHandles());
> nHandles -= cancelKeys();
> if (nHandles == 0) {
> synchronized (lock) {
> if (connectQueue.isEmpty()) {
> connector = null;
> break;
> }
> }
> }
> }
> ...
> {code}
> When IoSession.close(boolean) is called, the above Connector thread cancels the SelectionKey associated with the session, which reduces the number of handles from 1 to 0. Immediately afterwards, the thread stops executing because there are no handles and nothing in the connetQueue, however, the previously cancelled key is still in the Selector because its cancelledKeys Set is not processed until the next call to select(int)
> Calling dispose on the IoConnector restarts the Connector thread, which calls Selector.select(int), at which time, the Selector cleans out its canclledKeys.
> Creating a new connection causes the same thing to happen, because the new session also recreates the AbstractPollingIoConnector.Connector thread, as there is a new handle to be processed.
--
This message is automatically generated by JIRA.
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] [Updated] (DIRMINA-827) NioSocketConnector leaks the last
open NioSocketSession after close
Posted by "Matt Yates (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/DIRMINA-827?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Matt Yates updated DIRMINA-827:
-------------------------------
Attachment: IoConnectorWithCleanSelector.jpg
It looks like that worked! There's no SelectionKeys left in the cancellKeys or the channelArray of the Selector, which means no lingering IoSession.
> NioSocketConnector leaks the last open NioSocketSession after close
> -------------------------------------------------------------------
>
> Key: DIRMINA-827
> URL: https://issues.apache.org/jira/browse/DIRMINA-827
> Project: MINA
> Issue Type: Bug
> Components: Core
> Affects Versions: 2.0.2
> Environment: Windows 7/Solaris SPARC/Solaris x86
> Java versions 6u18 & 6u24
> Reporter: Matt Yates
> Assignee: Emmanuel Lecharny
> Priority: Critical
> Labels: connector, mina, session
> Attachments: IoConnectorWithCleanSelector.jpg, MinaMain-2011-04-10.hprof, mina-core-2.0.4-SNAPSHOT.jar, mina-core-2.0.4-SNAPSHOT.jar, sessionGcRoot.jpg
>
>
> My company's program uses MINA to make multiple (usually) simultaneous connections to various other machines, while reusing the same NioSocketConnector for each new connection. For better or worse, we store various objects in the IoSession's attributes, which we expect to get released on close. This is not always the case, however, as said session remains in memory until either a new connection is made or the IoConnector is disposed. After writing the simplest Connector program I could (I have several servers available on my network, so I did not write a matching Acceptor), and performing some profiling and debugging, I was able to confirm the leak and identify the issue.
> Below is my Connector test program
> {code}
> public class MinaMain {
> private static final Logger LOGGER = LoggerFactory.getLogger(MinaMain.class);
> public static void main(String[] args) throws InterruptedException {
> LOGGER.trace("Waiting for YourKit to start");
> Thread.sleep(15000);
> NioSocketConnector connector = new NioSocketConnector();
> connector.setHandler(new IoHandlerAdapter());
> closeSession(getConnectedSession(connector));
> // LOGGER.info("Creating and closing 5 sessions in series");
> //
> // for (int x = 0; x < 5; x++) {
> // IoSession session = getConnectedSession(connector);
> //
> // if (session == null) {
> // continue;
> // }
> //
> // closeSession(session);
> // }
> //
> // LOGGER.info("Creating 5 sessions and then closing 5 sessions");
> // IoSession[] sessions = new IoSession[5];
> //
> // for (int x = 0; x < 5; x++) {
> // sessions[x] = getConnectedSession(connector);
> // }
> //
> // for (int x = 0; x < 5; x++) {
> // IoSession session = sessions[x];
> //
> // if (session != null) {
> // closeSession(session);
> // sessions[x] = null;
> // }
> // }
> LOGGER.info("Test complete. Sleeping for 60s");
> Thread.sleep(60000);
> }
> private static IoSession getConnectedSession(IoConnector connector) throws InterruptedException {
> IoSession session = null;
> try {
> ConnectFuture future = connector.connect(new InetSocketAddress("134.64.37.183", 11109));
> future.addListener(new IoFutureListener<ConnectFuture>() {
> @Override
> public void operationComplete(ConnectFuture future) {
> LOGGER.debug("Connection completed callback for session " + future.getSession().getId());
> }
> });
> future.awaitUninterruptibly();
> LOGGER.debug("Connection created for session " + future.getSession().getId());
> session = future.getSession();
> Thread.sleep(15000);
> }
> catch (Exception e) {
> LOGGER.error("Failed to connect", e);
> }
> return session;
> }
> private static void closeSession(IoSession session) throws InterruptedException {
> try {
> CloseFuture closeFuture = session.getCloseFuture();
> closeFuture.addListener(new IoFutureListener<CloseFuture>() {
> @Override
> public void operationComplete(CloseFuture future) {
> LOGGER.debug("Session closed callback for session " + future.getSession().getId());
> }
> });
> LOGGER.debug("Attempting to close session " + session.getId());
> session.close(false);
> LOGGER.debug("IoSession.close(false) returned. Awaiting uninterruptibily for session " + session.getId());
> closeFuture.awaitUninterruptibly();
> LOGGER.debug("Close completed for session " + session.getId());
> }
> catch (Exception e) {
> LOGGER.error("Failed to close session " + session.getId());
> session.close(true);
> }
> Thread.sleep(15000);
> }
> }
> {code}
> Attached is the hprof file of my program, taken after the program has run (during the 60 second sleep at the end) and a screen shot of the GC Root of the leaked NioSocketSession.
> After a couple days of debugging, I've identified why this is happening. Below is a snippet from the AbstractPollingIoConnector.Connector thread
> {code}
> private class Connector implements Runnable {
> public void run() {
> int nHandles = 0;
> while (selectable) {
> try {
> // the timeout for select shall be smaller of the connect
> // timeout or 1 second...
> int timeout = (int)Math.min(getConnectTimeoutMillis(), 1000L);
> int selected = select(timeout);
> nHandles += registerNew();
> if (selected > 0) {
> nHandles -= processConnections(selectedHandles());
> }
> processTimedOutSessions(allHandles());
> nHandles -= cancelKeys();
> if (nHandles == 0) {
> synchronized (lock) {
> if (connectQueue.isEmpty()) {
> connector = null;
> break;
> }
> }
> }
> }
> ...
> {code}
> When IoSession.close(boolean) is called, the above Connector thread cancels the SelectionKey associated with the session, which reduces the number of handles from 1 to 0. Immediately afterwards, the thread stops executing because there are no handles and nothing in the connetQueue, however, the previously cancelled key is still in the Selector because its cancelledKeys Set is not processed until the next call to select(int)
> Calling dispose on the IoConnector restarts the Connector thread, which calls Selector.select(int), at which time, the Selector cleans out its canclledKeys.
> Creating a new connection causes the same thing to happen, because the new session also recreates the AbstractPollingIoConnector.Connector thread, as there is a new handle to be processed.
--
This message is automatically generated by JIRA.
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] [Commented] (DIRMINA-827) NioSocketConnector leaks the last
open NioSocketSession after close
Posted by "Matt Yates (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/DIRMINA-827?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13018486#comment-13018486 ]
Matt Yates commented on DIRMINA-827:
------------------------------------
Ah, I see. Since I'm using the IoHandlerAdapter as my IoHandler implmentation, that would explain why nothing happened. Calling wakeup() might work, so long as it triggers a select(), but I can't tell because wakeup() dives into native code
> NioSocketConnector leaks the last open NioSocketSession after close
> -------------------------------------------------------------------
>
> Key: DIRMINA-827
> URL: https://issues.apache.org/jira/browse/DIRMINA-827
> Project: MINA
> Issue Type: Bug
> Components: Core
> Affects Versions: 2.0.2
> Environment: Windows 7/Solaris SPARC/Solaris x86
> Java versions 6u18 & 6u24
> Reporter: Matt Yates
> Assignee: Emmanuel Lecharny
> Priority: Critical
> Labels: connector, mina, session
> Attachments: MinaMain-2011-04-10.hprof, mina-core-2.0.4-SNAPSHOT.jar, mina-core-2.0.4-SNAPSHOT.jar, sessionGcRoot.jpg
>
>
> My company's program uses MINA to make multiple (usually) simultaneous connections to various other machines, while reusing the same NioSocketConnector for each new connection. For better or worse, we store various objects in the IoSession's attributes, which we expect to get released on close. This is not always the case, however, as said session remains in memory until either a new connection is made or the IoConnector is disposed. After writing the simplest Connector program I could (I have several servers available on my network, so I did not write a matching Acceptor), and performing some profiling and debugging, I was able to confirm the leak and identify the issue.
> Below is my Connector test program
> {code}
> public class MinaMain {
> private static final Logger LOGGER = LoggerFactory.getLogger(MinaMain.class);
> public static void main(String[] args) throws InterruptedException {
> LOGGER.trace("Waiting for YourKit to start");
> Thread.sleep(15000);
> NioSocketConnector connector = new NioSocketConnector();
> connector.setHandler(new IoHandlerAdapter());
> closeSession(getConnectedSession(connector));
> // LOGGER.info("Creating and closing 5 sessions in series");
> //
> // for (int x = 0; x < 5; x++) {
> // IoSession session = getConnectedSession(connector);
> //
> // if (session == null) {
> // continue;
> // }
> //
> // closeSession(session);
> // }
> //
> // LOGGER.info("Creating 5 sessions and then closing 5 sessions");
> // IoSession[] sessions = new IoSession[5];
> //
> // for (int x = 0; x < 5; x++) {
> // sessions[x] = getConnectedSession(connector);
> // }
> //
> // for (int x = 0; x < 5; x++) {
> // IoSession session = sessions[x];
> //
> // if (session != null) {
> // closeSession(session);
> // sessions[x] = null;
> // }
> // }
> LOGGER.info("Test complete. Sleeping for 60s");
> Thread.sleep(60000);
> }
> private static IoSession getConnectedSession(IoConnector connector) throws InterruptedException {
> IoSession session = null;
> try {
> ConnectFuture future = connector.connect(new InetSocketAddress("134.64.37.183", 11109));
> future.addListener(new IoFutureListener<ConnectFuture>() {
> @Override
> public void operationComplete(ConnectFuture future) {
> LOGGER.debug("Connection completed callback for session " + future.getSession().getId());
> }
> });
> future.awaitUninterruptibly();
> LOGGER.debug("Connection created for session " + future.getSession().getId());
> session = future.getSession();
> Thread.sleep(15000);
> }
> catch (Exception e) {
> LOGGER.error("Failed to connect", e);
> }
> return session;
> }
> private static void closeSession(IoSession session) throws InterruptedException {
> try {
> CloseFuture closeFuture = session.getCloseFuture();
> closeFuture.addListener(new IoFutureListener<CloseFuture>() {
> @Override
> public void operationComplete(CloseFuture future) {
> LOGGER.debug("Session closed callback for session " + future.getSession().getId());
> }
> });
> LOGGER.debug("Attempting to close session " + session.getId());
> session.close(false);
> LOGGER.debug("IoSession.close(false) returned. Awaiting uninterruptibily for session " + session.getId());
> closeFuture.awaitUninterruptibly();
> LOGGER.debug("Close completed for session " + session.getId());
> }
> catch (Exception e) {
> LOGGER.error("Failed to close session " + session.getId());
> session.close(true);
> }
> Thread.sleep(15000);
> }
> }
> {code}
> Attached is the hprof file of my program, taken after the program has run (during the 60 second sleep at the end) and a screen shot of the GC Root of the leaked NioSocketSession.
> After a couple days of debugging, I've identified why this is happening. Below is a snippet from the AbstractPollingIoConnector.Connector thread
> {code}
> private class Connector implements Runnable {
> public void run() {
> int nHandles = 0;
> while (selectable) {
> try {
> // the timeout for select shall be smaller of the connect
> // timeout or 1 second...
> int timeout = (int)Math.min(getConnectTimeoutMillis(), 1000L);
> int selected = select(timeout);
> nHandles += registerNew();
> if (selected > 0) {
> nHandles -= processConnections(selectedHandles());
> }
> processTimedOutSessions(allHandles());
> nHandles -= cancelKeys();
> if (nHandles == 0) {
> synchronized (lock) {
> if (connectQueue.isEmpty()) {
> connector = null;
> break;
> }
> }
> }
> }
> ...
> {code}
> When IoSession.close(boolean) is called, the above Connector thread cancels the SelectionKey associated with the session, which reduces the number of handles from 1 to 0. Immediately afterwards, the thread stops executing because there are no handles and nothing in the connetQueue, however, the previously cancelled key is still in the Selector because its cancelledKeys Set is not processed until the next call to select(int)
> Calling dispose on the IoConnector restarts the Connector thread, which calls Selector.select(int), at which time, the Selector cleans out its canclledKeys.
> Creating a new connection causes the same thing to happen, because the new session also recreates the AbstractPollingIoConnector.Connector thread, as there is a new handle to be processed.
--
This message is automatically generated by JIRA.
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] [Commented] (DIRMINA-827) NioSocketConnector leaks the last
open NioSocketSession after close
Posted by "Emmanuel Lecharny (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/DIRMINA-827?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13018475#comment-13018475 ]
Emmanuel Lecharny commented on DIRMINA-827:
-------------------------------------------
The sessionClose() is an even handler by the IoHandler(). It gives the application a chance to cleanup correctly the sessions.
However, my patch was not good enough, as the attachement was still present in the SelectionKeyn and in the CancelledKeys set.
I'm just thinking we should also wakeup() the select, otherwise, we may be blocked, not sure though.
Let me patch agan, following your siggestion, and attach a new version of the jar.
> NioSocketConnector leaks the last open NioSocketSession after close
> -------------------------------------------------------------------
>
> Key: DIRMINA-827
> URL: https://issues.apache.org/jira/browse/DIRMINA-827
> Project: MINA
> Issue Type: Bug
> Components: Core
> Affects Versions: 2.0.2
> Environment: Windows 7/Solaris SPARC/Solaris x86
> Java versions 6u18 & 6u24
> Reporter: Matt Yates
> Priority: Critical
> Labels: connector, mina, session
> Attachments: MinaMain-2011-04-10.hprof, mina-core-2.0.4-SNAPSHOT.jar, sessionGcRoot.jpg
>
>
> My company's program uses MINA to make multiple (usually) simultaneous connections to various other machines, while reusing the same NioSocketConnector for each new connection. For better or worse, we store various objects in the IoSession's attributes, which we expect to get released on close. This is not always the case, however, as said session remains in memory until either a new connection is made or the IoConnector is disposed. After writing the simplest Connector program I could (I have several servers available on my network, so I did not write a matching Acceptor), and performing some profiling and debugging, I was able to confirm the leak and identify the issue.
> Below is my Connector test program
> {code}
> public class MinaMain {
> private static final Logger LOGGER = LoggerFactory.getLogger(MinaMain.class);
> public static void main(String[] args) throws InterruptedException {
> LOGGER.trace("Waiting for YourKit to start");
> Thread.sleep(15000);
> NioSocketConnector connector = new NioSocketConnector();
> connector.setHandler(new IoHandlerAdapter());
> closeSession(getConnectedSession(connector));
> // LOGGER.info("Creating and closing 5 sessions in series");
> //
> // for (int x = 0; x < 5; x++) {
> // IoSession session = getConnectedSession(connector);
> //
> // if (session == null) {
> // continue;
> // }
> //
> // closeSession(session);
> // }
> //
> // LOGGER.info("Creating 5 sessions and then closing 5 sessions");
> // IoSession[] sessions = new IoSession[5];
> //
> // for (int x = 0; x < 5; x++) {
> // sessions[x] = getConnectedSession(connector);
> // }
> //
> // for (int x = 0; x < 5; x++) {
> // IoSession session = sessions[x];
> //
> // if (session != null) {
> // closeSession(session);
> // sessions[x] = null;
> // }
> // }
> LOGGER.info("Test complete. Sleeping for 60s");
> Thread.sleep(60000);
> }
> private static IoSession getConnectedSession(IoConnector connector) throws InterruptedException {
> IoSession session = null;
> try {
> ConnectFuture future = connector.connect(new InetSocketAddress("134.64.37.183", 11109));
> future.addListener(new IoFutureListener<ConnectFuture>() {
> @Override
> public void operationComplete(ConnectFuture future) {
> LOGGER.debug("Connection completed callback for session " + future.getSession().getId());
> }
> });
> future.awaitUninterruptibly();
> LOGGER.debug("Connection created for session " + future.getSession().getId());
> session = future.getSession();
> Thread.sleep(15000);
> }
> catch (Exception e) {
> LOGGER.error("Failed to connect", e);
> }
> return session;
> }
> private static void closeSession(IoSession session) throws InterruptedException {
> try {
> CloseFuture closeFuture = session.getCloseFuture();
> closeFuture.addListener(new IoFutureListener<CloseFuture>() {
> @Override
> public void operationComplete(CloseFuture future) {
> LOGGER.debug("Session closed callback for session " + future.getSession().getId());
> }
> });
> LOGGER.debug("Attempting to close session " + session.getId());
> session.close(false);
> LOGGER.debug("IoSession.close(false) returned. Awaiting uninterruptibily for session " + session.getId());
> closeFuture.awaitUninterruptibly();
> LOGGER.debug("Close completed for session " + session.getId());
> }
> catch (Exception e) {
> LOGGER.error("Failed to close session " + session.getId());
> session.close(true);
> }
> Thread.sleep(15000);
> }
> }
> {code}
> Attached is the hprof file of my program, taken after the program has run (during the 60 second sleep at the end) and a screen shot of the GC Root of the leaked NioSocketSession.
> After a couple days of debugging, I've identified why this is happening. Below is a snippet from the AbstractPollingIoConnector.Connector thread
> {code}
> private class Connector implements Runnable {
> public void run() {
> int nHandles = 0;
> while (selectable) {
> try {
> // the timeout for select shall be smaller of the connect
> // timeout or 1 second...
> int timeout = (int)Math.min(getConnectTimeoutMillis(), 1000L);
> int selected = select(timeout);
> nHandles += registerNew();
> if (selected > 0) {
> nHandles -= processConnections(selectedHandles());
> }
> processTimedOutSessions(allHandles());
> nHandles -= cancelKeys();
> if (nHandles == 0) {
> synchronized (lock) {
> if (connectQueue.isEmpty()) {
> connector = null;
> break;
> }
> }
> }
> }
> ...
> {code}
> When IoSession.close(boolean) is called, the above Connector thread cancels the SelectionKey associated with the session, which reduces the number of handles from 1 to 0. Immediately afterwards, the thread stops executing because there are no handles and nothing in the connetQueue, however, the previously cancelled key is still in the Selector because its cancelledKeys Set is not processed until the next call to select(int)
> Calling dispose on the IoConnector restarts the Connector thread, which calls Selector.select(int), at which time, the Selector cleans out its canclledKeys.
> Creating a new connection causes the same thing to happen, because the new session also recreates the AbstractPollingIoConnector.Connector thread, as there is a new handle to be processed.
--
This message is automatically generated by JIRA.
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] [Updated] (DIRMINA-827) NioSocketConnector leaks the last
open NioSocketSession after close
Posted by "Emmanuel Lecharny (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/DIRMINA-827?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Emmanuel Lecharny updated DIRMINA-827:
--------------------------------------
Attachment: mina-core-2.0.4-SNAPSHOT.jar
A new version of the lib, with the suggested modification.
Can you test it and give me some feedback ?
Thanks !
> NioSocketConnector leaks the last open NioSocketSession after close
> -------------------------------------------------------------------
>
> Key: DIRMINA-827
> URL: https://issues.apache.org/jira/browse/DIRMINA-827
> Project: MINA
> Issue Type: Bug
> Components: Core
> Affects Versions: 2.0.2
> Environment: Windows 7/Solaris SPARC/Solaris x86
> Java versions 6u18 & 6u24
> Reporter: Matt Yates
> Assignee: Emmanuel Lecharny
> Priority: Critical
> Labels: connector, mina, session
> Attachments: MinaMain-2011-04-10.hprof, mina-core-2.0.4-SNAPSHOT.jar, mina-core-2.0.4-SNAPSHOT.jar, sessionGcRoot.jpg
>
>
> My company's program uses MINA to make multiple (usually) simultaneous connections to various other machines, while reusing the same NioSocketConnector for each new connection. For better or worse, we store various objects in the IoSession's attributes, which we expect to get released on close. This is not always the case, however, as said session remains in memory until either a new connection is made or the IoConnector is disposed. After writing the simplest Connector program I could (I have several servers available on my network, so I did not write a matching Acceptor), and performing some profiling and debugging, I was able to confirm the leak and identify the issue.
> Below is my Connector test program
> {code}
> public class MinaMain {
> private static final Logger LOGGER = LoggerFactory.getLogger(MinaMain.class);
> public static void main(String[] args) throws InterruptedException {
> LOGGER.trace("Waiting for YourKit to start");
> Thread.sleep(15000);
> NioSocketConnector connector = new NioSocketConnector();
> connector.setHandler(new IoHandlerAdapter());
> closeSession(getConnectedSession(connector));
> // LOGGER.info("Creating and closing 5 sessions in series");
> //
> // for (int x = 0; x < 5; x++) {
> // IoSession session = getConnectedSession(connector);
> //
> // if (session == null) {
> // continue;
> // }
> //
> // closeSession(session);
> // }
> //
> // LOGGER.info("Creating 5 sessions and then closing 5 sessions");
> // IoSession[] sessions = new IoSession[5];
> //
> // for (int x = 0; x < 5; x++) {
> // sessions[x] = getConnectedSession(connector);
> // }
> //
> // for (int x = 0; x < 5; x++) {
> // IoSession session = sessions[x];
> //
> // if (session != null) {
> // closeSession(session);
> // sessions[x] = null;
> // }
> // }
> LOGGER.info("Test complete. Sleeping for 60s");
> Thread.sleep(60000);
> }
> private static IoSession getConnectedSession(IoConnector connector) throws InterruptedException {
> IoSession session = null;
> try {
> ConnectFuture future = connector.connect(new InetSocketAddress("134.64.37.183", 11109));
> future.addListener(new IoFutureListener<ConnectFuture>() {
> @Override
> public void operationComplete(ConnectFuture future) {
> LOGGER.debug("Connection completed callback for session " + future.getSession().getId());
> }
> });
> future.awaitUninterruptibly();
> LOGGER.debug("Connection created for session " + future.getSession().getId());
> session = future.getSession();
> Thread.sleep(15000);
> }
> catch (Exception e) {
> LOGGER.error("Failed to connect", e);
> }
> return session;
> }
> private static void closeSession(IoSession session) throws InterruptedException {
> try {
> CloseFuture closeFuture = session.getCloseFuture();
> closeFuture.addListener(new IoFutureListener<CloseFuture>() {
> @Override
> public void operationComplete(CloseFuture future) {
> LOGGER.debug("Session closed callback for session " + future.getSession().getId());
> }
> });
> LOGGER.debug("Attempting to close session " + session.getId());
> session.close(false);
> LOGGER.debug("IoSession.close(false) returned. Awaiting uninterruptibily for session " + session.getId());
> closeFuture.awaitUninterruptibly();
> LOGGER.debug("Close completed for session " + session.getId());
> }
> catch (Exception e) {
> LOGGER.error("Failed to close session " + session.getId());
> session.close(true);
> }
> Thread.sleep(15000);
> }
> }
> {code}
> Attached is the hprof file of my program, taken after the program has run (during the 60 second sleep at the end) and a screen shot of the GC Root of the leaked NioSocketSession.
> After a couple days of debugging, I've identified why this is happening. Below is a snippet from the AbstractPollingIoConnector.Connector thread
> {code}
> private class Connector implements Runnable {
> public void run() {
> int nHandles = 0;
> while (selectable) {
> try {
> // the timeout for select shall be smaller of the connect
> // timeout or 1 second...
> int timeout = (int)Math.min(getConnectTimeoutMillis(), 1000L);
> int selected = select(timeout);
> nHandles += registerNew();
> if (selected > 0) {
> nHandles -= processConnections(selectedHandles());
> }
> processTimedOutSessions(allHandles());
> nHandles -= cancelKeys();
> if (nHandles == 0) {
> synchronized (lock) {
> if (connectQueue.isEmpty()) {
> connector = null;
> break;
> }
> }
> }
> }
> ...
> {code}
> When IoSession.close(boolean) is called, the above Connector thread cancels the SelectionKey associated with the session, which reduces the number of handles from 1 to 0. Immediately afterwards, the thread stops executing because there are no handles and nothing in the connetQueue, however, the previously cancelled key is still in the Selector because its cancelledKeys Set is not processed until the next call to select(int)
> Calling dispose on the IoConnector restarts the Connector thread, which calls Selector.select(int), at which time, the Selector cleans out its canclledKeys.
> Creating a new connection causes the same thing to happen, because the new session also recreates the AbstractPollingIoConnector.Connector thread, as there is a new handle to be processed.
--
This message is automatically generated by JIRA.
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] [Commented] (DIRMINA-827) NioSocketConnector leaks the last
open NioSocketSession after close
Posted by "Matt Yates (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/DIRMINA-827?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13018446#comment-13018446 ]
Matt Yates commented on DIRMINA-827:
------------------------------------
I'm not sure what 'sessionClosed()' event to which you are referring, but it does not seem to fix the problem. What if you simply moved the 'if (nHandles == 0)' block up to happen before the handle count potentially shrinks?
Currently:
...
int selected = select(timeout);
nHandles += registerNew();
if (selected > 0) {
nHandles -= processConnections(selectedHandles());
}
processTimedOutSessions(allHandles());
nHandles -= cancelKeys();
if (nHandles == 0) {
synchronized (lock) {
if (connectQueue.isEmpty()) {
connector = null;
break;
}
}
}
...
Proposed:
...
int selected = select(timeout);
nHandles += registerNew()
if (nHandles == 0) {
synchronized (lock) {
if (connectQueue.isEmpty()) {
connector = null;
break;
}
}
};
if (selected > 0) {
nHandles -= processConnections(selectedHandles());
}
processTimedOutSessions(allHandles());
nHandles -= cancelKeys();
...
This way if processConnections(Iterator<SocketChannel>) or cancelKeys() removes a handle, the Selector still gets one last select(int) call to clean up the next time through, and if a new connection is created in that time, the thread won't be destroyed and immediately recreated.
> NioSocketConnector leaks the last open NioSocketSession after close
> -------------------------------------------------------------------
>
> Key: DIRMINA-827
> URL: https://issues.apache.org/jira/browse/DIRMINA-827
> Project: MINA
> Issue Type: Bug
> Components: Core
> Affects Versions: 2.0.2
> Environment: Windows 7/Solaris SPARC/Solaris x86
> Java versions 6u18 & 6u24
> Reporter: Matt Yates
> Priority: Critical
> Labels: connector, mina, session
> Attachments: MinaMain-2011-04-10.hprof, mina-core-2.0.4-SNAPSHOT.jar, sessionGcRoot.jpg
>
>
> My company's program uses MINA to make multiple (usually) simultaneous connections to various other machines, while reusing the same NioSocketConnector for each new connection. For better or worse, we store various objects in the IoSession's attributes, which we expect to get released on close. This is not always the case, however, as said session remains in memory until either a new connection is made or the IoConnector is disposed. After writing the simplest Connector program I could (I have several servers available on my network, so I did not write a matching Acceptor), and performing some profiling and debugging, I was able to confirm the leak and identify the issue.
> Below is my Connector test program
> {code}
> public class MinaMain {
> private static final Logger LOGGER = LoggerFactory.getLogger(MinaMain.class);
> public static void main(String[] args) throws InterruptedException {
> LOGGER.trace("Waiting for YourKit to start");
> Thread.sleep(15000);
> NioSocketConnector connector = new NioSocketConnector();
> connector.setHandler(new IoHandlerAdapter());
> closeSession(getConnectedSession(connector));
> // LOGGER.info("Creating and closing 5 sessions in series");
> //
> // for (int x = 0; x < 5; x++) {
> // IoSession session = getConnectedSession(connector);
> //
> // if (session == null) {
> // continue;
> // }
> //
> // closeSession(session);
> // }
> //
> // LOGGER.info("Creating 5 sessions and then closing 5 sessions");
> // IoSession[] sessions = new IoSession[5];
> //
> // for (int x = 0; x < 5; x++) {
> // sessions[x] = getConnectedSession(connector);
> // }
> //
> // for (int x = 0; x < 5; x++) {
> // IoSession session = sessions[x];
> //
> // if (session != null) {
> // closeSession(session);
> // sessions[x] = null;
> // }
> // }
> LOGGER.info("Test complete. Sleeping for 60s");
> Thread.sleep(60000);
> }
> private static IoSession getConnectedSession(IoConnector connector) throws InterruptedException {
> IoSession session = null;
> try {
> ConnectFuture future = connector.connect(new InetSocketAddress("134.64.37.183", 11109));
> future.addListener(new IoFutureListener<ConnectFuture>() {
> @Override
> public void operationComplete(ConnectFuture future) {
> LOGGER.debug("Connection completed callback for session " + future.getSession().getId());
> }
> });
> future.awaitUninterruptibly();
> LOGGER.debug("Connection created for session " + future.getSession().getId());
> session = future.getSession();
> Thread.sleep(15000);
> }
> catch (Exception e) {
> LOGGER.error("Failed to connect", e);
> }
> return session;
> }
> private static void closeSession(IoSession session) throws InterruptedException {
> try {
> CloseFuture closeFuture = session.getCloseFuture();
> closeFuture.addListener(new IoFutureListener<CloseFuture>() {
> @Override
> public void operationComplete(CloseFuture future) {
> LOGGER.debug("Session closed callback for session " + future.getSession().getId());
> }
> });
> LOGGER.debug("Attempting to close session " + session.getId());
> session.close(false);
> LOGGER.debug("IoSession.close(false) returned. Awaiting uninterruptibily for session " + session.getId());
> closeFuture.awaitUninterruptibly();
> LOGGER.debug("Close completed for session " + session.getId());
> }
> catch (Exception e) {
> LOGGER.error("Failed to close session " + session.getId());
> session.close(true);
> }
> Thread.sleep(15000);
> }
> }
> {code}
> Attached is the hprof file of my program, taken after the program has run (during the 60 second sleep at the end) and a screen shot of the GC Root of the leaked NioSocketSession.
> After a couple days of debugging, I've identified why this is happening. Below is a snippet from the AbstractPollingIoConnector.Connector thread
> {code}
> private class Connector implements Runnable {
> public void run() {
> int nHandles = 0;
> while (selectable) {
> try {
> // the timeout for select shall be smaller of the connect
> // timeout or 1 second...
> int timeout = (int)Math.min(getConnectTimeoutMillis(), 1000L);
> int selected = select(timeout);
> nHandles += registerNew();
> if (selected > 0) {
> nHandles -= processConnections(selectedHandles());
> }
> processTimedOutSessions(allHandles());
> nHandles -= cancelKeys();
> if (nHandles == 0) {
> synchronized (lock) {
> if (connectQueue.isEmpty()) {
> connector = null;
> break;
> }
> }
> }
> }
> ...
> {code}
> When IoSession.close(boolean) is called, the above Connector thread cancels the SelectionKey associated with the session, which reduces the number of handles from 1 to 0. Immediately afterwards, the thread stops executing because there are no handles and nothing in the connetQueue, however, the previously cancelled key is still in the Selector because its cancelledKeys Set is not processed until the next call to select(int)
> Calling dispose on the IoConnector restarts the Connector thread, which calls Selector.select(int), at which time, the Selector cleans out its canclledKeys.
> Creating a new connection causes the same thing to happen, because the new session also recreates the AbstractPollingIoConnector.Connector thread, as there is a new handle to be processed.
--
This message is automatically generated by JIRA.
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] [Resolved] (DIRMINA-827) NioSocketConnector leaks the last
open NioSocketSession after close
Posted by "Emmanuel Lecharny (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/DIRMINA-827?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Emmanuel Lecharny resolved DIRMINA-827.
---------------------------------------
Resolution: Fixed
Fixed with http://svn.apache.org/viewvc?rev=1091209&view=rev
> NioSocketConnector leaks the last open NioSocketSession after close
> -------------------------------------------------------------------
>
> Key: DIRMINA-827
> URL: https://issues.apache.org/jira/browse/DIRMINA-827
> Project: MINA
> Issue Type: Bug
> Components: Core
> Affects Versions: 2.0.2
> Environment: Windows 7/Solaris SPARC/Solaris x86
> Java versions 6u18 & 6u24
> Reporter: Matt Yates
> Assignee: Emmanuel Lecharny
> Priority: Critical
> Labels: connector, mina, session
> Attachments: IoConnectorWithCleanSelector.jpg, MinaMain-2011-04-10.hprof, mina-core-2.0.4-SNAPSHOT.jar, mina-core-2.0.4-SNAPSHOT.jar, sessionGcRoot.jpg
>
>
> My company's program uses MINA to make multiple (usually) simultaneous connections to various other machines, while reusing the same NioSocketConnector for each new connection. For better or worse, we store various objects in the IoSession's attributes, which we expect to get released on close. This is not always the case, however, as said session remains in memory until either a new connection is made or the IoConnector is disposed. After writing the simplest Connector program I could (I have several servers available on my network, so I did not write a matching Acceptor), and performing some profiling and debugging, I was able to confirm the leak and identify the issue.
> Below is my Connector test program
> {code}
> public class MinaMain {
> private static final Logger LOGGER = LoggerFactory.getLogger(MinaMain.class);
> public static void main(String[] args) throws InterruptedException {
> LOGGER.trace("Waiting for YourKit to start");
> Thread.sleep(15000);
> NioSocketConnector connector = new NioSocketConnector();
> connector.setHandler(new IoHandlerAdapter());
> closeSession(getConnectedSession(connector));
> // LOGGER.info("Creating and closing 5 sessions in series");
> //
> // for (int x = 0; x < 5; x++) {
> // IoSession session = getConnectedSession(connector);
> //
> // if (session == null) {
> // continue;
> // }
> //
> // closeSession(session);
> // }
> //
> // LOGGER.info("Creating 5 sessions and then closing 5 sessions");
> // IoSession[] sessions = new IoSession[5];
> //
> // for (int x = 0; x < 5; x++) {
> // sessions[x] = getConnectedSession(connector);
> // }
> //
> // for (int x = 0; x < 5; x++) {
> // IoSession session = sessions[x];
> //
> // if (session != null) {
> // closeSession(session);
> // sessions[x] = null;
> // }
> // }
> LOGGER.info("Test complete. Sleeping for 60s");
> Thread.sleep(60000);
> }
> private static IoSession getConnectedSession(IoConnector connector) throws InterruptedException {
> IoSession session = null;
> try {
> ConnectFuture future = connector.connect(new InetSocketAddress("134.64.37.183", 11109));
> future.addListener(new IoFutureListener<ConnectFuture>() {
> @Override
> public void operationComplete(ConnectFuture future) {
> LOGGER.debug("Connection completed callback for session " + future.getSession().getId());
> }
> });
> future.awaitUninterruptibly();
> LOGGER.debug("Connection created for session " + future.getSession().getId());
> session = future.getSession();
> Thread.sleep(15000);
> }
> catch (Exception e) {
> LOGGER.error("Failed to connect", e);
> }
> return session;
> }
> private static void closeSession(IoSession session) throws InterruptedException {
> try {
> CloseFuture closeFuture = session.getCloseFuture();
> closeFuture.addListener(new IoFutureListener<CloseFuture>() {
> @Override
> public void operationComplete(CloseFuture future) {
> LOGGER.debug("Session closed callback for session " + future.getSession().getId());
> }
> });
> LOGGER.debug("Attempting to close session " + session.getId());
> session.close(false);
> LOGGER.debug("IoSession.close(false) returned. Awaiting uninterruptibily for session " + session.getId());
> closeFuture.awaitUninterruptibly();
> LOGGER.debug("Close completed for session " + session.getId());
> }
> catch (Exception e) {
> LOGGER.error("Failed to close session " + session.getId());
> session.close(true);
> }
> Thread.sleep(15000);
> }
> }
> {code}
> Attached is the hprof file of my program, taken after the program has run (during the 60 second sleep at the end) and a screen shot of the GC Root of the leaked NioSocketSession.
> After a couple days of debugging, I've identified why this is happening. Below is a snippet from the AbstractPollingIoConnector.Connector thread
> {code}
> private class Connector implements Runnable {
> public void run() {
> int nHandles = 0;
> while (selectable) {
> try {
> // the timeout for select shall be smaller of the connect
> // timeout or 1 second...
> int timeout = (int)Math.min(getConnectTimeoutMillis(), 1000L);
> int selected = select(timeout);
> nHandles += registerNew();
> if (selected > 0) {
> nHandles -= processConnections(selectedHandles());
> }
> processTimedOutSessions(allHandles());
> nHandles -= cancelKeys();
> if (nHandles == 0) {
> synchronized (lock) {
> if (connectQueue.isEmpty()) {
> connector = null;
> break;
> }
> }
> }
> }
> ...
> {code}
> When IoSession.close(boolean) is called, the above Connector thread cancels the SelectionKey associated with the session, which reduces the number of handles from 1 to 0. Immediately afterwards, the thread stops executing because there are no handles and nothing in the connetQueue, however, the previously cancelled key is still in the Selector because its cancelledKeys Set is not processed until the next call to select(int)
> Calling dispose on the IoConnector restarts the Connector thread, which calls Selector.select(int), at which time, the Selector cleans out its canclledKeys.
> Creating a new connection causes the same thing to happen, because the new session also recreates the AbstractPollingIoConnector.Connector thread, as there is a new handle to be processed.
--
This message is automatically generated by JIRA.
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] [Commented] (DIRMINA-827) NioSocketConnector leaks the last
open NioSocketSession after close
Posted by "Emmanuel Lecharny (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/DIRMINA-827?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13020348#comment-13020348 ]
Emmanuel Lecharny commented on DIRMINA-827:
-------------------------------------------
Definitively included in 2.0.3
2.0.3 vote has been closed 2 hours ago, the release is on its way. It will be announced tomorrow, because we have to wait for the mirrors to be updated all over the planet.
> NioSocketConnector leaks the last open NioSocketSession after close
> -------------------------------------------------------------------
>
> Key: DIRMINA-827
> URL: https://issues.apache.org/jira/browse/DIRMINA-827
> Project: MINA
> Issue Type: Bug
> Components: Core
> Affects Versions: 2.0.2
> Environment: Windows 7/Solaris SPARC/Solaris x86
> Java versions 6u18 & 6u24
> Reporter: Matt Yates
> Assignee: Emmanuel Lecharny
> Priority: Critical
> Labels: connector, mina, session
> Attachments: IoConnectorWithCleanSelector.jpg, MinaMain-2011-04-10.hprof, mina-core-2.0.4-SNAPSHOT.jar, mina-core-2.0.4-SNAPSHOT.jar, sessionGcRoot.jpg
>
>
> My company's program uses MINA to make multiple (usually) simultaneous connections to various other machines, while reusing the same NioSocketConnector for each new connection. For better or worse, we store various objects in the IoSession's attributes, which we expect to get released on close. This is not always the case, however, as said session remains in memory until either a new connection is made or the IoConnector is disposed. After writing the simplest Connector program I could (I have several servers available on my network, so I did not write a matching Acceptor), and performing some profiling and debugging, I was able to confirm the leak and identify the issue.
> Below is my Connector test program
> {code}
> public class MinaMain {
> private static final Logger LOGGER = LoggerFactory.getLogger(MinaMain.class);
> public static void main(String[] args) throws InterruptedException {
> LOGGER.trace("Waiting for YourKit to start");
> Thread.sleep(15000);
> NioSocketConnector connector = new NioSocketConnector();
> connector.setHandler(new IoHandlerAdapter());
> closeSession(getConnectedSession(connector));
> // LOGGER.info("Creating and closing 5 sessions in series");
> //
> // for (int x = 0; x < 5; x++) {
> // IoSession session = getConnectedSession(connector);
> //
> // if (session == null) {
> // continue;
> // }
> //
> // closeSession(session);
> // }
> //
> // LOGGER.info("Creating 5 sessions and then closing 5 sessions");
> // IoSession[] sessions = new IoSession[5];
> //
> // for (int x = 0; x < 5; x++) {
> // sessions[x] = getConnectedSession(connector);
> // }
> //
> // for (int x = 0; x < 5; x++) {
> // IoSession session = sessions[x];
> //
> // if (session != null) {
> // closeSession(session);
> // sessions[x] = null;
> // }
> // }
> LOGGER.info("Test complete. Sleeping for 60s");
> Thread.sleep(60000);
> }
> private static IoSession getConnectedSession(IoConnector connector) throws InterruptedException {
> IoSession session = null;
> try {
> ConnectFuture future = connector.connect(new InetSocketAddress("134.64.37.183", 11109));
> future.addListener(new IoFutureListener<ConnectFuture>() {
> @Override
> public void operationComplete(ConnectFuture future) {
> LOGGER.debug("Connection completed callback for session " + future.getSession().getId());
> }
> });
> future.awaitUninterruptibly();
> LOGGER.debug("Connection created for session " + future.getSession().getId());
> session = future.getSession();
> Thread.sleep(15000);
> }
> catch (Exception e) {
> LOGGER.error("Failed to connect", e);
> }
> return session;
> }
> private static void closeSession(IoSession session) throws InterruptedException {
> try {
> CloseFuture closeFuture = session.getCloseFuture();
> closeFuture.addListener(new IoFutureListener<CloseFuture>() {
> @Override
> public void operationComplete(CloseFuture future) {
> LOGGER.debug("Session closed callback for session " + future.getSession().getId());
> }
> });
> LOGGER.debug("Attempting to close session " + session.getId());
> session.close(false);
> LOGGER.debug("IoSession.close(false) returned. Awaiting uninterruptibily for session " + session.getId());
> closeFuture.awaitUninterruptibly();
> LOGGER.debug("Close completed for session " + session.getId());
> }
> catch (Exception e) {
> LOGGER.error("Failed to close session " + session.getId());
> session.close(true);
> }
> Thread.sleep(15000);
> }
> }
> {code}
> Attached is the hprof file of my program, taken after the program has run (during the 60 second sleep at the end) and a screen shot of the GC Root of the leaked NioSocketSession.
> After a couple days of debugging, I've identified why this is happening. Below is a snippet from the AbstractPollingIoConnector.Connector thread
> {code}
> private class Connector implements Runnable {
> public void run() {
> int nHandles = 0;
> while (selectable) {
> try {
> // the timeout for select shall be smaller of the connect
> // timeout or 1 second...
> int timeout = (int)Math.min(getConnectTimeoutMillis(), 1000L);
> int selected = select(timeout);
> nHandles += registerNew();
> if (selected > 0) {
> nHandles -= processConnections(selectedHandles());
> }
> processTimedOutSessions(allHandles());
> nHandles -= cancelKeys();
> if (nHandles == 0) {
> synchronized (lock) {
> if (connectQueue.isEmpty()) {
> connector = null;
> break;
> }
> }
> }
> }
> ...
> {code}
> When IoSession.close(boolean) is called, the above Connector thread cancels the SelectionKey associated with the session, which reduces the number of handles from 1 to 0. Immediately afterwards, the thread stops executing because there are no handles and nothing in the connetQueue, however, the previously cancelled key is still in the Selector because its cancelledKeys Set is not processed until the next call to select(int)
> Calling dispose on the IoConnector restarts the Connector thread, which calls Selector.select(int), at which time, the Selector cleans out its canclledKeys.
> Creating a new connection causes the same thing to happen, because the new session also recreates the AbstractPollingIoConnector.Connector thread, as there is a new handle to be processed.
--
This message is automatically generated by JIRA.
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] [Updated] (DIRMINA-827) NioSocketConnector leaks the last
open NioSocketSession after close
Posted by "Emmanuel Lecharny (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/DIRMINA-827?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Emmanuel Lecharny updated DIRMINA-827:
--------------------------------------
Attachment: (was: mina-core-2.0.4-SNAPSHOT.jar)
> NioSocketConnector leaks the last open NioSocketSession after close
> -------------------------------------------------------------------
>
> Key: DIRMINA-827
> URL: https://issues.apache.org/jira/browse/DIRMINA-827
> Project: MINA
> Issue Type: Bug
> Components: Core
> Affects Versions: 2.0.2
> Environment: Windows 7/Solaris SPARC/Solaris x86
> Java versions 6u18 & 6u24
> Reporter: Matt Yates
> Assignee: Emmanuel Lecharny
> Priority: Critical
> Labels: connector, mina, session
> Attachments: MinaMain-2011-04-10.hprof, mina-core-2.0.4-SNAPSHOT.jar, mina-core-2.0.4-SNAPSHOT.jar, sessionGcRoot.jpg
>
>
> My company's program uses MINA to make multiple (usually) simultaneous connections to various other machines, while reusing the same NioSocketConnector for each new connection. For better or worse, we store various objects in the IoSession's attributes, which we expect to get released on close. This is not always the case, however, as said session remains in memory until either a new connection is made or the IoConnector is disposed. After writing the simplest Connector program I could (I have several servers available on my network, so I did not write a matching Acceptor), and performing some profiling and debugging, I was able to confirm the leak and identify the issue.
> Below is my Connector test program
> {code}
> public class MinaMain {
> private static final Logger LOGGER = LoggerFactory.getLogger(MinaMain.class);
> public static void main(String[] args) throws InterruptedException {
> LOGGER.trace("Waiting for YourKit to start");
> Thread.sleep(15000);
> NioSocketConnector connector = new NioSocketConnector();
> connector.setHandler(new IoHandlerAdapter());
> closeSession(getConnectedSession(connector));
> // LOGGER.info("Creating and closing 5 sessions in series");
> //
> // for (int x = 0; x < 5; x++) {
> // IoSession session = getConnectedSession(connector);
> //
> // if (session == null) {
> // continue;
> // }
> //
> // closeSession(session);
> // }
> //
> // LOGGER.info("Creating 5 sessions and then closing 5 sessions");
> // IoSession[] sessions = new IoSession[5];
> //
> // for (int x = 0; x < 5; x++) {
> // sessions[x] = getConnectedSession(connector);
> // }
> //
> // for (int x = 0; x < 5; x++) {
> // IoSession session = sessions[x];
> //
> // if (session != null) {
> // closeSession(session);
> // sessions[x] = null;
> // }
> // }
> LOGGER.info("Test complete. Sleeping for 60s");
> Thread.sleep(60000);
> }
> private static IoSession getConnectedSession(IoConnector connector) throws InterruptedException {
> IoSession session = null;
> try {
> ConnectFuture future = connector.connect(new InetSocketAddress("134.64.37.183", 11109));
> future.addListener(new IoFutureListener<ConnectFuture>() {
> @Override
> public void operationComplete(ConnectFuture future) {
> LOGGER.debug("Connection completed callback for session " + future.getSession().getId());
> }
> });
> future.awaitUninterruptibly();
> LOGGER.debug("Connection created for session " + future.getSession().getId());
> session = future.getSession();
> Thread.sleep(15000);
> }
> catch (Exception e) {
> LOGGER.error("Failed to connect", e);
> }
> return session;
> }
> private static void closeSession(IoSession session) throws InterruptedException {
> try {
> CloseFuture closeFuture = session.getCloseFuture();
> closeFuture.addListener(new IoFutureListener<CloseFuture>() {
> @Override
> public void operationComplete(CloseFuture future) {
> LOGGER.debug("Session closed callback for session " + future.getSession().getId());
> }
> });
> LOGGER.debug("Attempting to close session " + session.getId());
> session.close(false);
> LOGGER.debug("IoSession.close(false) returned. Awaiting uninterruptibily for session " + session.getId());
> closeFuture.awaitUninterruptibly();
> LOGGER.debug("Close completed for session " + session.getId());
> }
> catch (Exception e) {
> LOGGER.error("Failed to close session " + session.getId());
> session.close(true);
> }
> Thread.sleep(15000);
> }
> }
> {code}
> Attached is the hprof file of my program, taken after the program has run (during the 60 second sleep at the end) and a screen shot of the GC Root of the leaked NioSocketSession.
> After a couple days of debugging, I've identified why this is happening. Below is a snippet from the AbstractPollingIoConnector.Connector thread
> {code}
> private class Connector implements Runnable {
> public void run() {
> int nHandles = 0;
> while (selectable) {
> try {
> // the timeout for select shall be smaller of the connect
> // timeout or 1 second...
> int timeout = (int)Math.min(getConnectTimeoutMillis(), 1000L);
> int selected = select(timeout);
> nHandles += registerNew();
> if (selected > 0) {
> nHandles -= processConnections(selectedHandles());
> }
> processTimedOutSessions(allHandles());
> nHandles -= cancelKeys();
> if (nHandles == 0) {
> synchronized (lock) {
> if (connectQueue.isEmpty()) {
> connector = null;
> break;
> }
> }
> }
> }
> ...
> {code}
> When IoSession.close(boolean) is called, the above Connector thread cancels the SelectionKey associated with the session, which reduces the number of handles from 1 to 0. Immediately afterwards, the thread stops executing because there are no handles and nothing in the connetQueue, however, the previously cancelled key is still in the Selector because its cancelledKeys Set is not processed until the next call to select(int)
> Calling dispose on the IoConnector restarts the Connector thread, which calls Selector.select(int), at which time, the Selector cleans out its canclledKeys.
> Creating a new connection causes the same thing to happen, because the new session also recreates the AbstractPollingIoConnector.Connector thread, as there is a new handle to be processed.
--
This message is automatically generated by JIRA.
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] [Updated] (DIRMINA-827) NioSocketConnector leaks the last
open NioSocketSession after close
Posted by "Matt Yates (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/DIRMINA-827?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Matt Yates updated DIRMINA-827:
-------------------------------
Attachment: MinaMain-2011-04-10.hprof
> NioSocketConnector leaks the last open NioSocketSession after close
> -------------------------------------------------------------------
>
> Key: DIRMINA-827
> URL: https://issues.apache.org/jira/browse/DIRMINA-827
> Project: MINA
> Issue Type: Bug
> Components: Core
> Affects Versions: 2.0.2
> Environment: Windows 7/Solaris SPARC/Solaris x86
> Java versions 6u18 & 6u24
> Reporter: Matt Yates
> Priority: Critical
> Labels: connector, mina, session
> Attachments: MinaMain-2011-04-10.hprof
>
>
> My company's program uses MINA to make multiple (usually) simultaneous connections to various other machines, while reusing the same NioSocketConnector for each new connection. For better or worse, we store various objects in the IoSession's attributes, which we expect to get released on close. This is not always the case, however, as said session remains in memory until either a new connection is made or the IoConnector is disposed. After writing the simplest Connector program I could (I have several servers available on my network, so I did not write a matching Acceptor), and performing some profiling and debugging, I was able to confirm the leak and identify the issue.
> Below is my Connector test program
> {code}
> public class MinaMain {
> private static final Logger LOGGER = LoggerFactory.getLogger(MinaMain.class);
> public static void main(String[] args) throws InterruptedException {
> LOGGER.trace("Waiting for YourKit to start");
> Thread.sleep(15000);
> NioSocketConnector connector = new NioSocketConnector();
> connector.setHandler(new IoHandlerAdapter());
> closeSession(getConnectedSession(connector));
> // LOGGER.info("Creating and closing 5 sessions in series");
> //
> // for (int x = 0; x < 5; x++) {
> // IoSession session = getConnectedSession(connector);
> //
> // if (session == null) {
> // continue;
> // }
> //
> // closeSession(session);
> // }
> //
> // LOGGER.info("Creating 5 sessions and then closing 5 sessions");
> // IoSession[] sessions = new IoSession[5];
> //
> // for (int x = 0; x < 5; x++) {
> // sessions[x] = getConnectedSession(connector);
> // }
> //
> // for (int x = 0; x < 5; x++) {
> // IoSession session = sessions[x];
> //
> // if (session != null) {
> // closeSession(session);
> // sessions[x] = null;
> // }
> // }
> LOGGER.info("Test complete. Sleeping for 60s");
> Thread.sleep(60000);
> }
> private static IoSession getConnectedSession(IoConnector connector) throws InterruptedException {
> IoSession session = null;
> try {
> ConnectFuture future = connector.connect(new InetSocketAddress("134.64.37.183", 11109));
> future.addListener(new IoFutureListener<ConnectFuture>() {
> @Override
> public void operationComplete(ConnectFuture future) {
> LOGGER.debug("Connection completed callback for session " + future.getSession().getId());
> }
> });
> future.awaitUninterruptibly();
> LOGGER.debug("Connection created for session " + future.getSession().getId());
> session = future.getSession();
> Thread.sleep(15000);
> }
> catch (Exception e) {
> LOGGER.error("Failed to connect", e);
> }
> return session;
> }
> private static void closeSession(IoSession session) throws InterruptedException {
> try {
> CloseFuture closeFuture = session.getCloseFuture();
> closeFuture.addListener(new IoFutureListener<CloseFuture>() {
> @Override
> public void operationComplete(CloseFuture future) {
> LOGGER.debug("Session closed callback for session " + future.getSession().getId());
> }
> });
> LOGGER.debug("Attempting to close session " + session.getId());
> session.close(false);
> LOGGER.debug("IoSession.close(false) returned. Awaiting uninterruptibily for session " + session.getId());
> closeFuture.awaitUninterruptibly();
> LOGGER.debug("Close completed for session " + session.getId());
> }
> catch (Exception e) {
> LOGGER.error("Failed to close session " + session.getId());
> session.close(true);
> }
> Thread.sleep(15000);
> }
> }
> Attached is the hprof file of my program, taken after the program has run (during the 60 second sleep at the end) and a screen shot of the GC Root of the leaked NioSocketSession.
> After a couple days of debugging, I've identified why this is happening. Below is a snippet from the AbstractPollingIoConnector.Connector thread
> private class Connector implements Runnable {
> public void run() {
> int nHandles = 0;
> while (selectable) {
> try {
> // the timeout for select shall be smaller of the connect
> // timeout or 1 second...
> int timeout = (int)Math.min(getConnectTimeoutMillis(), 1000L);
> int selected = select(timeout);
> nHandles += registerNew();
> if (selected > 0) {
> nHandles -= processConnections(selectedHandles());
> }
> processTimedOutSessions(allHandles());
> nHandles -= cancelKeys();
> if (nHandles == 0) {
> synchronized (lock) {
> if (connectQueue.isEmpty()) {
> connector = null;
> break;
> }
> }
> }
> }
> ...
> When IoSession.close(boolean) is called, the above Connector thread cancels the SelectionKey associated with the session, which reduces the number of handles from 1 to 0. Immediately afterwards, the thread stops executing because there are no handles and nothing in the connetQueue, however, the previously cancelled key is still in the Selector because its cancelledKeys Set is not processed until the next call to select(int)
> Calling dispose on the IoConnector restarts the Connector thread, which calls Selector.select(int), at which time, the Selector cleans out its canclledKeys.
> Creating a new connection causes the same thing to happen, because the new session also recreates the AbstractPollingIoConnector.Connector thread, as there is a new handle to be processed.
--
This message is automatically generated by JIRA.
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] [Updated] (DIRMINA-827) NioSocketConnector leaks the last
open NioSocketSession after close
Posted by "Emmanuel Lecharny (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/DIRMINA-827?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Emmanuel Lecharny updated DIRMINA-827:
--------------------------------------
Fix Version/s: 2.0.3
> NioSocketConnector leaks the last open NioSocketSession after close
> -------------------------------------------------------------------
>
> Key: DIRMINA-827
> URL: https://issues.apache.org/jira/browse/DIRMINA-827
> Project: MINA
> Issue Type: Bug
> Components: Core
> Affects Versions: 2.0.2
> Environment: Windows 7/Solaris SPARC/Solaris x86
> Java versions 6u18 & 6u24
> Reporter: Matt Yates
> Assignee: Emmanuel Lecharny
> Priority: Critical
> Labels: connector, mina, session
> Fix For: 2.0.3
>
> Attachments: IoConnectorWithCleanSelector.jpg, MinaMain-2011-04-10.hprof, mina-core-2.0.4-SNAPSHOT.jar, mina-core-2.0.4-SNAPSHOT.jar, sessionGcRoot.jpg
>
>
> My company's program uses MINA to make multiple (usually) simultaneous connections to various other machines, while reusing the same NioSocketConnector for each new connection. For better or worse, we store various objects in the IoSession's attributes, which we expect to get released on close. This is not always the case, however, as said session remains in memory until either a new connection is made or the IoConnector is disposed. After writing the simplest Connector program I could (I have several servers available on my network, so I did not write a matching Acceptor), and performing some profiling and debugging, I was able to confirm the leak and identify the issue.
> Below is my Connector test program
> {code}
> public class MinaMain {
> private static final Logger LOGGER = LoggerFactory.getLogger(MinaMain.class);
> public static void main(String[] args) throws InterruptedException {
> LOGGER.trace("Waiting for YourKit to start");
> Thread.sleep(15000);
> NioSocketConnector connector = new NioSocketConnector();
> connector.setHandler(new IoHandlerAdapter());
> closeSession(getConnectedSession(connector));
> // LOGGER.info("Creating and closing 5 sessions in series");
> //
> // for (int x = 0; x < 5; x++) {
> // IoSession session = getConnectedSession(connector);
> //
> // if (session == null) {
> // continue;
> // }
> //
> // closeSession(session);
> // }
> //
> // LOGGER.info("Creating 5 sessions and then closing 5 sessions");
> // IoSession[] sessions = new IoSession[5];
> //
> // for (int x = 0; x < 5; x++) {
> // sessions[x] = getConnectedSession(connector);
> // }
> //
> // for (int x = 0; x < 5; x++) {
> // IoSession session = sessions[x];
> //
> // if (session != null) {
> // closeSession(session);
> // sessions[x] = null;
> // }
> // }
> LOGGER.info("Test complete. Sleeping for 60s");
> Thread.sleep(60000);
> }
> private static IoSession getConnectedSession(IoConnector connector) throws InterruptedException {
> IoSession session = null;
> try {
> ConnectFuture future = connector.connect(new InetSocketAddress("134.64.37.183", 11109));
> future.addListener(new IoFutureListener<ConnectFuture>() {
> @Override
> public void operationComplete(ConnectFuture future) {
> LOGGER.debug("Connection completed callback for session " + future.getSession().getId());
> }
> });
> future.awaitUninterruptibly();
> LOGGER.debug("Connection created for session " + future.getSession().getId());
> session = future.getSession();
> Thread.sleep(15000);
> }
> catch (Exception e) {
> LOGGER.error("Failed to connect", e);
> }
> return session;
> }
> private static void closeSession(IoSession session) throws InterruptedException {
> try {
> CloseFuture closeFuture = session.getCloseFuture();
> closeFuture.addListener(new IoFutureListener<CloseFuture>() {
> @Override
> public void operationComplete(CloseFuture future) {
> LOGGER.debug("Session closed callback for session " + future.getSession().getId());
> }
> });
> LOGGER.debug("Attempting to close session " + session.getId());
> session.close(false);
> LOGGER.debug("IoSession.close(false) returned. Awaiting uninterruptibily for session " + session.getId());
> closeFuture.awaitUninterruptibly();
> LOGGER.debug("Close completed for session " + session.getId());
> }
> catch (Exception e) {
> LOGGER.error("Failed to close session " + session.getId());
> session.close(true);
> }
> Thread.sleep(15000);
> }
> }
> {code}
> Attached is the hprof file of my program, taken after the program has run (during the 60 second sleep at the end) and a screen shot of the GC Root of the leaked NioSocketSession.
> After a couple days of debugging, I've identified why this is happening. Below is a snippet from the AbstractPollingIoConnector.Connector thread
> {code}
> private class Connector implements Runnable {
> public void run() {
> int nHandles = 0;
> while (selectable) {
> try {
> // the timeout for select shall be smaller of the connect
> // timeout or 1 second...
> int timeout = (int)Math.min(getConnectTimeoutMillis(), 1000L);
> int selected = select(timeout);
> nHandles += registerNew();
> if (selected > 0) {
> nHandles -= processConnections(selectedHandles());
> }
> processTimedOutSessions(allHandles());
> nHandles -= cancelKeys();
> if (nHandles == 0) {
> synchronized (lock) {
> if (connectQueue.isEmpty()) {
> connector = null;
> break;
> }
> }
> }
> }
> ...
> {code}
> When IoSession.close(boolean) is called, the above Connector thread cancels the SelectionKey associated with the session, which reduces the number of handles from 1 to 0. Immediately afterwards, the thread stops executing because there are no handles and nothing in the connetQueue, however, the previously cancelled key is still in the Selector because its cancelledKeys Set is not processed until the next call to select(int)
> Calling dispose on the IoConnector restarts the Connector thread, which calls Selector.select(int), at which time, the Selector cleans out its canclledKeys.
> Creating a new connection causes the same thing to happen, because the new session also recreates the AbstractPollingIoConnector.Connector thread, as there is a new handle to be processed.
--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators: https://issues.apache.org/jira/secure/ContactAdministrators!default.jspa
For more information on JIRA, see: http://www.atlassian.com/software/jira