Re: querying with index on jsonb slower than standard column. Why?

On 12/08/2014 07:50 AM, Adrian Klaver wrote:
> On 12/08/2014 07:46 AM, Tom Lane wrote:
>> Adrian Klaver <adrian.klaver@aklaver.com> writes:
>>> On 12/07/2014 05:28 PM, Tom Lane wrote:
>>>> I don't see any particular difference ...
>>
>>> Running the above on my machine I do see the slow down the OP reports. I
>>> ran it several times and it stayed around 3.5x.
>>
>> Interesting.  A couple of points that might be worth checking:
>>
>> * I tried this on a 64-bit build, whereas you were evidently using
>> 32-bit.
>
> My laptop is 64-bit, so when I get a chance I will setup the test there
> and run it to see what happens.
>
>>

Seems work_mem is the key:

postgres@test=# select version();                                                               version 


-------------------------------------------------------------------------------------------------------------------------------------
PostgreSQL9.4rc1 on x86_64-unknown-linux-gnu, compiled by gcc (SUSE 
 
Linux) 4.8.1 20130909 [gcc-4_8-branch revision 202388], 64-bit
(1 row)

The default:

postgres@test=# show work_mem ; work_mem
---------- 4MB
(1 row)


postgres@test=# \timing
Timing is on.
postgres@test=#  explain analyze select count(*) from json_test where 
(data->>'assay1_ic50')::float > 90
test-# and (data->>'assay2_ic50')::float < 10;              QUERY PLAN

-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Aggregate (cost=198713.45..198713.46 rows=1 width=0) (actual 
 
time=8564.799..8564.799 rows=1 loops=1)   ->  Bitmap Heap Scan on json_test  (cost=36841.42..198465.53 
rows=99168 width=0) (actual time=1043.226..8550.183 rows=99781 loops=1)         Recheck Cond: ((((data ->>
'assay1_ic50'::text))::double
 
precision > 90::double precision) AND (((data ->> 
'assay2_ic50'::text))::double precision < 10::double precision))         Rows Removed by Index Recheck: 7236280
HeapBlocks: exact=30252 lossy=131908         ->  BitmapAnd  (cost=36841.42..36841.42 rows=99168 width=0) 
 
(actual time=1034.738..1034.738 rows=0 loops=1)               ->  Bitmap Index Scan on idx_data_json_assay1_ic50 
(cost=0.00..18157.96 rows=983136 width=0) (actual time=513.878..513.878 
rows=1001237 loops=1)                     Index Cond: (((data ->> 
'assay1_ic50'::text))::double precision > 90::double precision)               ->  Bitmap Index Scan on
idx_data_json_assay2_ic50
 
(cost=0.00..18633.62 rows=1008691 width=0) (actual time=502.396..502.396 
rows=1000930 loops=1)                     Index Cond: (((data ->> 
'assay2_ic50'::text))::double precision < 10::double precision) Planning time: 121.962 ms Execution time: 8565.609 ms
(12 rows)

Time: 9110.408 ms
postgres@test=# explain analyze select count(*) from json_test where 
assay1_ic50 > 90 and assay2_ic50 < 10;    QUERY PLAN

-----------------------------------------------------------------------------------------------------------------------------------------------------------------
Aggregate (cost=197225.91..197225.92 rows=1 width=0) (actual 
 
time=1848.769..1848.769 rows=1 loops=1)   ->  Bitmap Heap Scan on json_test  (cost=36841.41..196977.99 
rows=99168 width=0) (actual time=405.110..1839.299 rows=99781 loops=1)         Recheck Cond: ((assay1_ic50 > 90::double
precision)AND 
 
(assay2_ic50 < 10::double precision))         Rows Removed by Index Recheck: 7236280         Heap Blocks: exact=30252
lossy=131908        ->  BitmapAnd  (cost=36841.41..36841.41 rows=99168 width=0) 
 
(actual time=397.138..397.138 rows=0 loops=1)               ->  Bitmap Index Scan on idx_data_col_assay1_ic50 
(cost=0.00..18157.96 rows=983136 width=0) (actual time=196.304..196.304 
rows=1001237 loops=1)                     Index Cond: (assay1_ic50 > 90::double precision)               ->  Bitmap
IndexScan on idx_data_col_assay2_ic50 
 
(cost=0.00..18633.62 rows=1008691 width=0) (actual time=182.845..182.845 
rows=1000930 loops=1)                     Index Cond: (assay2_ic50 < 10::double precision) Planning time: 0.212 ms
Executiontime: 1848.814 ms
 
(12 rows)

Time: 1849.570 ms


****************************************************************************

Set work_mem up:

postgres@test=# set work_mem='16MB';
SET
Time: 0.143 ms
postgres@test=# show work_mem; work_mem
---------- 16MB
(1 row)

postgres@test=#  explain analyze select count(*) from json_test where 
(data->>'assay1_ic50')::float > 90
and (data->>'assay2_ic50')::float < 10;              QUERY PLAN 


-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Aggregate (cost=198713.45..198713.46 rows=1 width=0) (actual 
 
time=861.413..861.413 rows=1 loops=1)   ->  Bitmap Heap Scan on json_test  (cost=36841.42..198465.53 
rows=99168 width=0) (actual time=588.969..852.720 rows=99781 loops=1)         Recheck Cond: ((((data ->>
'assay1_ic50'::text))::double
 
precision > 90::double precision) AND (((data ->> 
'assay2_ic50'::text))::double precision < 10::double precision))         Heap Blocks: exact=77216         ->  BitmapAnd
(cost=36841.42..36841.42 rows=99168 width=0) 
 
