[Xapian-discuss] Search performance issues and profiling/debugging
ron at pidgintech.com
Wed Oct 24 03:04:07 BST 2007
Hi Richard & Olly.
Yes, the database is NOT being reopened. The databases are accessed
locally, not over the net. No data is being added to the databases while
testing the searches.
Indeed I found the estimates to be strange. Wasn't sure why, but was
more concerned with performance and the fact that things were not
I don't know anything yet about oprofile, will have to dig deeper there.
(any pinpoints would be handy)
What was not clear from your answers is if it makes sense that second
(and third) time searches take that long. Also, we are getting 15+ and
sometimes 50+ seconds searches on some simple (non phrased) search terms
(like: [map of the world] [Time: 15.703 sec] [Results: 25 of 1355];
[Time: 10.004 sec] [Results: 25 of 1230]; [Results: 25 of 1117]; and
there are ones that take even more time)
I'm attaching few link to outputs of more details debugs.
First I ran a test on all 8 databases (1, 2, 4, 6, 7, 8, 9 and 10)
This resulted in Segmentation fault.
Then I removed database 10 and reran.
This ran successfully. However, Estimates varied: , , 
And overall times were quite long, both for original search and for
sequential searches: [Total Time: 0.96 sec], [Total Time: 0.96 sec],
[Total Time: 0.941 sec]
Then I ran it on each of the databases separately. Note that by this
time it is likely (or at least I though it should be) that the blocks
are cached in memory from the previous test (of 1,2,4,6,7,8 and 9).
Summary for DB #1: Estimates fixed on ; Times did not speed up for
sequential searches: [Total Time: 0.187 sec], [Total Time: 0.183 sec],
[Total Time: 0.199 sec]
Summary for DB #2: Estimates fixed on ; Times became faster,
although first time is extremely long considering the single DB and its
size: [Total Time: 0.891 sec], [Total Time: 0.082 sec], [Total Time:
Summary for DB #4: Estimates fixed on  ; Times became faster,
although first time is extremely long, and the others are still long
(>0.2sec) considering the single DB: [Total Time: 1.18 sec], [Total
Time: 0.215 sec], [Total Time: 0.212 sec]
Summary for DB #6: Estimates varied , , ; Times were
extremely long in the first two searches, and even in the last one,
still long (>0.2sec): [Total Time: 1.961 sec], [Total Time: 4.299 sec],
[Total Time: 0.204 sec]
Summary for DB #7: Estimates varied , ,  ; Times
varied and were relatively long overall: [Total Time: 0.81 sec], [Total
Time: 0.429 sec], [Total Time: 0.779 sec]
Summary for DB #8: Estimates varied , ,  ; Times varied
and were relatively long for the first 2 tries: [Total Time: 0.431 sec],
[Total Time: 1.077 sec], [Total Time: 0.063 sec]
Summary for DB #9: Estimates fixed on  ; Times became faster,
although first time is extremely long, and the others are still long
(>0.2sec): [Total Time: 3.137 sec], [Total Time: 0.222 sec], [Total
Time: 0.212 sec]
Now I tied #10 (the one who, when added to a group with add_database,
causes seg fault), just in case.. and, on its own, it worked.
Summary for DB #10: Estimates fixed on  ; Times were overall fast:
[Total Time: 0.108 sec], [Total Time: 0.072 sec], [Total Time: 0.075 sec]
The following output is output of delve on the 8 databases, including
delve on the specific terms (no, recip) to try to figure out why we are
getting segmentation fault when database 10 is combined with the others.
Note that it manages to run through the delve. I wonder where the
segmentation fault is coming from. It happens during the get of the MSET
[root at fts1 maintenance]# delve /fts/Database_1/
number of documents = 20810000
average document length = 204.054
[root at fts1 maintenance]# delve /fts/Database_2/
number of documents = 6020000
average document length = 203.334
[root at fts1 maintenance]# delve /fts/Database_4/
number of documents = 22365000
average document length = 204.573
[root at fts1 maintenance]# delve /fts/Database_6/
number of documents = 21875000
average document length = 204.567
[root at fts1 maintenance]# delve /fts/Database_7/
number of documents = 24480000
average document length = 205.822
[root at fts1 maintenance]# delve /fts/Database_8/
number of documents = 3870000
average document length = 209.001
[root at fts1 maintenance]# delve /fts/Database_9/
number of documents = 23870000
average document length = 205.659
[root at fts1 maintenance]# delve /fts/Database_10/
number of documents = 5325000
average document length = 202.337
[root at fts1 maintenance]# delve /fts/Database_10/ -1 -t Zno | tail -n 5
[root at fts1 maintenance]# delve /fts/Database_10/ -1 -t Zrecip | tail
We have used a very minimal code, stripped of all the "other stuff" we
had in it before. Its simply openning the DB once, executing the search
and timing things.
This is very strange (and frustrating).. I hope I gave enough details.
If not, please let me know.
Since in some cases, on the nodes that show variance in estimates, two
searches show the same estimate while the other is different, it can be
that this variance is on all the nodes if tried enough times.
I think, that speed is overall very poor, especially for sequential
searches, considering it should all be in OS cache.
Last notes.. Olly..
1. Regarding your stable-sort, theory, if its something we can test, let
me know how.
2. What undefined value might anything depend on?
3. I don't know the testsuite and valgrind and what you refer to
regarding that.. I'll have a look into that and into oprofile. If you
have any pinpoints, that would help.
Looking forward to your thoughts..
Richard Boulton wrote:
> Ron Kass wrote:
>> * Estimates vary, although its exactly the same search done right one
>> after the other with no changes to the DB (no data added). This is
>> not really a big issue.
> This is the issue which looks oddest to me, however (though there are
> other oddities). If I understood you correctly, each search is
> performed on the same Database object, without reopening the Database
> object between each search. This should result in exactly the same
> results (and estimates) for each repeated search, since a Database
> object accesses a snapshot of the underlying database. Since this
> isn't happening, there must be something we don't understand about
> your setup, and this is the first thing to resolve.
> Are you using the network (ie, "remote") backend? If so, the problem
> could be that some of the database connections are timing out
> Is the database mounted locally, or over a network filing system?
> If the database isn't being modified while searches are in progress,
> and/or Database objects aren't being reopened between searches,
> something very weird is happening. Try doing the search on just a
> single database, and see if you get the same effects. If not, add in
> databases gradually until you do.
> Other than that, it would be useful to separate timings for the search
> (ie, the get_mset() call) from the calls which fetch the document
> data, to see where most of the time is being spent.
> > 4. Anyone has ideas how we can profile things to see why we have such
> > performance issues? We would be happy to dig deeper to find out where
> > the problems arise from.
> oprofile is your best bet for seeing where the time is being spent.
Olly Betts wrote:
> On Tue, Oct 23, 2007 at 10:25:47PM +0100, Richard Boulton wrote:
>> Ron Kass wrote:
>>> * Estimates vary, although its exactly the same search done right one
>>> after the other with no changes to the DB (no data added). This is not
>>> really a big issue.
>> This is the issue which looks oddest to me, however (though there are
>> other oddities).
> It would be interesting to work out why this is happening. I suspect
> doing so will also reveal why the timings vary.
>> If I understood you correctly, each search is
>> performed on the same Database object, without reopening the Database
>> object between each search. This should result in exactly the same
>> results (and estimates) for each repeated search, since a Database
>> object accesses a snapshot of the underlying database.
> I have a theory. We sort containers of postlists when building the
> postlist tree from the query. If we don't always use a stable sort,
> then the exact tree built may vary between runs, which I think could
> easily affect both the estimated number of matches and also how much
> work the query requires (and so how long it takes).
> If this is happening, we should see if using a stable sort for such
> cases imposes any overhead. I suspect it wouldn't since this is a
> one-off cost per query, and we're sorting a small number of items
> (at most the number of terms in the query).
> Another possibility is that there's some dependence on an undefined
> value. The testsuite is clean under valgrind, but I'm sure there's
> code which doesn't have testsuite coverage.
> Ron: assuming this is on Linux, if you run a few of these varying cases
> under valgrind, does it report any problems?
More information about the Xapian-discuss