Explanation for dfc.diagnostics.resources.enable

It is bit weird, but everybody who previously asked me about session leaks didn’t properly understand the root cause of the problem – the typical question was: we started getting a lot of DM_API_E_NO_SESSION errors, we increased value of concurrent_sessions parameter in server.ini, but this didn’t help. Well, I have written this blogpost in order to shed a light on session leaks in DFC. First of all, you may face with two following errors:

DfServiceException:: THREAD: main; MSG: [DM_SESSION_E_MAX_SESSIONS_EXCEEDED]
  error:  "Maximum number of server sessions exceeded"; ERRORCODE: 100; NEXT: null
	at com.documentum.fc.client.impl.docbase.DocbaseExceptionMapper.newException(DocbaseExceptionMapper.java:44)
	at com.documentum.fc.client.impl.docbase.DocbaseExceptionMapper.newException(DocbaseExceptionMapper.java:34)
	at com.documentum.fc.client.impl.connection.docbase.netwise.NetwiseDocbaseRpcClient.newSessionByAddr(NetwiseDocbaseRpcClient.java:118)
	at com.documentum.fc.client.impl.connection.docbase.DocbaseConnection.beginSession(DocbaseConnection.java:299)
	at com.documentum.fc.client.impl.connection.docbase.DocbaseConnection.open(DocbaseConnection.java:130)
	at com.documentum.fc.client.impl.connection.docbase.DocbaseConnection.<init>(DocbaseConnection.java:100)
	at com.documentum.fc.client.impl.connection.docbase.DocbaseConnection.<init>(DocbaseConnection.java:60)
	at com.documentum.fc.client.impl.connection.docbase.DocbaseConnectionFactory.newDocbaseConnection(DocbaseConnectionFactory.java:26)
	at com.documentum.fc.client.impl.connection.docbase.DocbaseConnectionManager.createNewConnection(DocbaseConnectionManager.java:180)
	at com.documentum.fc.client.impl.connection.docbase.DocbaseConnectionManager.getDocbaseConnection(DocbaseConnectionManager.java:110)
	at com.documentum.fc.client.impl.session.SessionFactory.newSession(SessionFactory.java:23)
	at com.documentum.fc.client.impl.session.PrincipalAwareSessionFactory.newSession(PrincipalAwareSessionFactory.java:44)
	at com.documentum.fc.client.impl.session.PooledSessionFactory.newSession(PooledSessionFactory.java:49)
	at com.documentum.fc.client.impl.session.SessionManager.getSessionFromFactory(SessionManager.java:134)
	at com.documentum.fc.client.impl.session.SessionManager.newSession(SessionManager.java:72)
	at com.documentum.fc.client.impl.session.SessionManager.getSession(SessionManager.java:191)

and

DfServiceException:: THREAD: main; MSG: [DM_API_E_NO_SESSION]
  error:  "There are no more available sessions."; ERRORCODE: 100; NEXT: null
	at com.documentum.fc.client.impl.connection.docbase.DocbaseConnectionManager.getConnectionFromPool(DocbaseConnectionManager.java:168)
	at com.documentum.fc.client.impl.connection.docbase.DocbaseConnectionManager.getDocbaseConnection(DocbaseConnectionManager.java:94)
	at com.documentum.fc.client.impl.session.SessionFactory.newSession(SessionFactory.java:23)
	at com.documentum.fc.client.impl.session.PrincipalAwareSessionFactory.newSession(PrincipalAwareSessionFactory.java:44)
	at com.documentum.fc.client.impl.session.PooledSessionFactory.newSession(PooledSessionFactory.java:49)
	at com.documentum.fc.client.impl.session.SessionManager.getSessionFromFactory(SessionManager.java:134)
	at com.documentum.fc.client.impl.session.SessionManager.newSession(SessionManager.java:72)
	at com.documentum.fc.client.impl.session.SessionManager.getSession(SessionManager.java:191)

The first one (DM_SESSION_E_MAX_SESSIONS_EXCEEDED) means that you are running out of Content Server sessions (concurrent_sessions parameter in server.ini), the second one (DM_API_E_NO_SESSION) means that you are running out of DFC sessions (dfc.session.max_count parameter in dfc.propetries), the problem is both errors may relate to either incorrect sizing or programming mistake. So, before trying to investigate memory leaks you need to eliminate sizing issue – it is might be bit challenging because dumb DFC does not provide any runtime statistics about sessions (recent DFC versions support dfc.connection.profile_connections and dfc.connection.trace_connections_only flags in dfc.properties, these flags cause com.documentum.fc.client.impl.connection.docbase.DocbaseConnectionManager class to write extra debug information into log files, but I would prefer something more reliable, JMX for example), so, let’s pretend that sizing issue is not our case. What is the next?

