________________________________________
From: Anne Rosset [aros...@collab.net]
Sent: Monday, May 06, 2013 5:51 PM
To: Igor Neyman; k...@rice.edu
Cc: pgsql-performance@postgresql.org
Subject: RE: [PERFORM] Deterioration in performance when query executed in
multi threads
Hi Igor,
Result with enable_nestloop off:
------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
-----------
Hash Join (cost=49946.49..58830.02 rows=1 width=181) (actual
time=2189.474..2664.888 rows=180 loops=1)
Hash Cond: ((item.created_by_id)::text = (sfuser.id)::text)
-> Hash Join (cost=49470.50..58345.53 rows=1 width=167) (actual
time=1931.870..2404.745 rows=180 loops=1)
Hash Cond: ((relationship.origin_id)::text = (sfuser2.id)::text)
-> Hash Join (cost=48994.51..57869.52 rows=1 width=153) (actual
time=1927.603..2400.334 rows=180 loops=1)
Hash Cond: ((relationship.target_id)::text = (artifact.id)::text)
-> Seq Scan on relationship (cost=0.00..7973.38 rows=240435
width=19) (actual time=0.036..492.442 rows=241285 loops=1)
Filter: ((NOT is_deleted) AND
((relationship_type_name)::text = 'ArtifactAssignment'::text))
-> Hash (cost=48994.49..48994.49 rows=1 width=154) (actual
time=1858.350..1858.350 rows=180 loops=1)
Buckets: 1024 Batches: 1 Memory Usage: 34kB
-> Hash Join (cost=47260.54..48994.49 rows=1 width=154)
(actual time=1836.495..1858.151 rows=180 loops=1)
Hash Cond: ((field_value4.id)::text =
(artifact.customer_fv)::text)
-> Seq Scan on field_value field_value4
(cost=0.00..1443.78 rows=77378 width=9) (actual time=22.104..30.694 rows=77378
loops=1)
-> Hash (cost=47260.52..47260.52 rows=1 width=163)
(actual time=1814.005..1814.005 rows=180 loops=1)
Buckets: 1024 Batches: 1 Memory Usage: 35kB
-> Hash Join (cost=45526.57..47260.52 rows=1
width=163) (actual time=1790.908..1813.780 rows=180 loops=1)
Hash Cond: ((field_value3.id)::text =
(artifact.category_fv)::text)
-> Seq Scan on field_value field_value3
(cost=0.00..1443.78 rows=77378 width=15) (actual time=0.002..9.262 rows=77378
loops=1)
-> Hash (cost=45526.55..45526.55
rows=1 width=166) (actual time=1790.505..1790.505 rows=180 loops=1)
Buckets: 1024 Batches: 1 Memory
Usage: 36kB
-> Hash Join
(cost=43792.60..45526.55 rows=1 width=166) (actual time=1768.362..1790.304
rows=180 loops=1)
Hash Cond:
((field_value.id)::text = (artifact.group_fv)::text)
-> Seq Scan on field_value
(cost=0.00..1443.78 rows=77378 width=9) (actual time=0.002..8.687 rows=77378
loops=1)
-> Hash
(cost=43792.58..43792.58 rows=1 width=175) (actual time=1767.928..1767.928
rows=180 loops=1)
Buckets: 1024
Batches: 1 Memory Usage: 38kB
-> Hash Join
(cost=42058.63..43792.58 rows=1 width=175) (actual time=1499.822..1767.734
rows=180 loops=1)
Hash Cond:
((field_value2.id)::text = (artifact.status_fv)::text)
-> Seq Scan on
field_value field_value2 (cost=0.00..1443.78 rows=77378 width=15) (actual
time=0.002..261.082 rows=77378 loops=1)
-> Hash
(cost=42058.61..42058.61 rows=1 width=178) (actual time=1492.707..1492.707
rows=180 loops=1)
Buckets:
1024 Batches: 1 Memory Usage: 38kB
-> Hash
Join (cost=18039.59..42058.61 rows=1 width=178) (actual
time=1175.659..1492.482 rows=180 loops=1)
Hash
Cond: ((item.id)::text = (artifact.id)::text)
->
Hash Join (cost=12112.31..36130.95 rows=30 width=128) (actual
time=304.035..702.745 rows=1015 loops=1)
Hash Cond: ((item.folder_id)::text = (folder.id)::text)
-> Seq Scan on item (cost=0.00..21381.10 rows=703322 width=58) (actual
time=0.020..382.847 rows=704018 loops=1)
Filter: (NOT is_deleted)
-> Hash (cost=12112.27..12112.27 rows=3 width=92) (actual
time=189.285..189.285 rows=10 loops=1)
Buckets: 1024 Batches: 1 Memory Usage: 2kB
-> Hash Join (cost=195.86..12112.27 rows=3 width=92) (actual
time=31.304..189.269 rows=10 loops=1)
Hash Cond: ((folder.id)::text = (tracker.id)::text)
-> Hash Join (cost=8.28..11923.31 rows=155 width=65) (actual
time=3.195..161.619 rows=612 loops=1)
Hash Cond: ((folder.project_id)::text = (project.id)::text)
-> Seq Scan on folder (cost=0.00..10858.71 rows=281271
width=32) (actual time=0.017..75.451 rows=280356 loops=1)
-> Hash (cost=8.27..8.27 rows=1 width=42) (actual
time=0.041..0.041 rows=1 loops=1)
Buckets: 1024 Batches: 1 Memory Usage: 1kB
-> Index Scan using project_path on project
(cost=0.00..8.27 rows=1 width=42) (actual time=0.038..0.039 rows=
1 loops=1)
Index Cond: ((path)::text =
'projects.psr-pub-13'::text)
-> Hash (cost=129.48..129.48 rows=4648 width=27) (actual
time=27.439..27.439 rows=4648 loops=1)
Buckets: 1024 Batches: 1 Memory Usage: 267kB
-> Seq Scan on tracker (cost=0.00..129.48 rows=4648
width=27) (actual time=19.880..25.635 rows=4648 loops=1)
-> Hash Join (cost=45526.57..47260.52 rows=1 width=163) (actual
time=1790.908..1813.780 rows=180 loops=1)
Hash Cond: ((field_value3.id)::text =
(artifact.category_fv)::text)
-> Seq Scan on field_value field_value3
(cost=0.00..1443.78 rows=77378 width=15) (actual time=0.002..9.262 rows=77378
loops=1)
-> Hash (cost=45526.55..45526.55
rows=1 width=166) (actual time=1790.505..1790.505 rows=180 loops=1)
Buckets: 1024 Batches: 1 Memory
Usage: 36kB
-> Hash Join
(cost=43792.60..45526.55 rows=1 width=166) (actual time=1768.362..1790.304
rows=180 loops=1)
Hash Cond:
((field_value.id)::text = (artifact.group_fv)::text)
-> Seq Scan on field_value
(cost=0.00..1443.78 rows=77378 width=9) (actual time=0.002..8.687 rows=77378
loops=1)
-> Hash
(cost=43792.58..43792.58 rows=1 width=175) (actual time=1767.928..1767.928
rows=180 loops=1)
Buckets: 1024
Batches: 1 Memory Usage: 38kB
-> Hash Join
(cost=42058.63..43792.58 rows=1 width=175) (actual time=1499.822..1767.734
rows=180 loops=1)
Hash Cond:
((field_value2.id)::text = (artifact.status_fv)::text)
-> Seq Scan on
field_value field_value2 (cost=0.00..1443.78 rows=77378 width=15) (actual
time=0.002..261.082 rows=77378 loops=1)
-> Hash
(cost=42058.61..42058.61 rows=1 width=178) (actual time=1492.707..1492.707
rows=180 loops=1)
Buckets:
1024 Batches: 1 Memory Usage: 38kB
-> Hash
Join (cost=18039.59..42058.61 rows=1 width=178) (actual
time=1175.659..1492.482 rows=180 loops=1)
Hash
Cond: ((item.id)::text = (artifact.id)::text)
->
Hash Join (cost=12112.31..36130.95 rows=30 width=128) (actual
time=304.035..702.745 rows=1015 loops=1)
Hash Cond: ((item.folder_id)::text = (folder.id)::text)
-> Seq Scan on item (cost=0.00..21381.10 rows=703322 width=58) (actual
time=0.020..382.847 rows=704018 loops=1)
Filter: (NOT is_deleted)
-> Hash (cost=12112.27..12112.27 rows=3 width=92) (actual
time=189.285..189.285 rows=10 loops=1)
Buckets: 1024 Batches: 1 Memory Usage: 2kB
-> Hash Join (cost=195.86..12112.27 rows=3 width=92) (actual
time=31.304..189.269 rows=10 loops=1)
Hash Cond: ((folder.id)::text = (tracker.id)::text)
-> Hash Join (cost=8.28..11923.31 rows=155 width=65) (actual
time=3.195..161.619 rows=612 loops=1)
Hash Cond: ((folder.project_id)::text = (project.id)::text)
-> Seq Scan on folder (cost=0.00..10858.71 rows=281271
width=32) (actual time=0.017..75.451 rows=280356 loops=1)
-> Hash (cost=8.27..8.27 rows=1 width=42) (actual
time=0.041..0.041 rows=1 loops=1)
Buckets: 1024 Batches: 1 Memory Usage: 1kB
-> Index Scan using project_path on project
(cost=0.00..8.27 rows=1 width=42) (actual time=0.038..0.039 rows=
1 loops=1)
Index Cond: ((path)::text =
'projects.psr-pub-13'::text)
-> Hash (cost=129.48..129.48 rows=4648 width=27) (actual
time=27.439..27.439 rows=4648 loops=1)
Buckets: 1024 Batches: 1 Memory Usage: 267kB
-> Seq Scan on tracker (cost=0.00..129.48 rows=4648
width=27) (actual time=19.880..25.635 rows=4648 loops=1)
->
Hash (cost=5527.28..5527.28 rows=32000 width=50) (actual time=788.470..788.470
rows=31183 loops=1)
Buckets: 4096 Batches: 1 Memory Usage: 2662kB
-> Bitmap Heap Scan on artifact (cost=628.28..5527.28 rows=32000 width=50)
(actual time=83.568..771.651 rows=31183 loops=1)
Recheck Cond: (priority = 3)
-> Bitmap Index Scan on artifact_priority (cost=0.00..620.28
rows=32000 width=0) (actual time=82.877..82.877 rows=31260 loops=1
)
Index Cond: (priority = 3)
-> Hash (cost=404.33..404.33 rows=5733 width=32) (actual
time=4.232..4.232 rows=5733 loops=1)
Buckets: 1024 Batches: 1 Memory Usage: 364kB
-> Seq Scan on sfuser sfuser2 (cost=0.00..404.33 rows=5733
width=32) (actual time=0.006..1.941 rows=5733 loops=1)
-> Hash (cost=404.33..404.33 rows=5733 width=32) (actual
time=257.485..257.485 rows=5733 loops=1)
Buckets: 1024 Batches: 1 Memory Usage: 364kB
-> Seq Scan on sfuser (cost=0.00..404.33 rows=5733 width=32) (actual
time=9.555..255.085 rows=5733 loops=1)
SubPlan 1
-> Index Scan using mntr_subscr_user on mntr_subscription
(cost=0.00..8.47 rows=1 width=9) (actual time=0.013..0.013 rows=0 loops=180)
Index Cond: ((($0)::text = (object_key)::text) AND ((user_id)::text
= 'user1439'::text))
Total runtime: 2666.011 ms
effective_cache_size | 512MB
Thanks,
Anne
--------------------------------------------------------------
Anne,
So, this shows that original execution plan (with nested loops) was not that
bad.
Still, considering your hardware config (and I think, you mentioned it's a
"dedicated" database server), I'd set:
buffer_cache = 3GB
effective_cache_size = 7GB
buffer_cache is "global" setting and requires Postgres restart after changing
in postgresql.conf.
But, besides postgres config parameters, it seems your particular problem is in
correct setting of conection pooler.
Igor Neyman
--
Sent via pgsql-performance mailing list (pgsql-performance@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-performance
