Mailing-List: contact solr-user-help@lucene.apache.org; run by ezmlm
Precedence: bulk
Reply-To: solr-user@lucene.apache.org
Received-SPF: pass (athena.apache.org: domain of daubman@gmail.com designates
 209.85.215.48 as permitted sender)
MIME-Version: 1.0
In-Reply-To: 
 <CALyTvnqFiUrVMLUayOO_r7Ymq8CdQBQCpq1XmH+jnCbCFSM3OQ@mail.gmail.com>
References: 
 <CALyTvnqFiUrVMLUayOO_r7Ymq8CdQBQCpq1XmH+jnCbCFSM3OQ@mail.gmail.com>
Date: Thu, 6 Sep 2012 22:23:25 -0400
Message-ID: 
 <CALyTvnoLa4SbBjdg7LuM7MMCmKZQjV+pHSPCZ=cPzu_UZxSX2A@mail.gmail.com>
Subject: Re: Solr request/response lifecycle and logging full response time
From: Aaron Daubman <daubman@gmail.com>
To: solr-user@lucene.apache.org
Content-Type: text/plain; charset=ISO-8859-1

I'd still love to see a query lifecycle flowchart, but, in case it
helps any future users or in case this is still incorrect, here's how
I'm tackling this:

1) Override default json responseWriter with my own in solrconfig.xml:
    <queryResponseWriter name="json"
class="com.mydomain.solr.component.JSONResponseWriterWithTiming"/>
2) Define JSONResponseWriterWithTiming as just extending
JSONResponseWriter and adding in a log statement:

public class JSONResponseWriterWithTiming extends JSONResponseWriter {
    private static final Logger logger =
LoggerFactory.getLogger(JSONResponseWriterWithTiming.class);
    @Override
    public void write(Writer writer, SolrQueryRequest req,
SolrQueryResponse rsp) throws IOException {
        super.write(writer, req, rsp);
        if (logger.isInfoEnabled()) {
            final long st = req.getStartTime();
            logger.info(String.format("Total solr time for query with
QTime: %d is: %d", (int) (rsp.getEndTime() - st), (int)
(System.currentTimeMillis() - st)));
        }
    }
}

Please advise if:
- Flowcharts for any solr/lucene-related lifecycles exist
- There is a better way of doing this

Thanks,
      Aaron

On Thu, Sep 6, 2012 at 9:16 PM, Aaron Daubman <daubman@gmail.com> wrote:
> Greetings,
>
> I'm looking to add some additional logging to a solr 3.6.0 setup to
> allow us to determine actual time spent by Solr responding to a
> request.
>
> We have a custom QueryComponent that sometimes returns 1+ MB of data
> and while QTime is always on the order of ~100ms, the response time at
> the client can be longer than a second (as measured with JMeter
> running on the same server using localhost).
>
> The end goal is to be able to:
> 1) determine if this large variance in response time is due to Solr,
> and if so where (to help determine if/how it can be optimized)
> 2) determine if the large variance is due to how jetty handles
> connections, buffering, etc... (and if so, if/how we can optimize
> there)
> ...or some combination of the two.
>
> As it stands now, where the second or so between when the actual query
> finishes as indicated by QTime, when solr gathers all the data to be
> returned as requested by fl, and when the client actually receives the
> data (even when the client is on the localhost) is completely opaque.
>
> My main question:
> - Is there any documentation (a diagram / flowchart would be oh so
> wonderful) on the lifecycle of a Solr request? So far I've attempted
> to modify and rebuild solr, adding logging to SolrCore's execute()
> method (this pretty much mirrors QTime), as well as add timing
> calculations and logging to various different overriden methods in the
> QueryComponent custom extension, all to no avail so far.
>
> What I'm getting at is how to:
> - start a stopwatch when solr receives the request from the client
> - stop the stopwatch and log the elapsed time right before solr hands
> the response body off to Jetty to be delivered back to the client.
>
> Thanks, as always!
>      Aaron