Official documentation (DFC Development Guide) states following:

and there are at least two mistakes:

  1. it also logs information about leaks of stream objects, which were created through ISysObjectInternal#getStream method, corresponding log message looks like:
    [Resource Housekeeper] ERROR com.documentum.fc.impl.util.io.InputStreamHandle$DisposableData  - [DFC_STREAM_NOT_CLOSED] Unclosed stream found during garbage collection, com.documentum.fc.client.content.impl.PullerInputStream@28aac04e.
    com.documentum.fc.impl.util.ThrowableStack: Stack when stream was created
    	at com.documentum.fc.client.content.impl.ContentInputStream.<init>(ContentInputStream.java:17)
    	at com.documentum.fc.client.content.impl.PusherPullerContentAccessor.buildStreamFromContext(PusherPullerContentAccessor.java:46)
    	at com.documentum.fc.client.content.impl.PusherPullerContentAccessor.getStream(PusherPullerContentAccessor.java:28)
    	at com.documentum.fc.client.content.impl.ContentAccessorFactory.getStream(ContentAccessorFactory.java:37)
    	at com.documentum.fc.client.content.impl.Store.getStream(Store.java:63)
    	at com.documentum.fc.client.content.impl.FileStore___PROXY.getStream(FileStore___PROXY.java)
    	at com.documentum.fc.client.content.impl.Content.getStream(Content.java:185)
    	at com.documentum.fc.client.content.impl.Content___PROXY.getStream(Content___PROXY.java)
    	at com.documentum.fc.client.content.impl.ContentManager.getStream(ContentManager.java:84)
    	at com.documentum.fc.client.content.impl.ContentManager.getStream(ContentManager.java:53)
    	at com.documentum.fc.client.DfSysObject.getStream(DfSysObject.java:1994)
  2. the last statement is incorrect, correct is: if DFC wasn’t buggy it would place an appropriate message in the log

So, what does happen when we enable dfc.diagnostics.resources.enable? The short answer is: if your code suffers from leaks of transaction sessions DFC replaces them by a memory leak 🙂

Now the long answer. DFC manages following types of sessions:

  • com.documentum.fc.client.impl.session.Session
  • com.documentum.fc.client.impl.session.WeakSessionHandle
  • com.documentum.fc.client.impl.session.StrongSessionHandle
  • com.documentum.fc.client.impl.session.DynamicSessionHandle

