Received: from malur.postgresql.org ([217.196.149.56]) by arkaria.postgresql.org with esmtp (Exim 4.80) (envelope-from ) id 1Xy1Qj-0000ud-N1 for pgsql-sql@arkaria.postgresql.org; Mon, 08 Dec 2014 16:45:02 +0000 Received: from localhost ([127.0.0.1] helo=postgresql.org) by malur.postgresql.org with smtp (Exim 4.80) (envelope-from ) id 1Xy1Qj-00042k-3s for pgsql-sql@arkaria.postgresql.org; Mon, 08 Dec 2014 16:45:01 +0000 Received: from makus.postgresql.org ([2001:4800:1501:1::229]) by malur.postgresql.org with esmtps (TLS1.2:DHE_RSA_AES_256_CBC_SHA256:256) (Exim 4.80) (envelope-from ) id 1Xy1Qh-00042b-HN for pgsql-sql@postgresql.org; Mon, 08 Dec 2014 16:44:59 +0000 Received: from out3-smtp.messagingengine.com ([66.111.4.27]) by makus.postgresql.org with esmtps (TLS1.2:DHE_RSA_AES_256_CBC_SHA256:256) (Exim 4.80) (envelope-from ) id 1Xy1Qd-0000z6-LQ for pgsql-sql@postgresql.org; Mon, 08 Dec 2014 16:44:57 +0000 Received: from compute2.internal (compute2.nyi.internal [10.202.2.42]) by mailout.nyi.internal (Postfix) with ESMTP id 479A720B55 for ; Mon, 8 Dec 2014 11:44:54 -0500 (EST) Received: from frontend1 ([10.202.2.160]) by compute2.internal (MEProxy); Mon, 08 Dec 2014 11:44:54 -0500 DKIM-Signature: v=1; a=rsa-sha1; c=relaxed/relaxed; d=aklaver.com; h= x-sasl-enc:message-id:date:from:mime-version:to:cc:subject :references:in-reply-to:content-type:content-transfer-encoding; s=mesmtp; bh=SzQmLM54Fs50X8wVpZjHgL5JNro=; b=GRVJctpacDE6njHMtd ftH4nh5zCZwF0POnAekOldHPzjn6WPYkHa0iexrbQDGDoXGlSCU2E5KRA7zJWw7f 72c/QoUgknnWc6u/lOO4ixdZ+0kimXTeduEuB+th0RzjQpGlZe7j07lFGqRoB5Zy TP435VoxhrPVSH3KaUhBv4cgQ= DKIM-Signature: v=1; a=rsa-sha1; c=relaxed/relaxed; d= messagingengine.com; h=x-sasl-enc:message-id:date:from :mime-version:to:cc:subject:references:in-reply-to:content-type :content-transfer-encoding; s=smtpout; bh=SzQmLM54Fs50X8wVpZjHgL 5JNro=; b=T4d9sKVnI/Lh5hY/Gaxsu4VQ6qhVQp/TGSN6s3ZASRT8l50S3O/tfg o5kewOIzsLHrB9AUNQhZ2MNeou8gHRgX/h3MZwS+ktEOUqpiEj8uoKGL7OSqsMer QvF0rHlkhg441yWMhKgwRvrCAWOZZzJosAGsWd/qyZbVvBU3DLWqQ= X-Sasl-enc: AOOZqIr1rE3tOoftWBY+vy7YHR8x+j5UJzdxTzdEdH/n 1418057093 Received: from killi.site (unknown [173.160.167.74]) by mail.messagingengine.com (Postfix) with ESMTPA id 84F93C00281; Mon, 8 Dec 2014 11:44:53 -0500 (EST) Message-ID: <5485D584.8080105@aklaver.com> Date: Mon, 08 Dec 2014 08:44:52 -0800 From: Adrian Klaver User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:31.0) Gecko/20100101 Thunderbird/31.3.0 MIME-Version: 1.0 To: Tom Lane CC: Tim Dudgeon , pgsql-sql@postgresql.org Subject: Re: querying with index on jsonb slower than standard column. Why? References: <5484DBDA.6090405@gmail.com> <5484EEA7.1030403@aklaver.com> <5484F437.2080402@gmail.com> <16147.1418002090@sss.pgh.pa.us> <5485C449.4020204@aklaver.com> <26002.1418053572@sss.pgh.pa.us> <5485C8BA.7040704@aklaver.com> In-Reply-To: <5485C8BA.7040704@aklaver.com> Content-Type: text/plain; charset=windows-1252; format=flowed Content-Transfer-Encoding: 7bit X-Pg-Spam-Score: -2.7 (--) List-Archive: List-Help: List-ID: List-Owner: List-Post: List-Subscribe: List-Unsubscribe: X-Mailing-List: pgsql-sql Precedence: bulk Sender: pgsql-sql-owner@postgresql.org On 12/08/2014 07:50 AM, Adrian Klaver wrote: > On 12/08/2014 07:46 AM, Tom Lane wrote: >> Adrian Klaver 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 ------------------------------------------------------------------------------------------------------------------------------------- PostgreSQL 9.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 Heap Blocks: 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 Index Scan 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 Execution time: 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=99168 width=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 Index Scan 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 Execution time: 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 Heap Blocks: 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 Index Scan 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 Execution time: 1836.422 ms (12 rows) -- Adrian Klaver adrian.klaver@aklaver.com -- Sent via pgsql-sql mailing list (pgsql-sql@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-sql