(actual time=564.927..564.927 rows=0 loops=1)               ->  Bitmap Index Scan on idx_data_json_assay1_ic50 
(cost=0.00..18157.96 rows=983136 width=0) (actual time=265.318..265.318 
rows=1001237 loops=1)                     Index Cond: (((data ->> 
'assay1_ic50'::text))::double precision > 90::double precision)               ->  Bitmap Index Scan on
idx_data_json_assay2_ic50
 
(cost=0.00..18633.62 rows=1008691 width=0) (actual time=256.225..256.225 
rows=1000930 loops=1)                     Index Cond: (((data ->> 
'assay2_ic50'::text))::double precision < 10::double precision) Planning time: 0.126 ms Execution time: 861.453 ms
(11 rows)

Time: 861.965 ms
postgres@test=# explain analyze select count(*) from json_test where 
assay1_ic50 > 90 and assay2_ic50 < 10;    QUERY PLAN 


-----------------------------------------------------------------------------------------------------------------------------------------------------------------
Aggregate (cost=197225.91..197225.92 rows=1 width=0) (actual 
 
time=848.410..848.410 rows=1 loops=1)   ->  Bitmap Heap Scan on json_test  (cost=36841.41..196977.99 
rows=99168 width=0) (actual time=578.360..839.659 rows=99781 loops=1)         Recheck Cond: ((assay1_ic50 > 90::double
precision)AND 
 
(assay2_ic50 < 10::double precision))         Heap Blocks: exact=77216         ->  BitmapAnd  (cost=36841.41..36841.41
rows=99168width=0) 
 
(actual time=554.387..554.387 rows=0 loops=1)               ->  Bitmap Index Scan on idx_data_col_assay1_ic50 
(cost=0.00..18157.96 rows=983136 width=0) (actual time=263.961..263.961 
rows=1001237 loops=1)                     Index Cond: (assay1_ic50 > 90::double precision)               ->  Bitmap
IndexScan on idx_data_col_assay2_ic50 
 
(cost=0.00..18633.62 rows=1008691 width=0) (actual time=247.268..247.268 
rows=1000930 loops=1)                     Index Cond: (assay2_ic50 < 10::double precision) Planning time: 0.128 ms
Executiontime: 848.453 ms
 
(11 rows)


*****************************************************************

Then set it back:

postgres@test=# set work_mem='4MB';
SET
Time: 0.213 ms
postgres@test=# show work_mem ; work_mem
---------- 4MB
(1 row)


postgres@test=#  explain analyze select count(*) from json_test where 
(data->>'assay1_ic50')::float > 90
and (data->>'assay2_ic50')::float < 10;              QUERY PLAN 


-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Aggregate (cost=198713.45..198713.46 rows=1 width=0) (actual 
 
time=6607.650..6607.650 rows=1 loops=1)   ->  Bitmap Heap Scan on json_test  (cost=36841.42..198465.53 
rows=99168 width=0) (actual time=400.598..6594.442 rows=99781 loops=1)         Recheck Cond: ((((data ->>
'assay1_ic50'::text))::double
 
precision > 90::double precision) AND (((data ->> 
'assay2_ic50'::text))::double precision < 10::double precision))         Rows Removed by Index Recheck: 7236280
HeapBlocks: exact=30252 lossy=131908         ->  BitmapAnd  (cost=36841.42..36841.42 rows=99168 width=0) 
 
(actual time=392.622..392.622 rows=0 loops=1)               ->  Bitmap Index Scan on idx_data_json_assay1_ic50 
(cost=0.00..18157.96 rows=983136 width=0) (actual time=191.598..191.598 
rows=1001237 loops=1)                     Index Cond: (((data ->> 
'assay1_ic50'::text))::double precision > 90::double precision)               ->  Bitmap Index Scan on
idx_data_json_assay2_ic50
 
(cost=0.00..18633.62 rows=1008691 width=0) (actual time=183.107..183.107 
rows=1000930 loops=1)                     Index Cond: (((data ->> 
'assay2_ic50'::text))::double precision < 10::double precision) Planning time: 0.126 ms Execution time: 6607.692 ms
(12 rows)

Time: 6608.197 ms
postgres@test=# explain analyze select count(*) from json_test where 
assay1_ic50 > 90 and assay2_ic50 < 10;    QUERY PLAN 


-----------------------------------------------------------------------------------------------------------------------------------------------------------------
Aggregate (cost=197225.91..197225.92 rows=1 width=0) (actual 
 
time=1836.383..1836.383 rows=1 loops=1)   ->  Bitmap Heap Scan on json_test  (cost=36841.41..196977.99 
rows=99168 width=0) (actual time=396.414..1826.818 rows=99781 loops=1)         Recheck Cond: ((assay1_ic50 > 90::double
precision)AND 
 
(assay2_ic50 < 10::double precision))         Rows Removed by Index Recheck: 7236280         Heap Blocks: exact=30252
lossy=131908        ->  BitmapAnd  (cost=36841.41..36841.41 rows=99168 width=0) 
 
(actual time=388.498..388.498 rows=0 loops=1)               ->  Bitmap Index Scan on idx_data_col_assay1_ic50 
(cost=0.00..18157.96 rows=983136 width=0) (actual time=187.928..187.928 
rows=1001237 loops=1)                     Index Cond: (assay1_ic50 > 90::double precision)               ->  Bitmap
IndexScan on idx_data_col_assay2_ic50 
 
(cost=0.00..18633.62 rows=1008691 width=0) (actual time=182.743..182.743 
rows=1000930 loops=1)                     Index Cond: (assay2_ic50 < 10::double precision) Planning time: 0.109 ms
Executiontime: 1836.422 ms
 
(12 rows)


-- 
Adrian Klaver
adrian.klaver@aklaver.com