mina-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Matt Yates (JIRA)" <j...@apache.org>
Subject [jira] [Updated] (DIRMINA-827) NioSocketConnector leaks the last open NioSocketSession after close
Date Sun, 10 Apr 2011 17:00:06 GMT

     [ 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

Mime
View raw message