Re: Deterioration in performance when query executed in multi threads

________________________________________
From: Anne Rosset [arosset(at)collab(dot)net]
Sent: Monday, May 06, 2013 5:51 PM
To: Igor Neyman; ktm(at)rice(dot)edu
Cc: pgsql-performance(at)postgresql(dot)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