As you might know, the Sphinx team is focused not only on full-text search improvements like the blended characters support we introduced in 2.0.1-beta, we also care about general performance improvements. One of the performance questions we run into frequently is, “how do you measure a single query’s speed.. especially in a scalable, distributed environment?”

Before 2.0.1-beta you could only see the full-text part of the search queries. Imagine a query like this:

SELECT * FROM lj8tdistr WHERE MATCH('test') AND channel_id = 124660 ORDER BY ts DESC

You would only see the following record in the query log:

[Thu Oct 27 16:51:10.406 2011] 0.015 sec [ext2/1/ext 5 (0,20)] [lj8tdistr] test

It’s good to know that your query is as fast as 15 milliseconds, but with this format, it can be quite difficult to identify the query itself. And, if you happened to use a distributed environment, you had to look across the whole search cluster to find out which node is the slowest. So, needless to say, it was quite a tedious process to analyze query speed.

Things are getting easier with the introduction of the new query log format in 2.0.1-beta called sphinxql.

Just make sure these two lines are in your sphinx config file

query_log_format = sphinxql
query_log = query.log

Then restart the Sphinx daemon. Here is what you should see now:

/* Thu Oct 27 16:58:01.222 2011 conn 1 wall 0.010 found 5 */ SELECT * 
FROM lj8tdistr WHERE MATCH('test') AND channel_id=124660 ORDER BY ts DESC; 
# agents=(0.001, 0.009, 0.008, 0.009, 0.001, 0.001, 0.001, 0.002)

Much easier to understand what’s going on, right?

Same timestamp and wall clock data (query time is slightly less because filesystem cache has warmed up) but now you can see the whole query in SphinxQL format… even for API calls! So it’s a great API-to-SphinxQL convertor too! The query structure is internally reconstructed inside so don’t be surprised if you see a difference between the query log entry and the actual SphinxQL request.

And finally, there is -agent time for distributed requests:

# agents=(0.001, 0.009, 0.008, 0.009, 0.001, 0.001, 0.001, 0.002)

Here we go! This is actually how much time takes for each agent to return all the results including network round-trip time. Agents are listed in exactly the same order as they were defined in the configuration file.

Have fun! We’ll continue our Sphinx performance classes next week, stay tuned! :)

Tags: Sphinx performance

This entry was posted on Thursday, October 27th, 2011 at 18:26 and is filed under performance. You can follow any responses to this entry through the RSS 2.0 feed. You can leave a response, or trackback from your own site.