the first one is the real/original session, last three are decorators. We typically deal with StrongSessionHandle (IDfSessionManager#getSession) and DynamicSessionHandle (IDfTypedObject#getSession):

@Test
public void test() throws Exception {
    IDfClientX clientX = new DfClientX();
    IDfClient client = clientX.getLocalClient();
    IDfSessionManager sessionManager = client.newSessionManager();
    IDfLoginInfo loginInfo = clientX.getLoginInfo();
    loginInfo.setUser("dmadmin");
    loginInfo.setPassword("dmadmin");
    sessionManager.setIdentity("DCTM_DEV", loginInfo);
    IDfSession session = sessionManager.getSession("DCTM_DEV");
    System.out.println("session managers return "
            + session.getClass().getName());
    IDfSysObject object = (IDfSysObject) session
            .getObjectByQualification("dm_document");
    System.out.println("typed objects store "
            + object.getSession().getClass().getName());
    sessionManager.release(session);
    sessionManager.flushSessions();
    System.out.println("we may use dynamic session handles "
            + "even if original session was released");
    object.getString("object_name");
    object.save();
    System.out.println("we may not use strong session handles "
            + "if it was released");
    object = (IDfSysObject) session.getObjectByQualification("dm_document");
}

session managers return com.documentum.fc.client.impl.session.StrongSessionHandle
typed objects store com.documentum.fc.client.impl.session.DynamicSessionHandle
we may use dynamic session handles even if original session was released
we may not use strong session handles if it was released

com.documentum.fc.common.DfRuntimeException: Using session handle that has already been released

	at com.documentum.fc.client.impl.session.StrongSessionHandle.referenceSession(StrongSessionHandle.java:64)
	at com.documentum.fc.client.impl.session.SessionHandle.referenceScopableSession(SessionHandle.java:74)
	at com.documentum.fc.client.impl.session.SessionHandle.getObjectByQualification(SessionHandle.java:752)

And when we enable dfc.diagnostics.resources.enable DFC starts keeping track of StrongSessionHandle instances, i.e. if instance of StrongSessionHandle class wasn’t properly released DFC logs corresponding error. How would you implement such functionality? Actually the implementation is pretty straightforward – we need to know circumstances under which our object was constructed, in order to do that we save construction stack into object and log that stack in finalize() method, something like:

public class FinalizationDemo {

    private final boolean _diagnosticsEnabled = true;

    @Test
    public void test() throws Exception {
        try {
            while (true) {
                IResource resource = getResource();
            }
        } catch (OutOfMemoryError error) {
            error.printStackTrace();
            System.exit(1);
        }
    }

    private IResource getResource() {
        return new Resource();
    }

    interface IResource extends Closeable {

        boolean isClosed();

    }

    class Resource implements IResource {

        private boolean _closed;

        private Throwable _construction;

        private final byte[] data = new byte[1000 * 100];

        public Resource() {
            if (_diagnosticsEnabled) {
                _construction = new Exception();
            }
        }

        @Override
        public void close() throws IOException {
            System.out.println("Closed");
            _closed = true;
            _construction = null;
        }

        @Override
        public boolean isClosed() {
            return _closed;
        }

        @Override
        protected void finalize() throws Throwable {
            if (_construction != null && !isClosed()) {
                _construction.printStackTrace();
            }
        }
    }

}

ECD’s implementation is different – instead of using finalizers they use weak references, moreover before logging error message they try to cleanup resources (such behaviour suffers from side effects described in previous post) and their code looks like:

public class DisposableDemo {

    private final ReferenceQueue<WeakReference> _queue = new ReferenceQueue<>();
    private final Map<Reference, IDisposable> _data = Collections
            .synchronizedMap(new IdentityHashMap<Reference, IDisposable>());

    private final boolean _diagnosticsEnabled = true;

    public DisposableDemo() {
        Thread thread = new Thread(new DisposingTask());
        thread.setPriority(Thread.MAX_PRIORITY);
        thread.start();
    }

    class DisposingTask implements Runnable {
        @Override
        public void run() {
            try {
                Reference reference;
                while ((reference = _queue.remove()) != null) {
                    IDisposable disposable = _data.remove(reference);
                    if (disposable == null) {
                        continue;
                    }
                    try {
                        disposable.dispose();
                    } catch (IOException ex) {
                        ex.printStackTrace();
                    }
                }
            } catch (InterruptedException ex) {
                Thread.currentThread().interrupt();
            }
        }
    }

    private void register(Object resource, IDisposable disposable) {
        WeakReference reference = new WeakReference(resource, _queue);
        _data.put(reference, disposable);
    }

    @Test
    public void test() throws Exception {
        try {
            while (true) {
                IResource resource = getResource();
                // System.gc();
            }
        } catch (OutOfMemoryError error) {
            error.printStackTrace();
            System.exit(1);
        }
    }

    private IResource getResource() {
        IResource resource = new Resource();
        ResourceDecorator decorator = new ResourceDecorator(resource);
        if (_diagnosticsEnabled) {
            register(decorator, decorator._disposable);
        }
        return decorator;
    }

    interface IDisposable {

        void dispose() throws IOException;

    }

    interface IResource extends Closeable {

        boolean isClosed();

    }

    class Resource implements IResource {

        private boolean _closed;

        private final byte[] data = new byte[1000 * 100];

        @Override
        public void close() throws IOException {
            System.out.println("Closed");
            _closed = true;
        }

        @Override
        public boolean isClosed() {
            return _closed;
        }

    }

    class ResourceDecorator implements IResource {

        private final IResource _resource;

        private final IDisposable _disposable;

        public ResourceDecorator(IResource resource) {
            _resource = resource;
            if (_diagnosticsEnabled) {
                _disposable = new Disposable(_resource);
            } else {
                _disposable = null;
            }
        }

        @Override
        public void close() throws IOException {
            _resource.close();
        }

        @Override
        public boolean isClosed() {
            return _resource.isClosed();
        }
    }

    // !!! must not refer to ResourceDecorator
    static class Disposable implements IDisposable {

        private IResource _resource;

        private final Throwable _construction;

        public Disposable(IResource resource) {
            _resource = resource;
            _construction = new Exception();
        }

        @Override
        public void dispose() throws IOException {
            if (!_resource.isClosed()) {
                // closing resource
                _resource.close();
                // log construction stacktrace
                _construction.printStackTrace();
            }
        }

    }

}

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s