Обсуждение: Re: Unexpected (bad) performance when querying indexed JSONB column
Just checked: the execution time is the same when I drop the index.
Execution plan with index:
---
"Bitmap Heap Scan on articles (cost=16.25..135.64 rows=33 width=427)"
" Recheck Cond: (data @> '{"locked": true}'::jsonb)"
" -> Bitmap Index Scan on idx_data (cost=0.00..16.24 rows=33 width=0)"
" Index Cond: (data @> '{"locked": true}'::jsonb)"
---
And without the index:
---
"Seq Scan on articles (cost=0.00..2289.21 rows=33 width=427)"
" Filter: (data @> '{"locked": true}'::jsonb)"
---
-C.
From: Christian Weyer
Date: Samstag, 31. Januar 2015 17:00
To: "pgsql-performance@postgresql.org"
Subject: [PERFORM] Unexpected (bad) performance when querying indexed JSONB column
Date: Samstag, 31. Januar 2015 17:00
To: "pgsql-performance@postgresql.org"
Subject: [PERFORM] Unexpected (bad) performance when querying indexed JSONB column
Hi all,
The pg version in question is the latest 9.4., running on Windows.
For testing out the NoSQL features of pg I have a simple table called ‘articles’ with a column called ‘data’.
There is an index on ‘data’ like this:
CREATE INDEX idx_data ON articles USING gin (data jsonb_path_ops);
The current test data set has 32570 entires of JSON docs like this:
{
"title": "Foo Bar",
"locked": true,
"valid_until": "2049-12-31T00:00:00",
"art_number": 12345678,
"valid_since": "2013-10-05T00:00:00",
"number_valid": false,
"combinations": {
"var1": "4711",
"var2": "4711",
"var3": "0815",
"int_art_number": "000001"
}
}
Nothing too complex, I think.
When I run a simple query:
SELECT data #>> ‘{"title"}'
FROM articles
WHERE data @> '{ “locked" : true }';
Reproducingly, it takes approx. 900ms to get the results back.
Honestly, I was expecting a much faster query.
Any opinions on this?
Thanks,
-C.
On 01/31/2015 11:02 AM, Christian Weyer wrote:
> Just checked: the execution time is the same when I drop the index.
>
> Execution plan with index:
> ---
> "Bitmap Heap Scan on articles (cost=16.25..135.64 rows=33 width=427)"
> " Recheck Cond: (data @> '{"locked": true}'::jsonb)"
> " -> Bitmap Index Scan on idx_data (cost=0.00..16.24 rows=33 width=0)"
> " Index Cond: (data @> '{"locked": true}'::jsonb)"
> ---
>
> And without the index:
> ---
> "Seq Scan on articles (cost=0.00..2289.21 rows=33 width=427)"
> " Filter: (data @> '{"locked": true}'::jsonb)"
> ---
Please send us the output of EXPLAIN ( ANALYZE ON, BUFFERS ON ) so that
we can see what the query is actually doing, rather than just what the
plan was.
--
Josh Berkus
PostgreSQL Experts Inc.
http://pgexperts.com
On 01.02.15 22:06, "Josh Berkus" <josh@agliodbs.com> wrote: >Please send us the output of EXPLAIN ( ANALYZE ON, BUFFERS ON ) so that >we can see what the query is actually doing, rather than just what the >plan was. > >-- >Josh Berkus >PostgreSQL Experts Inc. >http://pgexperts.com Sure. Here we go: "Bitmap Heap Scan on articles (cost=16.25..135.64 rows=33 width=427) (actual time=6.425..43.603 rows=18584 loops=1)" " Recheck Cond: (data @> ‘{"locked": true}'::jsonb)" " Heap Blocks: exact=1496" " Buffers: shared hit=1504" " -> Bitmap Index Scan on idx_data (cost=0.00..16.24 rows=33 width=0) (actual time=6.090..6.090 rows=18584 loops=1)" " Index Cond: (data @> ‘{"locked": true}'::jsonb)" " Buffers: shared hit=8" "Planning time: 0.348 ms" "Execution time: 47.788 ms" Thanks for looking into this. -C.
Christian Weyer <christian.weyer@thinktecture.com> writes:
> On 01.02.15 22:06, "Josh Berkus" <josh@agliodbs.com> wrote:
>> Please send us the output of EXPLAIN ( ANALYZE ON, BUFFERS ON ) so that
>> we can see what the query is actually doing, rather than just what the
>> plan was.
> Sure. Here we go:
> "Bitmap Heap Scan on articles (cost=16.25..135.64 rows=33 width=427)
> (actual time=6.425..43.603 rows=18584 loops=1)"
> " Recheck Cond: (data @> ‘{"locked": true}'::jsonb)"
> " Heap Blocks: exact=1496"
> " Buffers: shared hit=1504"
> " -> Bitmap Index Scan on idx_data (cost=0.00..16.24 rows=33 width=0)
> (actual time=6.090..6.090 rows=18584 loops=1)"
> " Index Cond: (data @> ‘{"locked": true}'::jsonb)"
> " Buffers: shared hit=8"
> "Planning time: 0.348 ms"
> "Execution time: 47.788 ms"
So that's showing a runtime of 48 ms, not 900. For retrieving 18584
rows, doesn't sound that bad to me.
(If the planner had had a better rowcount estimate, it'd likely have
not bothered with the index at all but just done a seqscan. This is
a consequence of the lack of any very useful stats for JSONB columns,
which is something we hope to address soon; but it's not done in 9.4
and likely won't be in 9.5 either ...)
regards, tom lane
>>"Bitmap Heap Scan on articles (cost=16.25..135.64 rows=33 width=427)
>> (actual time=6.425..43.603 rows=18584 loops=1)"
>> " Recheck Cond: (data @> ‘{"locked": true}'::jsonb)"
>> " Heap Blocks: exact=1496"
>> " Buffers: shared hit=1504"
>> " -> Bitmap Index Scan on idx_data (cost=0.00..16.24 rows=33
>>width=0)
>> (actual time=6.090..6.090 rows=18584 loops=1)"
>> " Index Cond: (data @> ‘{"locked": true}'::jsonb)"
>> " Buffers: shared hit=8"
>> "Planning time: 0.348 ms"
>> "Execution time: 47.788 ms"
>
>So that's showing a runtime of 48 ms, not 900. For retrieving 18584
>rows, doesn't sound that bad to me.
>
>(If the planner had had a better rowcount estimate, it'd likely have
>not bothered with the index at all but just done a seqscan. This is
>a consequence of the lack of any very useful stats for JSONB columns,
>which is something we hope to address soon; but it's not done in 9.4
>and likely won't be in 9.5 either ...)
>
> regards, tom lane
Thanks for your insights.
This greatly helped.
-C.