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 <daub...@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
