Oct 27, 2011. Sphinx performance – know your queries time

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! :)


« »

7 Responses to “Sphinx performance – know your queries time”

  1. Cool staff! Thank you!

  2. Hi. Thanks for the feature. Are things like [ios=4 kb=0.2 ioms=23.3 cpums=3.7] supported in the new log format?

  3. oleg says:

    It’s very good and usefull! Thanx^^)
    Can i use this feature in SphSQL “SHOW META”?

  4. vlad says:

    Oleg, apparently not. But it’s might be a good idea to have remote agent times in the SHOW META output. I’ll talk to Andrew about this, thanks!

  5. vlad says:

    Sergey, yes, extended statistics are available as well, I’ll blog on that too, thanks for asking!

  6. If you used the same format as MySQL’s slow query log, then pt-query-digest would Just Work as a log aggregator. This would be very beneficial, because it’s a great tool with a lot of time invested into it.

    Or you could write a module that understands the Sphinx log format, with unit tests, and contribute it… your choice :-)

  7. Vlad says:

    Baron, query-digest is just brilliant thing and I’m looking forward to add Sphinx support there. But it’s always about the time.

Leave a Reply