directory-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Norval Hope (JIRA)" <j...@apache.org>
Subject [jira] Commented: (DIRSERVER-1161) search results are not streamed to the client until final done response is queued
Date Fri, 11 Apr 2008 05:00:05 GMT

    [ https://issues.apache.org/jira/browse/DIRSERVER-1161?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=12587843#action_12587843
] 

Norval Hope commented on DIRSERVER-1161:
----------------------------------------

I should reiterate if it isn't clear - that the 1.0 and 1.5 patch attachments for this issue
add some extra debug log output to two classes only, the software is vanilla 1.0 and 5.1.

Here a dump of the stack when I stop at a breakpoint in SearchHandler as it does a session.write()
on the first search result and I now see exactly why the problem occurs:

-------------------------
UberjarMain [Java Application]   
    org.apache.directory.server.UberjarMain at localhost:1066   
        Thread [SocketAcceptor-0] (Running)   
        Thread [DestroyJavaVM] (Running)   
        Thread [SynchWorkerThread] (Running)   
        Thread [SocketAcceptorIoProcessor-0.0] (Running)   
        Thread [pool-2-thread-1] (Running)   
        Thread [pool-2-thread-2] (Running)   
        Thread [pool-2-thread-3] (Running)   
        Thread [pool-2-thread-4] (Suspended (breakpoint at line 393 in SearchHandler))   
            SearchHandler.messageReceived(IoSession, Object) line: 393   
            LdapProtocolProvider$LdapProtocolHandler(DemuxingIoHandler).messageReceived(IoSession,
Object) line: 141   
            LdapProtocolProvider$LdapProtocolHandler.messageReceived(IoSession, Object) line:
428   
            AbstractIoFilterChain$TailFilter.messageReceived(IoFilter$NextFilter, IoSession,
Object) line: 570   
            SocketFilterChain(AbstractIoFilterChain).callNextMessageReceived(IoFilterChain$Entry,
IoSession, Object) line: 299   
            AbstractIoFilterChain.access$5(AbstractIoFilterChain, IoFilterChain$Entry, IoSession,
Object) line: 296   
            AbstractIoFilterChain$EntryImpl$1.messageReceived(IoSession, Object) line: 648
  
            SimpleProtocolDecoderOutput.flush() line: 58   
            ProtocolCodecFilter.messageReceived(IoFilter$NextFilter, IoSession, Object) line:
180   
            SocketFilterChain(AbstractIoFilterChain).callNextMessageReceived(IoFilterChain$Entry,
IoSession, Object) line: 299   
            AbstractIoFilterChain.access$5(AbstractIoFilterChain, IoFilterChain$Entry, IoSession,
Object) line: 296   
            AbstractIoFilterChain$EntryImpl$1.messageReceived(IoSession, Object) line: 648
  
            ExecutorFilter.processEvent(IoFilter$NextFilter, IoSession, ExecutorFilter$EventType,
Object) line: 228   
            ExecutorFilter$ProcessEventsRunnable.run() line: 280   
            ThreadPoolExecutor$Worker.runTask(Runnable) line: 650   
            ThreadPoolExecutor$Worker.run() line: 675   
            Thread.run() line: 595   
    C:\jdk1.5.0_11\bin\javaw.exe (11/04/2008 1:56:36 PM)   

------------------------------

The problem is that SearchHandler is called via

      AbstractIoFilterChain$EntryImpl$1.messageReceived(IoSession, Object) line: 648

and after submitting the search to the underlying framework, it synchronously steps through
all of the the results submitting session.write()s for each one. However, none of the queued
events are flushed to the JNDI client until SearchHandler has completely drained the SearchResponseIterator
over the results of the search and exited, at which point the stack unwinds back to

     ExecutorFilter$ProcessEventsRunnable.run() line: 280

which results in the outputting of a log message like this:

    2008-04-11 14:49:06,984 3130859 [pool-2-thread-6] (org.apache.mina.filter.executor.ExecutorFilter$ProcessEventsRunnable:276)
DEBUG  - About to process event for /127.0.0.1:1090 size of queue is currently=1973

and then all the queued output SENT messages actually get flushed out to the JNDI client via
this call:

    processEvent(event.getNextFilter(), buffer.session, event
                        .getType(), event.getData());

So my immediate thought is to change SearchHandler so that it spawns a thread to take care
of iterating through the search results asynchronously and then returns immediately. With
some luck this will result in the desired streaming behaviour, but of course I don't know
the relevant bits of the code well enough to know if this approach is too simplistic and will
violate any implicit or explicit assumptions in the ApacheDS / MINA architecures. I'm going
to try it out anyway ...


> search results are not streamed to the client until final done response is queued
> ---------------------------------------------------------------------------------
>
>                 Key: DIRSERVER-1161
>                 URL: https://issues.apache.org/jira/browse/DIRSERVER-1161
>             Project: Directory ApacheDS
>          Issue Type: Bug
>          Components: core
>    Affects Versions: 1.0
>         Environment: JDK 1.5.0_11 
>            Reporter: Norval Hope
>         Attachments: apacheds_1.5.1_streaming.patch, apacheds_1.5.1_streaming_log_output.txt,
installers_1.5.1_streaming.patch, mina_1.1.2_streaming.patch, pom.xml, streaming_log_output.txt,
streaming_logging.patch
>
>   Original Estimate: 120h
>  Remaining Estimate: 120h
>
> Search results accumulate in Events on the SessionBuffer.eventQueue within ExecutorFilter.fireEvent()
until final done response for the search is written to the session and then all results for
the search (possibly millions depending on the search and state of the directory) are written
out at once. This is a big problem for scalability and I gather from previous correspondence
with Alex that this behaviour is unexpected.

-- 
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.


Mime
View raw message