On Saturday 02 June 2007 11:21:41 Michael Fuhr wrote: > If you post an example query and the > EXPLAIN ANALYZE output then we might be able to see if the slowness > is due to query plans. Query 1: (SELECT project.path AS rbac_project_path_string, role_operation.resource_name AS rbac_resource_name, role_operation.resource_value AS rbac_resource_value FROM project project, role role, role_default_user role_default_user, role_operation role_operation WHERE role.id=role_default_user.role_id AND role_default_user.project_id=project.id AND role.id=role_operation.role_id AND role.is_deleted=false AND role_operation.object_type_id='Scm.Repository' AND role_operation.operation_category='use' AND role_operation.operation_name='access' AND project.path='projects.barnes_and_nobles_college_bookse_3' AND project.is_deleted=false AND role_default_user.default_user_class_id='1' ) UNION (SELECT project.path AS rbac_project_path_string, role_operation.resource_name AS rbac_resource_name, role_operation.resource_value AS rbac_resource_value FROM project project, role role, role_default_user role_default_user, role_operation role_operation WHERE role.id=role_default_user.role_id AND role_default_user.project_id=project.id AND role.id=role_operation.role_id AND role.is_deleted=false AND role_operation.object_type_id='Scm.Repository' AND role_operation.operation_category='use' AND role_operation.operation_name='access' AND project.path='projects.barnes_and_nobles_college_bookse_3' AND project.is_deleted=false AND role_default_user.default_user_class_id='2' ) UNION (SELECT project.path AS rbac_project_path_string, role_operation.resource_name AS rbac_resource_name, role_operation.resource_value AS rbac_resource_value FROM project project, role role, role_default_user role_default_user, role_operation role_operation WHERE role.id=role_default_user.role_id AND role_default_user.project_id=project.id AND role.id=role_operation.role_id AND role.is_deleted=false AND role_operation.object_type_id='Scm.Repository' AND role_operation.operation_category='use' AND role_operation.operation_name='access' AND project.path='projects.barnes_and_nobles_college_bookse_3' AND project.is_deleted=false AND role_default_user.default_user_class_id='3' ) UNION (SELECT project.path AS rbac_project_path_string, role_operation.resource_name AS rbac_resource_name, role_operation.resource_value AS rbac_resource_value FROM sfuser sfuser, project project, role role, projectmembership projectmembership, role_default_user role_default_user, role_operation role_operation WHERE role.id=role_default_user.role_id AND role_default_user.project_id=project.id AND role.id=role_operation.role_id AND role.is_deleted=false AND role_operation.object_type_id='Scm.Repository' AND role_operation.operation_category='use' AND role_operation.operation_name='access' AND project.path='projects.barnes_and_nobles_college_bookse_3' AND project.is_deleted=false AND role_default_user.default_user_class_id='4' AND projectmembership.member_id=sfuser.id AND role_default_user.project_id=projectmembership.project_id AND sfuser.username='rtrejo' ) UNION (SELECT project.path AS rbac_project_path_string, role_operation.resource_name AS rbac_resource_name, role_operation.resource_value AS rbac_resource_value FROM sfuser sfuser, project project, role role, role_user role_user, role_operation role_operation WHERE role.id=role_user.role_id AND role_user.project_id=project.id AND role.id=role_operation.role_id AND role.is_deleted=false AND role_operation.object_type_id='Scm.Repository' AND role_operation.operation_category='use' AND role_operation.operation_name='access' AND role_user.user_id=sfuser.id AND project.path='projects.barnes_and_nobles_college_bookse_3' AND project.is_deleted=false AND sfuser.username='rtrejo' ); take 0m1.693s according to 'time' Explain attached as explain1 Query 2: SELECT artifact.id AS id, artifact.priority AS priority, project.path AS projectPathString, project.title AS projectTitle, folder.project_id AS projectId, folder.path AS folderPathString, folder.title AS folderTitle, item.folder_id AS folderId, item.title AS title, item.name AS name, artifact.description AS description, field_value.value AS artifactGroup, field_value2.value AS status, field_value2.value_class AS statusClass, field_value3.value AS category, field_value4.value AS customer, sfuser.username AS submittedByUsername, sfuser.full_name AS submittedByFullname, item.date_created AS submittedDate, artifact.close_date AS closeDate, sfuser2.username AS assignedToUsername, sfuser2.full_name AS assignedToFullname, item.date_last_modified AS lastModifiedDate, artifact.estimated_hours AS estimatedHours, artifact.actual_hours AS actualHours, item.version AS version FROM relationship relationship, sfuser sfuser, sfuser sfuser2, field_value field_value3, item item, project project, field_value field_value2, field_value field_value, artifact artifact, folder folder, field_value field_value4 WHERE artifact.id=item.id AND item.folder_id=folder.id AND folder.project_id=project.id AND artifact.group_fv=field_value.id AND artifact.status_fv=field_value2.id AND artifact.category_fv=field_value3.id AND artifact.customer_fv=field_value4.id AND item.created_by_id=sfuser.id AND relationship.is_deleted=false AND relationship.relationship_type_name='ArtifactAssignment' AND relationship.origin_id=sfuser2.id AND artifact.id=relationship.target_id AND item.is_deleted=false AND ((project.path='projects.union_gas_gdar_ebt' AND ((folder.path IN ('tracker.cutover_tasks', 'tracker.peer_review_tracker', 'tracker.tars_0', 'tracker.reviews', 'tracker.defects', 'tracker.tars', 'tracker.database_change_requests')) OR folder.path LIKE 'tracker.cutover_tasks.%' OR folder.path LIKE 'tracker.peer_review_tracker.%' OR folder.path LIKE 'tracker.tars_0.%' OR folder.path LIKE 'tracker.reviews.%' OR folder.path LIKE 'tracker.defects. %' OR folder.path LIKE 'tracker.tars.%' OR folder.path LIKE 'tracker.database_change_requests.%'))) AND folder.project_id='proj1775' AND item.folder_id='tracker11923' AND folder.path='tracker.defects' AND (sfuser2.username='nobody' AND field_value2.value_class='Open'); takes 0m9.506s according to time.. it's attached as explain2 TIA, again -- Douglas J Hunley (doug at hunley.homeip.net) - Linux User #174778 http://doug.hunley.homeip.net It's not the pace of life that concerns me, it's the sudden stop at the end.
QUERY PLAN ---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- Unique (cost=101.98..102.03 rows=5 width=56) (actual time=3049.469..3049.479 rows=1 loops=1) -> Sort (cost=101.98..101.99 rows=5 width=56) (actual time=3049.461..3049.465 rows=1 loops=1) Sort Key: rbac_project_path_string, rbac_resource_name, rbac_resource_value -> Append (cost=0.00..101.92 rows=5 width=56) (actual time=2101.795..3049.325 rows=1 loops=1) -> Nested Loop (cost=0.00..13.35 rows=1 width=56) (actual time=505.275..505.275 rows=0 loops=1) -> Nested Loop (cost=0.00..12.97 rows=1 width=30) (actual time=505.268..505.268 rows=0 loops=1) -> Nested Loop (cost=0.00..8.68 rows=1 width=42) (actual time=0.347..346.759 rows=7294 loops=1) -> Index Scan using role_oper_obj_oper on role_operation (cost=0.00..4.40 rows=1 width=30) (actual time=0.235..71.840 rows=7294 loops=1) Index Cond: (((object_type_id)::text = 'Scm.Repository'::text) AND ((operation_category)::text = 'use'::text) AND ((operation_name)::text = 'access'::text)) -> Index Scan using role_pk on "role" (cost=0.00..4.27 rows=1 width=12) (actual time=0.020..0.024 rows=1 loops=7294) Index Cond: (("role".id)::text = (role_operation.role_id)::text) Filter: (NOT is_deleted) -> Index Scan using role_def_u_prj_idx on role_default_user (cost=0.00..4.27 rows=1 width=24) (actual time=0.015..0.015 rows=0 loops=7294) Index Cond: ((("role".id)::text = (role_default_user.role_id)::text) AND (role_default_user.default_user_class_id = 1)) -> Index Scan using project_pk on project (cost=0.00..0.37 rows=1 width=50) (never executed) Index Cond: ((role_default_user.project_id)::text = (project.id)::text) Filter: (((path)::text = 'projects.barnes_and_nobles_college_bookse_3'::text) AND (NOT is_deleted)) -> Nested Loop (cost=0.00..13.35 rows=1 width=56) (actual time=442.680..442.680 rows=0 loops=1) -> Nested Loop (cost=0.00..12.97 rows=1 width=30) (actual time=442.674..442.674 rows=0 loops=1) -> Nested Loop (cost=0.00..8.68 rows=1 width=42) (actual time=0.124..289.008 rows=7294 loops=1) -> Index Scan using role_oper_obj_oper on role_operation (cost=0.00..4.40 rows=1 width=30) (actual time=0.093..35.719 rows=7294 loops=1) Index Cond: (((object_type_id)::text = 'Scm.Repository'::text) AND ((operation_category)::text = 'use'::text) AND ((operation_name)::text = 'access'::text)) -> Index Scan using role_pk on "role" (cost=0.00..4.27 rows=1 width=12) (actual time=0.018..0.021 rows=1 loops=7294) Index Cond: (("role".id)::text = (role_operation.role_id)::text) Filter: (NOT is_deleted) -> Index Scan using role_def_u_prj_idx on role_default_user (cost=0.00..4.27 rows=1 width=24) (actual time=0.014..0.014 rows=0 loops=7294) Index Cond: ((("role".id)::text = (role_default_user.role_id)::text) AND (role_default_user.default_user_class_id = 2)) -> Index Scan using project_pk on project (cost=0.00..0.37 rows=1 width=50) (never executed) Index Cond: ((role_default_user.project_id)::text = (project.id)::text) Filter: (((path)::text = 'projects.barnes_and_nobles_college_bookse_3'::text) AND (NOT is_deleted)) -> Nested Loop (cost=0.00..13.35 rows=1 width=56) (actual time=184.063..184.063 rows=0 loops=1) -> Nested Loop (cost=0.00..9.07 rows=1 width=80) (actual time=184.055..184.055 rows=0 loops=1) -> Nested Loop (cost=0.00..8.69 rows=1 width=54) (actual time=8.814..183.848 rows=4 loops=1) -> Index Scan using role_oper_obj_oper on role_operation (cost=0.00..4.40 rows=1 width=30) (actual time=0.095..34.567 rows=7294 loops=1) Index Cond: (((object_type_id)::text = 'Scm.Repository'::text) AND ((operation_category)::text = 'use'::text) AND ((operation_name)::text = 'access'::text)) -> Index Scan using role_def_u_prj_idx on role_default_user (cost=0.00..4.27 rows=1 width=24) (actual time=0.014..0.014 rows=0 loops=7294) Index Cond: (((role_operation.role_id)::text = (role_default_user.role_id)::text) AND (role_default_user.default_user_class_id = 3)) -> Index Scan using project_pk on project (cost=0.00..0.37 rows=1 width=50) (actual time=0.042..0.042 rows=0 loops=4) Index Cond: ((role_default_user.project_id)::text = (project.id)::text) Filter: (((path)::text = 'projects.barnes_and_nobles_college_bookse_3'::text) AND (NOT is_deleted)) -> Index Scan using role_pk on "role" (cost=0.00..4.27 rows=1 width=12) (never executed) Index Cond: (("role".id)::text = (role_default_user.role_id)::text) Filter: (NOT is_deleted) -> Nested Loop (cost=0.00..16.02 rows=1 width=56) (actual time=202.991..202.991 rows=0 loops=1) -> Nested Loop (cost=0.00..15.73 rows=1 width=42) (actual time=202.984..202.984 rows=0 loops=1) -> Nested Loop (cost=0.00..11.45 rows=1 width=66) (actual time=202.978..202.978 rows=0 loops=1) Join Filter: ((projectmembership.member_id)::text = (sfuser.id)::text) -> Nested Loop (cost=0.00..10.13 rows=4 width=78) (actual time=10.425..190.540 rows=437 loops=1) -> Nested Loop (cost=0.00..8.69 rows=1 width=54) (actual time=8.747..182.982 rows=10 loops=1) -> Index Scan using role_oper_obj_oper on role_operation (cost=0.00..4.40 rows=1 width=30) (actual time=0.093..34.379 rows=7294 loops=1) Index Cond: (((object_type_id)::text = 'Scm.Repository'::text) AND ((operation_category)::text = 'use'::text) AND ((operation_name)::text = 'access'::text)) -> Index Scan using role_def_u_prj_idx on role_default_user (cost=0.00..4.27 rows=1 width=24) (actual time=0.014..0.014 rows=0 loops=7294) Index Cond: (((role_operation.role_id)::text = (role_default_user.role_id)::text) AND (role_default_user.default_user_class_id = 4)) -> Index Scan using pjmb_projmember on projectmembership (cost=0.00..1.13 rows=25 width=24) (actual time=0.053..0.453 rows=44 loops=10) Index Cond: ((role_default_user.project_id)::text = (projectmembership.project_id)::text) -> Index Scan using sfuser_username on sfuser (cost=0.00..0.32 rows=1 width=12) (actual time=0.014..0.018 rows=1 loops=437) Index Cond: ((username)::text = 'rtrejo'::text) -> Index Scan using role_pk on "role" (cost=0.00..4.27 rows=1 width=12) (never executed) Index Cond: (("role".id)::text = (role_default_user.role_id)::text) Filter: (NOT is_deleted) -> Index Scan using project_pk on project (cost=0.00..0.28 rows=1 width=50) (never executed) Index Cond: ((role_default_user.project_id)::text = (project.id)::text) Filter: (((path)::text = 'projects.barnes_and_nobles_college_bookse_3'::text) AND (NOT is_deleted)) -> Nested Loop (cost=2.40..45.80 rows=1 width=56) (actual time=766.764..1714.288 rows=1 loops=1) Join Filter: ((role_user.user_id)::text = (sfuser.id)::text) -> Nested Loop (cost=2.40..45.49 rows=1 width=68) (actual time=762.629..1712.222 rows=82 loops=1) -> Nested Loop (cost=2.40..44.63 rows=3 width=42) (actual time=0.356..944.773 rows=37814 loops=1) -> Nested Loop (cost=0.00..8.68 rows=1 width=42) (actual time=0.134..272.836 rows=7294 loops=1) -> Index Scan using role_oper_obj_oper on role_operation (cost=0.00..4.40 rows=1 width=30) (actual time=0.098..34.408 rows=7294 loops=1) Index Cond: (((object_type_id)::text = 'Scm.Repository'::text) AND ((operation_category)::text = 'use'::text) AND ((operation_name)::text = 'access'::text)) -> Index Scan using role_pk on "role" (cost=0.00..4.27 rows=1 width=12) (actual time=0.016..0.019 rows=1 loops=7294) Index Cond: (("role".id)::text = (role_operation.role_id)::text) Filter: (NOT is_deleted) -> Bitmap Heap Scan on role_user (cost=2.40..35.73 rows=18 width=36) (actual time=0.029..0.050 rows=5 loops=7294) Recheck Cond: (("role".id)::text = (role_user.role_id)::text) -> Bitmap Index Scan on role_user_proj_idx (cost=0.00..2.39 rows=18 width=0) (actual time=0.021..0.021 rows=5 loops=7294) Index Cond: (("role".id)::text = (role_user.role_id)::text) -> Index Scan using project_pk on project (cost=0.00..0.27 rows=1 width=50) (actual time=0.014..0.014 rows=0 loops=37814) Index Cond: ((role_user.project_id)::text = (project.id)::text) Filter: (((path)::text = 'projects.barnes_and_nobles_college_bookse_3'::text) AND (NOT is_deleted)) -> Index Scan using sfuser_username on sfuser (cost=0.00..0.30 rows=1 width=12) (actual time=0.012..0.015 rows=1 loops=82) Index Cond: ((username)::text = 'rtrejo'::text) Total runtime: 3050.582 ms (83 rows)
QUERY PLAN ----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- Nested Loop (cost=6.67..616.24 rows=1 width=629) (actual time=11870.870..11870.870 rows=0 loops=1) -> Nested Loop (cost=6.67..611.96 rows=1 width=555) (actual time=11870.863..11870.863 rows=0 loops=1) -> Nested Loop (cost=6.67..607.64 rows=1 width=492) (actual time=11870.857..11870.857 rows=0 loops=1) -> Nested Loop (cost=6.67..606.26 rows=1 width=471) (actual time=11870.850..11870.850 rows=0 loops=1) -> Nested Loop (cost=6.67..605.92 rows=1 width=473) (actual time=11870.844..11870.844 rows=0 loops=1) -> Nested Loop (cost=6.67..605.58 rows=1 width=475) (actual time=11870.838..11870.838 rows=0 loops=1) -> Nested Loop (cost=6.67..605.23 rows=1 width=477) (actual time=11870.831..11870.831 rows=0 loops=1) -> Nested Loop (cost=6.67..602.90 rows=3 width=393) (actual time=62.032..10750.797 rows=29905 loops=1) -> Nested Loop (cost=6.67..595.64 rows=21 width=387) (actual time=61.558..6905.828 rows=126625 loops=1) -> Nested Loop (cost=6.67..585.73 rows=21 width=46) (actual time=61.399..1590.547 rows=126625 loops=1) -> Index Scan using sfuser_username on sfuser sfuser2 (cost=0.00..4.27 rows=1 width=45) (actual time=0.122..0.127 rows=1 loops=1) Index Cond: ((username)::text = 'nobody'::text) -> Bitmap Heap Scan on relationship (cost=6.67..577.58 rows=311 width=25) (actual time=61.260..783.652 rows=126625 loops=1) Recheck Cond: ((relationship.origin_id)::text = (sfuser2.id)::text) Filter: ((NOT is_deleted) AND ((relationship_type_name)::text = 'ArtifactAssignment'::text)) -> Bitmap Index Scan on relation_origin (cost=0.00..6.62 rows=311 width=0) (actual time=57.009..57.009 rows=220230 loops=1) Index Cond: ((relationship.origin_id)::text = (sfuser2.id)::text) -> Index Scan using artifact_pk on artifact (cost=0.00..0.46 rows=1 width=341) (actual time=0.025..0.029 rows=1 loops=126625) Index Cond: ((artifact.id)::text = (relationship.target_id)::text) -> Index Scan using field_value_pk on field_value field_value2 (cost=0.00..0.33 rows=1 width=32) (actual time=0.021..0.022 rows=0 loops=126625) Index Cond: ((artifact.status_fv)::text = (field_value2.id)::text) Filter: ((value_class)::text = 'Open'::text) -> Index Scan using item_pk on item (cost=0.00..0.76 rows=1 width=110) (actual time=0.031..0.031 rows=0 loops=29905) Index Cond: ((artifact.id)::text = (item.id)::text) Filter: ((NOT is_deleted) AND ((folder_id)::text = 'tracker11923'::text)) -> Index Scan using field_value_pk on field_value field_value4 (cost=0.00..0.33 rows=1 width=24) (never executed) Index Cond: ((artifact.customer_fv)::text = (field_value4.id)::text) -> Index Scan using field_value_pk on field_value (cost=0.00..0.33 rows=1 width=24) (never executed) Index Cond: ((artifact.group_fv)::text = (field_value.id)::text) -> Index Scan using field_value_pk on field_value field_value3 (cost=0.00..0.33 rows=1 width=24) (never executed) Index Cond: ((artifact.category_fv)::text = (field_value3.id)::text) -> Index Scan using sfuser_pk on sfuser (cost=0.00..1.37 rows=1 width=45) (never executed) Index Cond: ((item.created_by_id)::text = (sfuser.id)::text) -> Index Scan using folder_pk on folder (cost=0.00..4.31 rows=1 width=77) (never executed) Index Cond: ('tracker11923'::text = (id)::text) Filter: ((((path)::text = ANY (('{tracker.cutover_tasks,tracker.peer_review_tracker,tracker.tars_0,tracker.reviews,tracker.defects,tracker.tars,tracker.database_change_requests}'::character varying[])::text[])) OR ((path)::text ~~ 'tracker.cutover_tasks.%'::text) OR ((path)::text ~~ 'tracker.peer_review_tracker.%'::text) OR ((path)::text ~~ 'tracker.tars_0.%'::text) OR ((path)::text ~~ 'tracker.reviews.%'::text) OR ((path)::text ~~ 'tracker.defects.%'::text) OR ((path)::text ~~ 'tracker.tars.%'::text) OR ((path)::text ~~ 'tracker.database_change_requests.%'::text)) AND ((project_id)::text = 'proj1775'::text) AND ((path)::text = 'tracker.defects'::text)) -> Index Scan using project_pk on project (cost=0.00..4.27 rows=1 width=86) (never executed) Index Cond: ('proj1775'::text = (id)::text) Filter: ((path)::text = 'projects.union_gas_gdar_ebt'::text) Total runtime: 11871.582 ms (40 rows)