Received: from malur.postgresql.org ([217.196.149.56]) by arkaria.postgresql.org with esmtp (Exim 4.80) (envelope-from ) id 1Wep6t-0000yo-CU for pgsql-performance@arkaria.postgresql.org; Mon, 28 Apr 2014 17:12:55 +0000 Received: from localhost ([127.0.0.1] helo=postgresql.org) by malur.postgresql.org with smtp (Exim 4.80) (envelope-from ) id 1Wep6s-0006Gv-Ps for pgsql-performance@arkaria.postgresql.org; Mon, 28 Apr 2014 17:12:54 +0000 Received: from makus.postgresql.org ([2001:4800:7903:4::125]) by malur.postgresql.org with esmtp (Exim 4.80) (envelope-from ) id 1Wep6r-0006Go-GK for pgsql-performance@postgresql.org; Mon, 28 Apr 2014 17:12:53 +0000 Received: from www.loot.co.za ([41.185.56.26] helo=mail.loot.co.za) by makus.postgresql.org with esmtp (Exim 4.80) (envelope-from ) id 1Wep6f-0007dI-Uy for pgsql-performance@postgresql.org; Mon, 28 Apr 2014 17:12:52 +0000 Received: from sun.loot.co.za (sun [192.168.0.14]) by mail.loot.co.za (8.13.8/8.13.8) with SMTP id s3SHBm6l011883 for ; Mon, 28 Apr 2014 19:11:53 +0200 DomainKey-Signature: a=rsa-sha1; s=mail; d=loot.co.za; c=nofws; q=dns; b=H/Z+xVBqv9r/W+luJE9GNWfVLpYnLvKdwvKbAi/9D44LlLbroRzHFc4p2Pxc3wMhr ZJVAd3EDXIFUGL2xhCXW0jqpfZQOp4j6OD8iehDy//XgUp9edenDkL+BVPhzUYc Received: (qmail 29230 invoked from network); 28 Apr 2014 17:12:34 -0000 Received: from unknown (HELO ?192.168.0.2?) (192.168.0.2) by 0 with SMTP; 28 Apr 2014 17:12:34 -0000 Message-ID: <535E8BFF.1010503@loot.co.za> Date: Mon, 28 Apr 2014 19:12:31 +0200 From: Michael van Rooyen User-Agent: Mozilla/5.0 (Windows NT 6.1; WOW64; rv:24.0) Gecko/20100101 Thunderbird/24.4.0 MIME-Version: 1.0 To: pgsql-performance@postgresql.org Subject: Slow queries on 9.3.1 despite use of index Content-Type: text/plain; charset=ISO-8859-1; format=flowed Content-Transfer-Encoding: quoted-printable X-Pg-Spam-Score: -5.0 (-----) List-Archive: List-Help: List-ID: List-Owner: List-Post: List-Subscribe: List-Unsubscribe: X-Mailing-List: pgsql-performance Precedence: bulk Sender: pgsql-performance-owner@postgresql.org I'm trying to get to the bottom of a performance issue on a server=20 running PostgreSQL 9.3.1 on Centos 5. The machine is a dual quad-core=20 Xeon E5620 with 24GB ECC RAM and four enterprise SATA Seagate=20 Constellation ES drives configured as 2 software RAID1 volumes. The=20 main DB is on one volume and some, more used indexes and WAL logs are on=20 the other. Overall, the load doesn't appear to be heavy, but we're still getting=20 slow queries, for example, here's an extract from the log: 2014-04-28 16:51:02.904 GMT 25998: LOG: checkpoint starting: time 2014-04-28 16:53:37.204 GMT 30053: LOG: duration: 1067.464 ms execute=20 : select "id" from "ProductSupplier" where=20 "product"=3D'25553848082928' 2014-04-28 16:54:12.701 GMT 30053: LOG: duration: 1105.844 ms execute=20 : select "id" from "ProductSupplier" where=20 "product"=3D'1626407082928' 2014-04-28 16:54:46.789 GMT 30053: LOG: duration: 1060.585 ms execute=20 : select=20 "id","updated","ean","frontImagePresent","backImagePresent","jacketScanned"= ,"x80ImagePresent","x120ImagePresent","x200ImagePresent","x400ImagePresent"= ,"type","brand","manProductCode","name","series","subtitle","keywords","mas= s","length","width","thickness","releaseDate","originalReleaseDate","firstA= vailableDate","stockLevel","stockCost","url","ratingTotal","ratingCount","b= eta","available","reorderSource","reorderPoint","reorderQuantity","status",= "replacement","countryOfOrigin","formType","formDetail","formDetail1","form= Detail2","formDetail3","formDetail4","contentType","packagingType","ebookTy= pe","mixedMedia","mediaCount","shortAnnotationType","longAnnotationType","w= ikipediaTopic","allMusicId","allMovieId","allGameId","imdbId","boost","sale= sMovingAverage","movingAverageDate","lifetimeSales","shippingRequirement","= shippingSubsidyCalculator","edition","dewey","lcc","lccn","pages","minutes"= ,"bicSubjects","bisacSubjects","regionEncoding","audioFormat","videoFormat"= ,"platform","audit"=20 from "Product" where id=3D'6686838082928' 2014-04-28 16:55:58.058 GMT 30053: LOG: duration: 1309.192 ms execute=20 : select "id" from "ProductCategory" where=20 "product"=3D'1932872082928' 2014-04-28 16:56:06.019 GMT 25998: LOG: checkpoint complete: wrote 6647=20 buffers (2.5%); 0 transaction log file(s) added, 0 removed, 2 recycled;=20 write=3D298.862 s, sync=3D4.072 s, total=3D303.115 s; sync files=3D155,=20 longest=3D0.234 s, average=3D0.026 s Although these tables (ProductSupplier, Product, ProductCategory) are=20 large (millions of rows), all these queries are done via indexes, for=20 example: =3D# explain (analyze, buffers) select "id" from "ProductSupplier" where=20 "product"=3D'25553848082928'; QUERY PLAN ---------------------------------------------------------------------------= ---------------------------------------------------------------- Index Scan using "i433275-productIndex" on "ProductSupplier"=20 (cost=3D0.57..15.81 rows=3D3 width=3D8) (actual time=3D0.069..0.105 rows=3D= 6 loops=3D1) Index Cond: (product =3D 25553848082928::bigint) Buffers: shared hit=3D10 Total runtime: 0.138 ms (4 rows) So, I would expect it to be really quick, and > 1 second seems really slow. Overall the load on the server seems quite low, for example, typical=20 vmstat -1 is: procs -----------memory---------- ---swap-- -----io---- --system--=20 -----cpu------ r b swpd free buff cache si so bi bo in cs us sy=20 id wa st 0 1 304 77740 11960 17709156 0 0 99 82 2 2 2=20=20 1 89 8 0 1 0 304 75228 11960 17711164 0 0 1256 635 1418 6498 0=20=20 0 94 6 0 0 1 304 73440 11968 17712036 0 0 1232 149 1253 6232 1=20=20 0 94 6 0 0 2 304 78472 11968 17706016 0 0 1760 89 1325 6361 1=20=20 0 94 5 0 0 1 304 75616 11968 17708480 0 0 2164 72 1371 6855 1=20=20 0 94 5 0 0 1 304 73292 11968 17710320 0 0 1760 112 1335 6673 1=20=20 0 94 5 0 0 2 304 77956 11964 17703528 0 0 1204 5614 1867 6712 0=20=20 0 94 6 0 And iostat also seems okay: sda sdb sdc sdd=20=20=20=20=20=20=20=20=20= =20=20=20=20 md0 md1 cpu kps tps svc_t kps tps svc_t kps tps svc_t kps tps svc_t kps tps=20 svc_t kps tps svc_t us sy wt id 619 64 5.4 1478 96 8.9 1494 98 8.7 542 60 5.5 1998=20 139 0.0 804 96 0.0 2 1 8 89 1147 151 3.7 5328 88 8.0 5388 90 8.3 1147 145 3.0 5638=20 171 0.0 2245 284 0.0 0 0 4 95 865 110 4.6 214 24 12.6 214 24 13.1 885 113 4.5 252=20=20 28 0.0 1749 222 0.0 4 0 1 95 937 107 5.0 40 5 10.0 40 5 13.0 821 93 6.4 80=20=20 10 0.0 1596 193 0.0 9 0 1 90 1206 154 3.2 0 0 0.0 0 0 0.0 1195 153 3.2 0 0=20= =20=20 0.0 2401 307 0.0 6 0 0 94 1111 139 3.8 24 3 10.0 16 2 12.0 1115 144 3.8 40=20=20=20 5 0.0 2141 274 0.0 10 0 0 89 1222 156 3.6 101 12 4.8 101 12 4.2 1171 150 4.2 93=20=20 10 0.0 1986 252 0.0 10 0 0 90 739 98 5.5 0 0 0.0 0 0 0.0 687 93 5.2 0 0=20= =20=20 0.0 1425 191 0.0 7 0 0 93 775 102 5.2 8 1 13.0 8 1 21.0 755 99 5.1 16=20=20=20 2 0.0 1529 201 0.0 10 0 0 89 780 105 5.3 16 2 13.0 16 2 11.0 784 103 5.4 32=20=20=20 4 0.0 1555 205 0.0 6 0 1 92 573 75 6.8 110 32 1.3 110 31 1.1 561 73 7.6 102=20=20 30 0.0 1109 143 0.0 10 1 0 89 639 84 7.3 2833 349 2.1 3085 367 2.0 683 90 6.0 4854=20 592 0.0 1026 135 0.0 2 0 4 93 510 70 7.8 2020 240 4.2 1808 227 4.2 586 81 7.2 40=20=20=20 5 0.0 1077 146 0.0 0 0 7 93 538 75 7.8 24 3 290.0 20 3 239.7 582 81 7.5 40=20=20=20 5 0.0 1066 147 0.0 0 0 6 94 504 69 9.3 132 17 25.8 128 16 14.4 600 81 8.2 256=20=20 32 0.0 1083 144 0.0 1 0 6 94 I've tried to optimise postgresql.conf for performance: max_connections =3D 1000 # (change requires restart) shared_buffers =3D 2GB # min 128kB or max_connections*16= kB work_mem =3D 100MB # min 64kB maintenance_work_mem =3D 100MB # min 1MB synchronous_commit =3D off # immediate fsync at commit wal_buffers =3D 16MB # min 32kB checkpoint_segments =3D 64 # in logfile segments, min 1,=20 16MB each checkpoint_timeout =3D 10min # range 30s-1h effective_cache_size =3D 16GB logging_collector =3D on # Enable capturing of stderr and= =20 csvlog log_directory =3D 'pg_log' # directory where log files are=20 written, log_filename =3D 'postgresql-%Y-%m-%d_%H%M%S.log' # log file name pattern, log_rotation_age =3D 1d # Automatic rotation of logfiles= =20 will log_min_duration_statement =3D 1000 # -1 is disabled, 0 logs all=20 statements log_checkpoints =3D on log_line_prefix =3D '%m %p: ' # special values: autovacuum =3D on # Enable autovacuum subprocess?= =20=20 'on' autovacuum_vacuum_threshold =3D 10000 # min number of row updates before autovacuum_analyze_threshold =3D 1000 # min number of row updates before autovacuum_vacuum_scale_factor =3D 0.1 # fraction of table size before=20 vacuum autovacuum_analyze_scale_factor =3D 0.05 # fraction of table size before=20 analyze autovacuum_vacuum_cost_delay =3D 5 # default vacuum cost delay for datestyle =3D 'iso, dmy' default_text_search_config =3D 'pg_catalog.english' backslash_quote =3D on # on, off, or safe_encoding standard_conforming_strings =3D off If anyone can see anything amiss in the above info, I'd be grateful for=20 any suggestions... Thanks, Michael. --=20 Sent via pgsql-performance mailing list (pgsql-performance@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-performance