Re: 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

-----Original Message-----
From: Igor Neyman [mailto:ineyman(at)perceptron(dot)com]
Sent: Monday, May 06, 2013 10:13 AM
To: Anne Rosset; ktm(at)rice(dot)edu
Cc: pgsql-performance(at)postgresql(dot)org
Subject: RE: [PERFORM] Deterioration in performance when query executed in multi threads

> -----Original Message-----
> From: Anne Rosset [mailto:arosset(at)collab(dot)net]
> Sent: Monday, May 06, 2013 1:01 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,
> The explain analyze is from when there was no load.
>
> Artifact table: 251831 rows
> Field_value table: 77378 rows
> Mntr_subscription: 929071 rows
> Relationship: 270478 row
> Folder: 280356 rows
> Item: 716465 rows
> Sfuser: 5733 rows
> Project: 1817 rows
>
> 8CPUs
> RAM: 8GB
>
> Postgres version: 9.0.13
>
> And no we haven't switched or tested yet with pgbouncer. We would
> like to do a bit more analysis before trying this.
>
> Thanks for your help,
> Anne
>
>

Anne,

Just as a quick test, try in the psql session/connection locally change enable_nestloop setting and run your query:

set enable_nestloop = off;
explain analyze <your_query>;

just to see if different execution plan will be better and optimizer needs to be "convinced" to use this different plan.
Please post what you get with the modified setting.

Also, what is the setting for effective_cache_size in postgresql.conf?

Regards,
Igor Neyman