Re: Deterioration in performance when query executed in multi threads

> -----Original Message-----
> From: Anne Rosset [mailto:arosset(at)collab(dot)net]
> Sent: Friday, May 03, 2013 4:52 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
>
> We saw a little bit improvement by increasing the min_pool_size but
> again I see a bigvariation in the time the query is executed. Here is
> the query:
>
> srdb=> explain analyze SELECT
> psrdb-> artifact.id AS id,
> psrdb-> artifact.priority AS priority,
> psrdb-> project.path AS projectPathString,
> psrdb-> project.title AS projectTitle,
> psrdb-> folder.project_id AS projectId,
> psrdb-> folder.title AS folderTitle,
> psrdb-> item.folder_id AS folderId,
> psrdb-> item.title AS title,
> psrdb-> item.name AS name,
> psrdb-> field_value2.value AS status,
> psrdb-> field_value3.value AS category,
> psrdb-> sfuser.username AS submittedByUsername,
> psrdb-> sfuser.full_name AS submittedByFullname,
> psrdb-> sfuser2.username AS assignedToUsername,
> psrdb-> sfuser2.full_name AS assignedToFullname,
> psrdb-> item.version AS version,
> psrdb-> CASE when ((SELECT
> psrdb(> mntr_subscription.user_id AS userId
> psrdb(> FROM
> psrdb(> mntr_subscription mntr_subscription
> psrdb(> WHERE
> psrdb(> artifact.id=mntr_subscription.object_key
> psrdb(> AND mntr_subscription.user_id='user1439'
> psrdb(> )= 'user1439') THEN 'user1439' ELSE null END AS
> monitoringUserId,
> psrdb-> tracker.icon AS trackerIcon,
> psrdb-> tracker.remaining_effort_disabled AS
> remainingEffortDisabled,
> psrdb-> tracker.actual_effort_disabled AS actualEffortDisabled,
> psrdb-> tracker.estimated_effort_disabled AS
> estimatedEffortDisabled
> psrdb-> FROM
> psrdb-> field_value field_value2,
> psrdb-> field_value field_value,
> psrdb-> sfuser sfuser2,
> psrdb-> field_value field_value3,
> psrdb-> field_value field_value4,
> psrdb-> item item,
> psrdb-> project project,
> psrdb-> relationship relationship,
> psrdb-> tracker tracker,
> psrdb-> artifact artifact,
> psrdb-> sfuser sfuser,
> psrdb-> folder folder
> psrdb-> WHERE
> psrdb-> artifact.id=item.id
> psrdb-> AND item.folder_id=folder.id
> psrdb-> AND folder.project_id=project.id
> psrdb-> AND artifact.group_fv=field_value.id
> psrdb-> AND artifact.status_fv=field_value2.id
> psrdb-> AND artifact.category_fv=field_value3.id
> psrdb-> AND artifact.customer_fv=field_value4.id
> psrdb-> AND item.created_by_id=sfuser.id
> psrdb-> AND relationship.is_deleted=false
> psrdb-> AND
> relationship.relationship_type_name='ArtifactAssignment'
> psrdb-> AND relationship.origin_id=sfuser2.id
> psrdb-> AND artifact.id=relationship.target_id
> psrdb-> AND item.is_deleted=false
> psrdb-> AND ((artifact.priority=3))
> psrdb-> AND (project.path='projects.psr-pub-13')
> psrdb-> AND item.folder_id=tracker.id
> psrdb-> ;
>
> QUERY PLAN
>
> -----------------------------------------------------------------------
> -------------------------------------------------
> -----------------------------------------------------------------------
> ----
> Nested Loop (cost=0.00..272.62 rows=1 width=181) (actual
> time=805.934..1792.596 rows=177 loops=1)
>
> -> Nested Loop (cost=0.00..263.87 rows=1 width=167) (actual
> time=707.739..1553.348 rows=177 loops=1)
>
> -> Nested Loop (cost=0.00..263.58 rows=1 width=153) (actual
> time=653.053..1496.839 rows=177 loops=1)
>
> -> Nested Loop (cost=0.00..262.50 rows=1 width=154)
> (actual time=565.627..1385.667 rows=177 loops=1)
>
> -> Nested Loop (cost=0.00..262.08 rows=1
> width=163) (actual time=565.605..1383.686 rows=177 loops
> =1)
> -> Nested Loop (cost=0.00..261.67 rows=1
> width=166) (actual time=530.928..1347.053 rows=177
> loops=1)
> -> Nested Loop (cost=0.00..261.26
> rows=1 width=175) (actual time=530.866..1345.032
> rows=177 loops=1)
> -> Nested Loop
> (cost=0.00..260.84 rows=1 width=178) (actual time=372.825..1184.
> 668 rows=177 loops=1)
> -> Nested Loop
> (cost=0.00..250.33 rows=29 width=128) (actual time=317.897
> ..534.645 rows=1011 loops=1)
> -> Nested Loop
> (cost=0.00..207.56 rows=3 width=92) (actual time=251
> .014..408.868 rows=10 loops=1)
> -> Nested
> Loop (cost=0.00..163.54 rows=155 width=65) (actual
> time=146.176..382.023 rows=615 loops=1)
> ->
> Index Scan using project_path on project (cost=0.00.
> .8.27 rows=1 width=42) (actual time=76.581..76.583 rows=1 loops=1)
>
> Index Cond: ((path)::text = 'projects.psr-pub-13'::
> text)
> ->
> Index Scan using folder_project on folder (cost=0.00
> ..153.26 rows=161 width=32) (actual time=69.564..305.083 rows=615
> loops=1)
>
> Index Cond: ((folder.project_id)::text = (project.
> id)::text)
> -> Index Scan
> using tracker_pk on tracker (cost=0.00..0.27
> rows=1 width=27) (actual time=0.043..0.043 rows=0 loops=615)
> Index
> Cond: ((tracker.id)::text = (folder.id)::text)
> -> Index Scan using
> item_folder on item (cost=0.00..14.11 rows=12
> width=58) (actual time=7.603..12.532 rows=101 loops=10)
> Index Cond:
> ((item.folder_id)::text = (folder.id)::text)
> Filter: (NOT
> item.is_deleted)
> -> Index Scan using
> artifact_pk on artifact (cost=0.00..0.35 rows=1 width
> =50) (actual time=0.642..0.642 rows=0 loops=1011)
> Index Cond:
> ((artifact.id)::text = (item.id)::text)
> Filter:
> (artifact.priority = 3)
> -> Index Scan using
> field_value_pk on field_value field_value2 (cost=0.00..0.40
> rows=1 width=15) (actual time=0.904..0.905 rows=1 loops=177)
> Index Cond:
> ((field_value2.id)::text = (artifact.status_fv)::text)
> -> Index Scan using field_value_pk on
> field_value (cost=0.00..0.40 rows=1 width=9)
> (actual time=0.010..0.010 rows=1 loops=177)
> Index Cond:
> ((field_value.id)::text = (artifact.group_fv)::text)
> -> Index Scan using field_value_pk on
> field_value field_value3 (cost=0.00..0.40 rows=1
> width=15) (actual time=0.205..0.206 rows=1 loops=177)
> Index Cond: ((field_value3.id)::text =
> (artifact.category_fv)::text)
> -> Index Scan using field_value_pk on field_value
> field_value4 (cost=0.00..0.40 rows=1 width=9)
> (actual time=0.010..0.010 rows=1 loops=177)
> Index Cond: ((field_value4.id)::text =
> (artifact.customer_fv)::text)
> -> Index Scan using relation_target on relationship
> (cost=0.00..1.07 rows=1 width=19) (actual time=0.
> 627..0.627 rows=1 loops=177)
> Index Cond: ((relationship.target_id)::text =
> (artifact.id)::text)
> Filter: ((NOT relationship.is_deleted) AND
> ((relationship.relationship_type_name)::text =
> 'ArtifactAssignment'::text))
> -> Index Scan using sfuser_pk on sfuser sfuser2
> (cost=0.00..0.28 rows=1 width=32) (actual time=0.318..0.318
> rows=1 loops=177)
> Index Cond: ((sfuser2.id)::text =
> (relationship.origin_id)::text)
> -> Index Scan using sfuser_pk on sfuser (cost=0.00..0.27 rows=1
> width=32) (actual time=0.178..0.179 rows=1 loops=
> 177)
> Index Cond: ((sfuser.id)::text = (item.created_by_id)::text)
> SubPlan 1
> -> Index Scan using mntr_subscr_user on mntr_subscription
> (cost=0.00..8.47 rows=1 width=9) (actual time=1.170..1.
> 170 rows=0 loops=177)
> Index Cond: ((($0)::text = (object_key)::text) AND
> ((user_id)::text = 'user1439'::text))
> Total runtime: 1793.203 ms
> (42 rows)
>
>
> Work_mem is set to 64MB
> Shared_buffer to 240MB
> Segment_size is 1GB
> Wal_buffer is 10MB
>
> If you can give me some pointers, I would really appreciate.
> Thanks,
> Anne
>
>

Anne,

So, results of "explain analyze" that you provided - is this the case, when the query considered "slow" (when you have many threads running)?

Looks like optimizer clearly favors "nested loops" (never hash joins). What are the sizes of tables involved in this query?

You never told us about your server hardware configuration: # of CPUs, RAM size? Version of Postgres that you are using?

And, (again) did you consider switching from "client-side polling" to using PgBouncer for pooling purposes? It is very "light-weight" tool and very easy to install/configure.

Regards,
Igor Neyman