Re: GIN improvements part2: fast scan

On Mon, Jan 27, 2014 at 2:32 PM, Alexander Korotkov <aekorotkov(at)gmail(dot)com>wrote:

> On Sun, Jan 26, 2014 at 8:14 PM, Heikki Linnakangas <
> hlinnakangas(at)vmware(dot)com> wrote:
>
>> On 01/26/2014 08:24 AM, Tomas Vondra wrote:
>>
>>> Hi!
>>>
>>> On 25.1.2014 22:21, Heikki Linnakangas wrote:
>>>
>>>> Attached is a new version of the patch set, with those bugs fixed.
>>>>
>>>
>>> I've done a bunch of tests with all the 4 patches applied, and it seems
>>> to work now. I've done tests with various conditions (AND/OR, number of
>>> words, number of conditions) and I so far I did not get any crashes,
>>> infinite loops or anything like that.
>>>
>>> I've also compared the results to 9.3 - by dumping the database and
>>> running the same set of queries on both machines, and indeed I got 100%
>>> match.
>>>
>>> I also did some performance tests, and that's when I started to worry.
>>>
>>> For example, I generated and ran 1000 queries that look like this:
>>>
>>> SELECT id FROM messages
>>> WHERE body_tsvector @@ to_tsquery('english','(header & 53 & 32 &
>>> useful & dropped)')
>>> ORDER BY ts_rank(body_tsvector, to_tsquery('english','(header & 53 &
>>> 32 & useful & dropped)')) DESC;
>>>
>>> i.e. in this case the query always was 5 words connected by AND. This
>>> query is a pretty common pattern for fulltext search - sort by a list of
>>> words and give me the best ranked results.
>>>
>>> On 9.3, the script was running for ~23 seconds, on patched HEAD it was
>>> ~40. It's perfectly reproducible, I've repeated the test several times
>>> with exactly the same results. The test is CPU bound, there's no I/O
>>> activity at all. I got the same results with more queries (~100k).
>>>
>>> Attached is a simple chart with x-axis used for durations measured on
>>> 9.3.2, y-axis used for durations measured on patched HEAD. It's obvious
>>> a vast majority of queries is up to 2x slower - that's pretty obvious
>>> from the chart.
>>>
>>> Only about 50 queries are faster on HEAD, and >700 queries are more than
>>> 50% slower on HEAD (i.e. if the query took 100ms on 9.3, it takes >150ms
>>> on HEAD).
>>>
>>> Typically, the EXPLAIN ANALYZE looks something like this (on 9.3):
>>>
>>> http://explain.depesz.com/s/5tv
>>>
>>> and on HEAD (same query):
>>>
>>> http://explain.depesz.com/s/1lI
>>>
>>> Clearly the main difference is in the "Bitmap Index Scan" which takes
>>> 60ms on 9.3 and 120ms on HEAD.
>>>
>>> On 9.3 the "perf top" looks like this:
>>>
>>> 34.79% postgres [.] gingetbitmap
>>> 28.96% postgres [.] ginCompareItemPointers
>>> 9.36% postgres [.] TS_execute
>>> 5.36% postgres [.] check_stack_depth
>>> 3.57% postgres [.] FunctionCall8Coll
>>>
>>> while on 9.4 it looks like this:
>>>
>>> 28.20% postgres [.] gingetbitmap
>>> 21.17% postgres [.] TS_execute
>>> 8.08% postgres [.] check_stack_depth
>>> 7.11% postgres [.] FunctionCall8Coll
>>> 4.34% postgres [.] shimTriConsistentFn
>>>
>>> Not sure how to interpret that, though. For example where did the
>>> ginCompareItemPointers go? I suspect it's thanks to inlining, and that
>>> it might be related to the performance decrease. Or maybe not.
>>>
>>
>> Yeah, inlining makes it disappear from the profile, and spreads that time
>> to the functions calling it.
>>
>> The profile tells us that the consistent function is called a lot more
>> than before. That is expected - with the fast scan feature, we're calling
>> consistent not only for potential matches, but also to refute TIDs based on
>> just a few entries matching. If that's effective, it allows us to skip many
>> TIDs and avoid consistent calls, which compensates, but if it's not
>> effective, it's just overhead.
>>
>> I would actually expect it to be fairly effective for that query, so
>> that's a bit surprising. I added counters to see where the calls are coming
>> from, and it seems that about 80% of the calls are actually coming from
>> this little the feature I explained earlier:
>>
>>
>> In addition to that, I'm using the ternary consistent function to check
>>> if minItem is a match, even if we haven't loaded all the entries yet.
>>> That's less important, but I think for something like "rare1 | (rare2 &
>>> frequent)" it might be useful. It would allow us to skip fetching
>>> 'frequent', when we already know that 'rare1' matches for the current
>>> item. I'm not sure if that's worth the cycles, but it seemed like an
>>> obvious thing to do, now that we have the ternary consistent function.
>>>
>>
>> So, that clearly isn't worth the cycles :-). At least not with an
>> expensive consistent function; it might be worthwhile if we pre-build the
>> truth-table, or cache the results of the consistent function.
>>
>> Attached is a quick patch to remove that, on top of all the other
>> patches, if you want to test the effect.
>
>
> Every single change you did in fast scan seems to be reasonable, but
> testing shows that something went wrong. Simple test with 3 words of
> different selectivities.
>
> After applying your patches:
>
> # select count(*) from fts_test where fti @@ plainto_tsquery('english',
> 'gin index select');
> count
> ───────
> 627
> (1 row)
>
> Time: 21,252 ms
>
> In original fast-scan:
>
> # select count(*) from fts_test where fti @@ plainto_tsquery('english',
> 'gin index select');
> count
> ───────
> 627
> (1 row)
>
> Time: 3,382 ms
>
> I'm trying to get deeper into it.
>

I had two guesses about why it's become so slower than in my original
fast-scan:
1) Not using native consistent function
2) Not sorting entries

I attach two patches which rollback these two features (sorry for awful
quality of second). Native consistent function accelerates thing
significantly, as expected. Tt seems that sorting entries have almost no
effect. However it's still not as fast as initial fast-scan:

# select count(*) from fts_test where fti @@ plainto_tsquery('english',
'gin index select');
count
───────
627
(1 row)

Time: 5,381 ms

Tomas, could you rerun your tests with first and both these patches applied
against patches by Heikki?

------
With best regards,
Alexander Korotkov.